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