sys/kern/kern_boottrace.c

   1 /*-
   2  * SPDX-License-Identifier: BSD-2-Clause-FreeBSD
   3  *
   4  * Copyright (c) 2008-2022 NetApp, Inc.
   5  *
   6  * Redistribution and use in source and binary forms, with or without
   7  * modification, are permitted provided that the following conditions
   8  * are met:
   9  * 1. Redistributions of source code must retain the above copyright
  10  *    notice, this list of conditions and the following disclaimer.
  11  * 2. Redistributions in binary form must reproduce the above copyright
  12  *    notice, this list of conditions and the following disclaimer in the
  13  *    documentation and/or other materials provided with the distribution.
  14  *
  15  * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR
  16  * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
  17  * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED.
  18  * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT,
  19  * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT
  20  * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
  21  * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
  22  * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
  23  * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
  24  * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
  25  */
  26
  27 #include <sys/param.h>
  28 #include <sys/systm.h>
  29 #include <sys/boottrace.h>
  30 #include <sys/kernel.h>
  31 #include <sys/malloc.h>
  32 #include <sys/pcpu.h>
  33 #include <sys/proc.h>
  34 #include <sys/resourcevar.h>
  35 #include <sys/sbuf.h>
  36 #include <sys/syscallsubr.h>
  37 #include <sys/sysctl.h>
  38 #include <sys/time.h>
  39
  40 #include <machine/stdarg.h>
  41
  42 #define dprintf(fmt, ...)                                               \
  43         do {                                                            \
  44                 if (dotrace_debugging)                                  \
  45                         printf(fmt, ##__VA_ARGS__);                     \
  46         } while (0);
  47
  48 static MALLOC_DEFINE(M_BOOTTRACE, "boottrace", "memory for boot tracing");
  49
  50 #define BT_TABLE_DEFSIZE        3000
  51 #define BT_TABLE_RUNSIZE        2000
  52 #define BT_TABLE_SHTSIZE        1000
  53 #define BT_TABLE_MINSIZE        500
  54
  55 /*
  56  * Boot-time & shutdown-time event.
  57  */
  58 struct bt_event {
  59         uint64_t tsc;                   /* Timestamp */
  60         uint64_t tick;                  /* Kernel tick */
  61         uint64_t cputime;               /* Microseconds of process CPU time */
  62         uint32_t cpuid;                 /* CPU on which the event ran */
  63         uint32_t inblock;               /* # of blocks in */
  64         uint32_t oublock;               /* # of blocks out */
  65         pid_t pid;                      /* Current PID */
  66         char name[BT_EVENT_NAMELEN];    /* Event name */
  67         char tdname[BT_EVENT_TDNAMELEN]; /* Thread name */
  68 };
  69
  70 struct bt_table {
  71         uint32_t size;                  /* Trace table size */
  72         uint32_t curr;                  /* Trace entry to use */
  73         uint32_t wrap;                  /* Wrap-around, instead of dropping */
  74         uint32_t drops_early;           /* Trace entries dropped before init */
  75         uint32_t drops_full;            /* Trace entries dropped after full */
  76         struct bt_event *table;
  77 };
  78
  79 /* Boot-time tracing */
  80 static struct bt_table bt;
  81
  82 /* Run-time tracing */
  83 static struct bt_table rt;
  84
  85 /* Shutdown-time tracing */
  86 static struct bt_table st;
  87
  88 /* Set when system boot is complete, and we've switched to runtime tracing. */
  89 static bool bootdone;
  90
  91 /* Set when system shutdown has started. */
  92 static bool shutdown;
  93
  94 /* Turn on dotrace() debug logging to console. */
  95 static bool dotrace_debugging;
  96 TUNABLE_BOOL("debug.boottrace.dotrace_debugging", &dotrace_debugging);
  97
  98 /* Trace kernel events */
  99 static bool dotrace_kernel = true;
 100 TUNABLE_BOOL("kern.boottrace.dotrace_kernel", &dotrace_kernel);
 101
 102 /* Trace userspace events */
 103 static bool dotrace_user = true;
 104 TUNABLE_BOOL("kern.boottrace.dotrace_user", &dotrace_user);
 105
 106 static int sysctl_log(SYSCTL_HANDLER_ARGS);
 107 static int sysctl_boottrace(SYSCTL_HANDLER_ARGS);
 108 static int sysctl_runtrace(SYSCTL_HANDLER_ARGS);
 109 static int sysctl_shuttrace(SYSCTL_HANDLER_ARGS);
 110 static int sysctl_boottrace_reset(SYSCTL_HANDLER_ARGS);
 111
 112 SYSCTL_NODE(_kern, OID_AUTO, boottrace, CTLFLAG_RD | CTLFLAG_MPSAFE, 0,
 113     "boottrace statistics");
 114
 115 SYSCTL_PROC(_kern_boottrace, OID_AUTO, log,
 116     CTLTYPE_STRING | CTLFLAG_RD | CTLFLAG_MPSAFE | CTLFLAG_SKIP,
 117     0, 0, sysctl_log, "A",
 118     "Print a log of the boottrace trace data");
 119 SYSCTL_PROC(_kern_boottrace, OID_AUTO, boottrace,
 120     CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
 121     0, 0, sysctl_boottrace, "A",
 122     "Capture a boot-time trace event");
 123 SYSCTL_PROC(_kern_boottrace, OID_AUTO, runtrace,
 124     CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
 125     0, 0, sysctl_runtrace, "A",
 126     "Capture a run-time trace event");
 127 SYSCTL_PROC(_kern_boottrace, OID_AUTO, shuttrace,
 128     CTLTYPE_STRING | CTLFLAG_WR | CTLFLAG_MPSAFE,
 129     0, 0, sysctl_shuttrace, "A",
 130     "Capture a shutdown-time trace event");
 131 SYSCTL_PROC(_kern_boottrace, OID_AUTO, reset,
 132     CTLTYPE_INT | CTLFLAG_WR | CTLFLAG_MPSAFE,
 133     0, 0, sysctl_boottrace_reset, "A",
 134     "Reset run-time tracing table");
 135
 136 /*
 137  * Global enable.
 138  */
 139 bool __read_mostly boottrace_enabled = false;
 140 SYSCTL_BOOL(_kern_boottrace, OID_AUTO, enabled, CTLFLAG_RDTUN,
 141     &boottrace_enabled, 0,
 142     "Boot-time and shutdown-time tracing enabled");
 143
 144 /*
 145  * Enable dumping of the shutdown trace entries to console.
 146  */
 147 bool shutdown_trace = false;
 148 SYSCTL_BOOL(_kern_boottrace, OID_AUTO, shutdown_trace, CTLFLAG_RWTUN,
 149    &shutdown_trace, 0,
 150    "Enable kernel shutdown tracing to the console");
 151
 152 /*
 153  * Set the delta threshold (ms) below which events are ignored, used in
 154  * determining what to dump to the console.
 155  */
 156 static int shutdown_trace_threshold;
 157 SYSCTL_INT(_kern_boottrace, OID_AUTO, shutdown_trace_threshold, CTLFLAG_RWTUN,
 158    &shutdown_trace_threshold, 0,
 159    "Tracing threshold (ms) below which tracing is ignored");
 160
 161 /*
 162  * Dump a trace to buffer or if buffer is NULL to console.
 163  *
 164  * Non-zero delta_threshold selectively prints entries based on delta
 165  * with current and previous entry. Otherwise, delta_threshold of 0
 166  * prints every trace entry and delta.
 167  *
 168  * Output something like this:
 169  *
 170  * CPU      msecs      delta process                  event
 171  *  11 1228262715          0 init                     shutdown pre sync begin
 172  *   3 1228265622       2907 init                     shutdown pre sync complete
 173  *   3 1228265623          0 init                     shutdown turned swap off
 174  *  18 1228266466        843 init                     shutdown unmounted all filesystems
 175  *
 176  * How to interpret:
 177  *
 178  * delta column represents the time in milliseconds between this event and the previous.
 179  * Usually that means you can take the previous event, current event, match them
 180  * up in the code, and whatever lies between is the culprit taking time.
 181  *
 182  * For example, above: Pre-Sync is taking 2907ms, and something between swap and unmount
 183  * filesystems is taking 843 milliseconds.
 184  *
 185  * An event with a delta of 0 are 'landmark' events that simply exist in the output
 186  * for the developer to know where the time measurement begins. The 0 is an arbitrary
 187  * number that can effectively be ignored.
 188  */
 189 #define BTC_DELTA_PRINT(bte, msecs, delta) do {                         \
 190         if (sbp) {                                                      \
 191                 sbuf_printf(sbp, fmt, (bte)->cpuid, msecs, delta,       \
 192                     (bte)->tdname, (bte)->name, (bte)->pid,             \
 193                     (bte)->cputime / 1000000,                           \
 194                     ((bte)->cputime % 1000000) / 10000,                 \
 195                     (bte)->inblock, (bte)->oublock);                    \
 196         } else {                                                        \
 197                 printf(fmt, (bte)->cpuid, msecs, delta,                 \
 198                     (bte)->tdname, (bte)->name, (bte)->pid,             \
 199                     (bte)->cputime / 1000000,                           \
 200                     ((bte)->cputime % 1000000) / 10000,                 \
 201                     (bte)->inblock, (bte)->oublock);                    \
 202         }                                                               \
 203 } while (0)
 204
 205 /*
 206  * Print the trace entries to the message buffer, or to an sbuf, if provided.
 207  *
 208  * Entries with a difference less than dthres will not be printed.
 209  */
 210 static void
 211 boottrace_display(struct sbuf *sbp, struct bt_table *btp, uint64_t dthres)
 212 {
 213         struct bt_event *evtp;
 214         struct bt_event *last_evtp;
 215         uint64_t msecs;
 216         uint64_t first_msecs;
 217         uint64_t last_msecs;
 218         uint64_t dmsecs;
 219         uint64_t last_dmsecs;
 220         uint64_t total_dmsecs;
 221         uint32_t i;
 222         uint32_t curr;
 223         const char *fmt     = "%3u %10llu %10llu %-24s %-40s %5d %4d.%02d %5u %5u\n";
 224         const char *hdr_fmt = "\n\n%3s %10s %10s %-24s %-40s %5s %6s %5s %5s\n";
 225         bool printed;
 226         bool last_printed;
 227
 228         /* Print the header */
 229         if (sbp != NULL)
 230                 sbuf_printf(sbp, hdr_fmt,
 231                     "CPU", "msecs", "delta", "process",
 232                     "event", "PID", "CPUtime", "IBlks", "OBlks");
 233         else
 234                 printf(hdr_fmt,
 235                     "CPU", "msecs", "delta", "process",
 236                     "event", "PID", "CPUtime", "IBlks", "OBlks");
 237
 238         first_msecs = 0;
 239         last_evtp = NULL;
 240         last_msecs = 0;
 241         last_dmsecs = 0;
 242         last_printed = false;
 243         i = curr = btp->curr;
 244
 245         do {
 246                 evtp = &btp->table[i];
 247                 if (evtp->tsc == 0)
 248                         goto next;
 249
 250                 msecs = cputick2usec(evtp->tick) / 1000;
 251                 dmsecs = (last_msecs != 0 && msecs > last_msecs) ?
 252                     msecs - last_msecs : 0;
 253                 printed = false;
 254
 255                 /*
 256                  * If a threshold is defined, start filtering events by the
 257                  * delta of msecs.
 258                  */
 259                 if (dthres != 0 && (dmsecs > dthres)) {
 260                         /*
 261                          * Print the previous entry as a landmark, even if it
 262                          * falls below the threshold.
 263                          */
 264                         if (last_evtp != NULL && !last_printed)
 265                                 BTC_DELTA_PRINT(last_evtp, last_msecs,
 266                                     last_dmsecs);
 267                         BTC_DELTA_PRINT(evtp, msecs, dmsecs);
 268                         printed = true;
 269                 } else if (dthres == 0) {
 270                         BTC_DELTA_PRINT(evtp, msecs, dmsecs);
 271                         printed = true;
 272                 }
 273                 if (first_msecs == 0 || msecs < first_msecs)
 274                         first_msecs = msecs;
 275                 last_evtp = evtp;
 276                 last_msecs = msecs;
 277                 last_dmsecs = dmsecs;
 278                 last_printed = printed;
 279                 maybe_yield();
 280 next:
 281                 i = (i + 1) % btp->size;
 282         } while (i != curr);
 283
 284         total_dmsecs = last_msecs > first_msecs ?
 285             (last_msecs - first_msecs) : 0;
 286         if (sbp != NULL)
 287                 sbuf_printf(sbp, "Total measured time: %ju msecs\n",
 288                     (uintmax_t)total_dmsecs);
 289         else
 290                 printf("Total measured time: %ju msecs\n",
 291                     (uintmax_t)total_dmsecs);
 292 }
 293
 294 /*
 295  * Dump trace table entries to the console, given a delta threshold.
 296  */
 297 void
 298 boottrace_dump_console(void)
 299 {
 300         if (!boottrace_enabled)
 301                 return;
 302
 303         if (shutdown || rebooting || KERNEL_PANICKED()) {
 304                 boottrace_display(NULL, &st, shutdown_trace_threshold);
 305         } else {
 306                 boottrace_display(NULL, &bt, 0);
 307                 boottrace_display(NULL, &rt, 0);
 308         }
 309 }
 310
 311 /*
 312  * Records a new tracing event to the specified table.
 313  *
 314  * We don't use a lock because we want this to be callable from interrupt
 315  * context.
 316  */
 317 static int
 318 dotrace(struct bt_table *btp, const char *eventname, const char *tdname)
 319 {
 320         uint32_t idx, nxt;
 321         struct rusage usage;
 322
 323         MPASS(boottrace_enabled);
 324         if (tdname == NULL)
 325                 tdname = (curproc->p_flag & P_SYSTEM) ?
 326                     curthread->td_name : curproc->p_comm;
 327
 328         dprintf("dotrace[");
 329         dprintf("cpu=%u, pid=%d, tsc=%ju, tick=%d, td='%s', event='%s'",
 330             PCPU_GET(cpuid), curthread->td_proc->p_pid,
 331             (uintmax_t)get_cyclecount(), ticks, tdname, eventname);
 332         if (btp->table == NULL) {
 333                 btp->drops_early++;
 334                 dprintf(", return=ENOSPC_1]\n");
 335                 return (ENOSPC);
 336         }
 337
 338         /* Claim a slot in the table. */
 339         do {
 340                 idx = btp->curr;
 341                 nxt = (idx + 1) % btp->size;
 342                 if (nxt == 0 && btp->wrap == 0) {
 343                         btp->drops_full++;
 344                         dprintf(", return=ENOSPC_2]\n");
 345                         return (ENOSPC);
 346                 }
 347         } while (!atomic_cmpset_int(&btp->curr, idx, nxt));
 348
 349         btp->table[idx].cpuid = PCPU_GET(cpuid);
 350         btp->table[idx].tsc = get_cyclecount(),
 351         btp->table[idx].tick = cpu_ticks();
 352         btp->table[idx].pid = curthread->td_proc->p_pid;
 353
 354         /*
 355          * Get the resource usage for the process. Don't attempt this for the
 356          * kernel proc0 or for critical section activities.
 357          */
 358         if ((curthread->td_proc == &proc0) || (curthread->td_critnest != 0)) {
 359                 btp->table[idx].cputime = 0;
 360                 btp->table[idx].inblock = 0;
 361                 btp->table[idx].oublock = 0;
 362         } else {
 363                 kern_getrusage(curthread, RUSAGE_CHILDREN, &usage);
 364                 btp->table[idx].cputime =
 365                     (uint64_t)(usage.ru_utime.tv_sec * 1000000 +
 366                     usage.ru_utime.tv_usec + usage.ru_stime.tv_sec * 1000000 +
 367                     usage.ru_stime.tv_usec);
 368                 btp->table[idx].inblock = (uint32_t)usage.ru_inblock;
 369                 btp->table[idx].oublock = (uint32_t)usage.ru_oublock;
 370         }
 371         strlcpy(btp->table[idx].name, eventname, BT_EVENT_NAMELEN);
 372         strlcpy(btp->table[idx].tdname, tdname, BT_EVENT_TDNAMELEN);
 373
 374         dprintf(", return=0]\n");
 375         return (0);
 376 }
 377
 378 /*
 379  * Log various boot-time events, with the trace message encoded using
 380  * printf-like arguments.
 381  */
 382 int
 383 boottrace(const char *tdname, const char *fmt, ...)
 384 {
 385         char eventname[BT_EVENT_NAMELEN];
 386         struct bt_table *btp;
 387         va_list ap;
 388
 389         if (!dotrace_kernel)
 390                  return (ENXIO);
 391
 392         va_start(ap, fmt);
 393         vsnprintf(eventname, sizeof(eventname), fmt, ap);
 394         va_end(ap);
 395
 396         btp = &bt;
 397         if (bootdone)
 398                 btp = &rt;
 399         if (shutdown || rebooting || KERNEL_PANICKED())
 400                 btp = &st;
 401
 402         return (dotrace(btp, eventname, tdname));
 403 }
 404
 405 /*
 406  * Log a run-time event & switch over to run-time tracing mode.
 407  */
 408 static int
 409 runtrace(const char *eventname, const char *tdname)
 410 {
 411
 412         bootdone = true;
 413         return (dotrace(&rt, eventname, tdname));
 414 }
 415
 416 /*
 417  * Parse a boottrace message from userspace.
 418  *
 419  * The input from may contain a ':' to denote tdname. If not, tdname is
 420  * inferred from the process' name.
 421  *
 422  * e.g. reboot(8):SIGINT to init(8)
 423  */
 424 static void
 425 boottrace_parse_message(char *message, char **eventname, char **tdname)
 426 {
 427         char *delim;
 428
 429         delim = strchr(message, ':');
 430         if (delim != NULL) {
 431                 *delim = '\0';
 432                 *tdname = message;
 433                 *eventname = ++delim;
 434         } else {
 435                 *tdname = curproc->p_comm;
 436                 *eventname = message;
 437         }
 438 }
 439
 440 static int
 441 _boottrace_sysctl(struct bt_table *btp, struct sysctl_oid *oidp,
 442     struct sysctl_req *req)
 443 {
 444         char message[BT_MSGLEN];
 445         char *eventname, *tdname;
 446         int error;
 447
 448         if (!dotrace_user)
 449                return (ENXIO);
 450
 451         message[0] = '\0';
 452         error = sysctl_handle_string(oidp, message, sizeof(message), req);
 453         if (error)
 454                 return (error);
 455
 456         boottrace_parse_message(message, &eventname, &tdname);
 457         error = dotrace(btp, eventname, tdname);
 458         if (error == ENOSPC) {
 459                 /* Ignore table full error. */
 460                 error = 0;
 461         }
 462         return (error);
 463 }
 464
 465 static int
 466 sysctl_log(SYSCTL_HANDLER_ARGS)
 467 {
 468         struct sbuf *sbuf;
 469         int error;
 470
 471         if (!boottrace_enabled || req->newptr != NULL)
 472                 return (0);
 473
 474         sbuf = sbuf_new(NULL, NULL, 0, SBUF_AUTOEXTEND);
 475         boottrace_display(sbuf, &bt, 0);
 476         boottrace_display(sbuf, &rt, 0);
 477         sbuf_finish(sbuf);
 478         error = SYSCTL_OUT(req, sbuf_data(sbuf), sbuf_len(sbuf));
 479         sbuf_delete(sbuf);
 480
 481         return (error);
 482 }
 483
 484 static int
 485 sysctl_boottrace(SYSCTL_HANDLER_ARGS)
 486 {
 487
 488         if (!boottrace_enabled)
 489                 return (0);
 490
 491         /* No output */
 492         if (req->newptr == NULL)
 493                 return (0);
 494
 495         /* Trace to rt if we have reached multi-user. */
 496         return (_boottrace_sysctl(bootdone ? &rt : &bt, oidp, req));
 497 }
 498
 499 /*
 500  * Log a run-time event and switch over to run-time tracing mode.
 501  */
 502 static int
 503 sysctl_runtrace(SYSCTL_HANDLER_ARGS)
 504 {
 505
 506         if (!boottrace_enabled)
 507                 return (0);
 508
 509         /* No output */
 510         if (req->newptr == NULL)
 511                 return (0);
 512
 513         bootdone = true;
 514         return (_boottrace_sysctl(&rt, oidp, req));
 515 }
 516
 517 /*
 518  * Log a shutdown-time event and switch over to shutdown tracing mode.
 519  */
 520 static int
 521 sysctl_shuttrace(SYSCTL_HANDLER_ARGS)
 522 {
 523
 524         if (!boottrace_enabled)
 525                 return (0);
 526
 527         /* No output */
 528         if (req->newptr == NULL)
 529                 return (0);
 530
 531         shutdown = true;
 532         return (_boottrace_sysctl(&st, oidp, req));
 533 }
 534
 535 /*
 536  * Reset the runtime tracing buffer.
 537  */
 538 void
 539 boottrace_reset(const char *actor)
 540 {
 541         char tmpbuf[64];
 542
 543         snprintf(tmpbuf, sizeof(tmpbuf), "reset: %s", actor);
 544         runtrace(tmpbuf, NULL);
 545 }
 546
 547 /*
 548  * Note that a resize implies a reset, i.e., the index is reset to 0.
 549  * We never shrink the array; we can only increase its size.
 550  */
 551 int
 552 boottrace_resize(u_int newsize)
 553 {
 554
 555         if (newsize <= rt.size) {
 556                 return (EINVAL);
 557         }
 558         rt.table = realloc(rt.table, newsize * sizeof(struct bt_event),
 559             M_BOOTTRACE, M_WAITOK | M_ZERO);
 560         if (rt.table == NULL)
 561                 return (ENOMEM);
 562
 563         rt.size = newsize;
 564         boottrace_reset("boottrace_resize");
 565         return (0);
 566 }
 567
 568 static int
 569 sysctl_boottrace_reset(SYSCTL_HANDLER_ARGS)
 570 {
 571
 572         if (!boottrace_enabled)
 573                 return (0);
 574
 575         if (req->newptr != NULL)
 576                 boottrace_reset("sysctl_boottrace_reset");
 577
 578         return (0);
 579 }
 580
 581 static void
 582 boottrace_init(void)
 583 {
 584
 585         if (!boottrace_enabled)
 586                 return;
 587
 588         /* Boottime trace table */
 589         bt.size = BT_TABLE_DEFSIZE;
 590         TUNABLE_INT_FETCH("kern.boottrace.table_size", &bt.size);
 591         bt.size = max(bt.size, BT_TABLE_MINSIZE);
 592         bt.table = malloc(bt.size * sizeof(struct bt_event), M_BOOTTRACE,
 593             M_WAITOK | M_ZERO);
 594
 595         /* Stick in an initial entry. */
 596         bt.table[0].cpuid = PCPU_GET(cpuid);
 597         strlcpy(bt.table[0].tdname, "boottime", BT_EVENT_TDNAMELEN);
 598         strlcpy(bt.table[0].name, "initial event", BT_EVENT_NAMELEN);
 599         bt.curr = 1;
 600
 601         /* Run-time trace table (may wrap-around). */
 602         rt.wrap = 1;
 603         rt.size = BT_TABLE_RUNSIZE;
 604         rt.table = malloc(rt.size * sizeof(struct bt_event), M_BOOTTRACE,
 605             M_WAITOK | M_ZERO);
 606
 607         /* Shutdown trace table */
 608         st.size = BT_TABLE_SHTSIZE;
 609         st.table = malloc(st.size * sizeof(struct bt_event), M_BOOTTRACE,
 610             M_WAITOK | M_ZERO);
 611 }
 612 SYSINIT(boottrace, SI_SUB_CPU, SI_ORDER_ANY, boottrace_init, 0);