1tnfdump(1) User Commands tnfdump(1)
2
6 tnfdump - convert binary TNF file to ASCII
7
9 tnfdump [-r] [-x] tnf_file...
10
13 The tnfdump utility converts the specified binary TNF trace files to
14 ASCII. The ASCII output can be used to do performance analysis. The
15 default mode (without the -r option) prints all the event records (that
16 were generated by TNF_PROBE(3TNF)) and the event descriptor records
17 only. It also orders the events by time.
18
20 The following option is supported:
21 -r Does a raw conversion of TNF to ASCII. The output is a literal
23 transalation of the binary TNF file and includes all the records
24 in the file. This output is useful only if you have a good
25 understanding of TNF. A sample output is listed in EXAMPLES
26 below.
27 -x Prints all TNF unsigned type argument values in hexadecimal for‐
30 mat instead of decimal format.
31
34 tnfdump returns 0 on succcessful exit.
35
37 Example 1 Converting a file into ASCII
38 To convert the file /tmp/trace-2130 into ASCII, use the tnfdump command
41 and the name of the binary trace file. Be aware that the tnfdump output
42 goes to stdout by default.
43 example% tnfdump /tmp/trace-2130
46 probe tnf_name: "inloop" tnf_string: "keys cookie main loop;\
50 file cookie2.c;line 50;sunw%debug in the loop"
51 probe tnf_name: "end" tnf_string: "keys cookie main end;\
52 file cookie2.c;line 41;sunw%debug exiting program"
53 ------------- ----------- ---- ------ --- ---------- ----------------
54 Elapsed (ms) Delta (ms) PID LWPID TID CPU Probe Data/
55 Name Description . . .
56 ------------- ----------- ---- ------ --- ---------- ----------------
57 0.000000 0.000000 8792 1 0 - inloop loop_count: 0
58 total_iterations: 0
59 0.339000 0.339000 8792 1 0 - inloop loop_count: 1
60 total_iterations: 1
61 0.350500 0.011500 8792 1 0 - inloop loop_count: 2
62 total_iterations: 2
63 0.359500 0.009000 8792 1 0 - inloop loop_count: 3
64 total_iterations: 3
65 0.369500 0.010000 8792 1 0 - inloop loop_count: 4
66 total_iterations: 4
67 7775.969500 7775.600000 8792 1 0 - inloop loop_count: 0
68 total_iterations: 5
69 7776.016000 0.046500 8792 1 0 - inloop loop_count: 1
70 total_iterations: 6
71 7776.025000 0.009000 8792 1 0 - inloop loop_count: 2
72 total_iterations: 7
73 7776.034000 0.009000 8792 1 0 - inloop loop_count: 3
74 total_iterations: 8
75 7776.043000 0.009000 8792 1 0 - inloop loop_count: 4
76 total_iterations: 9
77 7776.052000 0.009000 8792 1 0 - inloop loop_count: 5
78 total_iterations: 10
79 7776.061000 0.009000 8792 1 0 - inloop loop_count: 6
80 total_iterations: 11
81 9475.979500 1699.918500 8792 1 0 - end node_struct:
82 { type: node_tnf
83 cur_sum: 9 max_cnt: 12 }
84 All probes that are encountered during execution have a description of
89 it printed out. The description is one per line prefixed by the key‐
90 word 'probe'. The name of the probe is in double quotes after the key‐
91 word 'tnf_name'. The description of this probe is in double quotes
92 after the keyword 'tnf_string'.
93 A heading is printed after all the description of the probes are
97 printed. The first column gives the elapsed time in milli-seconds since
98 the first event. The second column gives the elapsed time in milli-sec‐
99 onds since the previous event. The next four columns are the process
100 id, lwp id, thread id, and cpu number. The next column is the name of
101 the probe that generated this event. This can be matched to the probe
102 description explained above. The last column is the data that the event
103 contains, formatted as arg_name_n (see TNF_PROBE(3TNF)) followed by a
104 colon and the value of that argument. The format of the value depends
105 on its type. tnf_opaque arguments are printed in hexadecimal. All other
106 integers are printed in decimal. Strings are printed in double quotes
107 and user-defined records are enclosed in braces `{ }'. The first field
108 of a user defined record indicates its TNF type (see
109 TNF_DECLARE_RECORD(3TNF)). The rest of the fields are the members of
110 the record.
111 A `-' in any column indicates that there is no data for that particular
115 column.
116 Example 2 To do a raw conversion of a file into ASCII
119 To do a raw conversion of the file /tmp/trace-4000 into ASCII, use:
122 example% tnfdump -r /tmp/trace-4000
125 The output will look like the following:
130 0x10e00 : {
133 tnf_tag 0x109c0 tnf_block_header
134 generation 1
135 bytes_valid 320
136 A_lock 0
137 B_lock 0
138 next_block 0x0
139 }
140 0x10e10 : {
141 tnf_tag 0x10010 probe1
142 tnf_tag_arg 0x10e24 <tnf_sched_rec>
143 time_delta 128
144 test_ulong 4294967295
145 test_long -1
146 }
147 0x10e24 : {
148 tnf_tag 0x10cf4 tnf_sched_rec
149 tid 0
150 lwpid 1
151 pid 13568
152 time_base 277077875828500
153 }
154 0x10e3c : {
155 tnf_tag 0x11010 probe2
156 tnf_tag_arg 0x10e24 <tnf_sched_rec>
157 time_delta 735500
158 test_str 0x10e48 "string1"
159 }
160 0x10e48 : {
161 tnf_tag 0x1072c tnf_string
162 tnf_self_size 16
163 chars "string1"
164 }
165 0x10e58 : {
166 tnf_tag 0x110ec probe3
167 tnf_tag_arg 0x10e24 <tnf_sched_rec>
168 time_delta 868000
169 test_ulonglong 18446744073709551615
170 test_longlong -1
171 test_float 3.142857
172 }
173 ...
174 ...
175 ...
176 0x110ec : {
177 tnf_tag 0x10030 tnf_probe_type
178 tnf_tag_code 42
179 tnf_name 0x1110c "probe3"
180 tnf_properties 0x1111c <tnf_properties>
181 tnf_slot_types 0x11130 <tnf_slot_types>
182 tnf_type_size 32
183 tnf_slot_names 0x111c4 <tnf_slot_names>
184 tnf_string 0x11268 "keys targdebug main;\
185 file targdebug.c;line 61;"
186 }
187 0x1110c : {
188 tnf_tag 0x10068 tnf_name
189 tnf_self_size 16
190 chars "probe3"
191 }
192 0x1111c : {
193 tnf_tag 0x100b4 tnf_properties
194 tnf_self_size 20
195 0 0x101a0 tnf_tagged
196 1 0x101c4 tnf_struct
197 2 0x10b84 tnf_tag_arg
198 }
199 0x11130 : {
200 tnf_tag 0x10210 tnf_slot_types
201 tnf_self_size 28
202 0 0x10bd0 tnf_probe_event
203 1 0x10c20 tnf_time_delta
204 2 0x1114c tnf_uint64
205 3 0x10d54 tnf_int64
206 4 0x11188 tnf_float32
207 }
208 The first number is the file offset of the record. The record is
213 enclosed in braces `{ }'. The first column in a record is the slot name
214 (for records whose fields do not have names, it is the type name). The
215 second column in the record is the value of that slot if it is a scalar
216 (only scalars that are of type tnf_opaque are printed in hex), or the
217 offset of the record if it is a reference to another record.
218 The third column in a record is optional. It does not exist for scalar
222 slots of records. If it exists, the third column is a type name with or
223 without angle brackets, or a string in double quotes. Unadorned names
224 indicate a reference to the named metatag record (that is, a reference
225 to a record with that name in the tnf_name field). Type names in angled
226 brackets indicate a reference to a record that is an instance of that
227 type (that is, a reference to a record with that name in the tnf_tag
228 field). The content of strings are printed out in double quotes at the
229 reference site.
230 Records that are arrays have their array elements follow the header
234 slots, and are numbered 0, 1, 2, and so on, except strings where the
235 string is written as the 'chars' (pseudo-name) slot.
236 Records that are events (generated by TNF_PROBE(3TNF)) will have a
240 slot name of tnf_tag_arg as their second field which is a reference to
241 the schedule record. Schedule records describe more information about
242 the event like the thread-id, process-id, and the time_base. The
243 time_delta of an event can be added to the time_base of the schedule
244 record that the event references, to give an absolute time. This time
245 is expressed as nanoseconds since some arbitrary time in the past (see
246 gethrtime(3C)).
247 Example 3 Printing TNF unsigned arguments in hexadecimal
250 To print TNF unsigned arguments in hexadecimal for the file
253 /tmp/trace-2192, use:
254 example% tnfdump -x /tmp/trace-2192
257 The output will look like the following:
262 probe tnf_name: "start" tnf_string: "keys cookie main;
265 file test17.c;line 20;sunw%debug starting main"
266 probe tnf_name: "inloop" tnf_string: "keys cookie main
267 loop;file test17.c;line 41;sunw%debug in the loop"
268 probe tnf_name: "final" tnf_string: "keys cookie main
269 final;file test17.c;line 32;sunw%debug in the final"
270 ------------ ----------- ---- ----- --- --------- ---------------------
271 Elapsed Delta PID LWPID TID CPU Probe Data/Description ...
272 (ms) (ms) Name
273 ------------ ----------- ---- ----- --- --------- ---------------------
274 0.000000 0.000000 6280 1 1 - start
275 2455.211311 2455.211311 6280 1 1 - inloop loop_count: 0x0
276 total_iterations: 0x0
277 2455.215768 0.004457 6280 1 1 - inloop loop_count: 0x1
278 total_iterations: 0x1
279 2455.217041 0.001273 6280 1 1 - inloop loop_count: 0x2
280 total_iterations: 0x2
281 2455.218285 0.001244 6280 1 1 - inloop loop_count: 0x3
282 total_iterations: 0x3
283 2455.219600 0.001315 6280 1 1 - inloop loop_count: 0x4
284 total_iterations: 0x4
285 4058.815125 1603.595525 6280 1 1 - inloop loop_count: 0x0
286 total_iterations: 0x5
287 4058.818699 0.003574 6280 1 1 - inloop loop_count: 0x1
288 total_iterations: 0x6
289 4058.819931 0.001232 6280 1 1 - inloop loop_count: 0x2
290 total_iterations: 0x7
291 4058.821264 0.001333 6280 1 1 - inloop loop_count: 0x3
292 total_iterations: 0x8
293 4058.822520 0.001256 6280 1 1 - inloop loop_count: 0x4
294 total_iterations: 0x9
295 4058.823781 0.001261 6280 1 1 - inloop loop_count: 0x5
296 total_iterations: 0xa
297 4058.825037 0.001256 6280 1 1 - inloop loop_count: 0x6
298 total_iterations: 0xb
299 13896.655450 9837.830413 6280 1 1 - final loop_count16: 0x258
300 total_iterations8: 0xb0
301 ::
302 ::
303 ::
304 Notice that the loop_count and the total_iterations are TNF unsigned
309 arguments. Their values are printed in hexadecimal when requested by
310 option -x.
311
314 See attributes(5) for descriptions of the following attributes:
315 ┌─────────────────────────────┬─────────────────────────────┐
320 │ ATTRIBUTE TYPE │ ATTRIBUTE VALUE │
321 ├─────────────────────────────┼─────────────────────────────┤
322 │Availability │SUNWtnfd │
323 └─────────────────────────────┴─────────────────────────────┘
324
326 prex(1), gethrtime(3C), TNF_DECLARE_RECORD(3TNF), TNF_PROBE(3TNF),
327 tnf_process_disable(3TNF), attributes(5)
328SunOS 5.11 22 Jan 2001 tnfdump(1)