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