Line | Count | Source (jump to first uncovered line) |
1 | | #include "git-compat-util.h" |
2 | | #include "config.h" |
3 | | #include "json-writer.h" |
4 | | #include "quote.h" |
5 | | #include "repository.h" |
6 | | #include "run-command.h" |
7 | | #include "sigchain.h" |
8 | | #include "thread-utils.h" |
9 | | #include "version.h" |
10 | | #include "trace.h" |
11 | | #include "trace2.h" |
12 | | #include "trace2/tr2_cfg.h" |
13 | | #include "trace2/tr2_cmd_name.h" |
14 | | #include "trace2/tr2_ctr.h" |
15 | | #include "trace2/tr2_dst.h" |
16 | | #include "trace2/tr2_sid.h" |
17 | | #include "trace2/tr2_sysenv.h" |
18 | | #include "trace2/tr2_tgt.h" |
19 | | #include "trace2/tr2_tls.h" |
20 | | #include "trace2/tr2_tmr.h" |
21 | | |
22 | | static int trace2_enabled; |
23 | | |
24 | | static int tr2_next_child_id; /* modify under lock */ |
25 | | static int tr2_next_exec_id; /* modify under lock */ |
26 | | static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */ |
27 | | |
28 | | /* |
29 | | * A table of the builtin TRACE2 targets. Each of these may be independently |
30 | | * enabled or disabled. Each TRACE2 API method will try to write an event to |
31 | | * *each* of the enabled targets. |
32 | | */ |
33 | | /* clang-format off */ |
34 | | static struct tr2_tgt *tr2_tgt_builtins[] = |
35 | | { |
36 | | &tr2_tgt_normal, |
37 | | &tr2_tgt_perf, |
38 | | &tr2_tgt_event, |
39 | | NULL |
40 | | }; |
41 | | /* clang-format on */ |
42 | | |
43 | | /* clang-format off */ |
44 | | #define for_each_builtin(j, tgt_j) \ |
45 | 0 | for (j = 0, tgt_j = tr2_tgt_builtins[j]; \ |
46 | 0 | tgt_j; \ |
47 | 0 | j++, tgt_j = tr2_tgt_builtins[j]) |
48 | | /* clang-format on */ |
49 | | |
50 | | /* clang-format off */ |
51 | | #define for_each_wanted_builtin(j, tgt_j) \ |
52 | 0 | for_each_builtin(j, tgt_j) \ |
53 | 0 | if (tr2_dst_trace_want(tgt_j->pdst)) |
54 | | /* clang-format on */ |
55 | | |
56 | | /* |
57 | | * Force (rather than lazily) initialize any of the requested |
58 | | * builtin TRACE2 targets at startup (and before we've seen an |
59 | | * actual TRACE2 event call) so we can see if we need to setup |
60 | | * private data structures and thread-local storage. |
61 | | * |
62 | | * Return the number of builtin targets enabled. |
63 | | */ |
64 | | static int tr2_tgt_want_builtins(void) |
65 | 0 | { |
66 | 0 | struct tr2_tgt *tgt_j; |
67 | 0 | int j; |
68 | 0 | int sum = 0; |
69 | |
|
70 | 0 | for_each_builtin (j, tgt_j) |
71 | 0 | if (tgt_j->pfn_init()) |
72 | 0 | sum++; |
73 | |
|
74 | 0 | return sum; |
75 | 0 | } |
76 | | |
77 | | /* |
78 | | * Properly terminate each builtin target. Give each target |
79 | | * a chance to write a summary event and/or flush if necessary |
80 | | * and then close the fd. |
81 | | */ |
82 | | static void tr2_tgt_disable_builtins(void) |
83 | 0 | { |
84 | 0 | struct tr2_tgt *tgt_j; |
85 | 0 | int j; |
86 | |
|
87 | 0 | for_each_builtin (j, tgt_j) |
88 | 0 | tgt_j->pfn_term(); |
89 | 0 | } |
90 | | |
91 | | /* |
92 | | * The signature of this function must match the pfn_timer |
93 | | * method in the targets. (Think of this is an apply operation |
94 | | * across the set of active targets.) |
95 | | */ |
96 | | static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata *meta, |
97 | | const struct tr2_timer *timer, |
98 | | int is_final_data) |
99 | 0 | { |
100 | 0 | struct tr2_tgt *tgt_j; |
101 | 0 | int j; |
102 | |
|
103 | 0 | for_each_wanted_builtin (j, tgt_j) |
104 | 0 | if (tgt_j->pfn_timer) |
105 | 0 | tgt_j->pfn_timer(meta, timer, is_final_data); |
106 | 0 | } |
107 | | |
108 | | /* |
109 | | * The signature of this function must match the pfn_counter |
110 | | * method in the targets. |
111 | | */ |
112 | | static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata *meta, |
113 | | const struct tr2_counter *counter, |
114 | | int is_final_data) |
115 | 0 | { |
116 | 0 | struct tr2_tgt *tgt_j; |
117 | 0 | int j; |
118 | |
|
119 | 0 | for_each_wanted_builtin (j, tgt_j) |
120 | 0 | if (tgt_j->pfn_counter) |
121 | 0 | tgt_j->pfn_counter(meta, counter, is_final_data); |
122 | 0 | } |
123 | | |
124 | | static int tr2main_exit_code; |
125 | | |
126 | | /* |
127 | | * Our atexit routine should run after everything has finished. |
128 | | * |
129 | | * Note that events generated here might not actually appear if |
130 | | * we are writing to fd 1 or 2 and our atexit routine runs after |
131 | | * the pager's atexit routine (since it closes them to shutdown |
132 | | * the pipes). |
133 | | */ |
134 | | static void tr2main_atexit_handler(void) |
135 | 0 | { |
136 | 0 | struct tr2_tgt *tgt_j; |
137 | 0 | int j; |
138 | 0 | uint64_t us_now; |
139 | 0 | uint64_t us_elapsed_absolute; |
140 | |
|
141 | 0 | us_now = getnanotime() / 1000; |
142 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
143 | | |
144 | | /* |
145 | | * Clear any unbalanced regions so that our atexit message |
146 | | * does not appear nested. This improves the appearance of |
147 | | * the trace output if someone calls die(), for example. |
148 | | */ |
149 | 0 | tr2tls_pop_unwind_self(); |
150 | | |
151 | | /* |
152 | | * Some timers want per-thread details. If the main thread |
153 | | * used one of those timers, emit the details now (before |
154 | | * we emit the aggregate timer values). |
155 | | * |
156 | | * Likewise for counters. |
157 | | */ |
158 | 0 | tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); |
159 | 0 | tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); |
160 | | |
161 | | /* |
162 | | * Add stopwatch timer and counter data for the main thread to |
163 | | * the final totals. And then emit the final values. |
164 | | * |
165 | | * Technically, we shouldn't need to hold the lock to update |
166 | | * and output the final_timer_block and final_counter_block |
167 | | * (since all other threads should be dead by now), but it |
168 | | * doesn't hurt anything. |
169 | | */ |
170 | 0 | tr2tls_lock(); |
171 | 0 | tr2_update_final_timers(); |
172 | 0 | tr2_update_final_counters(); |
173 | 0 | tr2_emit_final_timers(tr2_tgt_emit_a_timer); |
174 | 0 | tr2_emit_final_counters(tr2_tgt_emit_a_counter); |
175 | 0 | tr2tls_unlock(); |
176 | |
|
177 | 0 | for_each_wanted_builtin (j, tgt_j) |
178 | 0 | if (tgt_j->pfn_atexit) |
179 | 0 | tgt_j->pfn_atexit(us_elapsed_absolute, |
180 | 0 | tr2main_exit_code); |
181 | |
|
182 | 0 | tr2_tgt_disable_builtins(); |
183 | |
|
184 | 0 | tr2tls_release(); |
185 | 0 | tr2_sid_release(); |
186 | 0 | tr2_cmd_name_release(); |
187 | 0 | tr2_cfg_free_patterns(); |
188 | 0 | tr2_cfg_free_env_vars(); |
189 | 0 | tr2_sysenv_release(); |
190 | |
|
191 | 0 | trace2_enabled = 0; |
192 | 0 | } |
193 | | |
194 | | static void tr2main_signal_handler(int signo) |
195 | 0 | { |
196 | 0 | struct tr2_tgt *tgt_j; |
197 | 0 | int j; |
198 | 0 | uint64_t us_now; |
199 | 0 | uint64_t us_elapsed_absolute; |
200 | |
|
201 | 0 | us_now = getnanotime() / 1000; |
202 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
203 | |
|
204 | 0 | for_each_wanted_builtin (j, tgt_j) |
205 | 0 | if (tgt_j->pfn_signal) |
206 | 0 | tgt_j->pfn_signal(us_elapsed_absolute, signo); |
207 | |
|
208 | 0 | sigchain_pop(signo); |
209 | 0 | raise(signo); |
210 | 0 | } |
211 | | |
212 | | void trace2_initialize_clock(void) |
213 | 0 | { |
214 | 0 | tr2tls_start_process_clock(); |
215 | 0 | } |
216 | | |
217 | | void trace2_initialize_fl(const char *file, int line) |
218 | 0 | { |
219 | 0 | struct tr2_tgt *tgt_j; |
220 | 0 | int j; |
221 | |
|
222 | 0 | if (trace2_enabled) |
223 | 0 | return; |
224 | | |
225 | 0 | tr2_sysenv_load(); |
226 | |
|
227 | 0 | if (!tr2_tgt_want_builtins()) |
228 | 0 | return; |
229 | 0 | trace2_enabled = 1; |
230 | |
|
231 | 0 | tr2_sid_get(); |
232 | |
|
233 | 0 | atexit(tr2main_atexit_handler); |
234 | 0 | sigchain_push(SIGPIPE, tr2main_signal_handler); |
235 | 0 | tr2tls_init(); |
236 | | |
237 | | /* |
238 | | * Emit 'version' message on each active builtin target. |
239 | | */ |
240 | 0 | for_each_wanted_builtin (j, tgt_j) |
241 | 0 | if (tgt_j->pfn_version_fl) |
242 | 0 | tgt_j->pfn_version_fl(file, line); |
243 | 0 | } |
244 | | |
245 | | int trace2_is_enabled(void) |
246 | 22.6k | { |
247 | 22.6k | return trace2_enabled; |
248 | 22.6k | } |
249 | | |
250 | | void trace2_cmd_start_fl(const char *file, int line, const char **argv) |
251 | 0 | { |
252 | 0 | struct tr2_tgt *tgt_j; |
253 | 0 | int j; |
254 | 0 | uint64_t us_now; |
255 | 0 | uint64_t us_elapsed_absolute; |
256 | |
|
257 | 0 | if (!trace2_enabled) |
258 | 0 | return; |
259 | | |
260 | 0 | us_now = getnanotime() / 1000; |
261 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
262 | |
|
263 | 0 | for_each_wanted_builtin (j, tgt_j) |
264 | 0 | if (tgt_j->pfn_start_fl) |
265 | 0 | tgt_j->pfn_start_fl(file, line, us_elapsed_absolute, |
266 | 0 | argv); |
267 | 0 | } |
268 | | |
269 | | void trace2_cmd_exit_fl(const char *file, int line, int code) |
270 | 0 | { |
271 | 0 | struct tr2_tgt *tgt_j; |
272 | 0 | int j; |
273 | 0 | uint64_t us_now; |
274 | 0 | uint64_t us_elapsed_absolute; |
275 | |
|
276 | 0 | if (!trace2_enabled) |
277 | 0 | return; |
278 | | |
279 | 0 | trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT); |
280 | |
|
281 | 0 | tr2main_exit_code = code; |
282 | |
|
283 | 0 | us_now = getnanotime() / 1000; |
284 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
285 | |
|
286 | 0 | for_each_wanted_builtin (j, tgt_j) |
287 | 0 | if (tgt_j->pfn_exit_fl) |
288 | 0 | tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute, |
289 | 0 | code); |
290 | 0 | } |
291 | | |
292 | | void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt, |
293 | | va_list ap) |
294 | 1.02k | { |
295 | 1.02k | struct tr2_tgt *tgt_j; |
296 | 1.02k | int j; |
297 | | |
298 | 1.02k | if (!trace2_enabled) |
299 | 1.02k | return; |
300 | | |
301 | | /* |
302 | | * We expect each target function to treat 'ap' as constant |
303 | | * and use va_copy (because an 'ap' can only be walked once). |
304 | | */ |
305 | 1.02k | for_each_wanted_builtin (j, tgt_j) |
306 | 0 | if (tgt_j->pfn_error_va_fl) |
307 | 0 | tgt_j->pfn_error_va_fl(file, line, fmt, ap); |
308 | 0 | } |
309 | | |
310 | | void trace2_cmd_path_fl(const char *file, int line, const char *pathname) |
311 | 0 | { |
312 | 0 | struct tr2_tgt *tgt_j; |
313 | 0 | int j; |
314 | |
|
315 | 0 | if (!trace2_enabled) |
316 | 0 | return; |
317 | | |
318 | 0 | for_each_wanted_builtin (j, tgt_j) |
319 | 0 | if (tgt_j->pfn_command_path_fl) |
320 | 0 | tgt_j->pfn_command_path_fl(file, line, pathname); |
321 | 0 | } |
322 | | |
323 | | void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names) |
324 | 0 | { |
325 | 0 | struct tr2_tgt *tgt_j; |
326 | 0 | int j; |
327 | |
|
328 | 0 | if (!trace2_enabled) |
329 | 0 | return; |
330 | | |
331 | 0 | for_each_wanted_builtin (j, tgt_j) |
332 | 0 | if (tgt_j->pfn_command_ancestry_fl) |
333 | 0 | tgt_j->pfn_command_ancestry_fl(file, line, parent_names); |
334 | 0 | } |
335 | | |
336 | | void trace2_cmd_name_fl(const char *file, int line, const char *name) |
337 | 0 | { |
338 | 0 | struct tr2_tgt *tgt_j; |
339 | 0 | const char *hierarchy; |
340 | 0 | int j; |
341 | |
|
342 | 0 | if (!trace2_enabled) |
343 | 0 | return; |
344 | | |
345 | 0 | tr2_cmd_name_append_hierarchy(name); |
346 | 0 | hierarchy = tr2_cmd_name_get_hierarchy(); |
347 | |
|
348 | 0 | for_each_wanted_builtin (j, tgt_j) |
349 | 0 | if (tgt_j->pfn_command_name_fl) |
350 | 0 | tgt_j->pfn_command_name_fl(file, line, name, hierarchy); |
351 | 0 | } |
352 | | |
353 | | void trace2_cmd_mode_fl(const char *file, int line, const char *mode) |
354 | 0 | { |
355 | 0 | struct tr2_tgt *tgt_j; |
356 | 0 | int j; |
357 | |
|
358 | 0 | if (!trace2_enabled) |
359 | 0 | return; |
360 | | |
361 | 0 | for_each_wanted_builtin (j, tgt_j) |
362 | 0 | if (tgt_j->pfn_command_mode_fl) |
363 | 0 | tgt_j->pfn_command_mode_fl(file, line, mode); |
364 | 0 | } |
365 | | |
366 | | void trace2_cmd_alias_fl(const char *file, int line, const char *alias, |
367 | | const char **argv) |
368 | 0 | { |
369 | 0 | struct tr2_tgt *tgt_j; |
370 | 0 | int j; |
371 | |
|
372 | 0 | if (!trace2_enabled) |
373 | 0 | return; |
374 | | |
375 | 0 | for_each_wanted_builtin (j, tgt_j) |
376 | 0 | if (tgt_j->pfn_alias_fl) |
377 | 0 | tgt_j->pfn_alias_fl(file, line, alias, argv); |
378 | 0 | } |
379 | | |
380 | | void trace2_cmd_list_config_fl(const char *file, int line) |
381 | 0 | { |
382 | 0 | if (!trace2_enabled) |
383 | 0 | return; |
384 | | |
385 | 0 | tr2_cfg_list_config_fl(file, line); |
386 | 0 | } |
387 | | |
388 | | void trace2_cmd_list_env_vars_fl(const char *file, int line) |
389 | 0 | { |
390 | 0 | if (!trace2_enabled) |
391 | 0 | return; |
392 | | |
393 | 0 | tr2_list_env_vars_fl(file, line); |
394 | 0 | } |
395 | | |
396 | | void trace2_cmd_set_config_fl(const char *file, int line, const char *key, |
397 | | const char *value) |
398 | 3.67k | { |
399 | 3.67k | if (!trace2_enabled) |
400 | 3.67k | return; |
401 | | |
402 | 0 | tr2_cfg_set_fl(file, line, key, value); |
403 | 0 | } |
404 | | |
405 | | void trace2_child_start_fl(const char *file, int line, |
406 | | struct child_process *cmd) |
407 | 7.22k | { |
408 | 7.22k | struct tr2_tgt *tgt_j; |
409 | 7.22k | int j; |
410 | 7.22k | uint64_t us_now; |
411 | 7.22k | uint64_t us_elapsed_absolute; |
412 | | |
413 | 7.22k | if (!trace2_enabled) |
414 | 7.22k | return; |
415 | | |
416 | 0 | us_now = getnanotime() / 1000; |
417 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
418 | |
|
419 | 0 | cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id); |
420 | 0 | cmd->trace2_child_us_start = us_now; |
421 | |
|
422 | 0 | for_each_wanted_builtin (j, tgt_j) |
423 | 0 | if (tgt_j->pfn_child_start_fl) |
424 | 0 | tgt_j->pfn_child_start_fl(file, line, |
425 | 0 | us_elapsed_absolute, cmd); |
426 | 0 | } |
427 | | |
428 | | void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd, |
429 | | int child_exit_code) |
430 | 7.22k | { |
431 | 7.22k | struct tr2_tgt *tgt_j; |
432 | 7.22k | int j; |
433 | 7.22k | uint64_t us_now; |
434 | 7.22k | uint64_t us_elapsed_absolute; |
435 | 7.22k | uint64_t us_elapsed_child; |
436 | | |
437 | 7.22k | if (!trace2_enabled) |
438 | 7.22k | return; |
439 | | |
440 | 0 | us_now = getnanotime() / 1000; |
441 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
442 | |
|
443 | 0 | if (cmd->trace2_child_us_start) |
444 | 0 | us_elapsed_child = us_now - cmd->trace2_child_us_start; |
445 | 0 | else |
446 | 0 | us_elapsed_child = 0; |
447 | |
|
448 | 0 | for_each_wanted_builtin (j, tgt_j) |
449 | 0 | if (tgt_j->pfn_child_exit_fl) |
450 | 0 | tgt_j->pfn_child_exit_fl(file, line, |
451 | 0 | us_elapsed_absolute, |
452 | 0 | cmd->trace2_child_id, cmd->pid, |
453 | 0 | child_exit_code, |
454 | 0 | us_elapsed_child); |
455 | 0 | } |
456 | | |
457 | | void trace2_child_ready_fl(const char *file, int line, |
458 | | struct child_process *cmd, |
459 | | const char *ready) |
460 | 0 | { |
461 | 0 | struct tr2_tgt *tgt_j; |
462 | 0 | int j; |
463 | 0 | uint64_t us_now; |
464 | 0 | uint64_t us_elapsed_absolute; |
465 | 0 | uint64_t us_elapsed_child; |
466 | |
|
467 | 0 | if (!trace2_enabled) |
468 | 0 | return; |
469 | | |
470 | 0 | us_now = getnanotime() / 1000; |
471 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
472 | |
|
473 | 0 | if (cmd->trace2_child_us_start) |
474 | 0 | us_elapsed_child = us_now - cmd->trace2_child_us_start; |
475 | 0 | else |
476 | 0 | us_elapsed_child = 0; |
477 | |
|
478 | 0 | for_each_wanted_builtin (j, tgt_j) |
479 | 0 | if (tgt_j->pfn_child_ready_fl) |
480 | 0 | tgt_j->pfn_child_ready_fl(file, line, |
481 | 0 | us_elapsed_absolute, |
482 | 0 | cmd->trace2_child_id, |
483 | 0 | cmd->pid, |
484 | 0 | ready, |
485 | 0 | us_elapsed_child); |
486 | 0 | } |
487 | | |
488 | | int trace2_exec_fl(const char *file, int line, const char *exe, |
489 | | const char **argv) |
490 | 0 | { |
491 | 0 | struct tr2_tgt *tgt_j; |
492 | 0 | int j; |
493 | 0 | int exec_id; |
494 | 0 | uint64_t us_now; |
495 | 0 | uint64_t us_elapsed_absolute; |
496 | |
|
497 | 0 | if (!trace2_enabled) |
498 | 0 | return -1; |
499 | | |
500 | 0 | us_now = getnanotime() / 1000; |
501 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
502 | |
|
503 | 0 | exec_id = tr2tls_locked_increment(&tr2_next_exec_id); |
504 | |
|
505 | 0 | for_each_wanted_builtin (j, tgt_j) |
506 | 0 | if (tgt_j->pfn_exec_fl) |
507 | 0 | tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute, |
508 | 0 | exec_id, exe, argv); |
509 | |
|
510 | 0 | return exec_id; |
511 | 0 | } |
512 | | |
513 | | void trace2_exec_result_fl(const char *file, int line, int exec_id, int code) |
514 | 0 | { |
515 | 0 | struct tr2_tgt *tgt_j; |
516 | 0 | int j; |
517 | 0 | uint64_t us_now; |
518 | 0 | uint64_t us_elapsed_absolute; |
519 | |
|
520 | 0 | if (!trace2_enabled) |
521 | 0 | return; |
522 | | |
523 | 0 | us_now = getnanotime() / 1000; |
524 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
525 | |
|
526 | 0 | for_each_wanted_builtin (j, tgt_j) |
527 | 0 | if (tgt_j->pfn_exec_result_fl) |
528 | 0 | tgt_j->pfn_exec_result_fl( |
529 | 0 | file, line, us_elapsed_absolute, exec_id, code); |
530 | 0 | } |
531 | | |
532 | | void trace2_thread_start_fl(const char *file, int line, const char *thread_base_name) |
533 | 0 | { |
534 | 0 | struct tr2_tgt *tgt_j; |
535 | 0 | int j; |
536 | 0 | uint64_t us_now; |
537 | 0 | uint64_t us_elapsed_absolute; |
538 | |
|
539 | 0 | if (!trace2_enabled) |
540 | 0 | return; |
541 | | |
542 | 0 | if (tr2tls_is_main_thread()) { |
543 | | /* |
544 | | * We should only be called from the new thread's thread-proc, |
545 | | * so this is technically a bug. But in those cases where the |
546 | | * main thread also runs the thread-proc function (or when we |
547 | | * are built with threading disabled), we need to allow it. |
548 | | * |
549 | | * Convert this call to a region-enter so the nesting looks |
550 | | * correct. |
551 | | */ |
552 | 0 | trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL, |
553 | 0 | "thread-proc on main: %s", |
554 | 0 | thread_base_name); |
555 | 0 | return; |
556 | 0 | } |
557 | | |
558 | 0 | us_now = getnanotime() / 1000; |
559 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
560 | |
|
561 | 0 | tr2tls_create_self(thread_base_name, us_now); |
562 | |
|
563 | 0 | for_each_wanted_builtin (j, tgt_j) |
564 | 0 | if (tgt_j->pfn_thread_start_fl) |
565 | 0 | tgt_j->pfn_thread_start_fl(file, line, |
566 | 0 | us_elapsed_absolute); |
567 | 0 | } |
568 | | |
569 | | void trace2_thread_exit_fl(const char *file, int line) |
570 | 0 | { |
571 | 0 | struct tr2_tgt *tgt_j; |
572 | 0 | int j; |
573 | 0 | uint64_t us_now; |
574 | 0 | uint64_t us_elapsed_absolute; |
575 | 0 | uint64_t us_elapsed_thread; |
576 | |
|
577 | 0 | if (!trace2_enabled) |
578 | 0 | return; |
579 | | |
580 | 0 | if (tr2tls_is_main_thread()) { |
581 | | /* |
582 | | * We should only be called from the exiting thread's |
583 | | * thread-proc, so this is technically a bug. But in |
584 | | * those cases where the main thread also runs the |
585 | | * thread-proc function (or when we are built with |
586 | | * threading disabled), we need to allow it. |
587 | | * |
588 | | * Convert this call to a region-leave so the nesting |
589 | | * looks correct. |
590 | | */ |
591 | 0 | trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL, |
592 | 0 | "thread-proc on main"); |
593 | 0 | return; |
594 | 0 | } |
595 | | |
596 | 0 | us_now = getnanotime() / 1000; |
597 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
598 | | |
599 | | /* |
600 | | * Clear any unbalanced regions and then get the relative time |
601 | | * for the outer-most region (which we pushed when the thread |
602 | | * started). This gives us the run time of the thread. |
603 | | */ |
604 | 0 | tr2tls_pop_unwind_self(); |
605 | 0 | us_elapsed_thread = tr2tls_region_elasped_self(us_now); |
606 | | |
607 | | /* |
608 | | * Some timers want per-thread details. If this thread used |
609 | | * one of those timers, emit the details now. |
610 | | * |
611 | | * Likewise for counters. |
612 | | */ |
613 | 0 | tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); |
614 | 0 | tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); |
615 | | |
616 | | /* |
617 | | * Add stopwatch timer and counter data from the current |
618 | | * (non-main) thread to the final totals. (We'll accumulate |
619 | | * data for the main thread later during "atexit".) |
620 | | */ |
621 | 0 | tr2tls_lock(); |
622 | 0 | tr2_update_final_timers(); |
623 | 0 | tr2_update_final_counters(); |
624 | 0 | tr2tls_unlock(); |
625 | |
|
626 | 0 | for_each_wanted_builtin (j, tgt_j) |
627 | 0 | if (tgt_j->pfn_thread_exit_fl) |
628 | 0 | tgt_j->pfn_thread_exit_fl(file, line, |
629 | 0 | us_elapsed_absolute, |
630 | 0 | us_elapsed_thread); |
631 | |
|
632 | 0 | tr2tls_unset_self(); |
633 | 0 | } |
634 | | |
635 | | void trace2_def_param_fl(const char *file, int line, const char *param, |
636 | | const char *value, const struct key_value_info *kvi) |
637 | 0 | { |
638 | 0 | struct tr2_tgt *tgt_j; |
639 | 0 | int j; |
640 | |
|
641 | 0 | if (!trace2_enabled) |
642 | 0 | return; |
643 | | |
644 | 0 | for_each_wanted_builtin (j, tgt_j) |
645 | 0 | if (tgt_j->pfn_param_fl) |
646 | 0 | tgt_j->pfn_param_fl(file, line, param, value, kvi); |
647 | 0 | } |
648 | | |
649 | | void trace2_def_repo_fl(const char *file, int line, struct repository *repo) |
650 | 11.3k | { |
651 | 11.3k | struct tr2_tgt *tgt_j; |
652 | 11.3k | int j; |
653 | | |
654 | 11.3k | if (!trace2_enabled) |
655 | 11.3k | return; |
656 | | |
657 | 0 | if (repo->trace2_repo_id) |
658 | 0 | return; |
659 | | |
660 | 0 | repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id); |
661 | |
|
662 | 0 | for_each_wanted_builtin (j, tgt_j) |
663 | 0 | if (tgt_j->pfn_repo_fl) |
664 | 0 | tgt_j->pfn_repo_fl(file, line, repo); |
665 | 0 | } |
666 | | |
667 | | void trace2_region_enter_printf_va_fl(const char *file, int line, |
668 | | const char *category, const char *label, |
669 | | const struct repository *repo, |
670 | | const char *fmt, va_list ap) |
671 | 170k | { |
672 | 170k | struct tr2_tgt *tgt_j; |
673 | 170k | int j; |
674 | 170k | uint64_t us_now; |
675 | 170k | uint64_t us_elapsed_absolute; |
676 | | |
677 | 170k | if (!trace2_enabled) |
678 | 170k | return; |
679 | | |
680 | 0 | us_now = getnanotime() / 1000; |
681 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
682 | | |
683 | | /* |
684 | | * Print the region-enter message at the current nesting |
685 | | * (indentation) level and then push a new level. |
686 | | * |
687 | | * We expect each target function to treat 'ap' as constant |
688 | | * and use va_copy. |
689 | | */ |
690 | 0 | for_each_wanted_builtin (j, tgt_j) |
691 | 0 | if (tgt_j->pfn_region_enter_printf_va_fl) |
692 | 0 | tgt_j->pfn_region_enter_printf_va_fl( |
693 | 0 | file, line, us_elapsed_absolute, category, |
694 | 0 | label, repo, fmt, ap); |
695 | |
|
696 | 0 | tr2tls_push_self(us_now); |
697 | 0 | } |
698 | | |
699 | | void trace2_region_enter_fl(const char *file, int line, const char *category, |
700 | | const char *label, const struct repository *repo, ...) |
701 | 154k | { |
702 | 154k | va_list ap; |
703 | 154k | va_start(ap, repo); |
704 | 154k | trace2_region_enter_printf_va_fl(file, line, category, label, repo, |
705 | 154k | NULL, ap); |
706 | 154k | va_end(ap); |
707 | | |
708 | 154k | } |
709 | | |
710 | | void trace2_region_enter_printf_fl(const char *file, int line, |
711 | | const char *category, const char *label, |
712 | | const struct repository *repo, |
713 | | const char *fmt, ...) |
714 | 15.8k | { |
715 | 15.8k | va_list ap; |
716 | | |
717 | 15.8k | va_start(ap, fmt); |
718 | 15.8k | trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt, |
719 | 15.8k | ap); |
720 | 15.8k | va_end(ap); |
721 | 15.8k | } |
722 | | |
723 | | void trace2_region_leave_printf_va_fl(const char *file, int line, |
724 | | const char *category, const char *label, |
725 | | const struct repository *repo, |
726 | | const char *fmt, va_list ap) |
727 | 170k | { |
728 | 170k | struct tr2_tgt *tgt_j; |
729 | 170k | int j; |
730 | 170k | uint64_t us_now; |
731 | 170k | uint64_t us_elapsed_absolute; |
732 | 170k | uint64_t us_elapsed_region; |
733 | | |
734 | 170k | if (!trace2_enabled) |
735 | 170k | return; |
736 | | |
737 | 0 | us_now = getnanotime() / 1000; |
738 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
739 | | |
740 | | /* |
741 | | * Get the elapsed time in the current region before we |
742 | | * pop it off the stack. Pop the stack. And then print |
743 | | * the perf message at the new (shallower) level so that |
744 | | * it lines up with the corresponding push/enter. |
745 | | */ |
746 | 0 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
747 | |
|
748 | 0 | tr2tls_pop_self(); |
749 | | |
750 | | /* |
751 | | * We expect each target function to treat 'ap' as constant |
752 | | * and use va_copy. |
753 | | */ |
754 | 0 | for_each_wanted_builtin (j, tgt_j) |
755 | 0 | if (tgt_j->pfn_region_leave_printf_va_fl) |
756 | 0 | tgt_j->pfn_region_leave_printf_va_fl( |
757 | 0 | file, line, us_elapsed_absolute, |
758 | 0 | us_elapsed_region, category, label, repo, fmt, |
759 | 0 | ap); |
760 | 0 | } |
761 | | |
762 | | void trace2_region_leave_fl(const char *file, int line, const char *category, |
763 | | const char *label, const struct repository *repo, ...) |
764 | 154k | { |
765 | 154k | va_list ap; |
766 | 154k | va_start(ap, repo); |
767 | 154k | trace2_region_leave_printf_va_fl(file, line, category, label, repo, |
768 | 154k | NULL, ap); |
769 | 154k | va_end(ap); |
770 | 154k | } |
771 | | |
772 | | void trace2_region_leave_printf_fl(const char *file, int line, |
773 | | const char *category, const char *label, |
774 | | const struct repository *repo, |
775 | | const char *fmt, ...) |
776 | 15.8k | { |
777 | 15.8k | va_list ap; |
778 | | |
779 | 15.8k | va_start(ap, fmt); |
780 | 15.8k | trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt, |
781 | 15.8k | ap); |
782 | 15.8k | va_end(ap); |
783 | 15.8k | } |
784 | | |
785 | | void trace2_data_string_fl(const char *file, int line, const char *category, |
786 | | const struct repository *repo, const char *key, |
787 | | const char *value) |
788 | 0 | { |
789 | 0 | struct tr2_tgt *tgt_j; |
790 | 0 | int j; |
791 | 0 | uint64_t us_now; |
792 | 0 | uint64_t us_elapsed_absolute; |
793 | 0 | uint64_t us_elapsed_region; |
794 | |
|
795 | 0 | if (!trace2_enabled) |
796 | 0 | return; |
797 | | |
798 | 0 | us_now = getnanotime() / 1000; |
799 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
800 | 0 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
801 | |
|
802 | 0 | for_each_wanted_builtin (j, tgt_j) |
803 | 0 | if (tgt_j->pfn_data_fl) |
804 | 0 | tgt_j->pfn_data_fl(file, line, us_elapsed_absolute, |
805 | 0 | us_elapsed_region, category, repo, |
806 | 0 | key, value); |
807 | 0 | } |
808 | | |
809 | | void trace2_data_intmax_fl(const char *file, int line, const char *category, |
810 | | const struct repository *repo, const char *key, |
811 | | intmax_t value) |
812 | 44.2k | { |
813 | 44.2k | struct strbuf buf_string = STRBUF_INIT; |
814 | | |
815 | 44.2k | if (!trace2_enabled) |
816 | 44.2k | return; |
817 | | |
818 | 0 | strbuf_addf(&buf_string, "%" PRIdMAX, value); |
819 | 0 | trace2_data_string_fl(file, line, category, repo, key, buf_string.buf); |
820 | 0 | strbuf_release(&buf_string); |
821 | 0 | } |
822 | | |
823 | | void trace2_data_json_fl(const char *file, int line, const char *category, |
824 | | const struct repository *repo, const char *key, |
825 | | const struct json_writer *value) |
826 | 0 | { |
827 | 0 | struct tr2_tgt *tgt_j; |
828 | 0 | int j; |
829 | 0 | uint64_t us_now; |
830 | 0 | uint64_t us_elapsed_absolute; |
831 | 0 | uint64_t us_elapsed_region; |
832 | |
|
833 | 0 | if (!trace2_enabled) |
834 | 0 | return; |
835 | | |
836 | 0 | us_now = getnanotime() / 1000; |
837 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
838 | 0 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
839 | |
|
840 | 0 | for_each_wanted_builtin (j, tgt_j) |
841 | 0 | if (tgt_j->pfn_data_json_fl) |
842 | 0 | tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute, |
843 | 0 | us_elapsed_region, category, |
844 | 0 | repo, key, value); |
845 | 0 | } |
846 | | |
847 | | void trace2_printf_va_fl(const char *file, int line, const char *fmt, |
848 | | va_list ap) |
849 | 0 | { |
850 | 0 | struct tr2_tgt *tgt_j; |
851 | 0 | int j; |
852 | 0 | uint64_t us_now; |
853 | 0 | uint64_t us_elapsed_absolute; |
854 | |
|
855 | 0 | if (!trace2_enabled) |
856 | 0 | return; |
857 | | |
858 | 0 | us_now = getnanotime() / 1000; |
859 | 0 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
860 | | |
861 | | /* |
862 | | * We expect each target function to treat 'ap' as constant |
863 | | * and use va_copy. |
864 | | */ |
865 | 0 | for_each_wanted_builtin (j, tgt_j) |
866 | 0 | if (tgt_j->pfn_printf_va_fl) |
867 | 0 | tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute, |
868 | 0 | fmt, ap); |
869 | 0 | } |
870 | | |
871 | | void trace2_printf_fl(const char *file, int line, const char *fmt, ...) |
872 | 0 | { |
873 | 0 | va_list ap; |
874 | |
|
875 | 0 | va_start(ap, fmt); |
876 | 0 | trace2_printf_va_fl(file, line, fmt, ap); |
877 | 0 | va_end(ap); |
878 | 0 | } |
879 | | |
880 | | void trace2_timer_start(enum trace2_timer_id tid) |
881 | 0 | { |
882 | 0 | if (!trace2_enabled) |
883 | 0 | return; |
884 | | |
885 | 0 | if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) |
886 | 0 | BUG("trace2_timer_start: invalid timer id: %d", tid); |
887 | | |
888 | 0 | tr2_start_timer(tid); |
889 | 0 | } |
890 | | |
891 | | void trace2_timer_stop(enum trace2_timer_id tid) |
892 | 0 | { |
893 | 0 | if (!trace2_enabled) |
894 | 0 | return; |
895 | | |
896 | 0 | if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) |
897 | 0 | BUG("trace2_timer_stop: invalid timer id: %d", tid); |
898 | | |
899 | 0 | tr2_stop_timer(tid); |
900 | 0 | } |
901 | | |
902 | | void trace2_counter_add(enum trace2_counter_id cid, uint64_t value) |
903 | 0 | { |
904 | 0 | if (!trace2_enabled) |
905 | 0 | return; |
906 | | |
907 | 0 | if (cid < 0 || cid >= TRACE2_NUMBER_OF_COUNTERS) |
908 | 0 | BUG("trace2_counter_add: invalid counter id: %d", cid); |
909 | | |
910 | 0 | tr2_counter_increment(cid, value); |
911 | 0 | } |
912 | | |
913 | | const char *trace2_session_id(void) |
914 | 0 | { |
915 | 0 | return tr2_sid_get(); |
916 | 0 | } |