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