trace2/tr2_tgt_perf.c

   1 #include "cache.h"
   2 #include "config.h"
   3 #include "run-command.h"
   4 #include "quote.h"
   5 #include "version.h"
   6 #include "json-writer.h"
   7 #include "trace2/tr2_dst.h"
   8 #include "trace2/tr2_sid.h"
   9 #include "trace2/tr2_sysenv.h"
  10 #include "trace2/tr2_tbuf.h"
  11 #include "trace2/tr2_tgt.h"
  12 #include "trace2/tr2_tls.h"
  13
  14 static struct tr2_dst tr2dst_perf = {
  15         .sysenv_var = TR2_SYSENV_PERF,
  16 };
  17
  18 /*
  19  * Use TR2_SYSENV_PERF_BRIEF to omit the "<time> <file>:<line>"
  20  * fields from each line written to the builtin performance target.
  21  *
  22  * Unit tests may want to use this to help with testing.
  23  */
  24 static int tr2env_perf_be_brief;
  25
  26 #define TR2FMT_PERF_FL_WIDTH (28)
  27 #define TR2FMT_PERF_MAX_EVENT_NAME (12)
  28 #define TR2FMT_PERF_REPO_WIDTH (3)
  29 #define TR2FMT_PERF_CATEGORY_WIDTH (12)
  30
  31 #define TR2_INDENT (2)
  32 #define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)
  33
  34 static int fn_init(void)
  35 {
  36         int want = tr2_dst_trace_want(&tr2dst_perf);
  37         int want_brief;
  38         const char *brief;
  39
  40         if (!want)
  41                 return want;
  42
  43         brief = tr2_sysenv_get(TR2_SYSENV_PERF_BRIEF);
  44         if (brief && *brief &&
  45             ((want_brief = git_parse_maybe_bool(brief)) != -1))
  46                 tr2env_perf_be_brief = want_brief;
  47
  48         return want;
  49 }
  50
  51 static void fn_term(void)
  52 {
  53         tr2_dst_trace_disable(&tr2dst_perf);
  54 }
  55
  56 /*
  57  * Format trace line prefix in human-readable classic format for
  58  * the performance target:
  59  *     "[<time> [<file>:<line>] <bar>] <nr_parents> <bar>
  60  *         <thread_name> <bar> <event_name> <bar> [<repo>] <bar>
  61  *         [<elapsed_absolute>] [<elapsed_relative>] <bar>
  62  *         [<category>] <bar> [<dots>] "
  63  */
  64 static void perf_fmt_prepare(const char *event_name,
  65                              struct tr2tls_thread_ctx *ctx, const char *file,
  66                              int line, const struct repository *repo,
  67                              uint64_t *p_us_elapsed_absolute,
  68                              uint64_t *p_us_elapsed_relative,
  69                              const char *category, struct strbuf *buf)
  70 {
  71         int len;
  72
  73         strbuf_setlen(buf, 0);
  74
  75         if (!tr2env_perf_be_brief) {
  76                 struct tr2_tbuf tb_now;
  77                 size_t fl_end_col;
  78
  79                 tr2_tbuf_local_time(&tb_now);
  80                 strbuf_addstr(buf, tb_now.buf);
  81                 strbuf_addch(buf, ' ');
  82
  83                 fl_end_col = buf->len + TR2FMT_PERF_FL_WIDTH;
  84
  85                 if (file && *file) {
  86                         struct strbuf buf_fl = STRBUF_INIT;
  87
  88                         strbuf_addf(&buf_fl, "%s:%d", file, line);
  89
  90                         if (buf_fl.len <= TR2FMT_PERF_FL_WIDTH)
  91                                 strbuf_addbuf(buf, &buf_fl);
  92                         else {
  93                                 size_t avail = TR2FMT_PERF_FL_WIDTH - 3;
  94                                 strbuf_addstr(buf, "...");
  95                                 strbuf_add(buf,
  96                                            &buf_fl.buf[buf_fl.len - avail],
  97                                            avail);
  98                         }
  99
 100                         strbuf_release(&buf_fl);
 101                 }
 102
 103                 while (buf->len < fl_end_col)
 104                         strbuf_addch(buf, ' ');
 105
 106                 strbuf_addstr(buf, " | ");
 107         }
 108
 109         strbuf_addf(buf, "d%d | ", tr2_sid_depth());
 110         strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME,
 111                     ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME,
 112                     event_name);
 113
 114         len = buf->len + TR2FMT_PERF_REPO_WIDTH;
 115         if (repo)
 116                 strbuf_addf(buf, "r%d ", repo->trace2_repo_id);
 117         while (buf->len < len)
 118                 strbuf_addch(buf, ' ');
 119         strbuf_addstr(buf, " | ");
 120
 121         if (p_us_elapsed_absolute)
 122                 strbuf_addf(buf, "%9.6f | ",
 123                             ((double)(*p_us_elapsed_absolute)) / 1000000.0);
 124         else
 125                 strbuf_addf(buf, "%9s | ", " ");
 126
 127         if (p_us_elapsed_relative)
 128                 strbuf_addf(buf, "%9.6f | ",
 129                             ((double)(*p_us_elapsed_relative)) / 1000000.0);
 130         else
 131                 strbuf_addf(buf, "%9s | ", " ");
 132
 133         strbuf_addf(buf, "%-*.*s | ", TR2FMT_PERF_CATEGORY_WIDTH,
 134                     TR2FMT_PERF_CATEGORY_WIDTH, (category ? category : ""));
 135
 136         if (ctx->nr_open_regions > 0)
 137                 strbuf_addchars(buf, '.', TR2_INDENT_LENGTH(ctx));
 138 }
 139
 140 static void perf_io_write_fl(const char *file, int line, const char *event_name,
 141                              const struct repository *repo,
 142                              uint64_t *p_us_elapsed_absolute,
 143                              uint64_t *p_us_elapsed_relative,
 144                              const char *category,
 145                              const struct strbuf *buf_payload)
 146 {
 147         struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
 148         struct strbuf buf_line = STRBUF_INIT;
 149
 150         perf_fmt_prepare(event_name, ctx, file, line, repo,
 151                          p_us_elapsed_absolute, p_us_elapsed_relative, category,
 152                          &buf_line);
 153         strbuf_addbuf(&buf_line, buf_payload);
 154         tr2_dst_write_line(&tr2dst_perf, &buf_line);
 155         strbuf_release(&buf_line);
 156 }
 157
 158 static void fn_version_fl(const char *file, int line)
 159 {
 160         const char *event_name = "version";
 161         struct strbuf buf_payload = STRBUF_INIT;
 162
 163         strbuf_addstr(&buf_payload, git_version_string);
 164
 165         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 166                          &buf_payload);
 167         strbuf_release(&buf_payload);
 168 }
 169
 170 static void fn_start_fl(const char *file, int line,
 171                         uint64_t us_elapsed_absolute, const char **argv)
 172 {
 173         const char *event_name = "start";
 174         struct strbuf buf_payload = STRBUF_INIT;
 175
 176         sq_append_quote_argv_pretty(&buf_payload, argv);
 177
 178         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 179                          NULL, NULL, &buf_payload);
 180         strbuf_release(&buf_payload);
 181 }
 182
 183 static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
 184                        int code)
 185 {
 186         const char *event_name = "exit";
 187         struct strbuf buf_payload = STRBUF_INIT;
 188
 189         strbuf_addf(&buf_payload, "code:%d", code);
 190
 191         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 192                          NULL, NULL, &buf_payload);
 193         strbuf_release(&buf_payload);
 194 }
 195
 196 static void fn_signal(uint64_t us_elapsed_absolute, int signo)
 197 {
 198         const char *event_name = "signal";
 199         struct strbuf buf_payload = STRBUF_INIT;
 200
 201         strbuf_addf(&buf_payload, "signo:%d", signo);
 202
 203         perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
 204                          &us_elapsed_absolute, NULL, NULL, &buf_payload);
 205         strbuf_release(&buf_payload);
 206 }
 207
 208 static void fn_atexit(uint64_t us_elapsed_absolute, int code)
 209 {
 210         const char *event_name = "atexit";
 211         struct strbuf buf_payload = STRBUF_INIT;
 212
 213         strbuf_addf(&buf_payload, "code:%d", code);
 214
 215         perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
 216                          &us_elapsed_absolute, NULL, NULL, &buf_payload);
 217         strbuf_release(&buf_payload);
 218 }
 219
 220 static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
 221                                    va_list ap)
 222 {
 223         if (fmt && *fmt) {
 224                 va_list copy_ap;
 225
 226                 va_copy(copy_ap, ap);
 227                 strbuf_vaddf(buf, fmt, copy_ap);
 228                 va_end(copy_ap);
 229                 return;
 230         }
 231 }
 232
 233 static void fn_error_va_fl(const char *file, int line, const char *fmt,
 234                            va_list ap)
 235 {
 236         const char *event_name = "error";
 237         struct strbuf buf_payload = STRBUF_INIT;
 238
 239         maybe_append_string_va(&buf_payload, fmt, ap);
 240
 241         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 242                          &buf_payload);
 243         strbuf_release(&buf_payload);
 244 }
 245
 246 static void fn_command_path_fl(const char *file, int line, const char *pathname)
 247 {
 248         const char *event_name = "cmd_path";
 249         struct strbuf buf_payload = STRBUF_INIT;
 250
 251         strbuf_addstr(&buf_payload, pathname);
 252
 253         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 254                          &buf_payload);
 255         strbuf_release(&buf_payload);
 256 }
 257
 258 static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names)
 259 {
 260         const char *event_name = "cmd_ancestry";
 261         struct strbuf buf_payload = STRBUF_INIT;
 262
 263         strbuf_addstr(&buf_payload, "ancestry:[");
 264         /* It's not an argv but the rules are basically the same. */
 265         sq_append_quote_argv_pretty(&buf_payload, parent_names);
 266         strbuf_addch(&buf_payload, ']');
 267
 268         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 269                          &buf_payload);
 270         strbuf_release(&buf_payload);
 271 }
 272
 273 static void fn_command_name_fl(const char *file, int line, const char *name,
 274                                const char *hierarchy)
 275 {
 276         const char *event_name = "cmd_name";
 277         struct strbuf buf_payload = STRBUF_INIT;
 278
 279         strbuf_addstr(&buf_payload, name);
 280         if (hierarchy && *hierarchy)
 281                 strbuf_addf(&buf_payload, " (%s)", hierarchy);
 282
 283         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 284                          &buf_payload);
 285         strbuf_release(&buf_payload);
 286 }
 287
 288 static void fn_command_mode_fl(const char *file, int line, const char *mode)
 289 {
 290         const char *event_name = "cmd_mode";
 291         struct strbuf buf_payload = STRBUF_INIT;
 292
 293         strbuf_addstr(&buf_payload, mode);
 294
 295         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 296                          &buf_payload);
 297         strbuf_release(&buf_payload);
 298 }
 299
 300 static void fn_alias_fl(const char *file, int line, const char *alias,
 301                         const char **argv)
 302 {
 303         const char *event_name = "alias";
 304         struct strbuf buf_payload = STRBUF_INIT;
 305
 306         strbuf_addf(&buf_payload, "alias:%s argv:[", alias);
 307         sq_append_quote_argv_pretty(&buf_payload, argv);
 308         strbuf_addch(&buf_payload, ']');
 309
 310         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
 311                          &buf_payload);
 312         strbuf_release(&buf_payload);
 313 }
 314
 315 static void fn_child_start_fl(const char *file, int line,
 316                               uint64_t us_elapsed_absolute,
 317                               const struct child_process *cmd)
 318 {
 319         const char *event_name = "child_start";
 320         struct strbuf buf_payload = STRBUF_INIT;
 321
 322         if (cmd->trace2_hook_name) {
 323                 strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s",
 324                             cmd->trace2_child_id, cmd->trace2_hook_name);
 325         } else {
 326                 const char *child_class =
 327                         cmd->trace2_child_class ? cmd->trace2_child_class : "?";
 328                 strbuf_addf(&buf_payload, "[ch%d] class:%s",
 329                             cmd->trace2_child_id, child_class);
 330         }
 331
 332         if (cmd->dir) {
 333                 strbuf_addstr(&buf_payload, " cd:");
 334                 sq_quote_buf_pretty(&buf_payload, cmd->dir);
 335         }
 336
 337         strbuf_addstr(&buf_payload, " argv:[");
 338         if (cmd->git_cmd) {
 339                 strbuf_addstr(&buf_payload, "git");
 340                 if (cmd->args.nr)
 341                         strbuf_addch(&buf_payload, ' ');
 342         }
 343         sq_append_quote_argv_pretty(&buf_payload, cmd->args.v);
 344         strbuf_addch(&buf_payload, ']');
 345
 346         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 347                          NULL, NULL, &buf_payload);
 348         strbuf_release(&buf_payload);
 349 }
 350
 351 static void fn_child_exit_fl(const char *file, int line,
 352                              uint64_t us_elapsed_absolute, int cid, int pid,
 353                              int code, uint64_t us_elapsed_child)
 354 {
 355         const char *event_name = "child_exit";
 356         struct strbuf buf_payload = STRBUF_INIT;
 357
 358         strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code);
 359
 360         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 361                          &us_elapsed_child, NULL, &buf_payload);
 362         strbuf_release(&buf_payload);
 363 }
 364
 365 static void fn_child_ready_fl(const char *file, int line,
 366                               uint64_t us_elapsed_absolute, int cid, int pid,
 367                               const char *ready, uint64_t us_elapsed_child)
 368 {
 369         const char *event_name = "child_ready";
 370         struct strbuf buf_payload = STRBUF_INIT;
 371
 372         strbuf_addf(&buf_payload, "[ch%d] pid:%d ready:%s", cid, pid, ready);
 373
 374         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 375                          &us_elapsed_child, NULL, &buf_payload);
 376         strbuf_release(&buf_payload);
 377 }
 378
 379 static void fn_thread_start_fl(const char *file, int line,
 380                                uint64_t us_elapsed_absolute)
 381 {
 382         const char *event_name = "thread_start";
 383         struct strbuf buf_payload = STRBUF_INIT;
 384
 385         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 386                          NULL, NULL, &buf_payload);
 387         strbuf_release(&buf_payload);
 388 }
 389
 390 static void fn_thread_exit_fl(const char *file, int line,
 391                               uint64_t us_elapsed_absolute,
 392                               uint64_t us_elapsed_thread)
 393 {
 394         const char *event_name = "thread_exit";
 395         struct strbuf buf_payload = STRBUF_INIT;
 396
 397         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 398                          &us_elapsed_thread, NULL, &buf_payload);
 399         strbuf_release(&buf_payload);
 400 }
 401
 402 static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
 403                        int exec_id, const char *exe, const char **argv)
 404 {
 405         const char *event_name = "exec";
 406         struct strbuf buf_payload = STRBUF_INIT;
 407
 408         strbuf_addf(&buf_payload, "id:%d ", exec_id);
 409         strbuf_addstr(&buf_payload, "argv:[");
 410         if (exe) {
 411                 strbuf_addstr(&buf_payload, exe);
 412                 if (argv[0])
 413                         strbuf_addch(&buf_payload, ' ');
 414         }
 415         sq_append_quote_argv_pretty(&buf_payload, argv);
 416         strbuf_addch(&buf_payload, ']');
 417
 418         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 419                          NULL, NULL, &buf_payload);
 420         strbuf_release(&buf_payload);
 421 }
 422
 423 static void fn_exec_result_fl(const char *file, int line,
 424                               uint64_t us_elapsed_absolute, int exec_id,
 425                               int code)
 426 {
 427         const char *event_name = "exec_result";
 428         struct strbuf buf_payload = STRBUF_INIT;
 429
 430         strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code);
 431         if (code > 0)
 432                 strbuf_addf(&buf_payload, " err:%s", strerror(code));
 433
 434         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 435                          NULL, NULL, &buf_payload);
 436         strbuf_release(&buf_payload);
 437 }
 438
 439 static void fn_param_fl(const char *file, int line, const char *param,
 440                         const char *value)
 441 {
 442         const char *event_name = "def_param";
 443         struct strbuf buf_payload = STRBUF_INIT;
 444         struct strbuf scope_payload = STRBUF_INIT;
 445         enum config_scope scope = current_config_scope();
 446         const char *scope_name = config_scope_name(scope);
 447
 448         strbuf_addf(&buf_payload, "%s:%s", param, value);
 449         strbuf_addf(&scope_payload, "%s:%s", "scope", scope_name);
 450
 451         perf_io_write_fl(file, line, event_name, NULL, NULL, NULL,
 452                          scope_payload.buf, &buf_payload);
 453         strbuf_release(&buf_payload);
 454         strbuf_release(&scope_payload);
 455 }
 456
 457 static void fn_repo_fl(const char *file, int line,
 458                        const struct repository *repo)
 459 {
 460         const char *event_name = "def_repo";
 461         struct strbuf buf_payload = STRBUF_INIT;
 462
 463         strbuf_addstr(&buf_payload, "worktree:");
 464         sq_quote_buf_pretty(&buf_payload, repo->worktree);
 465
 466         perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL,
 467                          &buf_payload);
 468         strbuf_release(&buf_payload);
 469 }
 470
 471 static void fn_region_enter_printf_va_fl(const char *file, int line,
 472                                          uint64_t us_elapsed_absolute,
 473                                          const char *category,
 474                                          const char *label,
 475                                          const struct repository *repo,
 476                                          const char *fmt, va_list ap)
 477 {
 478         const char *event_name = "region_enter";
 479         struct strbuf buf_payload = STRBUF_INIT;
 480
 481         if (label)
 482                 strbuf_addf(&buf_payload, "label:%s", label);
 483         if (fmt && *fmt) {
 484                 strbuf_addch(&buf_payload, ' ');
 485                 maybe_append_string_va(&buf_payload, fmt, ap);
 486         }
 487
 488         perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
 489                          NULL, category, &buf_payload);
 490         strbuf_release(&buf_payload);
 491 }
 492
 493 static void fn_region_leave_printf_va_fl(
 494         const char *file, int line, uint64_t us_elapsed_absolute,
 495         uint64_t us_elapsed_region, const char *category, const char *label,
 496         const struct repository *repo, const char *fmt, va_list ap)
 497 {
 498         const char *event_name = "region_leave";
 499         struct strbuf buf_payload = STRBUF_INIT;
 500
 501         if (label)
 502                 strbuf_addf(&buf_payload, "label:%s", label);
 503         if (fmt && *fmt) {
 504                 strbuf_addch(&buf_payload, ' ' );
 505                 maybe_append_string_va(&buf_payload, fmt, ap);
 506         }
 507
 508         perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
 509                          &us_elapsed_region, category, &buf_payload);
 510         strbuf_release(&buf_payload);
 511 }
 512
 513 static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
 514                        uint64_t us_elapsed_region, const char *category,
 515                        const struct repository *repo, const char *key,
 516                        const char *value)
 517 {
 518         const char *event_name = "data";
 519         struct strbuf buf_payload = STRBUF_INIT;
 520
 521         strbuf_addf(&buf_payload, "%s:%s", key, value);
 522
 523         perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
 524                          &us_elapsed_region, category, &buf_payload);
 525         strbuf_release(&buf_payload);
 526 }
 527
 528 static void fn_data_json_fl(const char *file, int line,
 529                             uint64_t us_elapsed_absolute,
 530                             uint64_t us_elapsed_region, const char *category,
 531                             const struct repository *repo, const char *key,
 532                             const struct json_writer *value)
 533 {
 534         const char *event_name = "data_json";
 535         struct strbuf buf_payload = STRBUF_INIT;
 536
 537         strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf);
 538
 539         perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
 540                          &us_elapsed_region, category, &buf_payload);
 541         strbuf_release(&buf_payload);
 542 }
 543
 544 static void fn_printf_va_fl(const char *file, int line,
 545                             uint64_t us_elapsed_absolute, const char *fmt,
 546                             va_list ap)
 547 {
 548         const char *event_name = "printf";
 549         struct strbuf buf_payload = STRBUF_INIT;
 550
 551         maybe_append_string_va(&buf_payload, fmt, ap);
 552
 553         perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
 554                          NULL, NULL, &buf_payload);
 555         strbuf_release(&buf_payload);
 556 }
 557
 558 struct tr2_tgt tr2_tgt_perf = {
 559         .pdst = &tr2dst_perf,
 560
 561         .pfn_init = fn_init,
 562         .pfn_term = fn_term,
 563
 564         .pfn_version_fl = fn_version_fl,
 565         .pfn_start_fl = fn_start_fl,
 566         .pfn_exit_fl = fn_exit_fl,
 567         .pfn_signal = fn_signal,
 568         .pfn_atexit = fn_atexit,
 569         .pfn_error_va_fl = fn_error_va_fl,
 570         .pfn_command_path_fl = fn_command_path_fl,
 571         .pfn_command_ancestry_fl = fn_command_ancestry_fl,
 572         .pfn_command_name_fl = fn_command_name_fl,
 573         .pfn_command_mode_fl = fn_command_mode_fl,
 574         .pfn_alias_fl = fn_alias_fl,
 575         .pfn_child_start_fl = fn_child_start_fl,
 576         .pfn_child_exit_fl = fn_child_exit_fl,
 577         .pfn_child_ready_fl = fn_child_ready_fl,
 578         .pfn_thread_start_fl = fn_thread_start_fl,
 579         .pfn_thread_exit_fl = fn_thread_exit_fl,
 580         .pfn_exec_fl = fn_exec_fl,
 581         .pfn_exec_result_fl = fn_exec_result_fl,
 582         .pfn_param_fl = fn_param_fl,
 583         .pfn_repo_fl = fn_repo_fl,
 584         .pfn_region_enter_printf_va_fl = fn_region_enter_printf_va_fl,
 585         .pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl,
 586         .pfn_data_fl = fn_data_fl,
 587         .pfn_data_json_fl = fn_data_json_fl,
 588         .pfn_printf_va_fl = fn_printf_va_fl,
 589 };