sys/kern/kern_tslog.c

   1 /*-
   2  * Copyright (c) 2017 Colin Percival
   3  * All rights reserved.
   4  *
   5  * Redistribution and use in source and binary forms, with or without
   6  * modification, are permitted provided that the following conditions
   7  * are met:
   8  * 1. Redistributions of source code must retain the above copyright
   9  *    notice, this list of conditions and the following disclaimer.
  10  * 2. Redistributions in binary form must reproduce the above copyright
  11  *    notice, this list of conditions and the following disclaimer in the
  12  *    documentation and/or other materials provided with the distribution.
  13  *
  14  * THIS SOFTWARE IS PROVIDED BY THE AUTHOR AND CONTRIBUTORS ``AS IS'' AND
  15  * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE
  16  * IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE
  17  * ARE DISCLAIMED.  IN NO EVENT SHALL THE AUTHOR OR CONTRIBUTORS BE LIABLE
  18  * FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL
  19  * DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS
  20  * OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
  21  * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
  22  * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY
  23  * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  24  * SUCH DAMAGE.
  25  */
  26
  27 #include <sys/param.h>
  28 #include <sys/kernel.h>
  29 #include <sys/linker.h>
  30 #include <sys/malloc.h>
  31 #include <sys/proc.h>
  32 #include <sys/sbuf.h>
  33 #include <sys/sysctl.h>
  34 #include <sys/systm.h>
  35 #include <sys/tslog.h>
  36
  37 #include <machine/atomic.h>
  38 #include <machine/cpu.h>
  39
  40 #ifndef TSLOGSIZE
  41 #define TSLOGSIZE 262144
  42 #endif
  43
  44 static volatile long nrecs = 0;
  45 static struct timestamp {
  46         void * td;
  47         int type;
  48         const char * f;
  49         const char * s;
  50         uint64_t tsc;
  51 } timestamps[TSLOGSIZE];
  52
  53 void
  54 tslog(void * td, int type, const char * f, const char * s)
  55 {
  56         uint64_t tsc = get_cyclecount();
  57         long pos;
  58
  59         /* A NULL thread is thread0 before curthread is set. */
  60         if (td == NULL)
  61                 td = &thread0;
  62
  63         /* Grab a slot. */
  64         pos = atomic_fetchadd_long(&nrecs, 1);
  65
  66         /* Store record. */
  67         if (pos < nitems(timestamps)) {
  68                 timestamps[pos].td = td;
  69                 timestamps[pos].type = type;
  70                 timestamps[pos].f = f;
  71                 timestamps[pos].s = s;
  72                 timestamps[pos].tsc = tsc;
  73         }
  74 }
  75
  76 static int
  77 sysctl_debug_tslog(SYSCTL_HANDLER_ARGS)
  78 {
  79         int error;
  80         struct sbuf *sb;
  81         size_t i, limit;
  82         caddr_t loader_tslog;
  83         void * loader_tslog_buf;
  84         size_t loader_tslog_len;
  85
  86         /*
  87          * This code can race against the code in tslog() which stores
  88          * records: Theoretically we could end up reading a record after
  89          * its slots have been reserved but before it has been written.
  90          * Since this code takes orders of magnitude longer to run than
  91          * tslog() takes to write a record, it is highly unlikely that
  92          * anyone will ever experience this race.
  93          */
  94         sb = sbuf_new_for_sysctl(NULL, NULL, 1024, req);
  95
  96         /* Get data from the boot loader, if it provided any. */
  97         loader_tslog = preload_search_by_type("TSLOG data");
  98         if (loader_tslog != NULL) {
  99                 loader_tslog_buf = preload_fetch_addr(loader_tslog);
 100                 loader_tslog_len = preload_fetch_size(loader_tslog);
 101                 sbuf_bcat(sb, loader_tslog_buf, loader_tslog_len);
 102         }
 103
 104         /* Add data logged within the kernel. */
 105         limit = MIN(nrecs, nitems(timestamps));
 106         for (i = 0; i < limit; i++) {
 107                 sbuf_printf(sb, "%p", timestamps[i].td);
 108                 sbuf_printf(sb, " %llu",
 109                     (unsigned long long)timestamps[i].tsc);
 110                 switch (timestamps[i].type) {
 111                 case TS_ENTER:
 112                         sbuf_cat(sb, " ENTER");
 113                         break;
 114                 case TS_EXIT:
 115                         sbuf_cat(sb, " EXIT");
 116                         break;
 117                 case TS_THREAD:
 118                         sbuf_cat(sb, " THREAD");
 119                         break;
 120                 case TS_EVENT:
 121                         sbuf_cat(sb, " EVENT");
 122                         break;
 123                 }
 124                 sbuf_printf(sb, " %s", timestamps[i].f ? timestamps[i].f : "(null)");
 125                 if (timestamps[i].s)
 126                         sbuf_printf(sb, " %s\n", timestamps[i].s);
 127                 else
 128                         sbuf_putc(sb, '\n');
 129         }
 130         error = sbuf_finish(sb);
 131         sbuf_delete(sb);
 132         return (error);
 133 }
 134
 135 SYSCTL_PROC(_debug, OID_AUTO, tslog,
 136     CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE|CTLFLAG_SKIP,
 137     0, 0, sysctl_debug_tslog, "", "Dump recorded event timestamps");
 138
 139 MALLOC_DEFINE(M_TSLOGUSER, "tsloguser", "Strings used by userland tslog");
 140 static struct procdata {
 141         pid_t ppid;
 142         uint64_t tsc_forked;
 143         uint64_t tsc_exited;
 144         char * execname;
 145         char * namei;
 146         int reused;
 147 } procs[PID_MAX + 1];
 148
 149 void
 150 tslog_user(pid_t pid, pid_t ppid, const char * execname, const char * namei)
 151 {
 152         uint64_t tsc = get_cyclecount();
 153
 154         /* If we wrapped, do nothing. */
 155         if (procs[pid].reused)
 156                 return;
 157
 158         /* If we have a ppid, we're recording a fork. */
 159         if (ppid != (pid_t)(-1)) {
 160                 /* If we have a ppid already, we wrapped. */
 161                 if (procs[pid].ppid) {
 162                         procs[pid].reused = 1;
 163                         return;
 164                 }
 165
 166                 /* Fill in some fields. */
 167                 procs[pid].ppid = ppid;
 168                 procs[pid].tsc_forked = tsc;
 169                 return;
 170         }
 171
 172         /* If we have an execname, record it. */
 173         if (execname != NULL) {
 174                 if (procs[pid].execname != NULL)
 175                         free(procs[pid].execname, M_TSLOGUSER);
 176                 procs[pid].execname = strdup(execname, M_TSLOGUSER);
 177                 return;
 178         }
 179
 180         /* Record the first namei for the process. */
 181         if (namei != NULL) {
 182                 if (procs[pid].namei == NULL)
 183                         procs[pid].namei = strdup(namei, M_TSLOGUSER);
 184                 return;
 185         }
 186
 187         /* Otherwise we're recording an exit. */
 188         procs[pid].tsc_exited = tsc;
 189 }
 190
 191 static int
 192 sysctl_debug_tslog_user(SYSCTL_HANDLER_ARGS)
 193 {
 194         int error;
 195         struct sbuf *sb;
 196         pid_t pid;
 197
 198         sb = sbuf_new_for_sysctl(NULL, NULL, 1024, req);
 199
 200         /* Export the data we logged. */
 201         for (pid = 0; pid <= PID_MAX; pid++) {
 202                 sbuf_printf(sb, "%zu", (size_t)pid);
 203                 sbuf_printf(sb, " %zu", (size_t)procs[pid].ppid);
 204                 sbuf_printf(sb, " %llu",
 205                     (unsigned long long)procs[pid].tsc_forked);
 206                 sbuf_printf(sb, " %llu",
 207                     (unsigned long long)procs[pid].tsc_exited);
 208                 sbuf_printf(sb, " \"%s\"", procs[pid].execname ?
 209                     procs[pid].execname : "");
 210                 sbuf_printf(sb, " \"%s\"", procs[pid].namei ?
 211                     procs[pid].namei : "");
 212                 sbuf_putc(sb, '\n');
 213         }
 214         error = sbuf_finish(sb);
 215         sbuf_delete(sb);
 216         return (error);
 217 }
 218
 219 SYSCTL_PROC(_debug, OID_AUTO, tslog_user,
 220     CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE|CTLFLAG_SKIP,
 221     0, 0, sysctl_debug_tslog_user,
 222     "", "Dump recorded userland event timestamps");