trace2: refactor setting process starting time
[git/git.git] / trace2.c
CommitLineData
ee4512ed
JH
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
a0897249
JH
145void trace2_initialize_clock(void)
146{
147 tr2tls_start_process_clock();
148}
149
ee4512ed
JH
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
186 if (!trace2_enabled)
187 return;
188
189 for_each_wanted_builtin (j, tgt_j)
190 if (tgt_j->pfn_start_fl)
191 tgt_j->pfn_start_fl(file, line, argv);
192}
193
194int trace2_cmd_exit_fl(const char *file, int line, int code)
195{
196 struct tr2_tgt *tgt_j;
197 int j;
198 uint64_t us_now;
199 uint64_t us_elapsed_absolute;
200
201 code &= 0xff;
202
203 if (!trace2_enabled)
204 return code;
205
206 tr2main_exit_code = code;
207
208 us_now = getnanotime() / 1000;
209 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
210
211 for_each_wanted_builtin (j, tgt_j)
212 if (tgt_j->pfn_exit_fl)
213 tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute,
214 code);
215
216 return code;
217}
218
219void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
220 va_list ap)
221{
222 struct tr2_tgt *tgt_j;
223 int j;
224
225 if (!trace2_enabled)
226 return;
227
228 /*
229 * We expect each target function to treat 'ap' as constant
230 * and use va_copy (because an 'ap' can only be walked once).
231 */
232 for_each_wanted_builtin (j, tgt_j)
233 if (tgt_j->pfn_error_va_fl)
234 tgt_j->pfn_error_va_fl(file, line, fmt, ap);
235}
236
237void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
238{
239 struct tr2_tgt *tgt_j;
240 int j;
241
242 if (!trace2_enabled)
243 return;
244
245 for_each_wanted_builtin (j, tgt_j)
246 if (tgt_j->pfn_command_path_fl)
247 tgt_j->pfn_command_path_fl(file, line, pathname);
248}
249
250void trace2_cmd_name_fl(const char *file, int line, const char *name)
251{
252 struct tr2_tgt *tgt_j;
253 const char *hierarchy;
254 int j;
255
256 if (!trace2_enabled)
257 return;
258
259 tr2_cmd_name_append_hierarchy(name);
260 hierarchy = tr2_cmd_name_get_hierarchy();
261
262 for_each_wanted_builtin (j, tgt_j)
263 if (tgt_j->pfn_command_name_fl)
264 tgt_j->pfn_command_name_fl(file, line, name, hierarchy);
265}
266
267void trace2_cmd_mode_fl(const char *file, int line, const char *mode)
268{
269 struct tr2_tgt *tgt_j;
270 int j;
271
272 if (!trace2_enabled)
273 return;
274
275 for_each_wanted_builtin (j, tgt_j)
276 if (tgt_j->pfn_command_mode_fl)
277 tgt_j->pfn_command_mode_fl(file, line, mode);
278}
279
280void trace2_cmd_alias_fl(const char *file, int line, const char *alias,
281 const char **argv)
282{
283 struct tr2_tgt *tgt_j;
284 int j;
285
286 if (!trace2_enabled)
287 return;
288
289 for_each_wanted_builtin (j, tgt_j)
290 if (tgt_j->pfn_alias_fl)
291 tgt_j->pfn_alias_fl(file, line, alias, argv);
292}
293
294void trace2_cmd_list_config_fl(const char *file, int line)
295{
296 if (!trace2_enabled)
297 return;
298
299 tr2_cfg_list_config_fl(file, line);
300}
301
302void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
303 const char *value)
304{
305 if (!trace2_enabled)
306 return;
307
308 tr2_cfg_set_fl(file, line, key, value);
309}
310
311void trace2_child_start_fl(const char *file, int line,
312 struct child_process *cmd)
313{
314 struct tr2_tgt *tgt_j;
315 int j;
316 uint64_t us_now;
317 uint64_t us_elapsed_absolute;
318
319 if (!trace2_enabled)
320 return;
321
322 us_now = getnanotime() / 1000;
323 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
324
325 cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
326 cmd->trace2_child_us_start = us_now;
327
328 for_each_wanted_builtin (j, tgt_j)
329 if (tgt_j->pfn_child_start_fl)
330 tgt_j->pfn_child_start_fl(file, line,
331 us_elapsed_absolute, cmd);
332}
333
334void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
335 int child_exit_code)
336{
337 struct tr2_tgt *tgt_j;
338 int j;
339 uint64_t us_now;
340 uint64_t us_elapsed_absolute;
341 uint64_t us_elapsed_child;
342
343 if (!trace2_enabled)
344 return;
345
346 us_now = getnanotime() / 1000;
347 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
348
349 if (cmd->trace2_child_us_start)
350 us_elapsed_child = us_now - cmd->trace2_child_us_start;
351 else
352 us_elapsed_child = 0;
353
354 for_each_wanted_builtin (j, tgt_j)
355 if (tgt_j->pfn_child_exit_fl)
356 tgt_j->pfn_child_exit_fl(file, line,
357 us_elapsed_absolute,
358 cmd->trace2_child_id, cmd->pid,
359 child_exit_code,
360 us_elapsed_child);
361}
362
363int trace2_exec_fl(const char *file, int line, const char *exe,
364 const char **argv)
365{
366 struct tr2_tgt *tgt_j;
367 int j;
368 int exec_id;
369 uint64_t us_now;
370 uint64_t us_elapsed_absolute;
371
372 if (!trace2_enabled)
373 return -1;
374
375 us_now = getnanotime() / 1000;
376 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
377
378 exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
379
380 for_each_wanted_builtin (j, tgt_j)
381 if (tgt_j->pfn_exec_fl)
382 tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
383 exec_id, exe, argv);
384
385 return exec_id;
386}
387
388void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
389{
390 struct tr2_tgt *tgt_j;
391 int j;
392 uint64_t us_now;
393 uint64_t us_elapsed_absolute;
394
395 if (!trace2_enabled)
396 return;
397
398 us_now = getnanotime() / 1000;
399 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
400
401 for_each_wanted_builtin (j, tgt_j)
402 if (tgt_j->pfn_exec_result_fl)
403 tgt_j->pfn_exec_result_fl(
404 file, line, us_elapsed_absolute, exec_id, code);
405}
406
407void trace2_thread_start_fl(const char *file, int line, const char *thread_name)
408{
409 struct tr2_tgt *tgt_j;
410 int j;
411 uint64_t us_now;
412 uint64_t us_elapsed_absolute;
413
414 if (!trace2_enabled)
415 return;
416
417 if (tr2tls_is_main_thread()) {
418 /*
419 * We should only be called from the new thread's thread-proc,
420 * so this is technically a bug. But in those cases where the
421 * main thread also runs the thread-proc function (or when we
422 * are built with threading disabled), we need to allow it.
423 *
424 * Convert this call to a region-enter so the nesting looks
425 * correct.
426 */
427 trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
428 "thread-proc on main: %s",
429 thread_name);
430 return;
431 }
432
433 us_now = getnanotime() / 1000;
434 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
435
a0897249 436 tr2tls_create_self(thread_name, us_now);
ee4512ed
JH
437
438 for_each_wanted_builtin (j, tgt_j)
439 if (tgt_j->pfn_thread_start_fl)
440 tgt_j->pfn_thread_start_fl(file, line,
441 us_elapsed_absolute);
442}
443
444void trace2_thread_exit_fl(const char *file, int line)
445{
446 struct tr2_tgt *tgt_j;
447 int j;
448 uint64_t us_now;
449 uint64_t us_elapsed_absolute;
450 uint64_t us_elapsed_thread;
451
452 if (!trace2_enabled)
453 return;
454
455 if (tr2tls_is_main_thread()) {
456 /*
457 * We should only be called from the exiting thread's
458 * thread-proc, so this is technically a bug. But in
459 * those cases where the main thread also runs the
460 * thread-proc function (or when we are built with
461 * threading disabled), we need to allow it.
462 *
463 * Convert this call to a region-leave so the nesting
464 * looks correct.
465 */
466 trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
467 "thread-proc on main");
468 return;
469 }
470
471 us_now = getnanotime() / 1000;
472 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
473
474 /*
475 * Clear any unbalanced regions and then get the relative time
476 * for the outer-most region (which we pushed when the thread
477 * started). This gives us the run time of the thread.
478 */
479 tr2tls_pop_unwind_self();
480 us_elapsed_thread = tr2tls_region_elasped_self(us_now);
481
482 for_each_wanted_builtin (j, tgt_j)
483 if (tgt_j->pfn_thread_exit_fl)
484 tgt_j->pfn_thread_exit_fl(file, line,
485 us_elapsed_absolute,
486 us_elapsed_thread);
487
488 tr2tls_unset_self();
489}
490
491void trace2_def_param_fl(const char *file, int line, const char *param,
492 const char *value)
493{
494 struct tr2_tgt *tgt_j;
495 int j;
496
497 if (!trace2_enabled)
498 return;
499
500 for_each_wanted_builtin (j, tgt_j)
501 if (tgt_j->pfn_param_fl)
502 tgt_j->pfn_param_fl(file, line, param, value);
503}
504
505void trace2_def_repo_fl(const char *file, int line, struct repository *repo)
506{
507 struct tr2_tgt *tgt_j;
508 int j;
509
510 if (!trace2_enabled)
511 return;
512
513 if (repo->trace2_repo_id)
514 return;
515
516 repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
517
518 for_each_wanted_builtin (j, tgt_j)
519 if (tgt_j->pfn_repo_fl)
520 tgt_j->pfn_repo_fl(file, line, repo);
521}
522
523void trace2_region_enter_printf_va_fl(const char *file, int line,
524 const char *category, const char *label,
525 const struct repository *repo,
526 const char *fmt, va_list ap)
527{
528 struct tr2_tgt *tgt_j;
529 int j;
530 uint64_t us_now;
531 uint64_t us_elapsed_absolute;
532
533 if (!trace2_enabled)
534 return;
535
536 us_now = getnanotime() / 1000;
537 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
538
539 /*
540 * Print the region-enter message at the current nesting
541 * (indentation) level and then push a new level.
542 *
543 * We expect each target function to treat 'ap' as constant
544 * and use va_copy.
545 */
546 for_each_wanted_builtin (j, tgt_j)
547 if (tgt_j->pfn_region_enter_printf_va_fl)
548 tgt_j->pfn_region_enter_printf_va_fl(
549 file, line, us_elapsed_absolute, category,
550 label, repo, fmt, ap);
551
552 tr2tls_push_self(us_now);
553}
554
555void trace2_region_enter_fl(const char *file, int line, const char *category,
556 const char *label, const struct repository *repo)
557{
558 trace2_region_enter_printf_va_fl(file, line, category, label, repo,
559 NULL, NULL);
560}
561
562void trace2_region_enter_printf_fl(const char *file, int line,
563 const char *category, const char *label,
564 const struct repository *repo,
565 const char *fmt, ...)
566{
567 va_list ap;
568
569 va_start(ap, fmt);
570 trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt,
571 ap);
572 va_end(ap);
573}
574
575#ifndef HAVE_VARIADIC_MACROS
576void trace2_region_enter_printf(const char *category, const char *label,
577 const struct repository *repo, const char *fmt,
578 ...)
579{
580 va_list ap;
581
582 va_start(ap, fmt);
583 trace2_region_enter_printf_va_fl(NULL, 0, category, label, repo, fmt,
584 ap);
585 va_end(ap);
586}
587#endif
588
589void trace2_region_leave_printf_va_fl(const char *file, int line,
590 const char *category, const char *label,
591 const struct repository *repo,
592 const char *fmt, va_list ap)
593{
594 struct tr2_tgt *tgt_j;
595 int j;
596 uint64_t us_now;
597 uint64_t us_elapsed_absolute;
598 uint64_t us_elapsed_region;
599
600 if (!trace2_enabled)
601 return;
602
603 us_now = getnanotime() / 1000;
604 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
605
606 /*
607 * Get the elapsed time in the current region before we
608 * pop it off the stack. Pop the stack. And then print
609 * the perf message at the new (shallower) level so that
610 * it lines up with the corresponding push/enter.
611 */
612 us_elapsed_region = tr2tls_region_elasped_self(us_now);
613
614 tr2tls_pop_self();
615
616 /*
617 * We expect each target function to treat 'ap' as constant
618 * and use va_copy.
619 */
620 for_each_wanted_builtin (j, tgt_j)
621 if (tgt_j->pfn_region_leave_printf_va_fl)
622 tgt_j->pfn_region_leave_printf_va_fl(
623 file, line, us_elapsed_absolute,
624 us_elapsed_region, category, label, repo, fmt,
625 ap);
626}
627
628void trace2_region_leave_fl(const char *file, int line, const char *category,
629 const char *label, const struct repository *repo)
630{
631 trace2_region_leave_printf_va_fl(file, line, category, label, repo,
632 NULL, NULL);
633}
634
635void trace2_region_leave_printf_fl(const char *file, int line,
636 const char *category, const char *label,
637 const struct repository *repo,
638 const char *fmt, ...)
639{
640 va_list ap;
641
642 va_start(ap, fmt);
643 trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt,
644 ap);
645 va_end(ap);
646}
647
648#ifndef HAVE_VARIADIC_MACROS
649void trace2_region_leave_printf(const char *category, const char *label,
650 const struct repository *repo, const char *fmt,
651 ...)
652{
653 va_list ap;
654
655 va_start(ap, fmt);
656 trace2_region_leave_printf_va_fl(NULL, 0, category, label, repo, fmt,
657 ap);
658 va_end(ap);
659}
660#endif
661
662void trace2_data_string_fl(const char *file, int line, const char *category,
663 const struct repository *repo, const char *key,
664 const char *value)
665{
666 struct tr2_tgt *tgt_j;
667 int j;
668 uint64_t us_now;
669 uint64_t us_elapsed_absolute;
670 uint64_t us_elapsed_region;
671
672 if (!trace2_enabled)
673 return;
674
675 us_now = getnanotime() / 1000;
676 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
677 us_elapsed_region = tr2tls_region_elasped_self(us_now);
678
679 for_each_wanted_builtin (j, tgt_j)
680 if (tgt_j->pfn_data_fl)
681 tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
682 us_elapsed_region, category, repo,
683 key, value);
684}
685
686void trace2_data_intmax_fl(const char *file, int line, const char *category,
687 const struct repository *repo, const char *key,
688 intmax_t value)
689{
690 struct strbuf buf_string = STRBUF_INIT;
691
692 if (!trace2_enabled)
693 return;
694
695 strbuf_addf(&buf_string, "%" PRIdMAX, value);
696 trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
697 strbuf_release(&buf_string);
698}
699
700void trace2_data_json_fl(const char *file, int line, const char *category,
701 const struct repository *repo, const char *key,
702 const struct json_writer *value)
703{
704 struct tr2_tgt *tgt_j;
705 int j;
706 uint64_t us_now;
707 uint64_t us_elapsed_absolute;
708 uint64_t us_elapsed_region;
709
710 if (!trace2_enabled)
711 return;
712
713 us_now = getnanotime() / 1000;
714 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
715 us_elapsed_region = tr2tls_region_elasped_self(us_now);
716
717 for_each_wanted_builtin (j, tgt_j)
718 if (tgt_j->pfn_data_fl)
719 tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,
720 us_elapsed_region, category,
721 repo, key, value);
722}
723
724void trace2_printf_va_fl(const char *file, int line, const char *fmt,
725 va_list ap)
726{
727 struct tr2_tgt *tgt_j;
728 int j;
729 uint64_t us_now;
730 uint64_t us_elapsed_absolute;
731
732 if (!trace2_enabled)
733 return;
734
735 us_now = getnanotime() / 1000;
736 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
737
738 /*
739 * We expect each target function to treat 'ap' as constant
740 * and use va_copy.
741 */
742 for_each_wanted_builtin (j, tgt_j)
743 if (tgt_j->pfn_printf_va_fl)
744 tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
745 fmt, ap);
746}
747
748void trace2_printf_fl(const char *file, int line, const char *fmt, ...)
749{
750 va_list ap;
751
752 va_start(ap, fmt);
753 trace2_printf_va_fl(file, line, fmt, ap);
754 va_end(ap);
755}
756
757#ifndef HAVE_VARIADIC_MACROS
758void trace2_printf(const char *fmt, ...)
759{
760 va_list ap;
761
762 va_start(ap, fmt);
763 trace2_printf_va_fl(NULL, 0, fmt, ap);
764 va_end(ap);
765}
766#endif