X-Git-Url: https://git.saurik.com/apple/system_cmds.git/blobdiff_plain/1815bff58803503e37009deeb85cfa8c22acf9d9..1376a029661d3e15c9df96255af119554cd8a4ae:/latency.tproj/latency.c diff --git a/latency.tproj/latency.c b/latency.tproj/latency.c index 16ef9e7..0b6da26 100644 --- a/latency.tproj/latency.c +++ b/latency.tproj/latency.c @@ -24,7 +24,7 @@ /* - cc -I. -DKERNEL_PRIVATE -O -o latency latency.c + cc -I. -DPRIVATE -D__APPLE_PRIVATE -O -o latency latency.c -lncurses */ #include @@ -42,7 +42,7 @@ #include #include -#include +#include #include #ifndef KERNEL_PRIVATE @@ -62,8 +62,8 @@ #include #include #include -#include #include +#include #include @@ -124,6 +124,8 @@ char pcstring[128]; double divisor; int gotSIGWINCH = 0; int trace_enabled = 0; +struct host_basic_info hi; + #define SAMPLE_SIZE 300000 @@ -146,14 +148,16 @@ struct ct { } codes_tab[MAX_ENTRIES]; +#define NUMPARMS 23 + struct th_info { int thread; int type; int child_thread; - int vfslookup; int arg1; double stime; - char pathname[32]; + long *pathptr; + long pathname[NUMPARMS + 1]; }; #define MAX_THREADS 512 @@ -182,6 +186,8 @@ int cur_max = 0; #define DBG_FUNC_ALL (DBG_FUNC_START | DBG_FUNC_END) #define DBG_FUNC_MASK 0xfffffffc +#define CPU_NUMBER(ts) ((ts & KDBG_CPU_MASK) >> KDBG_CPU_SHIFT) + #define DBG_ZERO_FILL_FAULT 1 #define DBG_PAGEIN_FAULT 2 #define DBG_COW_FAULT 3 @@ -202,39 +208,8 @@ static kern_return_t set_standard_policy(void); int decrementer_val = 0; /* Value used to reset decrementer */ int set_remove_flag = 1; /* By default, remove trace buffer */ -/* raw read of the timebase register */ -void clock_get_uptime( register AbsoluteTime *result) -{ -#ifdef __ppc__ - - register UInt32 hic; - do { - asm volatile(" mftbu %0" : "=r" (result->hi)); - asm volatile(" mftb %0" : "=r" (result->lo)); - asm volatile(" mftbu %0" : "=r" (hic)); - } while (hic != result->hi); - -#else - result->lo = 0; - result->hi = 0; -#endif /* __ppc__ */ - -} - -typedef unsigned long long abstime_scalar_t; - -#define AbsoluteTime_to_scalar(x) \ - (*(abstime_scalar_t *)(x)) - -/* t1 += t2 */ -#define ADD_ABSOLUTETIME(t1, t2) \ - (AbsoluteTime_to_scalar(t1) += \ - AbsoluteTime_to_scalar(t2)) - -/* t1 -= t2 */ -#define SUB_ABSOLUTETIME(t1, t2) \ - (AbsoluteTime_to_scalar(t1) -= \ - AbsoluteTime_to_scalar(t2)) +kd_buf **last_decrementer_kd; /* last DECR_TRAP per cpu */ +#define MAX_LOG_COUNT 30 /* limits the number of entries dumped in log_decrementer */ int quit(s) @@ -320,7 +295,7 @@ set_pidexclude(int pid, int on_off) sysctl(mib, 3, &kr, &needed, NULL, 0); } -set_rtcdec(decval) +void set_rtcdec(decval) int decval; {kd_regtype kr; int ret; @@ -337,11 +312,14 @@ int decval; mib[5] = 0; /* no flags */ errno = 0; - if ((ret=sysctl(mib, 3, &kr, &needed, NULL, 0)) < 0) { - decrementer_val = 0; - quit("trace facility failure, KERN_KDSETRTCDEC\n"); + decrementer_val = 0; + /* ignore this sysctl error if it's not supported */ + if (errno == ENOENT) + return; + else + quit("trace facility failure, KERN_KDSETRTCDEC\n"); } } @@ -459,33 +437,24 @@ void sigintr() set_enable(0); set_pidexclude(getpid(), 0); screen_update(log_fp); + endwin(); set_rtcdec(0); set_remove(); exit(1); } -void sigquit() -{ - set_enable(0); - set_pidexclude(getpid(), 0); - set_rtcdec(0); - set_remove(); - - exit(1); -} - -void sigterm() +void leave() /* exit under normal conditions -- signal handler */ { set_enable(0); set_pidexclude(getpid(), 0); + endwin(); set_rtcdec(0); set_remove(); exit(1); } - void screen_update(FILE *fp) { @@ -520,7 +489,7 @@ screen_update(FILE *fp) elapsed_secs -= elapsed_mins * 60; sprintf(tbuf, "%-19.19s %2ld:%02ld:%02ld\n", &(ctime(&curr_time)[0]), - elapsed_hours, elapsed_mins, elapsed_secs); + (long)elapsed_hours, (long)elapsed_mins, (long)elapsed_secs); if (fp) fprintf(fp, "%s", tbuf); else @@ -693,8 +662,14 @@ exit_usage() { fprintf(stderr, "Usage: latency [-rt] [-c codefile] [-l logfile] [-st threshold]\n"); - fprintf(stderr, " [-it threshold] [-s sleep_in_usecs]\n"); + +#if defined (__i386__) + fprintf(stderr, " [-it threshold] [-s sleep_in_usecs] [-n kernel]\n\n"); +#else + fprintf(stderr, " [-it threshold] [-s sleep_in_usecs]\n"); fprintf(stderr, " [-d decrementer_in_usecs] [-n kernel]\n\n"); +#endif + fprintf(stderr, " -rt Set realtime scheduling policy. Default is timeshare.\n"); fprintf(stderr, " -c specify name of codes file\n"); @@ -702,7 +677,9 @@ exit_usage() fprintf(stderr, " -st set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n"); fprintf(stderr, " -it set interrupt latency threshold in microseconds... if latency exceeds this, then log trace\n"); fprintf(stderr, " -s set sleep time in microseconds\n"); +#if !defined (__i386__) fprintf(stderr, " -d set decrementer in microseconds.\n"); +#endif fprintf(stderr, " -n specify kernel, default is /mach_kernel\n"); fprintf(stderr, "\nlatency must be run as root\n\n"); @@ -711,21 +688,23 @@ exit_usage() } - +int main(argc, argv) int argc; char *argv[]; { - mach_timespec_t remain; - unsigned long long start, stop; - AbsoluteTime timestamp1; - AbsoluteTime timestamp2; - AbsoluteTime adeadline, adelay; + uint64_t start, stop; + uint64_t timestamp1; + uint64_t timestamp2; + uint64_t adeadline, adelay; double fdelay; int elapsed_usecs; double nanosecs_to_sleep; int loop_cnt, sample_sc_now; int decrementer_usec = 0; + kern_return_t ret; + unsigned int size; + host_name_port_t host; void getdivisor(); void sample_sc(); void init_code_file(); @@ -782,7 +761,8 @@ char *argv[]; num_of_usecs_to_sleep = atoi(argv[1]); else exit_usage(); - } else if (strcmp(argv[1], "-d") == 0) { + } + else if (strcmp(argv[1], "-d") == 0) { argc--; argv++; @@ -790,7 +770,12 @@ char *argv[]; decrementer_usec = atoi(argv[1]); else exit_usage(); - } else if (strcmp(argv[1], "-n") == 0) { +#if defined(__i386__) + /* ignore this option - setting the decrementer has no effect */ + decrementer_usec = 0; +#endif + } + else if (strcmp(argv[1], "-n") == 0) { argc--; argv++; @@ -823,9 +808,21 @@ char *argv[]; getdivisor(); decrementer_val = decrementer_usec * divisor; + /* get the cpu countfor the DECR_TRAP array */ + host = mach_host_self(); + size = sizeof(hi)/sizeof(int); + ret = host_info(host, HOST_BASIC_INFO, (host_info_t)&hi, &size); + if (ret != KERN_SUCCESS) { + mach_error(argv[0], ret); + exit(EXIT_FAILURE); + } + + if ((last_decrementer_kd = (kd_buf **)malloc(hi.avail_cpus * sizeof(kd_buf *))) == (kd_buf **)0) + quit("can't allocate memory for decrementer tracing info\n"); + nanosecs_to_sleep = (double)(num_of_usecs_to_sleep * 1000); fdelay = nanosecs_to_sleep * (divisor /1000); - AbsoluteTime_to_scalar(&adelay) = (abstime_scalar_t)fdelay; + adelay = (uint64_t)fdelay; init_code_file(); @@ -836,13 +833,19 @@ char *argv[]; */ set_rtcdec(decrementer_val); - initscr(); + if (initscr() == (WINDOW *) 0) + { + printf("Unrecognized TERM type, try vt100\n"); + exit(1); + } + clear(); refresh(); signal(SIGWINCH, sigwinch); signal(SIGINT, sigintr); - signal(SIGQUIT, sigquit); - signal(SIGTERM, sigterm); + signal(SIGQUIT, leave); + signal(SIGTERM, leave); + signal(SIGHUP, leave); if ((my_buffer = malloc(SAMPLE_SIZE * sizeof(kd_buf))) == (char *)0) @@ -890,17 +893,14 @@ char *argv[]; refresh_time = curr_time + 1; } - clock_get_uptime(×tamp1); - adeadline = timestamp1; - ADD_ABSOLUTETIME(&adeadline, &adelay); - mk_wait_until(adeadline); - clock_get_uptime(×tamp2); + timestamp1 = mach_absolute_time(); + adeadline = timestamp1 + adelay; + mach_wait_until(adeadline); + timestamp2 = mach_absolute_time(); - start = (((unsigned long long)timestamp1.hi) << 32) | - (unsigned long long)((unsigned int)(timestamp1.lo)); + start = timestamp1; - stop = (((unsigned long long)timestamp2.hi) << 32) | - (unsigned long long)((unsigned int)(timestamp2.lo)); + stop = timestamp2; elapsed_usecs = (int)(((double)(stop - start)) / divisor); @@ -938,30 +938,28 @@ char *argv[]; } } if (gotSIGWINCH) { - initscr(); + /* + No need to check for initscr error return. + We won't get here if it fails on the first call. + */ + endwin(); clear(); refresh(); gotSIGWINCH = 0; } } - } - +} void getdivisor() { + mach_timebase_info_data_t info; - unsigned int delta; - unsigned int abs_to_ns_num; - unsigned int abs_to_ns_denom; - unsigned int proc_to_abs_num; - unsigned int proc_to_abs_denom; + (void) mach_timebase_info (&info); - (void)MKGetTimeBaseInfo (&delta, &abs_to_ns_num, &abs_to_ns_denom, - &proc_to_abs_num, &proc_to_abs_denom); + divisor = ( (double)info.denom / (double)info.numer) * 1000; - divisor = ((double)abs_to_ns_denom / (double)abs_to_ns_num) * 1000; } /* This is the realtime band */ @@ -1022,7 +1020,7 @@ void read_command_map() size = bufinfo.nkdthreads * sizeof(kd_threadmap); if (size) { - if (mapptr = (kd_threadmap *) malloc(size)) + if ((mapptr = (kd_threadmap *) malloc(size))) bzero (mapptr, size); else { @@ -1097,8 +1095,13 @@ void create_map_entry(int thread, char *command) #endif map->valid = 1; map->thread = thread; - (void)strncpy (map->command, command, sizeof(map->command)); - map->command[sizeof(map->command)-1] = '\0'; + /* + The trace entry that returns the command name will hold + at most, MAXCOMLEN chars, and in that case, is not + guaranteed to be null terminated. + */ + (void)strncpy (map->command, command, MAXCOMLEN); + map->command[MAXCOMLEN] = '\0'; } @@ -1126,7 +1129,7 @@ kill_thread_map(int thread) { kd_threadmap *map; - if (map = find_thread_map(thread)) { + if ((map = find_thread_map(thread))) { #if 0 if (log_fp) @@ -1168,14 +1171,17 @@ char *find_code(type) } -void sample_sc(long long start, long long stop) +void sample_sc(uint64_t start, uint64_t stop) { - kd_buf *kd, *last_mach_sched, *last_decrementer_kd, *start_kd, *end_of_sample; - unsigned long long now; - int count; + kd_buf *kd, *last_mach_sched, *start_kd, *end_of_sample; + uint64_t now; + int count, i; int first_entry = 1; + double timestamp = 0.0; + double last_timestamp = 0.0; + double delta = 0.0; + double start_bias = 0.0; char command[32]; - double timestamp, last_timestamp, delta, start_bias; void read_command_map(); if (log_fp && (my_policy == THREAD_TIME_CONSTRAINT_POLICY)) @@ -1206,12 +1212,10 @@ void sample_sc(long long start, long long stop) count = needed; if (bufinfo.flags & KDBG_WRAPPED) { - int i; - for (i = 0; i < cur_max; i++) { th_state[i].thread = 0; th_state[i].type = -1; - th_state[i].vfslookup = 0; + th_state[i].pathptr = (long *)NULL; th_state[i].pathname[0] = 0; } cur_max = 0; @@ -1231,15 +1235,21 @@ void sample_sc(long long start, long long stop) } } end_of_sample = &((kd_buf *)my_buffer)[count]; - last_decrementer_kd = (kd_buf *)my_buffer; + + /* Always reinitialize the DECR_TRAP array */ + for (i=0; i < hi.avail_cpus; i++) + last_decrementer_kd[i] = (kd_buf *)my_buffer; + last_mach_sched = (kd_buf *)0; for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) { int debugid, thread, cpunum; int type, clen, mode; + int len; char *p; long *sargptr; - double i_latency; + kd_buf *cur_kd; + double i_latency = 0.0; struct th_info *ti; char command1[32]; char sched_info[64]; @@ -1252,8 +1262,8 @@ void sample_sc(long long start, long long stop) void exit_syscall(); void print_entry(); - thread = kd->arg5 & KDBG_THREAD_MASK; - cpunum = (kd->arg5 & KDBG_CPU_MASK) ? 1: 0; + thread = kd->arg5; + cpunum = CPU_NUMBER(kd->timestamp); debugid = kd->debugid; type = kd->debugid & DBG_FUNC_MASK; @@ -1263,8 +1273,7 @@ void sample_sc(long long start, long long stop) if (type == DECR_TRAP) i_latency = handle_decrementer(kd); - now = (((unsigned long long)kd->timestamp.tv_sec) << 32) | - (unsigned long long)((unsigned int)(kd->timestamp.tv_nsec)); + now = kd->timestamp & KDBG_TIMESTAMP_MASK; timestamp = ((double)now) / divisor; @@ -1274,21 +1283,27 @@ void sample_sc(long long start, long long stop) else if (debugid & DBG_FUNC_END) exit_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 0); else if (type == DECR_TRAP) { + cur_kd = kd; if (log_fp && i_thresh_hold && (int)i_latency > i_thresh_hold) { - start_kd = last_decrementer_kd; + start_kd = last_decrementer_kd[cpunum]; kd = log_decrementer(start_kd, kd, end_of_sample, i_latency); - if (kd >= end_of_sample) break; } - last_decrementer_kd = kd; + if ((kd->debugid & DBG_FUNC_MASK) == DECR_TRAP) + { + cpunum = CPU_NUMBER(kd->timestamp); + last_decrementer_kd[cpunum] = kd; + } + else + last_decrementer_kd[cpunum] = cur_kd; } continue; } if (first_entry) { double latency; - char buf1[128]; - char buf2[128]; + char buf1[132]; + char buf2[132]; latency = (double)(stop - start) / divisor; latency -= (double)num_of_usecs_to_sleep; @@ -1314,7 +1329,7 @@ void sample_sc(long long start, long long stop) } delta = timestamp - last_timestamp; - if (map = find_thread_map(thread)) + if ((map = find_thread_map(thread))) strcpy(command, map->command); else command[0] = 0; @@ -1357,7 +1372,7 @@ void sample_sc(long long start, long long stop) break; case DECR_TRAP: - last_decrementer_kd = kd; + last_decrementer_kd[cpunum] = kd; if (i_thresh_hold && (int)i_latency > i_thresh_hold) p = "*"; @@ -1366,7 +1381,7 @@ void sample_sc(long long start, long long stop) mode = 1; - if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) { + if ((ti = find_thread(kd->arg5, 0, 0))) { if (ti->type == -1 && strcmp(command, "kernel_task")) mode = 0; } @@ -1392,12 +1407,12 @@ void sample_sc(long long start, long long stop) case MACH_stkhandoff: last_mach_sched = kd; - if (map = find_thread_map(kd->arg2)) + if ((map = find_thread_map(kd->arg2))) strcpy(command1, map->command); else sprintf(command1, "%-8x", kd->arg2); - if (ti = find_thread(kd->arg2, 0, 0)) { + if ((ti = find_thread(kd->arg2, 0, 0))) { if (ti->type == -1 && strcmp(command1, "kernel_task")) p = "U"; else @@ -1432,34 +1447,83 @@ void sample_sc(long long start, long long stop) ti->thread = thread; ti->type = -1; - ti->vfslookup = 0; + ti->pathptr = (long *)0; ti->child_thread = 0; } - if (ti->vfslookup == 0) { - ti->vfslookup = 1; + while ( (kd < end_of_sample) && ((kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP)) + { + if (ti->pathptr == NULL) { ti->arg1 = kd->arg1; - memset(&ti->pathname[0], 0, 32); - sargptr = (long *)&ti->pathname[0]; + sargptr = ti->pathname; *sargptr++ = kd->arg2; *sargptr++ = kd->arg3; *sargptr++ = kd->arg4; + /* + * NULL terminate the 'string' + */ + *sargptr = 0; + ti->pathptr = sargptr; + + } else { + sargptr = ti->pathptr; + + /* + We don't want to overrun our pathname buffer if the + kernel sends us more VFS_LOOKUP entries than we can + handle. + */ + + if (sargptr >= &ti->pathname[NUMPARMS]) + { + kd++; + continue; + } + + /* + We need to detect consecutive vfslookup entries. + So, if we get here and find a START entry, + fake the pathptr so we can bypass all further + vfslookup entries. + */ + + if (kd->debugid & DBG_FUNC_START) + { + ti->pathptr = &ti->pathname[NUMPARMS]; + } + else + { + *sargptr++ = kd->arg1; + *sargptr++ = kd->arg2; + *sargptr++ = kd->arg3; + *sargptr++ = kd->arg4; + /* + * NULL terminate the 'string' + */ + *sargptr = 0; + + ti->pathptr = sargptr; + } + } + kd++; + } + p = (char *)ti->pathname; - } else if (ti->vfslookup == 1) { - ti->vfslookup = 0; - - sargptr = (long *)&ti->pathname[12]; - *sargptr++ = kd->arg1; - *sargptr++ = kd->arg2; - *sargptr++ = kd->arg3; - *sargptr++ = kd->arg4; + kd--; + + /* print the tail end of the pathname */ + len = strlen(p); + if (len > 42) + len -= 42; + else + len = 0; - if (log_fp) { - fprintf(log_fp, "%9.1f %8.1f\t\t%-28.28s %-28s %-8x %-8x %d %s\n", - timestamp - start_bias, delta, "VFS_LOOKUP", - ti->pathname, ti->arg1, thread, cpunum, command); - } + if (log_fp) { + fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s %-8x %-8x %d %s\n", + timestamp - start_bias, delta, "VFS_LOOKUP", + &p[len], ti->arg1, thread, cpunum, command); } + last_timestamp = timestamp; break; @@ -1500,14 +1564,14 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double int cpunum; char *p; - cpunum = (kd->arg5 & KDBG_CPU_MASK) ? 1: 0; + cpunum = CPU_NUMBER(kd->timestamp); if (print_info && fp) { - if (p = find_code(type)) { + if ((p = find_code(type))) { if (type == INTERRUPT) { int mode = 1; - if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) { + if ((ti = find_thread(kd->arg5, 0, 0))) { if (ti->type == -1 && strcmp(command, "kernel_task")) mode = 0; } @@ -1554,7 +1618,8 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double else ti->type = -1; ti->stime = timestamp; - ti->vfslookup = 0; + ti->pathptr = (long *)NULL; + #if 0 if (print_info && fp) fprintf(fp, "cur_max = %d, ti = %x, type = %x, thread = %x\n", cur_max, ti, ti->type, ti->thread); @@ -1569,7 +1634,8 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t int cpunum; char *p; - cpunum = (kd->arg5 & KDBG_CPU_MASK) ? 1: 0; + cpunum = CPU_NUMBER(kd->timestamp); + ti = find_thread(thread, type, type); #if 0 if (print_info && fp) @@ -1581,7 +1647,7 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t else fprintf(fp, "%9.1f %8.1f() \t", timestamp - bias, delta); - if (p = find_code(type)) { + if ((p = find_code(type))) { if (type == INTERRUPT) { fprintf(fp, "INTERRUPT %-8x %d %s\n", thread, cpunum, command); } else if (type == MACH_vmfault && kd->arg2 <= DBG_CACHE_HIT_FAULT) { @@ -1607,7 +1673,7 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t ti->thread = thread; ti->child_thread = 0; - ti->vfslookup = 0; + ti->pathptr = (long *)NULL; } } ti->type = -1; @@ -1622,12 +1688,11 @@ print_entry(FILE *fp, kd_buf *kd, int thread, int type, char *command, double ti if (!fp) return; - cpunum = (kd->arg5 & KDBG_CPU_MASK) ? 1: 0; - + cpunum = CPU_NUMBER(kd->timestamp); #if 0 fprintf(fp, "cur_max = %d, type = %x, thread = %x, cpunum = %d\n", cur_max, type, thread, cpunum); #endif - if (p = find_code(type)) { + if ((p = find_code(type))) { fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-8x %-8x %-8x %-8x %-8x %d %s\n", timestamp - bias, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4, thread, cpunum, command); @@ -1654,7 +1719,7 @@ check_for_thread_update(int thread, int type, kd_buf *kd) ti->thread = thread; ti->type = -1; - ti->vfslookup = 0; + ti->pathptr = (long *)NULL; } ti->child_thread = kd->arg1; return (1); @@ -1681,10 +1746,15 @@ check_for_thread_update(int thread, int type, kd_buf *kd) kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency) { kd_buf *kd, *kd_start, *kd_stop; - double timestamp, last_timestamp, delta, start_bias; + int kd_count; /* Limit the boundary of kd_start */ + double timestamp = 0.0; + double last_timestamp = 0.0; + double delta = 0.0; + double start_bias = 0.0; int thread, cpunum; int debugid, type, clen; - unsigned long long now; + int len; + uint64_t now; struct th_info *ti; long *sargptr; char *p; @@ -1705,30 +1775,50 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n"); - thread = kd_beg->arg5 & KDBG_THREAD_MASK; + thread = kd_beg->arg5; + cpunum = CPU_NUMBER(kd_end->timestamp); - for (kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer) && (kd_start->arg5 & KDBG_THREAD_MASK) == thread; kd_start--) { - if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) + for (kd_count = 0, kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer); kd_start--, kd_count++) { + if (kd_count == MAX_LOG_COUNT) + break; + + if (CPU_NUMBER(kd_start->timestamp) != cpunum) + continue; + + if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) + break; + + if (kd_start->arg5 != thread) break; } + if (kd_start < (kd_buf *)my_buffer) kd_start = (kd_buf *)my_buffer; - for (kd_stop = kd_end + 1; kd_stop < end_of_sample && (kd_start->arg5 & KDBG_THREAD_MASK) == thread; kd_stop++) { - if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP) + thread = kd_end->arg5; + + for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) { + + if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP) + break; + + if (CPU_NUMBER(kd_stop->timestamp) != cpunum) + continue; + + if (kd_stop->arg5 != thread) break; } + if (kd_stop >= end_of_sample) kd_stop = end_of_sample - 1; - now = (((unsigned long long)kd_start->timestamp.tv_sec) << 32) | - (unsigned long long)((unsigned int)(kd_start->timestamp.tv_nsec)); + now = kd_start->timestamp & KDBG_TIMESTAMP_MASK; timestamp = ((double)now) / divisor; for (kd = kd_start; kd <= kd_stop; kd++) { type = kd->debugid & DBG_FUNC_MASK; - if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), type, type)) { + if ((ti = find_thread(kd->arg5, type, type))) { if (ti->stime >= timestamp) ti->type = -1; } @@ -1736,13 +1826,12 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d for (kd = kd_start; kd <= kd_stop; kd++) { int mode; - thread = kd->arg5 & KDBG_THREAD_MASK; - cpunum = (kd->arg5 & KDBG_CPU_MASK) ? 1: 0; + thread = kd->arg5; + cpunum = CPU_NUMBER(kd->timestamp); debugid = kd->debugid; type = kd->debugid & DBG_FUNC_MASK; - now = (((unsigned long long)kd->timestamp.tv_sec) << 32) | - (unsigned long long)((unsigned int)(kd->timestamp.tv_nsec)); + now = kd->timestamp & KDBG_TIMESTAMP_MASK; timestamp = ((double)now) / divisor; @@ -1752,7 +1841,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d } delta = timestamp - last_timestamp; - if (map = find_thread_map(thread)) + if ((map = find_thread_map(thread))) strcpy(command, map->command); else command[0] = 0; @@ -1780,7 +1869,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d mode = 1; - if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) { + if ((ti = find_thread(kd->arg5, 0, 0))) { if (ti->type == -1 && strcmp(command, "kernel_task")) mode = 0; } @@ -1800,12 +1889,12 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d case MACH_sched: case MACH_stkhandoff: - if (map = find_thread_map(kd->arg2)) + if ((map = find_thread_map(kd->arg2))) strcpy(command1, map->command); else sprintf(command1, "%-8x", kd->arg2); - if (ti = find_thread(kd->arg2, 0, 0)) { + if ((ti = find_thread(kd->arg2, 0, 0))) { if (ti->type == -1 && strcmp(command1, "kernel_task")) p = "U"; else @@ -1838,32 +1927,82 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d ti->thread = thread; ti->type = -1; - ti->vfslookup = 0; + ti->pathptr = (long *)NULL; ti->child_thread = 0; } - if (ti->vfslookup == 0) { - ti->vfslookup = 1; + + while ( (kd <= kd_stop) && (kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP) + { + if (ti->pathptr == NULL) { ti->arg1 = kd->arg1; - memset(&ti->pathname[0], 0, 32); - sargptr = (long *)&ti->pathname[0]; + sargptr = ti->pathname; *sargptr++ = kd->arg2; *sargptr++ = kd->arg3; *sargptr++ = kd->arg4; - - } else if (ti->vfslookup == 1) { - ti->vfslookup = 0; - - sargptr = (long *)&ti->pathname[12]; - *sargptr++ = kd->arg1; - *sargptr++ = kd->arg2; - *sargptr++ = kd->arg3; - *sargptr++ = kd->arg4; - - fprintf(log_fp, "%9.1f %8.1f\t\t%-28.28s %-28s %-8x %-8x %d %s\n", - timestamp - start_bias, delta, "VFS_LOOKUP", - ti->pathname, ti->arg1, thread, cpunum, command); + /* + * NULL terminate the 'string' + */ + *sargptr = 0; + + ti->pathptr = sargptr; + + } else { + sargptr = ti->pathptr; + + /* + We don't want to overrun our pathname buffer if the + kernel sends us more VFS_LOOKUP entries than we can + handle. + */ + + if (sargptr >= &ti->pathname[NUMPARMS]) + { + kd++; + continue; + } + + /* + We need to detect consecutive vfslookup entries. + So, if we get here and find a START entry, + fake the pathptr so we can bypass all further + vfslookup entries. + */ + + if (kd->debugid & DBG_FUNC_START) + { + ti->pathptr = &ti->pathname[NUMPARMS]; + } + else + { + *sargptr++ = kd->arg1; + *sargptr++ = kd->arg2; + *sargptr++ = kd->arg3; + *sargptr++ = kd->arg4; + /* + * NULL terminate the 'string' + */ + *sargptr = 0; + + ti->pathptr = sargptr; + } + } + kd++; } + p = (char *)ti->pathname; + + kd--; + /* print the tail end of the pathname */ + len = strlen(p); + if (len > 42) + len -= 42; + else + len = 0; + + fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s %-8x %-8x %d %s\n", + timestamp - start_bias, delta, "VFS_LOOKUP", + &p[len], ti->arg1, thread, cpunum, command); + last_timestamp = timestamp; break; @@ -1958,7 +2097,7 @@ do_kernel_nm() FILE *fp = (FILE *)0; char tmp_nm_file[128]; char tmpstr[1024]; - int inchr; + char inchr; bzero(tmp_nm_file, 128); bzero(tmpstr, 1024); @@ -2010,7 +2149,7 @@ do_kernel_nm() for (i=0; i