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