X-Git-Url: https://git.saurik.com/apple/system_cmds.git/blobdiff_plain/83f6dbe8135dc38ce4ac497ebea7f0ebc87d9199..381af97e8c14a91b535443f88337e4c77362f7ac:/latency.tproj/latency.c diff --git a/latency.tproj/latency.c b/latency.tproj/latency.c index 0244241..65b3c9b 100644 --- a/latency.tproj/latency.c +++ b/latency.tproj/latency.c @@ -3,34 +3,34 @@ * * @APPLE_LICENSE_HEADER_START@ * - * Copyright (c) 1999-2003 Apple Computer, Inc. All Rights Reserved. - * - * This file contains Original Code and/or Modifications of Original Code - * as defined in and that are subject to the Apple Public Source License - * Version 2.0 (the 'License'). You may not use this file except in - * compliance with the License. Please obtain a copy of the License at - * http://www.opensource.apple.com/apsl/ and read it before using this - * file. + * "Portions Copyright (c) 1999 Apple Computer, Inc. All Rights + * Reserved. This file contains Original Code and/or Modifications of + * Original Code as defined in and that are subject to the Apple Public + * Source License Version 1.0 (the 'License'). You may not use this file + * except in compliance with the License. Please obtain a copy of the + * License at http://www.apple.com/publicsource and read it before using + * this file. * * The Original Code and all software distributed under the License are * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES, * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY, - * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT. - * Please see the License for the specific language governing rights and - * limitations under the License. + * FITNESS FOR A PARTICULAR PURPOSE OR NON-INFRINGEMENT. Please see the + * License for the specific language governing rights and limitations + * under the License." * * @APPLE_LICENSE_HEADER_END@ */ /* - cc -I. -DKERNEL_PRIVATE -O -o latency latency.c -lncurses + cc -I. -DPRIVATE -D__APPLE_PRIVATE -O -o latency latency.c -lncurses */ #include #include #include +#include #include #include #include @@ -54,6 +54,8 @@ #include #endif /*KERNEL_PRIVATE*/ +#include + #include #include #include @@ -106,6 +108,11 @@ int my_policy; int my_pri = -1; int num_of_usecs_to_sleep = 1000; +#define N_HIGH_RES_BINS 500 +int use_high_res_bins = false; +int i_high_res_bins[N_HIGH_RES_BINS]; +int i_highest_latency = 0; + char *kernelpath = (char *)0; char *code_file = (char *)0; @@ -142,24 +149,23 @@ int need_new_map = 0; int total_threads = 0; kd_threadmap *mapptr = 0; -#define MAX_ENTRIES 1024 +#define MAX_ENTRIES 4096 struct ct { int type; char name[32]; } codes_tab[MAX_ENTRIES]; -/* If NUMPARMS changes from the kernel, then PATHLENGTH will also reflect the change */ + #define NUMPARMS 23 -#define PATHLENGTH (NUMPARMS*sizeof(long)) struct th_info { - int thread; + uintptr_t thread; int type; - int child_thread; + uintptr_t child_thread; int arg1; double stime; long *pathptr; - char pathname[PATHLENGTH + 1]; + long pathname[NUMPARMS + 1]; }; #define MAX_THREADS 512 @@ -174,7 +180,7 @@ int cur_max = 0; #define INTERRUPT 0x01050000 #define DECR_TRAP 0x01090000 #define DECR_SET 0x01090004 -#define MACH_vmfault 0x01300000 +#define MACH_vmfault 0x01300008 #define MACH_sched 0x01400000 #define MACH_stkhandoff 0x01400008 #define VFS_LOOKUP 0x03010090 @@ -188,19 +194,19 @@ 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 CPU_NUMBER(kp) kdbg_get_cpu(kp) -#define DBG_ZERO_FILL_FAULT 1 -#define DBG_PAGEIN_FAULT 2 -#define DBG_COW_FAULT 3 -#define DBG_CACHE_HIT_FAULT 4 -char *fault_name[5] = { +char *fault_name[9] = { "", "ZeroFill", "PageIn", "COW", "CacheHit", + "NoZeroFill", + "Guard", + "PageInFile", + "PageInAnon" }; char *pc_to_string(); @@ -426,6 +432,21 @@ set_init_logging() quit("trace facility failure, KERN_KDSETUP\n"); } +void +write_high_res_latencies() +{ + int i; + FILE *f; + if(use_high_res_bins) + { + f = fopen("latencies.csv","w"); + for(i=0;iarg5; - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); debugid = kd->debugid; type = kd->debugid & DBG_FUNC_MASK; @@ -1295,7 +1359,7 @@ void sample_sc(uint64_t start, uint64_t stop) } if ((kd->debugid & DBG_FUNC_MASK) == DECR_TRAP) { - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); last_decrementer_kd[cpunum] = kd; } else @@ -1455,14 +1519,17 @@ void sample_sc(uint64_t start, uint64_t stop) } while ( (kd < end_of_sample) && ((kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP)) { - if (!ti->pathptr) { + if (ti->pathptr == NULL) { ti->arg1 = kd->arg1; - memset(&ti->pathname[0], 0, (PATHLENGTH + 1)); - 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 { @@ -1474,7 +1541,7 @@ void sample_sc(uint64_t start, uint64_t stop) handle. */ - if ((long *)sargptr >= (long *)&ti->pathname[PATHLENGTH]) + if (sargptr >= &ti->pathname[NUMPARMS]) { kd++; continue; @@ -1489,7 +1556,7 @@ void sample_sc(uint64_t start, uint64_t stop) if (kd->debugid & DBG_FUNC_START) { - (long *)ti->pathptr = (long *)&ti->pathname[PATHLENGTH]; + ti->pathptr = &ti->pathname[NUMPARMS]; } else { @@ -1497,16 +1564,22 @@ void sample_sc(uint64_t start, uint64_t stop) *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(ti->pathname); + /* print the tail end of the pathname */ + len = strlen(p); if (len > 42) len -= 42; else @@ -1515,7 +1588,7 @@ void sample_sc(uint64_t start, uint64_t stop) 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", - &ti->pathname[len], ti->arg1, thread, cpunum, command); + &p[len], ti->arg1, thread, cpunum, command); } last_timestamp = timestamp; @@ -1558,7 +1631,7 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double int cpunum; char *p; - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); if (print_info && fp) { if ((p = find_code(type))) { @@ -1612,7 +1685,7 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double else ti->type = -1; ti->stime = timestamp; - ti->pathptr = (long *)0; + ti->pathptr = (long *)NULL; #if 0 if (print_info && fp) @@ -1627,8 +1700,9 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t struct th_info *ti; int cpunum; char *p; + uint64_t user_addr; - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); ti = find_thread(thread, type, type); #if 0 @@ -1644,9 +1718,11 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t 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) { - fprintf(fp, "%-28.28s %-8.8s %-8x %-8x %d %s\n", - p, fault_name[kd->arg2], kd->arg1, + } else if (type == MACH_vmfault && kd->arg4 <= DBG_PAGEIND_FAULT) { + user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2; + + fprintf(fp, "%-28.28s %-10.10s %-16qx %-8x %d %s\n", + p, fault_name[kd->arg4], user_addr, thread, cpunum, command); } else { fprintf(fp, "%-28.28s %-8x %-8x %-8x %d %s\n", @@ -1667,7 +1743,7 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t ti->thread = thread; ti->child_thread = 0; - ti->pathptr = (long *)0; + ti->pathptr = (long *)NULL; } } ti->type = -1; @@ -1682,7 +1758,7 @@ print_entry(FILE *fp, kd_buf *kd, int thread, int type, char *command, double ti if (!fp) return; - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); #if 0 fprintf(fp, "cur_max = %d, type = %x, thread = %x, cpunum = %d\n", cur_max, type, thread, cpunum); #endif @@ -1713,7 +1789,7 @@ check_for_thread_update(int thread, int type, kd_buf *kd) ti->thread = thread; ti->type = -1; - ti->pathptr = (long *)0; + ti->pathptr = (long *)NULL; } ti->child_thread = kd->arg1; return (1); @@ -1770,13 +1846,13 @@ 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; - cpunum = CPU_NUMBER(kd_end->timestamp); + cpunum = CPU_NUMBER(kd_end); 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) + if (CPU_NUMBER(kd_start) != cpunum) continue; if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) @@ -1796,7 +1872,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP) break; - if (CPU_NUMBER(kd_stop->timestamp) != cpunum) + if (CPU_NUMBER(kd_stop) != cpunum) continue; if (kd_stop->arg5 != thread) @@ -1821,7 +1897,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d int mode; thread = kd->arg5; - cpunum = CPU_NUMBER(kd->timestamp); + cpunum = CPU_NUMBER(kd); debugid = kd->debugid; type = kd->debugid & DBG_FUNC_MASK; @@ -1921,20 +1997,24 @@ 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->pathptr = (long *)0; + ti->pathptr = (long *)NULL; ti->child_thread = 0; } while ( (kd <= kd_stop) && (kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP) { - if (!ti->pathptr) { + if (ti->pathptr == NULL) { ti->arg1 = kd->arg1; - memset(&ti->pathname[0], 0, (PATHLENGTH + 1)); - 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 { @@ -1946,7 +2026,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d handle. */ - if ((long *)sargptr >= (long *)&ti->pathname[PATHLENGTH]) + if (sargptr >= &ti->pathname[NUMPARMS]) { kd++; continue; @@ -1961,7 +2041,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d if (kd->debugid & DBG_FUNC_START) { - (long *)ti->pathptr = (long *)&ti->pathname[PATHLENGTH]; + ti->pathptr = &ti->pathname[NUMPARMS]; } else { @@ -1969,15 +2049,21 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d *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(ti->pathname); + len = strlen(p); if (len > 42) len -= 42; else @@ -1985,7 +2071,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s %-8x %-8x %d %s\n", timestamp - start_bias, delta, "VFS_LOOKUP", - &ti->pathname[len], ti->arg1, thread, cpunum, command); + &p[len], ti->arg1, thread, cpunum, command); last_timestamp = timestamp; break; @@ -2009,13 +2095,13 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d double handle_decrementer(kd_buf *kd) { double latency; - int elapsed_usecs; + long elapsed_usecs; - if ((int)(kd->arg1) >= 0) + if ((long)(kd->arg1) >= 0) latency = 1; else latency = (((double)(-1 - kd->arg1)) / divisor); - elapsed_usecs = (int)latency; + elapsed_usecs = (long)latency; if (elapsed_usecs < 100) i_usec_10_bins[elapsed_usecs/10]++; @@ -2028,6 +2114,12 @@ double handle_decrementer(kd_buf *kd) else i_too_slow++; + if(use_high_res_bins && elapsed_usecs < N_HIGH_RES_BINS) { + if(elapsed_usecs > i_highest_latency) + i_highest_latency = elapsed_usecs; + i_high_res_bins[elapsed_usecs]++; + } + if (i_thresh_hold && elapsed_usecs > i_thresh_hold) i_exceeded_threshold++; if (elapsed_usecs > i_max_latency) @@ -2044,7 +2136,7 @@ double handle_decrementer(kd_buf *kd) void init_code_file() { FILE *fp; - int i, n, cnt, code; + int i, n, code; char name[128]; if ((fp = fopen(code_file, "r")) == (FILE *)0) { @@ -2052,16 +2144,15 @@ void init_code_file() fprintf(log_fp, "open of %s failed\n", code_file); return; } - n = fscanf(fp, "%d\n", &cnt); - - if (n != 1) { - if (log_fp) - fprintf(log_fp, "bad format found in %s\n", code_file); - return; - } for (i = 0; i < MAX_ENTRIES; i++) { - n = fscanf(fp, "%x%s\n", &code, name); + n = fscanf(fp, "%x%127s\n", &code, name); + if (n == 1 && i == 0) { + /* + * old code file format, just skip + */ + continue; + } if (n != 2) break; @@ -2087,7 +2178,11 @@ do_kernel_nm() bzero(tmpstr, 1024); /* Build the temporary nm file path */ - sprintf(tmp_nm_file, "/tmp/knm.out.%d", getpid()); + strcpy(tmp_nm_file,"/tmp/knm.out.XXXXXX"); + if (!mktemp(tmp_nm_file)) { + fprintf(stderr, "Error in mktemp call\n"); + return; + } /* Build the nm command and create a tmp file with the output*/ sprintf (tmpstr, "/usr/bin/nm -f -n -s __TEXT __text %s > %s",