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