X-Git-Url: https://git.saurik.com/apple/system_cmds.git/blobdiff_plain/fc6d9e4b3869b070d680256cdce0a1acf93ae569..b58caf92d598c70ddd398b3909b0a2b8b5a110e1:/trace.tproj/trace.c?ds=inline diff --git a/trace.tproj/trace.c b/trace.tproj/trace.c index a850d2c..190e8b2 100644 --- a/trace.tproj/trace.c +++ b/trace.tproj/trace.c @@ -2,6 +2,10 @@ cc -I/System/Library/Frameworks/System.framework/Versions/B/PrivateHeaders -arch x86_64 -arch i386 -O -o trace trace.c */ +/* + * NOTE: There exists another copy of this file in the kernel_tools. Changes + * made here may also need to be made there. + */ #include #include @@ -28,6 +32,10 @@ #include #include #include +#include +#include +#include +#include #include @@ -43,7 +51,6 @@ #include #include - int nbufs = 0; int enable_flag=0; int execute_flag=0; @@ -93,6 +100,7 @@ extern char **environ; uint8_t* type_filter_bitmap; +#define SIZE_4KB (4 * (1 << 10)) #define DBG_FUNC_ALL (DBG_FUNC_START | DBG_FUNC_END) #define DBG_FUNC_MASK 0xfffffffc @@ -101,13 +109,8 @@ uint8_t* type_filter_bitmap; #define CSC_MASK 0xffff0000 -#define VFS_LOOKUP 0x03010090 #define BSC_exit 0x040c0004 #define BSC_thread_terminate 0x040c05a4 -#define TRACE_DATA_NEWTHREAD 0x07000004 -#define TRACE_STRING_NEWTHREAD 0x07010004 -#define TRACE_STRING_EXEC 0x07010008 -#define TRACE_LOST_EVENTS 0x07020008 #define MACH_SCHEDULED 0x01400000 #define MACH_MAKERUNNABLE 0x01400018 #define MACH_STKHANDOFF 0x01400008 @@ -124,8 +127,8 @@ kd_threadmap *mapptr = 0; kd_cpumap_header* cpumap_header = NULL; kd_cpumap* cpumap = NULL; -/* - If NUMPARMS changes from the kernel, +/* + If NUMPARMS changes from the kernel, then PATHLENGTH will also reflect the change This is for the vfslookup entries that return pathnames @@ -137,7 +140,7 @@ kd_cpumap* cpumap = NULL; #define US_TO_SLEEP 50000 #define BASE_EVENTS 500000 - +mach_timebase_info_data_t mach_timebase; double divisor; typedef struct { @@ -164,7 +167,7 @@ typedef struct lookup *lookup_t; struct lookup { lookup_t lk_next; - + uintptr_t lk_thread; uintptr_t lk_dvp; long *lk_pathptr; @@ -175,13 +178,12 @@ typedef struct threadmap *threadmap_t; struct threadmap { threadmap_t tm_next; - + uintptr_t tm_thread; uintptr_t tm_pthread; boolean_t tm_deleteme; char tm_command[MAXCOMLEN + 1]; }; - #define HASH_SIZE 1024 #define HASH_MASK 1023 @@ -229,6 +231,7 @@ static void set_pidexclude(int, int); static void set_numbufs(int); static void set_freerun(); static void get_bufinfo(kbufinfo_t *); +static int get_ktrace_state(void); static void set_init(); static void set_kval_list(); static void readtrace(char *); @@ -241,10 +244,11 @@ static void delete_thread_entry(uintptr_t); static void find_and_insert_tmp_map_entry(uintptr_t, char *); static void create_tmp_map_entry(uintptr_t, uintptr_t); static void find_thread_name(uintptr_t, char **, boolean_t); +static void execute_process(char * const argv[]); static int writetrace(int); static int write_command_map(int); -static int debugid_compar(code_type_t *, code_type_t *); +static int debugid_compar(const void *, const void *); static threadmap_t find_thread_entry(uintptr_t); @@ -314,16 +318,20 @@ void set_enable(int val) #endif mib[4] = 0; mib[5] = 0; - if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0) + if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0) { + if (errno == EINVAL) { + quit_args("trace facility failure, KERN_KDENABLE: trace buffer is uninitialized\n"); + } quit_args("trace facility failure, KERN_KDENABLE: %s\n", strerror(errno)); + } } -void set_remove() +void set_remove(void) { extern int errno; - + errno = 0; - + mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; mib[2] = KERN_KDREMOVE; @@ -349,7 +357,7 @@ void set_numbufs(int nbufs) mib[5] = 0; if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0) quit_args("trace facility failure, KERN_KDSETBUF: %s\n", strerror(errno)); - + mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; mib[2] = KERN_KDSETUP; @@ -360,7 +368,7 @@ void set_numbufs(int nbufs) quit_args("trace facility failure, KERN_KDSETUP: %s\n", strerror(errno)); } -void set_nowrap() +void set_nowrap(void) { mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; @@ -376,7 +384,7 @@ void set_nowrap() void set_pidcheck(int pid, int on_off_flag) { kd_regtype kr; - + kr.type = KDBG_TYPENONE; kr.value1 = pid; kr.value2 = on_off_flag; @@ -389,11 +397,20 @@ void set_pidcheck(int pid, int on_off_flag) mib[5] = 0; if (sysctl(mib, 3, &kr, &needed, NULL, 0) < 0) { - if (on_off_flag == 1) + if (errno == EACCES) + { + quit_args("trace facility failure, setting pid filter: %s\n", + strerror(errno)); + } + else if (on_off_flag == 1 && errno == ESRCH) { - printf("trace facility failure, KERN_KDPIDTR,\n\tpid %d does not exist\n", pid); set_remove(); - exit(2); + quit_args("trace facility failure, setting pid filter: " + "pid %d does not exist\n", pid); + } + else + { + quit_args("trace facility failure, KERN_KDPIDTR: %s\n", strerror(errno)); } } } @@ -401,7 +418,7 @@ void set_pidcheck(int pid, int on_off_flag) void set_pidexclude(int pid, int on_off_flag) { kd_regtype kr; - + kr.type = KDBG_TYPENONE; kr.value1 = pid; kr.value2 = on_off_flag; @@ -423,7 +440,7 @@ void set_pidexclude(int pid, int on_off_flag) } } -void set_freerun() +void set_freerun(void) { mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; @@ -435,6 +452,18 @@ void set_freerun() quit_args("trace facility failure, KDBG_FREERUN: %s\n", strerror(errno)); } +static int get_ktrace_state(void) +{ + int state; + size_t state_size = sizeof(state); + int err = sysctlbyname("ktrace.state", &state, &state_size, NULL, 0); + if (err) { + fprintf(stderr, "error: could not query ktrace.state sysctl (%d: %s)\n", errno, strerror(errno)); + exit(1); + } + return state; +} + void get_bufinfo(kbufinfo_t *val) { needed = sizeof (*val); @@ -448,10 +477,10 @@ void get_bufinfo(kbufinfo_t *val) quit_args("trace facility failure, KERN_KDGETBUF: %s\n", strerror(errno)); } -void set_init() +void set_init(void) { kd_regtype kr; - + kr.type = KDBG_RANGETYPE; kr.value1 = 0; kr.value2 = -1; @@ -464,7 +493,7 @@ void set_init() mib[5] = 0; if (sysctl(mib, 3, &kr, &needed, NULL, 0) < 0) quit_args("trace facility failure, KERN_KDSETREG (rangetype): %s\n", strerror(errno)); - + mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; mib[2] = KERN_KDSETUP; @@ -475,7 +504,6 @@ void set_init() quit_args("trace facility failure, KERN_KDSETUP: %s\n", strerror(errno)); } - static void set_filter(void) { @@ -488,10 +516,10 @@ set_filter(void) } } -void set_kval_list() +void set_kval_list(void) { kd_regtype kr; - + kr.type = KDBG_VALCHECK; kr.value1 = value1; kr.value2 = value2; @@ -513,7 +541,7 @@ void readtrace(char *buffer) { mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; - mib[2] = KERN_KDREADTR; + mib[2] = KERN_KDREADTR; mib[3] = 0; mib[4] = 0; mib[5] = 0; @@ -548,8 +576,15 @@ int write_command_map(int fd) mib[4] = 0; mib[5] = 0; - if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0) - return 1; + if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0) { + if (errno == ENODATA) { + if (verbose_flag) { + printf("Cannot write thread map -- this is not fatal\n"); + } + } else { + return 1; + } + } return 0; } @@ -680,7 +715,7 @@ uint64_t consume_start_event(uintptr_t thread, int debugid, uint64_t now) evp_prev = evp; for (evp = evp->ev_next; evp; evp = evp->ev_next) { - + if (evp->ev_thread == thread && evp->ev_debugid == debugid) { evp_prev->ev_next = evp->ev_next; break; @@ -690,7 +725,7 @@ uint64_t consume_start_event(uintptr_t thread, int debugid, uint64_t now) } if (evp) { elapsed = now - evp->ev_timestamp; - + evp->ev_next = event_freelist; event_freelist = evp; } @@ -698,19 +733,21 @@ uint64_t consume_start_event(uintptr_t thread, int debugid, uint64_t now) return (elapsed); } - void -log_trace() +log_trace(void) { - char *buffer; - uint32_t buffer_size; - int fd; - int size; - int pad_size; - char pad_buf[4096]; + int fd = -1; + int ret = 0; + char *buffer; + uint32_t buffer_size = 1000000 * sizeof(kd_buf); + if (logfile[0] == '-' && logfile[1] == '\0') { + fd = STDOUT_FILENO; + } else { + fd = open(logfile, O_TRUNC | O_WRONLY | O_CREAT, 0777); + } - if ((fd = open(logfile, O_TRUNC|O_WRONLY|O_CREAT, 0777)) == -1) { + if (fd == -1) { perror("Can't open logfile"); exit(1); } @@ -728,73 +765,61 @@ log_trace() else printf("Buffer has not wrapped\n"); } - buffer_size = 1000000 * sizeof(kd_buf); - buffer = malloc(buffer_size); - - if (buffer == (char *) 0) - quit("can't allocate memory for tracing info\n"); - read_command_map(0, 0); - read_cpu_map(0); - - raw_header.version_no = RAW_VERSION1; - raw_header.thread_count = total_threads; - raw_header.TOD_secs = time((long *)0); - raw_header.TOD_usecs = 0; - - write(fd, &raw_header, sizeof(RAW_header)); - - size = total_threads * sizeof(kd_threadmap); - write(fd, (char *)mapptr, size); - - pad_size = 4096 - ((sizeof(RAW_header) + size) & 4095); - - if (cpumap_header) { - size_t cpumap_size = sizeof(kd_cpumap_header) + cpumap_header->cpu_count * sizeof(kd_cpumap); - if (pad_size >= cpumap_size) { - write(fd, (char *)cpumap_header, cpumap_size); - pad_size -= cpumap_size; - } + ret = write_command_map(fd); + if (ret) { + close(fd); + perror("failed to write logfile"); + exit(1); } - memset(pad_buf, 0, pad_size); - write(fd, pad_buf, pad_size); + buffer = malloc(buffer_size); + if (buffer == NULL) { + quit("can't allocate memory for events\n"); + } for (;;) { needed = buffer_size; readtrace(buffer); - if (needed == 0) + if (needed == 0) { break; + } + write(fd, buffer, needed * sizeof(kd_buf)); } + + free(buffer); + close(fd); } +/* + * Why does this function exist? + * trace -L needs millisecond level wait times. + * When this code is running remotely, the mach_timebase_info_t data may + * be from a device with a different timebase. This code avoids using + * mach_absolute_time(), so that time calculations come out correct both + * locally and remotely. + */ +static uint64_t current_millis() { + struct timeval time; + gettimeofday(&time, NULL); + return (time.tv_sec * 1000) + (time.tv_usec / 1000); +} void -Log_trace() +Log_trace(void) { - int size; - kd_buf kd_tmp; size_t len; - int num_cpus; - int try_writetrace = 1; + int num_cpus = 0; int fd; - char *buffer; - kd_buf *kd; - uint64_t sample_window_abs; - uint64_t next_window_begins; - uint64_t current_abs; - uint64_t ending_abstime; + uint64_t current_ms; + uint64_t ending_ms = 0; uint64_t last_time_written; - uint32_t us_to_sleep; - uint32_t us_to_adjust; uint32_t ms_to_run; - memset(&kd_tmp, 0, sizeof(kd_tmp)); - if ((fd = open(logfile, O_TRUNC|O_WRONLY|O_CREAT, 0777)) == -1) { perror("Can't open logfile"); exit(1); @@ -823,123 +848,49 @@ Log_trace() if (kval_flag) set_kval_list(); } - /* Get kernel buffer information */ - get_bufinfo(&bufinfo); - - buffer = malloc(bufinfo.nkdbufs * sizeof(kd_buf)); - if (buffer == (char *) 0) - quit("can't allocate memory for tracing info\n"); - memset(buffer, 0, bufinfo.nkdbufs * sizeof(kd_buf)); if (use_current_buf == 0) set_enable(1); if (write_command_map(fd)) { - int pad_size; - char pad_buf[4096]; - - read_command_map(0, 0); - read_cpu_map(0); - - raw_header.version_no = RAW_VERSION1; - raw_header.thread_count = total_threads; - raw_header.TOD_secs = time((long *)0); - raw_header.TOD_usecs = 0; - - write(fd, &raw_header, sizeof(RAW_header)); - - size = total_threads * sizeof(kd_threadmap); - write(fd, (char *)mapptr, size); - - pad_size = 4096 - ((sizeof(RAW_header) + size) & 4095); - - if (cpumap_header) { - size_t cpumap_size = sizeof(kd_cpumap_header) + cpumap_header->cpu_count * sizeof(kd_cpumap); - if (pad_size >= cpumap_size) { - write(fd, (char *)cpumap_header, cpumap_size); - pad_size -= cpumap_size; - } - } - - memset(pad_buf, 0, pad_size); - write(fd, pad_buf, pad_size); + quit("can't write tracefile header\n"); } - sample_window_abs = (uint64_t)((double)US_TO_SLEEP * divisor); - next_window_begins = mach_absolute_time() + sample_window_abs; + last_time_written = current_millis(); if (secs_to_run) { - ending_abstime = mach_absolute_time() + (uint64_t)((double)secs_to_run * (double)1000000 * divisor); ms_to_run = secs_to_run * 1000; + ending_ms = last_time_written + ms_to_run; } else ms_to_run = 0; - last_time_written = mach_absolute_time(); while (LogRAW_flag) { - current_abs = mach_absolute_time(); + needed = ms_to_run; - if (try_writetrace) { - needed = ms_to_run; - - if (writetrace(fd)) - try_writetrace = 0; - else { - if (needed) { - current_abs = mach_absolute_time(); + if (writetrace(fd)) { + perror("KDWRITETR returned error"); - printf("wrote %d events - elapsed time = %.1f secs\n", - (int)needed, ((double)(current_abs - last_time_written) / divisor) / 1000000); - - last_time_written = current_abs; - } - } + /* Clean up and exit in case of write fail */ + break; } - if (try_writetrace == 0) { - - if (next_window_begins > current_abs) - us_to_adjust = US_TO_SLEEP - (uint32_t)((double)(next_window_begins - current_abs) / divisor); - else - us_to_adjust = US_TO_SLEEP; - - next_window_begins = current_abs + sample_window_abs; - - us_to_sleep = US_TO_SLEEP - us_to_adjust; - - next_window_begins = current_abs + (uint64_t)((double)(us_to_sleep + US_TO_SLEEP) * divisor); - - if (us_to_sleep) - usleep(us_to_sleep); - get_bufinfo(&bufinfo); + if (needed) { + current_ms = current_millis(); - if (bufinfo.flags & KDBG_WRAPPED) - printf("lost events\n"); - - needed = bufinfo.nkdbufs * sizeof(kd_buf); - - readtrace(buffer); - - if (bufinfo.flags & KDBG_WRAPPED) { - - kd = (kd_buf *) buffer; - - kd_tmp.timestamp = kd[0].timestamp; - kd_tmp.debugid = TRACE_LOST_EVENTS; - - write(fd, &kd_tmp, sizeof(kd_tmp)); - } - write(fd, buffer, needed * sizeof(kd_buf)); + printf("wrote %d events - elapsed time = %.1f secs\n", + (int)needed, (double)(current_ms - last_time_written) / 1000.0); - if (verbose_flag && needed > nbufs) - printf("needed = %ld\n", needed); + last_time_written = current_ms; } + if (secs_to_run) { - current_abs = mach_absolute_time(); + current_ms = current_millis(); - if (current_abs > ending_abstime) + if (current_ms > ending_ms) break; - ms_to_run = (ending_abstime - current_abs) / (1000 * 1000); - + + ms_to_run = (uint32_t)(ending_ms - current_ms); + if (ms_to_run == 0) break; } @@ -952,13 +903,13 @@ Log_trace() } -void read_trace() +void read_trace(void) { char *buffer; uint32_t buffer_size; kd_buf *kd; int fd; - int firsttime = 1; + int firsttime = 1; int lines = 0; int io_lines = 0; uint64_t bias = 0; @@ -1004,6 +955,34 @@ void read_trace() perror("read failed"); exit(2); } + } else if (raw_header.version_no == RAW_VERSION1) { +#if defined(__ILP32__) + /* + * If the raw trace file was written by armv7k, the 64-bit alignment + * of TOD_secs causes RAW_header to be 24 bytes. If we only read 20 + * bytes, the next 4 bytes might be a legitimate thread_id, but it might + * also be 0 or a leaked kernel pointer from an armv7k trace file. For + * both those cases, consume the 4 bytes and look for the thread map + * after it. + */ + if (sizeof(raw_header) == 20) { + uint32_t alignment_garbage; + + if (read(fd, &alignment_garbage, sizeof(alignment_garbage)) != sizeof(alignment_garbage)) { + perror("read failed"); + exit(2); + } + + if ((alignment_garbage == 0) || (alignment_garbage >= 0x80000000)) { + if (verbose_flag) { + printf("Skipping 4 bytes to find valid thread map\n"); + } + } else { + /* oops, go back to where we were */ + lseek(fd, -(off_t)sizeof(alignment_garbage), SEEK_CUR); + } + } +#endif } count_of_names = raw_header.thread_count; trace_time = (time_t) (raw_header.TOD_secs); @@ -1016,7 +995,7 @@ void read_trace() if (buffer == (char *) 0) quit("can't allocate memory for tracing info\n"); - kd = (kd_buf *)buffer; + kd = (kd_buf *)(uintptr_t)buffer; read_command_map(fd, count_of_names); read_cpu_map(fd); @@ -1025,12 +1004,12 @@ void read_trace() uint32_t count; uint64_t now = 0; uint64_t prev; - uint64_t prevdelta; - uint32_t cpunum; + uint64_t prevdelta = 0; + uint32_t cpunum = 0; uintptr_t thread; double x = 0.0; double y = 0.0; - double event_elapsed_time; + double event_elapsed_time = 0; kd_buf *kdp; lookup_t lkp; boolean_t ending_event; @@ -1047,7 +1026,7 @@ void read_trace() mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; - mib[2] = KERN_KDREADTR; + mib[2] = KERN_KDREADTR; mib[3] = 0; mib[4] = 0; mib[5] = 0; @@ -1056,12 +1035,12 @@ void read_trace() if (needed == 0) break; - count = needed; + count = (uint32_t)needed; } else { uint32_t bytes_read; - bytes_read = read(fd, buffer, buffer_size); + bytes_read = (uint32_t)read(fd, buffer, buffer_size); if (bytes_read == -1) { perror("read failed"); @@ -1079,11 +1058,34 @@ void read_trace() debugid_base = debugid & DBG_FUNC_MASK; now = kdp->timestamp & KDBG_TIMESTAMP_MASK; + /* + * Is this event from an IOP? If so, there will be no + * thread command, label it with the symbolic IOP name + */ + if (cpumap && (cpunum < cpumap_header->cpu_count) && (cpumap[cpunum].flags & KDBG_CPUMAP_IS_IOP)) { + command = cpumap[cpunum].name; + } else { + find_thread_command(kdp, &command); + } + + /* + * The internal use TRACE points clutter the output. + * Print them only if in verbose mode. + */ + if (!verbose_flag) + { + /* Is this entry of Class DBG_TRACE */ + if ((debugid >> 24) == DBG_TRACE) { + if (((debugid >> 16) & 0xff) != DBG_TRACE_INFO) + continue; + } + } + if (firsttime) bias = now; now -= bias; - cpunum = kdbg_get_cpu(kdp); + cpunum = kdbg_get_cpu(kdp); thread = kdp->arg5; if (lines == 64 || firsttime) @@ -1099,8 +1101,8 @@ void read_trace() fprintf(output_file, "\n\nNumber of microsecs since in last page %8.1f\n", x); } prevdelta = now; - - /* + + /* * Output description row to output file (make sure to format correctly for 32-bit and 64-bit) */ fprintf(output_file, @@ -1110,9 +1112,9 @@ void read_trace() " AbsTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu# command\n\n" #endif ); - + lines = 0; - + if (io_lines > 15000) { fcntl(output_fd, F_FLUSH_DATA, 0); @@ -1127,6 +1129,7 @@ void read_trace() if ( !lkp || !(debugid & DBG_FUNC_END)) continue; } + x = (double)now; x /= divisor; @@ -1137,31 +1140,9 @@ void read_trace() last_event_time = x; ending_event = FALSE; - /* - * Is this event from an IOP? If so, there will be no - * thread command, label it with the symbolic IOP name - */ - if (cpumap && (cpunum < cpumap_header->cpu_count) && (cpumap[cpunum].flags & KDBG_CPUMAP_IS_IOP)) { - command = cpumap[cpunum].name; - } else { - find_thread_command(kdp, &command); - } - - /* - * The internal use TRACE points clutter the output. - * Print them only if in verbose mode. - */ - if (!verbose_flag) - { - /* Is this entry of Class DBG_TRACE */ - if ((debugid >> 24) == DBG_TRACE) { - if (((debugid >> 16) & 0xff) != DBG_TRACE_INFO) - continue; - } - } if ( !lkp) { int t_debugid; - int t_thread; + uintptr_t t_thread; if ((debugid & DBG_FUNC_START) || debugid == MACH_MAKERUNNABLE) { @@ -1176,7 +1157,7 @@ void read_trace() } } else if ((debugid & DBG_FUNC_END) || debugid == MACH_STKHANDOFF || debugid == MACH_SCHEDULED) { - + if (debugid == MACH_STKHANDOFF || debugid == MACH_SCHEDULED) { t_debugid = MACH_MAKERUNNABLE; t_thread = kdp->arg2; @@ -1241,7 +1222,7 @@ void read_trace() /* * print the tail end of the pathname */ - len = strlen(strptr); + len = (int)strlen(strptr); if (len > 51) len -= 51; else @@ -1253,6 +1234,12 @@ void read_trace() fprintf(output_file, "%-8x %-51s %-8lx %-2d %s\n", (unsigned int)lkp->lk_dvp, &strptr[len], thread, cpunum, command); #endif delete_lookup_event(thread, lkp); + } else if (debugid == TRACE_INFO_STRING) { +#ifdef __LP64__ + fprintf(output_file, "%-32s%-36s %-16lx %-2d %s\n", (char *) &kdp->arg1, "", thread, cpunum, command); +#else + fprintf(output_file, "%-16s%-46s %-8lx %-2d %s\n", (char *) &kdp->arg1, "", thread, cpunum, command); +#endif } else { #ifdef __LP64__ fprintf(output_file, "%-16lx %-16lx %-16lx %-16lx %-16lx %-2d %s\n", kdp->arg1, kdp->arg2, kdp->arg3, kdp->arg4, thread, cpunum, command); @@ -1270,7 +1257,7 @@ void read_trace() -void signal_handler(int sig) +void signal_handler(int sig) { ptrace(PT_KILL, pid, (caddr_t)0, 0); /* @@ -1286,19 +1273,13 @@ void signal_handler_RAW(int sig) } - -int main(argc, argv, env) -int argc; -char **argv; -char **env; +int main (int argc, char* argv[], char *envp[]) { extern char *optarg; extern int optind; - int status; int ch; int i; char *output_filename = NULL; - char *filter_filename = NULL; unsigned int parsed_arg; for (i = 1; i < argc; i++) { @@ -1425,7 +1406,7 @@ char **env; case 'p': filter_flag = 1; parsed_arg = argtoi('p', "decimal, hex, or octal number", optarg, 0); - if (parsed_arg > 0xFF) + if (parsed_arg > 0xFF) quit_args("argument '-p %s' parsed as %u, " "end range value must be 0-255\n", optarg, parsed_arg); saw_filter_end_range(parsed_arg); @@ -1503,9 +1484,17 @@ char **env; if (LogRAW_flag) { get_bufinfo(&bufinfo); + int ktrace_state = get_ktrace_state(); - if (bufinfo.nolog == 0) + /* + * Only use the current kdebug configuration when foreground + * tracing is enabled. Both checks are necessary because the + * background tool might have enabled tracing, but as soon as we + * try to write a header, that configuration is removed for us. + */ + if ((ktrace_state == 1) && (bufinfo.nolog == 0)) { use_current_buf = 1; + } } if (disable_flag) @@ -1513,23 +1502,23 @@ char **env; if (pid_flag) { set_pidcheck(pid, 0); /* disable pid check for given pid */ - exit(1); + exit(0); } else if (pid_exflag) { set_pidexclude(pid, 0); /* disable pid exclusion for given pid */ - exit(1); + exit(0); } set_enable(0); - exit(1); + exit(0); } if (remove_flag) { set_remove(); - exit(1); + exit(0); } - + if (bufset_flag ) { if (!init_flag && !LogRAW_flag) @@ -1539,15 +1528,50 @@ char **env; } set_numbufs(nbufs); } - + if (nowrap_flag) set_nowrap(); if (freerun_flag) set_freerun(); - + if (bufget_flag) { + printf("The kernel tracing settings are:\n"); + + /* determine the state of ktrace */ + int state = get_ktrace_state(); + + /* get the name of the last process to configure ktrace */ + char execname[20] = { 0 }; + size_t execname_size = sizeof(execname); + int err = sysctlbyname("ktrace.configured_by", &execname, &execname_size, NULL, 0); + if (err) { + fprintf(stderr, "error: could not query ktrace.configured_by sysctl (%d: %s)\n", errno, strerror(errno)); + exit(1); + } + + printf("\tTracing is "); + switch (state) { + case 0: + printf("off"); + break; + case 1: + printf("active (foreground)"); + break; + case 2: + printf("active (background)"); + break; + default: + printf("in an invalid state"); + break; + } + printf("\n"); + + printf("\tLast configured by \"%s\"\n", execname[0] == '\0' ? "" : execname); + + /* get kdebug info */ + get_bufinfo(&bufinfo); printf("The kernel buffer settings are:\n"); @@ -1590,7 +1614,7 @@ char **env; printf("\tCollecting specific code values is enabled\n"); else printf("\tCollecting specific code values is disabled\n"); - + if (bufinfo.flags & KDBG_TYPEFILTER_CHECK) printf("\tCollection based on a filter is enabled\n"); else @@ -1610,6 +1634,50 @@ char **env; printf("\tKernel buffer is not controlled by any process.\n"); else printf("\tKernel buffer is controlled by proc id [%d]\n", bufinfo.bufid); + + + if (bufinfo.flags & KDBG_TYPEFILTER_CHECK) { + if (verbose_flag) { + bool (^should_print)(uint8_t*) = ^bool(uint8_t* ptr) { + for (uint32_t i=0; i<32; ++i) { + if (ptr[i] > 0) return true; + } + + return false; + }; + + uint8_t* typefilter = (uint8_t*)kdebug_typefilter(); + if (typefilter) { + bool header = false; + + // Reduce noise, only print lines that are allowing events. + for (uint32_t tclass = 0; tclass < 0x100; ++tclass) { + uint8_t* base = &typefilter[tclass * 32]; + if (should_print(base)) { + if (!header) { + header = true; + printf("\tTypefilter:\n"); + printf("%18s ",""); + for (uint32_t tsubclass=0; tsubclass<32; ++tsubclass) { + printf("%02x ", tsubclass * 8); + } + printf("\n"); + printf("%18s ",""); + for (uint32_t tsubclass=0; tsubclass<32; ++tsubclass) { + printf("---"); + } + printf("\n"); + } + printf("%16s%02x: ", "", tclass); + for (uint32_t tsubclass=0; tsubclass<32; ++tsubclass) { + printf("%02X ", typefilter[(tclass * 32) + tsubclass]); + } + printf("\n"); + } + } + } + } + } } if (init_flag) @@ -1627,26 +1695,8 @@ char **env; fflush(stdout); fflush(stderr); - switch ((pid = vfork())) - { - case -1: - perror("vfork: "); - exit(1); - case 0: /* child */ - setsid(); - ptrace(PT_TRACE_ME, 0, (caddr_t)0, 0); - execve(argv[optind], &argv[optind], environ); - perror("execve:"); - exit(1); - } - sleep(1); + execute_process(&(argv[optind])); - signal(SIGINT, signal_handler); - set_pidcheck(pid, 1); - set_enable(1); - ptrace(PT_CONTINUE, pid, (caddr_t)1, 0); - waitpid(pid, &status, 0); - /* child is gone; no need to disable the pid */ exit(0); } else if (enable_flag) @@ -1667,7 +1717,7 @@ char **env; usage(SHORT_HELP); } setbuffer(output_file, &sbuffer[0], SBUFFER_SIZE); - + if (fcntl(output_fd, F_NOCACHE, 1) < 0) { /* Not fatal */ @@ -1689,7 +1739,50 @@ char **env; } /* end main */ static void -quit_args(const char *fmt, ...) +execute_process(char * const argv[]) +{ + int status = 0; + int rc = 0; + posix_spawnattr_t spawn_attrs; + + assert(argv); + + /* ensure that the process being spawned starts suspended */ + rc = posix_spawnattr_init(&spawn_attrs); + if (rc != 0) { + quit_args("Failed to initialize spawn attrs: %s\n", strerror(rc)); + } + rc = posix_spawnattr_setflags(&spawn_attrs, + POSIX_SPAWN_START_SUSPENDED); + if (rc != 0) { + quit_args("Unable to start process suspended: %s\n", strerror(rc)); + } + + /* spawn the process with the rest of the arguments */ + rc = posix_spawnp(&pid, argv[0], NULL, &spawn_attrs, argv, environ); + if (rc != 0) { + quit_args("Unabled to start process: %s\n", strerror(rc)); + } + + signal(SIGINT, signal_handler); + set_pidcheck(pid, 1); + set_enable(1); + + /* start the child process */ + rc = kill(pid, SIGCONT); + if (rc != 0) { + perror("Failed to continue child process:"); + exit(EX_OSERR); + } + + rc = waitpid(pid, &status, 0); + if (rc == -1) { + perror("Failed to wait for process: "); + } +} + +static void +quit_args(const char *fmt, ...) { char buffer[1024]; @@ -1726,7 +1819,7 @@ quit(char *s) printf("trace: "); if (s) - printf("%s ", s); + printf("%s", s); exit(1); } @@ -1834,9 +1927,9 @@ usage(int short_help) (void)fprintf(stderr, "\tcollection of kernel trace elements for that process.\n"); (void)fprintf(stderr, "\tSee -e(enable) flag for option descriptions.\n\n"); - (void)fprintf(stderr, "usage: trace -t [-o OutputFilename] [-N] [ExtraCodeFilename1 ExtraCodeFilename2 ...] \n"); + (void)fprintf(stderr, "usage: trace -t [-o OutputFilename] [-N] [ExtraCodeFilename1 ExtraCodeFilename2 ...] \n"); (void)fprintf(stderr, "\tCollect the kernel buffer trace data and print it.\n\n"); - (void)fprintf(stderr, "\t -N Do not import /usr/share/misc/trace.codes (for raw hex tracing or supplying an alternate set of codefiles)\n"); + (void)fprintf(stderr, "\t -N Do not import /usr/share/misc/trace.codes (for raw hex tracing or supplying an alternate set of codefiles)\n"); (void)fprintf(stderr, "\t -o OutputFilename Print trace output to OutputFilename. Default is stdout.\n\n"); (void)fprintf(stderr, @@ -1844,7 +1937,7 @@ usage(int short_help) (void)fprintf(stderr, "\tRead raw trace file and print it.\n\n"); (void)fprintf(stderr, "\t -X Force trace to interpret trace data as 32 bit. \n"); (void)fprintf(stderr, "\t Default is to match the bit width of the current system. \n"); - (void)fprintf(stderr, "\t -N Do not import /usr/share/misc/trace.codes (for raw hex tracing or supplying an alternate set of codefiles)\n"); + (void)fprintf(stderr, "\t -N Do not import /usr/share/misc/trace.codes (for raw hex tracing or supplying an alternate set of codefiles)\n"); (void)fprintf(stderr, "\t -F frequency Specify the frequency of the clock used to timestamp entries in RawFilename.\n\t Use command \"sysctl hw.tbfrequency\" on the target device, to get target frequency.\n"); (void)fprintf(stderr, "\t -o OutputFilename Print trace output to OutputFilename. Default is stdout.\n\n"); @@ -1910,10 +2003,7 @@ usage(int short_help) static int -argtoi(flag, req, str, base) -int flag; -char *req, *str; -int base; +argtoi(int flag, char *req, char *str, int base) { char *cp; int ret; @@ -1924,12 +2014,8 @@ int base; return (ret); } - static unsigned long -argtoul(flag, req, str, base) -int flag; -char *req, *str; -int base; +argtoul(int flag, char *req, char *str, int base) { char *cp; unsigned long ret; @@ -1940,24 +2026,24 @@ int base; return (ret); } - /* * comparison function for qsort * sort by debugid */ -int debugid_compar(p1, p2) - code_type_t *p1; - code_type_t *p2; +int +debugid_compar(const void *p1, const void *p2) { - if (p1->debugid > p2->debugid) - return(1); - else if (p1->debugid == p2->debugid) - return(0); + const code_type_t *q1 = (const code_type_t *)p1; + const code_type_t *q2 = (const code_type_t *)p2; + + if (q1->debugid > q2->debugid) + return (1); + else if (q1->debugid == q2->debugid) + return (0); else - return(-1); + return (-1); } - /* * Filter args parsing state machine: * @@ -2114,7 +2200,7 @@ set_filter_subclass(uint8_t class, uint8_t subclass) uint16_t csc = ENCODE_CSC_LOW(class, subclass); - if (verbose_flag && !setting_class) + if (verbose_flag && !setting_class) printf("tracing subclass: 0x%4.4x\n", csc); if (verbose_flag && isset(type_filter_bitmap, csc)) @@ -2166,7 +2252,8 @@ set_filter_range(uint8_t class, uint8_t end) */ static void -parse_filter_file(char *filename) { +parse_filter_file(char *filename) +{ FILE* file; uint32_t current_line = 0; uint32_t parsed_arg = 0; @@ -2184,7 +2271,7 @@ parse_filter_file(char *filename) { while( fgets(line, sizeof(line), file) != NULL ) { current_line++; - + switch (line[0]) { case 'C': rval = sscanf(line, "C 0x%x\n", &parsed_arg); @@ -2230,14 +2317,11 @@ parse_filter_file(char *filename) { fclose(file); } - /* * Find the debugid code in the list and return its index */ -static int binary_search(list, lowbound, highbound, code) - code_type_t *list; - int lowbound, highbound; - unsigned int code; +static int +binary_search(code_type_t *list, int lowbound, int highbound, unsigned int code) { int low, high, mid; int tries = 0; @@ -2275,10 +2359,10 @@ static int parse_codefile(const char *filename) { int fd; - int i, j, line; + int j, line; size_t count; struct stat stat_buf; - unsigned long file_size; + size_t file_size; char *file_addr, *endp; if ((fd = open(filename, O_RDONLY, 0)) == -1) @@ -2297,11 +2381,11 @@ parse_codefile(const char *filename) * For some reason mapping files with zero size fails * so it has to be handled specially. */ - file_size = stat_buf.st_size; + file_size = (size_t)stat_buf.st_size; if (stat_buf.st_size != 0) { - if ((file_addr = mmap(0, stat_buf.st_size, PROT_READ|PROT_WRITE, + if ((file_addr = mmap(0, file_size, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FILE, fd, 0)) == (char*) -1) { printf("Error: Can't map file: %s\n", filename); @@ -2361,23 +2445,23 @@ parse_codefile(const char *filename) j++; line++; } - + /* Skip leading whitespace */ while (file_addr[j] == ' ' || file_addr[j] == '\t') j++; /* Get the debugid code */ - codesc[codesc_idx].debugid = strtoul(file_addr + j, &endp, 16); - j = endp - file_addr; + codesc[codesc_idx].debugid = (uint32_t)strtoul(file_addr + j, &endp, 16); + j = (int)(endp - file_addr); - if (codesc[codesc_idx].debugid == 0) + if (codesc[codesc_idx].debugid == 0) { /* We didn't find a debugid code - skip this line */ if (verbose_flag) printf("Error: while parsing line %d, skip\n", line); while (file_addr[j] != '\n' && j < file_size) j++; - codesc_idx--; + codesc_idx--; line++; continue; } @@ -2394,13 +2478,13 @@ parse_codefile(const char *filename) printf("Error: while parsing line %d, (0x%x) skip\n", line, codesc[codesc_idx].debugid); j++; - codesc_idx--; + codesc_idx--; line++; continue; } /* Next is the debugid string terminated by a newline */ - codesc[codesc_idx].debug_string = &file_addr[j]; + codesc[codesc_idx].debug_string = &file_addr[j]; /* Null out the newline terminator */ while ((j < file_size) && (file_addr[j] != '\n')) @@ -2419,25 +2503,27 @@ parse_codefile(const char *filename) } /* sort */ - qsort((void *)codesc, codesc_idx, sizeof(code_type_t), debugid_compar); + qsort((void *)codesc, codesc_idx, sizeof(code_type_t), debugid_compar); if (verbose_flag) { - printf("Sorted %zd codes in %s\n", codesc_idx, filename); + printf("Sorted %zd codes in %s\n", codesc_idx, filename); printf("lowbound [%6d]: 0x%8x %s\n", 0, codesc[0].debugid, codesc[0].debug_string); - printf("highbound [%6zd]: 0x%8x %s\n\n", codesc_idx - 1, codesc[codesc_idx - 1].debugid, codesc[codesc_idx - 1].debug_string); + printf("highbound [%6zd]: 0x%8x %s\n\n", codesc_idx - 1, codesc[codesc_idx - 1].debugid, codesc[codesc_idx - 1].debug_string); } codesc_find_dupes(); #if 0 /* Dump the codefile */ + int i; for (i = 0; i < codesc_idx; i++) printf("[%d] 0x%x %s\n",i+1, codesc[i].debugid, codesc[i].debug_string); #endif return(0); } -static void codesc_find_dupes(void) +static void +codesc_find_dupes(void) { boolean_t found_dupes = FALSE; if (codesc_idx == 0) @@ -2462,8 +2548,8 @@ static void codesc_find_dupes(void) } } - -int match_debugid(unsigned int xx, char * debugstr, int * yy) +int +match_debugid(unsigned int xx, char * debugstr, int * yy) { int indx; @@ -2499,17 +2585,16 @@ read_cpu_map(int fd) * cpumap size is one page. */ cpumap_header = malloc(PAGE_SIZE); - + if (readRAW_flag) { /* * cpu maps exist in a RAW_VERSION1+ header only */ if (raw_header.version_no == RAW_VERSION1) { - off_t base_offset = lseek(fd, (off_t)0, SEEK_CUR); - off_t aligned_offset = (base_offset + (4095)) & ~4095; /* */ - - size_t padding_bytes = (size_t)(aligned_offset - base_offset); - + off_t cpumap_position = lseek(fd, 0, SEEK_CUR); + /* cpumap is part of the last 4KB of padding in the preamble */ + size_t padding_bytes = SIZE_4KB - (cpumap_position & (SIZE_4KB - 1)); + if (read(fd, cpumap_header, padding_bytes) == padding_bytes) { if (cpumap_header->version_no == RAW_VERSION1) { cpumap = (kd_cpumap*)&cpumap_header[1]; @@ -2518,11 +2603,11 @@ read_cpu_map(int fd) } } else { int mib[3]; - + mib[0] = CTL_KERN; mib[1] = KERN_KDEBUG; mib[2] = KERN_KDCPUMAP; - + size_t temp = PAGE_SIZE; if (sysctl(mib, 3, cpumap_header, &temp, NULL, 0) == 0) { if (PAGE_SIZE >= temp) { @@ -2613,7 +2698,7 @@ read_command_map(int fd, uint32_t count) if (verbose_flag) { /* Dump the initial map */ - + printf("Size of maptable returned is %ld, thus %ld entries\n", size, (size/sizeof(kd_threadmap))); printf("Thread Command\n"); @@ -2623,11 +2708,12 @@ read_command_map(int fd, uint32_t count) mapptr[i].command); } } + return (int)size; } - -void create_map_entry(uintptr_t thread, char *command) +void +create_map_entry(uintptr_t thread, char *command) { threadmap_t tme; int hashid; @@ -2649,8 +2735,8 @@ void create_map_entry(uintptr_t thread, char *command) threadmap_hash[hashid] = tme; } - -void delete_thread_entry(uintptr_t thread) +void +delete_thread_entry(uintptr_t thread) { threadmap_t tme = 0; threadmap_t tme_prev; @@ -2679,8 +2765,8 @@ void delete_thread_entry(uintptr_t thread) } } - -void find_and_insert_tmp_map_entry(uintptr_t pthread, char *command) +void +find_and_insert_tmp_map_entry(uintptr_t pthread, char *command) { threadmap_t tme = 0; threadmap_t tme_prev; @@ -2714,8 +2800,8 @@ void find_and_insert_tmp_map_entry(uintptr_t pthread, char *command) } } - -void create_tmp_map_entry(uintptr_t thread, uintptr_t pthread) +void +create_tmp_map_entry(uintptr_t thread, uintptr_t pthread) { threadmap_t tme; @@ -2749,8 +2835,8 @@ find_thread_entry(uintptr_t thread) return (0); } - -void find_thread_name(uintptr_t thread, char **command, boolean_t deleteme) +void +find_thread_name(uintptr_t thread, char **command, boolean_t deleteme) { threadmap_t tme; @@ -2763,13 +2849,15 @@ void find_thread_name(uintptr_t thread, char **command, boolean_t deleteme) *command = EMPTYSTRING; } - -void find_thread_command(kd_buf *kbufp, char **command) +void +find_thread_command(kd_buf *kbufp, char **command) { uintptr_t thread; threadmap_t tme; int debugid_base; + *command = EMPTYSTRING; + thread = kbufp->arg5; debugid_base = kbufp->debugid & DBG_FUNC_MASK; @@ -2784,8 +2872,7 @@ void find_thread_command(kd_buf *kbufp, char **command) if (debugid_base == BSC_exit || tme->tm_deleteme == TRUE) delete_thread_entry(thread); - } else - *command = EMPTYSTRING; + } } else if (debugid_base == TRACE_DATA_NEWTHREAD) { /* @@ -2809,16 +2896,13 @@ void find_thread_command(kd_buf *kbufp, char **command) find_thread_name(thread, command, (debugid_base == BSC_thread_terminate)); } - -static -void getdivisor() +static void +getdivisor(void) { - mach_timebase_info_data_t info; + (void) mach_timebase_info (&mach_timebase); if (frequency == 0) { - (void) mach_timebase_info (&info); - - divisor = ( (double)info.denom / (double)info.numer) * 1000; + divisor = ( (double)mach_timebase.denom / (double)mach_timebase.numer) * 1000; } else divisor = (double)frequency / 1000000;