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