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/cdefs.h> 28 __FBSDID("$FreeBSD$"); 29 30 #include <sys/param.h> 31 #include <sys/kernel.h> 32 #include <sys/linker.h> 33 #include <sys/malloc.h> 34 #include <sys/proc.h> 35 #include <sys/sbuf.h> 36 #include <sys/sysctl.h> 37 #include <sys/systm.h> 38 #include <sys/tslog.h> 39 40 #include <machine/atomic.h> 41 #include <machine/cpu.h> 42 43 #ifndef TSLOGSIZE 44 #define TSLOGSIZE 262144 45 #endif 46 47 static volatile long nrecs = 0; 48 static struct timestamp { 49 void * td; 50 int type; 51 const char * f; 52 const char * s; 53 uint64_t tsc; 54 } timestamps[TSLOGSIZE]; 55 56 void 57 tslog(void * td, int type, const char * f, const char * s) 58 { 59 uint64_t tsc = get_cyclecount(); 60 long pos; 61 62 /* A NULL thread is thread0 before curthread is set. */ 63 if (td == NULL) 64 td = &thread0; 65 66 /* Grab a slot. */ 67 pos = atomic_fetchadd_long(&nrecs, 1); 68 69 /* Store record. */ 70 if (pos < nitems(timestamps)) { 71 timestamps[pos].td = td; 72 timestamps[pos].type = type; 73 timestamps[pos].f = f; 74 timestamps[pos].s = s; 75 timestamps[pos].tsc = tsc; 76 } 77 } 78 79 static int 80 sysctl_debug_tslog(SYSCTL_HANDLER_ARGS) 81 { 82 int error; 83 struct sbuf *sb; 84 size_t i, limit; 85 caddr_t loader_tslog; 86 void * loader_tslog_buf; 87 size_t loader_tslog_len; 88 89 /* 90 * This code can race against the code in tslog() which stores 91 * records: Theoretically we could end up reading a record after 92 * its slots have been reserved but before it has been written. 93 * Since this code takes orders of magnitude longer to run than 94 * tslog() takes to write a record, it is highly unlikely that 95 * anyone will ever experience this race. 96 */ 97 sb = sbuf_new_for_sysctl(NULL, NULL, 1024, req); 98 99 /* Get data from the boot loader, if it provided any. */ 100 loader_tslog = preload_search_by_type("TSLOG data"); 101 if (loader_tslog != NULL) { 102 loader_tslog_buf = preload_fetch_addr(loader_tslog); 103 loader_tslog_len = preload_fetch_size(loader_tslog); 104 sbuf_bcat(sb, loader_tslog_buf, loader_tslog_len); 105 } 106 107 /* Add data logged within the kernel. */ 108 limit = MIN(nrecs, nitems(timestamps)); 109 for (i = 0; i < limit; i++) { 110 sbuf_printf(sb, "%p", timestamps[i].td); 111 sbuf_printf(sb, " %llu", 112 (unsigned long long)timestamps[i].tsc); 113 switch (timestamps[i].type) { 114 case TS_ENTER: 115 sbuf_printf(sb, " ENTER"); 116 break; 117 case TS_EXIT: 118 sbuf_printf(sb, " EXIT"); 119 break; 120 case TS_THREAD: 121 sbuf_printf(sb, " THREAD"); 122 break; 123 case TS_EVENT: 124 sbuf_printf(sb, " EVENT"); 125 break; 126 } 127 sbuf_printf(sb, " %s", timestamps[i].f ? timestamps[i].f : "(null)"); 128 if (timestamps[i].s) 129 sbuf_printf(sb, " %s\n", timestamps[i].s); 130 else 131 sbuf_printf(sb, "\n"); 132 } 133 error = sbuf_finish(sb); 134 sbuf_delete(sb); 135 return (error); 136 } 137 138 SYSCTL_PROC(_debug, OID_AUTO, tslog, 139 CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE|CTLFLAG_SKIP, 140 0, 0, sysctl_debug_tslog, "", "Dump recorded event timestamps"); 141 142 MALLOC_DEFINE(M_TSLOGUSER, "tsloguser", "Strings used by userland tslog"); 143 static struct procdata { 144 pid_t ppid; 145 uint64_t tsc_forked; 146 uint64_t tsc_exited; 147 char * execname; 148 char * namei; 149 int reused; 150 } procs[PID_MAX + 1]; 151 152 void 153 tslog_user(pid_t pid, pid_t ppid, const char * execname, const char * namei) 154 { 155 uint64_t tsc = get_cyclecount(); 156 157 /* If we wrapped, do nothing. */ 158 if (procs[pid].reused) 159 return; 160 161 /* If we have a ppid, we're recording a fork. */ 162 if (ppid != (pid_t)(-1)) { 163 /* If we have a ppid already, we wrapped. */ 164 if (procs[pid].ppid) { 165 procs[pid].reused = 1; 166 return; 167 } 168 169 /* Fill in some fields. */ 170 procs[pid].ppid = ppid; 171 procs[pid].tsc_forked = tsc; 172 return; 173 } 174 175 /* If we have an execname, record it. */ 176 if (execname != NULL) { 177 if (procs[pid].execname != NULL) 178 free(procs[pid].execname, M_TSLOGUSER); 179 procs[pid].execname = strdup(execname, M_TSLOGUSER); 180 return; 181 } 182 183 /* Record the first namei for the process. */ 184 if (namei != NULL) { 185 if (procs[pid].namei == NULL) 186 procs[pid].namei = strdup(namei, M_TSLOGUSER); 187 return; 188 } 189 190 /* Otherwise we're recording an exit. */ 191 procs[pid].tsc_exited = tsc; 192 } 193 194 static int 195 sysctl_debug_tslog_user(SYSCTL_HANDLER_ARGS) 196 { 197 int error; 198 struct sbuf *sb; 199 pid_t pid; 200 201 sb = sbuf_new_for_sysctl(NULL, NULL, 1024, req); 202 203 /* Export the data we logged. */ 204 for (pid = 0; pid <= PID_MAX; pid++) { 205 sbuf_printf(sb, "%zu", (size_t)pid); 206 sbuf_printf(sb, " %zu", (size_t)procs[pid].ppid); 207 sbuf_printf(sb, " %llu", 208 (unsigned long long)procs[pid].tsc_forked); 209 sbuf_printf(sb, " %llu", 210 (unsigned long long)procs[pid].tsc_exited); 211 sbuf_printf(sb, " \"%s\"", procs[pid].execname ? 212 procs[pid].execname : ""); 213 sbuf_printf(sb, " \"%s\"", procs[pid].namei ? 214 procs[pid].namei : ""); 215 sbuf_printf(sb, "\n"); 216 } 217 error = sbuf_finish(sb); 218 sbuf_delete(sb); 219 return (error); 220 } 221 222 SYSCTL_PROC(_debug, OID_AUTO, tslog_user, 223 CTLTYPE_STRING|CTLFLAG_RD|CTLFLAG_MPSAFE|CTLFLAG_SKIP, 224 0, 0, sysctl_debug_tslog_user, 225 "", "Dump recorded userland event timestamps"); 226