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