cmake: increase time-out for a long-running test
[alt-git.git] / trace2.c
blob0c0a11e07d522e031bb4e8e3188953c74d872cc4
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"
17 static int trace2_enabled;
19 static int tr2_next_child_id; /* modify under lock */
20 static int tr2_next_exec_id; /* modify under lock */
21 static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */
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.
28 /* clang-format off */
29 static struct tr2_tgt *tr2_tgt_builtins[] =
31 &tr2_tgt_normal,
32 &tr2_tgt_perf,
33 &tr2_tgt_event,
34 NULL
36 /* clang-format on */
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 */
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 */
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.
57 * Return the number of builtin targets enabled.
59 static int tr2_tgt_want_builtins(void)
61 struct tr2_tgt *tgt_j;
62 int j;
63 int sum = 0;
65 for_each_builtin (j, tgt_j)
66 if (tgt_j->pfn_init())
67 sum++;
69 return sum;
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.
77 static void tr2_tgt_disable_builtins(void)
79 struct tr2_tgt *tgt_j;
80 int j;
82 for_each_builtin (j, tgt_j)
83 tgt_j->pfn_term();
86 static int tr2main_exit_code;
89 * Our atexit routine should run after everything has finished.
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).
96 static void tr2main_atexit_handler(void)
98 struct tr2_tgt *tgt_j;
99 int j;
100 uint64_t us_now;
101 uint64_t us_elapsed_absolute;
103 us_now = getnanotime() / 1000;
104 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
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.
111 tr2tls_pop_unwind_self();
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);
118 tr2_tgt_disable_builtins();
120 tr2tls_release();
121 tr2_sid_release();
122 tr2_cmd_name_release();
123 tr2_cfg_free_patterns();
124 tr2_cfg_free_env_vars();
125 tr2_sysenv_release();
127 trace2_enabled = 0;
130 static void tr2main_signal_handler(int signo)
132 struct tr2_tgt *tgt_j;
133 int j;
134 uint64_t us_now;
135 uint64_t us_elapsed_absolute;
137 us_now = getnanotime() / 1000;
138 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
140 for_each_wanted_builtin (j, tgt_j)
141 if (tgt_j->pfn_signal)
142 tgt_j->pfn_signal(us_elapsed_absolute, signo);
144 sigchain_pop(signo);
145 raise(signo);
148 void trace2_initialize_clock(void)
150 tr2tls_start_process_clock();
153 void trace2_initialize_fl(const char *file, int line)
155 struct tr2_tgt *tgt_j;
156 int j;
158 if (trace2_enabled)
159 return;
161 tr2_sysenv_load();
163 if (!tr2_tgt_want_builtins())
164 return;
165 trace2_enabled = 1;
167 tr2_sid_get();
169 atexit(tr2main_atexit_handler);
170 sigchain_push(SIGPIPE, tr2main_signal_handler);
171 tr2tls_init();
174 * Emit 'version' message on each active builtin target.
176 for_each_wanted_builtin (j, tgt_j)
177 if (tgt_j->pfn_version_fl)
178 tgt_j->pfn_version_fl(file, line);
181 int trace2_is_enabled(void)
183 return trace2_enabled;
186 void trace2_cmd_start_fl(const char *file, int line, const char **argv)
188 struct tr2_tgt *tgt_j;
189 int j;
190 uint64_t us_now;
191 uint64_t us_elapsed_absolute;
193 if (!trace2_enabled)
194 return;
196 us_now = getnanotime() / 1000;
197 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
199 for_each_wanted_builtin (j, tgt_j)
200 if (tgt_j->pfn_start_fl)
201 tgt_j->pfn_start_fl(file, line, us_elapsed_absolute,
202 argv);
205 void trace2_cmd_exit_fl(const char *file, int line, int code)
207 struct tr2_tgt *tgt_j;
208 int j;
209 uint64_t us_now;
210 uint64_t us_elapsed_absolute;
212 if (!trace2_enabled)
213 return;
215 trace_git_fsync_stats();
216 trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT);
218 tr2main_exit_code = code;
220 us_now = getnanotime() / 1000;
221 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
223 for_each_wanted_builtin (j, tgt_j)
224 if (tgt_j->pfn_exit_fl)
225 tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute,
226 code);
229 void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
230 va_list ap)
232 struct tr2_tgt *tgt_j;
233 int j;
235 if (!trace2_enabled)
236 return;
239 * We expect each target function to treat 'ap' as constant
240 * and use va_copy (because an 'ap' can only be walked once).
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);
247 void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
249 struct tr2_tgt *tgt_j;
250 int j;
252 if (!trace2_enabled)
253 return;
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);
260 void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names)
262 struct tr2_tgt *tgt_j;
263 int j;
265 if (!trace2_enabled)
266 return;
268 for_each_wanted_builtin (j, tgt_j)
269 if (tgt_j->pfn_command_ancestry_fl)
270 tgt_j->pfn_command_ancestry_fl(file, line, parent_names);
273 void trace2_cmd_name_fl(const char *file, int line, const char *name)
275 struct tr2_tgt *tgt_j;
276 const char *hierarchy;
277 int j;
279 if (!trace2_enabled)
280 return;
282 tr2_cmd_name_append_hierarchy(name);
283 hierarchy = tr2_cmd_name_get_hierarchy();
285 for_each_wanted_builtin (j, tgt_j)
286 if (tgt_j->pfn_command_name_fl)
287 tgt_j->pfn_command_name_fl(file, line, name, hierarchy);
290 void trace2_cmd_mode_fl(const char *file, int line, const char *mode)
292 struct tr2_tgt *tgt_j;
293 int j;
295 if (!trace2_enabled)
296 return;
298 for_each_wanted_builtin (j, tgt_j)
299 if (tgt_j->pfn_command_mode_fl)
300 tgt_j->pfn_command_mode_fl(file, line, mode);
303 void trace2_cmd_alias_fl(const char *file, int line, const char *alias,
304 const char **argv)
306 struct tr2_tgt *tgt_j;
307 int j;
309 if (!trace2_enabled)
310 return;
312 for_each_wanted_builtin (j, tgt_j)
313 if (tgt_j->pfn_alias_fl)
314 tgt_j->pfn_alias_fl(file, line, alias, argv);
317 void trace2_cmd_list_config_fl(const char *file, int line)
319 if (!trace2_enabled)
320 return;
322 tr2_cfg_list_config_fl(file, line);
325 void trace2_cmd_list_env_vars_fl(const char *file, int line)
327 if (!trace2_enabled)
328 return;
330 tr2_list_env_vars_fl(file, line);
333 void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
334 const char *value)
336 if (!trace2_enabled)
337 return;
339 tr2_cfg_set_fl(file, line, key, value);
342 void trace2_child_start_fl(const char *file, int line,
343 struct child_process *cmd)
345 struct tr2_tgt *tgt_j;
346 int j;
347 uint64_t us_now;
348 uint64_t us_elapsed_absolute;
350 if (!trace2_enabled)
351 return;
353 us_now = getnanotime() / 1000;
354 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
356 cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
357 cmd->trace2_child_us_start = us_now;
359 for_each_wanted_builtin (j, tgt_j)
360 if (tgt_j->pfn_child_start_fl)
361 tgt_j->pfn_child_start_fl(file, line,
362 us_elapsed_absolute, cmd);
365 void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
366 int child_exit_code)
368 struct tr2_tgt *tgt_j;
369 int j;
370 uint64_t us_now;
371 uint64_t us_elapsed_absolute;
372 uint64_t us_elapsed_child;
374 if (!trace2_enabled)
375 return;
377 us_now = getnanotime() / 1000;
378 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
380 if (cmd->trace2_child_us_start)
381 us_elapsed_child = us_now - cmd->trace2_child_us_start;
382 else
383 us_elapsed_child = 0;
385 for_each_wanted_builtin (j, tgt_j)
386 if (tgt_j->pfn_child_exit_fl)
387 tgt_j->pfn_child_exit_fl(file, line,
388 us_elapsed_absolute,
389 cmd->trace2_child_id, cmd->pid,
390 child_exit_code,
391 us_elapsed_child);
394 void trace2_child_ready_fl(const char *file, int line,
395 struct child_process *cmd,
396 const char *ready)
398 struct tr2_tgt *tgt_j;
399 int j;
400 uint64_t us_now;
401 uint64_t us_elapsed_absolute;
402 uint64_t us_elapsed_child;
404 if (!trace2_enabled)
405 return;
407 us_now = getnanotime() / 1000;
408 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
410 if (cmd->trace2_child_us_start)
411 us_elapsed_child = us_now - cmd->trace2_child_us_start;
412 else
413 us_elapsed_child = 0;
415 for_each_wanted_builtin (j, tgt_j)
416 if (tgt_j->pfn_child_ready_fl)
417 tgt_j->pfn_child_ready_fl(file, line,
418 us_elapsed_absolute,
419 cmd->trace2_child_id,
420 cmd->pid,
421 ready,
422 us_elapsed_child);
425 int trace2_exec_fl(const char *file, int line, const char *exe,
426 const char **argv)
428 struct tr2_tgt *tgt_j;
429 int j;
430 int exec_id;
431 uint64_t us_now;
432 uint64_t us_elapsed_absolute;
434 if (!trace2_enabled)
435 return -1;
437 us_now = getnanotime() / 1000;
438 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
440 exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
442 for_each_wanted_builtin (j, tgt_j)
443 if (tgt_j->pfn_exec_fl)
444 tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
445 exec_id, exe, argv);
447 return exec_id;
450 void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
452 struct tr2_tgt *tgt_j;
453 int j;
454 uint64_t us_now;
455 uint64_t us_elapsed_absolute;
457 if (!trace2_enabled)
458 return;
460 us_now = getnanotime() / 1000;
461 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
463 for_each_wanted_builtin (j, tgt_j)
464 if (tgt_j->pfn_exec_result_fl)
465 tgt_j->pfn_exec_result_fl(
466 file, line, us_elapsed_absolute, exec_id, code);
469 void trace2_thread_start_fl(const char *file, int line, const char *thread_name)
471 struct tr2_tgt *tgt_j;
472 int j;
473 uint64_t us_now;
474 uint64_t us_elapsed_absolute;
476 if (!trace2_enabled)
477 return;
479 if (tr2tls_is_main_thread()) {
481 * We should only be called from the new thread's thread-proc,
482 * so this is technically a bug. But in those cases where the
483 * main thread also runs the thread-proc function (or when we
484 * are built with threading disabled), we need to allow it.
486 * Convert this call to a region-enter so the nesting looks
487 * correct.
489 trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
490 "thread-proc on main: %s",
491 thread_name);
492 return;
495 us_now = getnanotime() / 1000;
496 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
498 tr2tls_create_self(thread_name, us_now);
500 for_each_wanted_builtin (j, tgt_j)
501 if (tgt_j->pfn_thread_start_fl)
502 tgt_j->pfn_thread_start_fl(file, line,
503 us_elapsed_absolute);
506 void trace2_thread_exit_fl(const char *file, int line)
508 struct tr2_tgt *tgt_j;
509 int j;
510 uint64_t us_now;
511 uint64_t us_elapsed_absolute;
512 uint64_t us_elapsed_thread;
514 if (!trace2_enabled)
515 return;
517 if (tr2tls_is_main_thread()) {
519 * We should only be called from the exiting thread's
520 * thread-proc, so this is technically a bug. But in
521 * those cases where the main thread also runs the
522 * thread-proc function (or when we are built with
523 * threading disabled), we need to allow it.
525 * Convert this call to a region-leave so the nesting
526 * looks correct.
528 trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
529 "thread-proc on main");
530 return;
533 us_now = getnanotime() / 1000;
534 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
537 * Clear any unbalanced regions and then get the relative time
538 * for the outer-most region (which we pushed when the thread
539 * started). This gives us the run time of the thread.
541 tr2tls_pop_unwind_self();
542 us_elapsed_thread = tr2tls_region_elasped_self(us_now);
544 for_each_wanted_builtin (j, tgt_j)
545 if (tgt_j->pfn_thread_exit_fl)
546 tgt_j->pfn_thread_exit_fl(file, line,
547 us_elapsed_absolute,
548 us_elapsed_thread);
550 tr2tls_unset_self();
553 void trace2_def_param_fl(const char *file, int line, const char *param,
554 const char *value)
556 struct tr2_tgt *tgt_j;
557 int j;
559 if (!trace2_enabled)
560 return;
562 for_each_wanted_builtin (j, tgt_j)
563 if (tgt_j->pfn_param_fl)
564 tgt_j->pfn_param_fl(file, line, param, value);
567 void trace2_def_repo_fl(const char *file, int line, struct repository *repo)
569 struct tr2_tgt *tgt_j;
570 int j;
572 if (!trace2_enabled)
573 return;
575 if (repo->trace2_repo_id)
576 return;
578 repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
580 for_each_wanted_builtin (j, tgt_j)
581 if (tgt_j->pfn_repo_fl)
582 tgt_j->pfn_repo_fl(file, line, repo);
585 void trace2_region_enter_printf_va_fl(const char *file, int line,
586 const char *category, const char *label,
587 const struct repository *repo,
588 const char *fmt, va_list ap)
590 struct tr2_tgt *tgt_j;
591 int j;
592 uint64_t us_now;
593 uint64_t us_elapsed_absolute;
595 if (!trace2_enabled)
596 return;
598 us_now = getnanotime() / 1000;
599 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
602 * Print the region-enter message at the current nesting
603 * (indentation) level and then push a new level.
605 * We expect each target function to treat 'ap' as constant
606 * and use va_copy.
608 for_each_wanted_builtin (j, tgt_j)
609 if (tgt_j->pfn_region_enter_printf_va_fl)
610 tgt_j->pfn_region_enter_printf_va_fl(
611 file, line, us_elapsed_absolute, category,
612 label, repo, fmt, ap);
614 tr2tls_push_self(us_now);
617 void trace2_region_enter_fl(const char *file, int line, const char *category,
618 const char *label, const struct repository *repo, ...)
620 va_list ap;
621 va_start(ap, repo);
622 trace2_region_enter_printf_va_fl(file, line, category, label, repo,
623 NULL, ap);
624 va_end(ap);
628 void trace2_region_enter_printf_fl(const char *file, int line,
629 const char *category, const char *label,
630 const struct repository *repo,
631 const char *fmt, ...)
633 va_list ap;
635 va_start(ap, fmt);
636 trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt,
637 ap);
638 va_end(ap);
641 void trace2_region_leave_printf_va_fl(const char *file, int line,
642 const char *category, const char *label,
643 const struct repository *repo,
644 const char *fmt, va_list ap)
646 struct tr2_tgt *tgt_j;
647 int j;
648 uint64_t us_now;
649 uint64_t us_elapsed_absolute;
650 uint64_t us_elapsed_region;
652 if (!trace2_enabled)
653 return;
655 us_now = getnanotime() / 1000;
656 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
659 * Get the elapsed time in the current region before we
660 * pop it off the stack. Pop the stack. And then print
661 * the perf message at the new (shallower) level so that
662 * it lines up with the corresponding push/enter.
664 us_elapsed_region = tr2tls_region_elasped_self(us_now);
666 tr2tls_pop_self();
669 * We expect each target function to treat 'ap' as constant
670 * and use va_copy.
672 for_each_wanted_builtin (j, tgt_j)
673 if (tgt_j->pfn_region_leave_printf_va_fl)
674 tgt_j->pfn_region_leave_printf_va_fl(
675 file, line, us_elapsed_absolute,
676 us_elapsed_region, category, label, repo, fmt,
677 ap);
680 void trace2_region_leave_fl(const char *file, int line, const char *category,
681 const char *label, const struct repository *repo, ...)
683 va_list ap;
684 va_start(ap, repo);
685 trace2_region_leave_printf_va_fl(file, line, category, label, repo,
686 NULL, ap);
687 va_end(ap);
690 void trace2_region_leave_printf_fl(const char *file, int line,
691 const char *category, const char *label,
692 const struct repository *repo,
693 const char *fmt, ...)
695 va_list ap;
697 va_start(ap, fmt);
698 trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt,
699 ap);
700 va_end(ap);
703 void trace2_data_string_fl(const char *file, int line, const char *category,
704 const struct repository *repo, const char *key,
705 const char *value)
707 struct tr2_tgt *tgt_j;
708 int j;
709 uint64_t us_now;
710 uint64_t us_elapsed_absolute;
711 uint64_t us_elapsed_region;
713 if (!trace2_enabled)
714 return;
716 us_now = getnanotime() / 1000;
717 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
718 us_elapsed_region = tr2tls_region_elasped_self(us_now);
720 for_each_wanted_builtin (j, tgt_j)
721 if (tgt_j->pfn_data_fl)
722 tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
723 us_elapsed_region, category, repo,
724 key, value);
727 void trace2_data_intmax_fl(const char *file, int line, const char *category,
728 const struct repository *repo, const char *key,
729 intmax_t value)
731 struct strbuf buf_string = STRBUF_INIT;
733 if (!trace2_enabled)
734 return;
736 strbuf_addf(&buf_string, "%" PRIdMAX, value);
737 trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
738 strbuf_release(&buf_string);
741 void trace2_data_json_fl(const char *file, int line, const char *category,
742 const struct repository *repo, const char *key,
743 const struct json_writer *value)
745 struct tr2_tgt *tgt_j;
746 int j;
747 uint64_t us_now;
748 uint64_t us_elapsed_absolute;
749 uint64_t us_elapsed_region;
751 if (!trace2_enabled)
752 return;
754 us_now = getnanotime() / 1000;
755 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
756 us_elapsed_region = tr2tls_region_elasped_self(us_now);
758 for_each_wanted_builtin (j, tgt_j)
759 if (tgt_j->pfn_data_json_fl)
760 tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,
761 us_elapsed_region, category,
762 repo, key, value);
765 void trace2_printf_va_fl(const char *file, int line, const char *fmt,
766 va_list ap)
768 struct tr2_tgt *tgt_j;
769 int j;
770 uint64_t us_now;
771 uint64_t us_elapsed_absolute;
773 if (!trace2_enabled)
774 return;
776 us_now = getnanotime() / 1000;
777 us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
780 * We expect each target function to treat 'ap' as constant
781 * and use va_copy.
783 for_each_wanted_builtin (j, tgt_j)
784 if (tgt_j->pfn_printf_va_fl)
785 tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
786 fmt, ap);
789 void trace2_printf_fl(const char *file, int line, const char *fmt, ...)
791 va_list ap;
793 va_start(ap, fmt);
794 trace2_printf_va_fl(file, line, fmt, ap);
795 va_end(ap);
798 const char *trace2_session_id(void)
800 return tr2_sid_get();