trace2: refactor setting process starting time
[git] / trace2.c
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
16 static int trace2_enabled;
17
18 static int tr2_next_child_id; /* modify under lock */
19 static int tr2_next_exec_id; /* modify under lock */
20 static 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 */
28 static 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  */
58 static 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  */
76 static 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
85 static 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  */
95 static 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
127 static 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
145 void trace2_initialize_clock(void)
146 {
147         tr2tls_start_process_clock();
148 }
149
150 void 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
176 int trace2_is_enabled(void)
177 {
178         return trace2_enabled;
179 }
180
181 void 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
194 int 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
219 void 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
237 void 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
250 void 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
267 void 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
280 void 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
294 void 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
302 void 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
311 void 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
334 void 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
363 int 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
388 void 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
407 void 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
436         tr2tls_create_self(thread_name, us_now);
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
444 void 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
491 void 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
505 void 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
523 void 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
555 void 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
562 void 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
576 void 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
589 void 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
628 void 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
635 void 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
649 void 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
662 void 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
686 void 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
700 void 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
724 void 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
748 void 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
758 void 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