/* * Copyright (c) 1999-2016 Apple Inc. All rights reserved. * * @APPLE_LICENSE_HEADER_START@ * * 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. * * 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. * * @APPLE_LICENSE_HEADER_END@ */ /* cc -I/System/Library/Frameworks/System.framework/Versions/B/PrivateHeaders -DPRIVATE -D__APPLE_PRIVATE -arch x86_64 -arch i386 -O -o latency latency.c -lncurses -lutil */ typedef char *kobject_description_t[512]; #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #ifndef KERNEL_PRIVATE #define KERNEL_PRIVATE #include #undef KERNEL_PRIVATE #else #include #endif /*KERNEL_PRIVATE*/ #include #include #include #include #include #include #include int s_usec_10_bins[10]; int s_usec_100_bins[10]; int s_msec_1_bins[10]; int s_msec_10_bins[5]; int s_too_slow; int s_max_latency; int s_min_latency = 0; long long s_total_latency = 0; int s_total_samples = 0; long s_thresh_hold; int s_exceeded_threshold = 0; #define N_HIGH_RES_BINS 500 int use_high_res_bins = false; struct i_latencies { int i_usec_10_bins[10]; int i_usec_100_bins[10]; int i_msec_1_bins[10]; int i_msec_10_bins[5]; int i_too_slow; long i_max_latency; long i_min_latency; int i_total_samples; int i_total; int i_exceeded_threshold; uint64_t i_total_latency; }; struct i_latencies *i_lat; boolean_t i_latency_per_cpu = FALSE; int i_high_res_bins[N_HIGH_RES_BINS]; long i_thresh_hold; int watch_priority_min = 97; int watch_priority_max = 97; long start_time; long curr_time; long refresh_time; char *kernelpath = NULL; typedef struct { void *k_sym_addr; /* kernel symbol address from nm */ size_t k_sym_len; /* length of kernel symbol string */ char *k_sym_name; /* kernel symbol string from nm */ } kern_sym_t; kern_sym_t *kern_sym_tbl; /* pointer to the nm table */ int kern_sym_count; /* number of entries in nm table */ #define MAX_ENTRIES 4096 struct ct { int type; char name[32]; } codes_tab[MAX_ENTRIES]; char *code_file = NULL; int num_of_codes = 0; double divisor; sig_atomic_t gotSIGWINCH = 0; int trace_enabled = 0; int need_new_map = 1; int set_remove_flag = 1; /* By default, remove trace buffer */ int RAW_flag = 0; int RAW_fd = 0; uint64_t first_now = 0; uint64_t last_now = 0; int first_read = 1; #define SAMPLE_TIME_USECS 50000 #define SAMPLE_SIZE 300000 #define MAX_LOG_COUNT 30 /* limits the number of entries dumped in log_decrementer */ kbufinfo_t bufinfo = {0, 0, 0}; FILE *log_fp = NULL; uint64_t sample_TOD_secs; uint32_t sample_TOD_usecs; uint64_t cpu_mask; int sample_generation = 0; int num_i_latency_cpus = 1; int num_cpus; void *my_buffer; int num_entries; kd_buf **last_decrementer_kd; /* last DECR_TRAP per cpu */ #define NUMPARMS 23 typedef struct event *event_t; struct event { event_t ev_next; uint64_t ev_thread; uint32_t ev_type; uint64_t ev_timestamp; }; typedef struct lookup *lookup_t; struct lookup { lookup_t lk_next; uint64_t lk_thread; uint64_t lk_dvp; int64_t *lk_pathptr; int64_t lk_pathname[NUMPARMS + 1]; }; typedef struct threadmap *threadmap_t; struct threadmap { threadmap_t tm_next; uint64_t tm_thread; uint64_t tm_pthread; char tm_command[MAXCOMLEN + 1]; char tm_orig_command[MAXCOMLEN + 1]; }; typedef struct threadrun *threadrun_t; struct threadrun { threadrun_t tr_next; uint64_t tr_thread; kd_buf *tr_entry; uint64_t tr_timestamp; int tr_priority; }; typedef struct thread_entry *thread_entry_t; struct thread_entry { thread_entry_t te_next; uint64_t te_thread; }; #define HASH_SIZE 1024 #define HASH_MASK 1023 event_t event_hash[HASH_SIZE]; lookup_t lookup_hash[HASH_SIZE]; threadmap_t threadmap_hash[HASH_SIZE]; threadrun_t threadrun_hash[HASH_SIZE]; event_t event_freelist; lookup_t lookup_freelist; threadrun_t threadrun_freelist; threadmap_t threadmap_freelist; threadmap_t threadmap_temp; thread_entry_t thread_entry_freelist; thread_entry_t thread_delete_list; thread_entry_t thread_reset_list; thread_entry_t thread_event_list; thread_entry_t thread_lookup_list; thread_entry_t thread_run_list; #ifndef RAW_VERSION1 typedef struct { int version_no; int thread_count; uint64_t TOD_secs; uint32_t TOD_usecs; } RAW_header; #define RAW_VERSION0 0x55aa0000 #define RAW_VERSION1 0x55aa0101 #endif #define USER_MODE 0 #define KERNEL_MODE 1 #define INTERRUPT 0x01050000 #define DECR_TRAP 0x01090000 #define DECR_SET 0x01090004 #define MACH_vmfault 0x01300008 #define MACH_sched 0x01400000 #define MACH_stkhandoff 0x01400008 #define MACH_makerunnable 0x01400018 #define MACH_idle 0x01400024 #define IES_action 0x050b0018 #define IES_filter 0x050b001c #define TES_action 0x050c0010 #define CQ_action 0x050d0018 #define CPUPM_CPUSTER_RUNCOUNT 0x05310144 #define BSC_exit 0x040C0004 #define BSC_thread_terminate 0x040c05a4 #define DBG_FUNC_MASK ~(DBG_FUNC_START | DBG_FUNC_END) #define CPU_NUMBER(kp) kdbg_get_cpu(kp) #define EMPTYSTRING "" const char *fault_name[] = { "", "ZeroFill", "PageIn", "COW", "CacheHit", "NoZeroFill", "Guard", "PageInFile", "PageInAnon" }; const char *sched_reasons[] = { "N", "P", "Q", "?", "u", "U", "?", "?", "H", "?", "?", "?", "?", "?", "?", "?", "Y" }; #define ARRAYSIZE(x) ((int)(sizeof(x) / sizeof(*x))) #define MAX_REASON ARRAYSIZE(sched_reasons) static double handle_decrementer(kd_buf *, int); static kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency); static void read_command_map(void); static void enter_syscall(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info); static void exit_syscall(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info); static void print_entry(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note); static void log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note); static char *find_code(int); static void pc_to_string(char *pcstring, uint64_t pc, int max_len, int mode); static void getdivisor(void); static int sample_sc(void); static void init_code_file(void); static void do_kernel_nm(void); static void open_logfile(const char*); static int binary_search(kern_sym_t *list, int low, int high, uint64_t addr); static void create_map_entry(uint64_t, char *); static void check_for_thread_update(uint64_t thread, int debugid_base, kd_buf *kbufp, char **command); static void log_scheduler(kd_buf *kd_start, kd_buf *kd_stop, kd_buf *end_of_sample, int s_priority, double s_latency, uint64_t thread); static int check_for_scheduler_latency(int type, uint64_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, int *priority, double *latency); static void open_rawfile(const char *path); static void screen_update(FILE *); static void set_enable(int); static void set_remove(void); static int quit(char *s) { if (!RAW_flag) { if (trace_enabled) { set_enable(0); } /* * This flag is turned off when calling * quit() due to a set_remove() failure. */ if (set_remove_flag) { set_remove(); } } endwin(); printf("latency: "); if (s) { printf("%s", s); } exit(1); } void set_enable(int val) { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDENABLE, val }; size_t needed; if (sysctl(mib, ARRAYSIZE(mib), NULL, &needed, NULL, 0) < 0) { quit("trace facility failure, KERN_KDENABLE\n"); } } static void set_numbufs(int nbufs) { int mib1[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETBUF, nbufs }; int mib2[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETUP }; size_t needed; if (sysctl(mib1, ARRAYSIZE(mib1), NULL, &needed, NULL, 0) < 0) { quit("trace facility failure, KERN_KDSETBUF\n"); } if (sysctl(mib2, ARRAYSIZE(mib2), NULL, &needed, NULL, 0) < 0) { quit("trace facility failure, KERN_KDSETUP\n"); } } static void set_pidexclude(int pid, int on_off) { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDPIDEX }; size_t needed = sizeof(kd_regtype); kd_regtype kr = { .type = KDBG_TYPENONE, .value1 = pid, .value2 = on_off }; sysctl(mib, ARRAYSIZE(mib), &kr, &needed, NULL, 0); } static void get_bufinfo(kbufinfo_t *val) { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDGETBUF }; size_t needed = sizeof (*val); if (sysctl(mib, ARRAYSIZE(mib), val, &needed, 0, 0) < 0) { quit("trace facility failure, KERN_KDGETBUF\n"); } } void set_remove(void) { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREMOVE }; size_t needed; errno = 0; if (sysctl(mib, ARRAYSIZE(mib), NULL, &needed, NULL, 0) < 0) { set_remove_flag = 0; if (errno == EBUSY) { quit("the trace facility is currently in use...\n fs_usage, sc_usage, and latency use this feature.\n\n"); } else { quit("trace facility failure, KERN_KDREMOVE\n"); } } } static void write_high_res_latencies(void) { int i; FILE *f; if (use_high_res_bins) { if ((f = fopen("latencies.csv","w"))) { for (i = 0; i < N_HIGH_RES_BINS; i++) { fprintf(f, "%d,%d\n", i, i_high_res_bins[i]); } fclose(f); } } } static void sigintr(int signo __attribute__((unused))) { write_high_res_latencies(); set_enable(0); set_pidexclude(getpid(), 0); screen_update(log_fp); endwin(); set_remove(); exit(1); } /* exit under normal conditions -- signal handler */ static void leave(int signo __attribute__((unused))) { write_high_res_latencies(); set_enable(0); set_pidexclude(getpid(), 0); endwin(); set_remove(); exit(1); } static void sigwinch(int signo __attribute__((unused))) { gotSIGWINCH = 1; } static void print_total(FILE *fp, char *s, int total) { int cpu; int clen; int itotal; struct i_latencies *il; char tbuf[512]; for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_total; } clen = sprintf(tbuf, "%s %10d %9d", s, total, itotal); for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; if (i_latency_per_cpu == TRUE) { clen += sprintf(&tbuf[clen], " %9d", il->i_total); } il->i_total = 0; } sprintf(&tbuf[clen], "\n"); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } void screen_update(FILE *fp) { int i; int cpu; int clen; int itotal, stotal; long elapsed_secs; long elapsed_mins; long elapsed_hours; long min_lat, max_lat; uint64_t tot_lat; unsigned int average_s_latency; unsigned int average_i_latency; struct i_latencies *il; char tbuf[1024]; if (fp == NULL) { erase(); move(0, 0); } else { fprintf(fp,"\n\n===================================================================================================\n"); } /* * Display the current time. * "ctime" always returns a string that looks like this: * * Sun Sep 16 01:03:52 1973 * 012345678901234567890123 * 1 2 * * We want indices 11 thru 18 (length 8). */ if (RAW_flag) { curr_time = (unsigned long)sample_TOD_secs; elapsed_secs = ((last_now - first_now) / divisor) / 1000000; } else { elapsed_secs = curr_time - start_time; } elapsed_hours = elapsed_secs / 3600; elapsed_secs -= elapsed_hours * 3600; elapsed_mins = elapsed_secs / 60; elapsed_secs -= elapsed_mins * 60; sprintf(tbuf, "%-19.19s %2ld:%02ld:%02ld\n", &(ctime(&curr_time)[0]), (long)elapsed_hours, (long)elapsed_mins, (long)elapsed_secs); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } sprintf(tbuf, " SCHEDULER INTERRUPTS\n"); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } if (i_latency_per_cpu == TRUE) { clen = sprintf(tbuf, " Total"); for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { if (cpu <= 9) { clen += sprintf(&tbuf[clen], " CPU %d", cpu); } else { clen += sprintf(&tbuf[clen], " CPU %d", cpu); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } clen = sprintf(tbuf, "\n-------------------------------------------------------"); for (cpu = 1; cpu < num_i_latency_cpus; cpu++) { clen += sprintf(&tbuf[clen], "----------"); } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } else { sprintf(tbuf, "---------------------------------------------"); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_total_samples; } clen = sprintf(tbuf, "\ntotal_samples %10d %9d", s_total_samples, itotal); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_total_samples); } } sprintf(&tbuf[clen], "\n"); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } for (stotal = 0, i = 0; i < 10; i++) { for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_usec_10_bins[i]; il->i_total += il->i_usec_10_bins[i]; } clen = sprintf(tbuf, "\ndelays < %3d usecs %10d %9d", (i + 1) * 10, s_usec_10_bins[i], itotal); stotal += s_usec_10_bins[i]; if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_usec_10_bins[i]); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } print_total(fp, "\ntotal < 100 usecs", stotal); for (stotal = 0, i = 1; i < 10; i++) { for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_usec_100_bins[i]; il->i_total += il->i_usec_100_bins[i]; } if (i < 9) { clen = sprintf(tbuf, "\ndelays < %3d usecs %10d %9d", (i + 1) * 100, s_usec_100_bins[i], itotal); } else { clen = sprintf(tbuf, "\ndelays < 1 msec %10d %9d", s_usec_100_bins[i], itotal); } stotal += s_usec_100_bins[i]; if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_usec_100_bins[i]); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } print_total(fp, "\ntotal < 1 msec ", stotal); for (stotal = 0, i = 1; i < 10; i++) { for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_msec_1_bins[i]; il->i_total += il->i_msec_1_bins[i]; } clen = sprintf(tbuf, "\ndelays < %3d msecs %10d %9d", (i + 1), s_msec_1_bins[i], itotal); stotal += s_msec_1_bins[i]; if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_msec_1_bins[i]); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } print_total(fp, "\ntotal < 10 msecs", stotal); for (stotal = 0, i = 1; i < 5; i++) { for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_msec_10_bins[i]; il->i_total += il->i_msec_10_bins[i]; } clen = sprintf(tbuf, "\ndelays < %3d msecs %10d %9d", (i + 1)*10, s_msec_10_bins[i], itotal); stotal += s_msec_10_bins[i]; if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_msec_10_bins[i]); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } } print_total(fp, "\ntotal < 50 msecs", stotal); for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_too_slow; } clen = sprintf(tbuf, "\ndelays > 50 msecs %10d %9d", s_too_slow, itotal); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_too_slow); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; if (cpu == 0 || (il->i_min_latency < min_lat)) { min_lat = il->i_min_latency; } } clen = sprintf(tbuf, "\n\nminimum latency(usecs) %7d %9ld", s_min_latency, min_lat); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9ld", il->i_min_latency); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; if (cpu == 0 || (il->i_max_latency > max_lat)) { max_lat = il->i_max_latency; } } clen = sprintf(tbuf, "\nmaximum latency(usecs) %7d %9ld", s_max_latency, max_lat); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9ld", il->i_max_latency); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } if (s_total_samples) { average_s_latency = (unsigned int)(s_total_latency/s_total_samples); } else { average_s_latency = 0; } for (itotal = 0, tot_lat = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_total_samples; tot_lat += il->i_total_latency; } if (itotal) { average_i_latency = (unsigned)(tot_lat/itotal); } else { average_i_latency = 0; } clen = sprintf(tbuf, "\naverage latency(usecs) %7d %9d", average_s_latency, average_i_latency); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; if (il->i_total_samples) { average_i_latency = (unsigned int)(il->i_total_latency/il->i_total_samples); } else { average_i_latency = 0; } clen += sprintf(&tbuf[clen], " %9d", average_i_latency); } } if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; itotal += il->i_exceeded_threshold; } clen = sprintf(tbuf, "\nexceeded threshold %7d %9d", s_exceeded_threshold, itotal); if (i_latency_per_cpu == TRUE) { for (cpu = 0; cpu < num_i_latency_cpus; cpu++) { il = &i_lat[cpu]; clen += sprintf(&tbuf[clen], " %9d", il->i_exceeded_threshold); } } sprintf(&tbuf[clen], "\n"); if (fp) { fprintf(fp, "%s", tbuf); } else { printw(tbuf); } if (fp == NULL) { refresh(); } else { fflush(fp); } } static int exit_usage(void) { fprintf(stderr, "Usage: latency [-p ] [-h] [-m] [-st ] [-it ]\n"); fprintf(stderr, " [-c ] [-l ] [-R ] [-n ]\n\n"); fprintf(stderr, " -p specify scheduling priority to watch... default is realtime. Can also be a range, e.g. \"31-47\".\n"); fprintf(stderr, " -h Display high resolution interrupt latencies and write them to latencies.csv (truncate existing file) upon exit.\n"); fprintf(stderr, " -st set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n"); fprintf(stderr, " -m specify per-CPU interrupt latency reporting\n"); fprintf(stderr, " -it set interrupt latency threshold in microseconds... if latency exceeds this, then log trace\n"); fprintf(stderr, " -c specify name of codes file... default is /usr/share/misc/trace.codes\n"); fprintf(stderr, " -l specify name of file to log trace entries to when the specified threshold is exceeded\n"); fprintf(stderr, " -R specify name of raw trace file to process\n"); fprintf(stderr, " -n specify kernel... default is /System/Library/Kernels/kernel.development\n"); fprintf(stderr, "\nlatency must be run as root\n\n"); exit(1); } static void resetscr(void) { (void)endwin(); } int main(int argc, char *argv[]) { int i; if (0 != reexec_to_match_kernel()) { fprintf(stderr, "Could not re-execute: %d\n", errno); exit(1); } while (argc > 1) { if (strcmp(argv[1], "-R") == 0) { argc--; argv++; if (argc > 1) { open_rawfile(argv[1]); } else { exit_usage(); } RAW_flag = 1; } else if (strcmp(argv[1], "-p") == 0) { argc--; argv++; if (argc > 1) { if (2 == sscanf(argv[1], "%d-%d", &watch_priority_min, &watch_priority_max)) { if (watch_priority_min > watch_priority_max) { exit_usage(); } else if (watch_priority_min < 0) { exit_usage(); } } else { if (1 == sscanf(argv[1], "%d", &watch_priority_min)) { watch_priority_max = watch_priority_min; } else { exit_usage(); } } } else { exit_usage(); } } else if (strcmp(argv[1], "-st") == 0) { argc--; argv++; if (argc > 1) { s_thresh_hold = atoi(argv[1]); } else { exit_usage(); } } else if (strcmp(argv[1], "-it") == 0) { argc--; argv++; if (argc > 1) { i_thresh_hold = atoi(argv[1]); } else { exit_usage(); } } else if (strcmp(argv[1], "-c") == 0) { argc--; argv++; if (argc > 1) { code_file = argv[1]; } else { exit_usage(); } } else if (strcmp(argv[1], "-l") == 0) { argc--; argv++; if (argc > 1) { open_logfile(argv[1]); } else { exit_usage(); } } else if (strcmp(argv[1], "-n") == 0) { argc--; argv++; if (argc > 1) { kernelpath = argv[1]; } else { exit_usage(); } } else if (strcmp(argv[1], "-h") == 0) { use_high_res_bins = TRUE; } else if (strcmp(argv[1], "-m") == 0) { i_latency_per_cpu = TRUE; } else { exit_usage(); } argc--; argv++; } if (!RAW_flag) { if (geteuid() != 0) { printf("'latency' must be run as root...\n"); exit(1); } } if (kernelpath == NULL) { kernelpath = "/System/Library/Kernels/kernel.development"; } if (code_file == NULL) { code_file = "/usr/share/misc/trace.codes"; } do_kernel_nm(); getdivisor(); init_code_file(); if (!RAW_flag) { if (initscr() == NULL) { fprintf(stderr, "Unrecognized TERM type, try vt100\n"); exit(1); } atexit(resetscr); clear(); refresh(); signal(SIGWINCH, sigwinch); signal(SIGINT, sigintr); signal(SIGQUIT, leave); signal(SIGTERM, leave); signal(SIGHUP, leave); /* * grab the number of cpus and scale the buffer size */ int mib[] = { CTL_HW, HW_NCPU }; size_t len = sizeof(num_cpus); sysctl(mib, ARRAYSIZE(mib), &num_cpus, &len, NULL, 0); set_remove(); set_numbufs(SAMPLE_SIZE * num_cpus); get_bufinfo(&bufinfo); set_enable(0); set_pidexclude(getpid(), 1); set_enable(1); num_entries = bufinfo.nkdbufs; } else { num_entries = 50000; num_cpus = 128; } for (cpu_mask = 0, i = 0; i < num_cpus; i++) cpu_mask |= ((uint64_t)1 << i); if ((my_buffer = malloc(num_entries * sizeof(kd_buf))) == NULL) { quit("can't allocate memory for tracing info\n"); } if ((last_decrementer_kd = (kd_buf **)malloc(num_cpus * sizeof(kd_buf *))) == NULL) { quit("can't allocate memory for decrementer tracing info\n"); } if (i_latency_per_cpu == FALSE) { num_i_latency_cpus = 1; } else { num_i_latency_cpus = num_cpus; } if ((i_lat = (struct i_latencies *)malloc(num_i_latency_cpus * sizeof(struct i_latencies))) == NULL) { quit("can't allocate memory for interrupt latency info\n"); } bzero((char *)i_lat, num_i_latency_cpus * sizeof(struct i_latencies)); if (RAW_flag) { while (sample_sc()) { continue; } if (log_fp) { screen_update(log_fp); } screen_update(stdout); } else { uint64_t adelay; double fdelay; double nanosecs_to_sleep; nanosecs_to_sleep = (double)(SAMPLE_TIME_USECS * 1000); fdelay = nanosecs_to_sleep * (divisor /1000); adelay = (uint64_t)fdelay; trace_enabled = 1; start_time = time(NULL); refresh_time = start_time; for (;;) { curr_time = time(NULL); if (curr_time >= refresh_time) { screen_update(NULL); refresh_time = curr_time + 1; } mach_wait_until(mach_absolute_time() + adelay); sample_sc(); if (gotSIGWINCH) { /* * 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 read_command_map(void) { kd_threadmap *mapptr = 0; int total_threads = 0; size_t size; off_t offset; int i; RAW_header header = {0}; if (RAW_flag) { if (read(RAW_fd, &header, sizeof(RAW_header)) != sizeof(RAW_header)) { perror("read failed"); exit(2); } if (header.version_no != RAW_VERSION1) { header.version_no = RAW_VERSION0; header.TOD_secs = time(NULL); header.TOD_usecs = 0; lseek(RAW_fd, (off_t)0, SEEK_SET); if (read(RAW_fd, &header.thread_count, sizeof(int)) != sizeof(int)) { perror("read failed"); exit(2); } } total_threads = header.thread_count; sample_TOD_secs = header.TOD_secs; sample_TOD_usecs = header.TOD_usecs; if (total_threads == 0 && header.version_no != RAW_VERSION0) { offset = lseek(RAW_fd, (off_t)0, SEEK_CUR); offset = (offset + (4095)) & ~4095; lseek(RAW_fd, offset, SEEK_SET); } } else { total_threads = bufinfo.nkdthreads; } size = total_threads * sizeof(kd_threadmap); if (size == 0 || ((mapptr = (kd_threadmap *) malloc(size)) == 0)) { return; } bzero (mapptr, size); /* * Now read the threadmap */ if (RAW_flag) { if (read(RAW_fd, mapptr, size) != size) { printf("Can't read the thread map -- this is not fatal\n"); } if (header.version_no != RAW_VERSION0) { offset = lseek(RAW_fd, (off_t)0, SEEK_CUR); offset = (offset + (4095)) & ~4095; lseek(RAW_fd, offset, SEEK_SET); } } else { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDTHRMAP}; if (sysctl(mib, ARRAYSIZE(mib), mapptr, &size, NULL, 0) < 0) { /* * This is not fatal -- just means I cant map command strings */ printf("Can't read the thread map -- this is not fatal\n"); total_threads = 0; } } for (i = 0; i < total_threads; i++) { create_map_entry(mapptr[i].thread, &mapptr[i].command[0]); } free(mapptr); } void create_map_entry(uint64_t thread, char *command) { threadmap_t tme; if ((tme = threadmap_freelist)) { threadmap_freelist = tme->tm_next; } else { tme = (threadmap_t)malloc(sizeof(struct threadmap)); } tme->tm_thread = thread; (void)strncpy (tme->tm_command, command, MAXCOMLEN); tme->tm_command[MAXCOMLEN] = '\0'; tme->tm_orig_command[0] = '\0'; int hashid = thread & HASH_MASK; tme->tm_next = threadmap_hash[hashid]; threadmap_hash[hashid] = tme; } static void delete_thread_entry(uint64_t thread) { threadmap_t tme; int hashid = thread & HASH_MASK; if ((tme = threadmap_hash[hashid])) { if (tme->tm_thread == thread) { threadmap_hash[hashid] = tme->tm_next; } else { threadmap_t tme_prev = tme; for (tme = tme->tm_next; tme; tme = tme->tm_next) { if (tme->tm_thread == thread) { tme_prev->tm_next = tme->tm_next; break; } tme_prev = tme; } } if (tme) { tme->tm_next = threadmap_freelist; threadmap_freelist = tme; } } } static void find_and_insert_tmp_map_entry(uint64_t pthread, char *command) { threadmap_t tme; if ((tme = threadmap_temp)) { if (tme->tm_pthread == pthread) { threadmap_temp = tme->tm_next; } else { threadmap_t tme_prev = tme; for (tme = tme->tm_next; tme; tme = tme->tm_next) { if (tme->tm_pthread == pthread) { tme_prev->tm_next = tme->tm_next; break; } tme_prev = tme; } } if (tme) { (void)strncpy (tme->tm_command, command, MAXCOMLEN); tme->tm_command[MAXCOMLEN] = '\0'; tme->tm_orig_command[0] = '\0'; int hashid = tme->tm_thread & HASH_MASK; tme->tm_next = threadmap_hash[hashid]; threadmap_hash[hashid] = tme; } } } static void create_tmp_map_entry(uint64_t thread, uint64_t pthread) { threadmap_t tme; if ((tme = threadmap_freelist)) { threadmap_freelist = tme->tm_next; } else { tme = malloc(sizeof(struct threadmap)); } tme->tm_thread = thread; tme->tm_pthread = pthread; tme->tm_command[0] = '\0'; tme->tm_orig_command[0] = '\0'; tme->tm_next = threadmap_temp; threadmap_temp = tme; } static threadmap_t find_thread_entry(uint64_t thread) { threadmap_t tme; int hashid = thread & HASH_MASK; for (tme = threadmap_hash[hashid]; tme; tme = tme->tm_next) { if (tme->tm_thread == thread) { return tme; } } return 0; } static void find_thread_name(uint64_t thread, char **command) { threadmap_t tme; if ((tme = find_thread_entry(thread))) { *command = tme->tm_command; } else { *command = EMPTYSTRING; } } static void add_thread_entry_to_list(thread_entry_t *list, uint64_t thread) { thread_entry_t te; if ((te = thread_entry_freelist)) { thread_entry_freelist = te->te_next; } else { te = (thread_entry_t)malloc(sizeof(struct thread_entry)); } te->te_thread = thread; te->te_next = *list; *list = te; } static void exec_thread_entry(uint64_t thread, char *command) { threadmap_t tme; if ((tme = find_thread_entry(thread))) { if (tme->tm_orig_command[0] == '\0') { (void)strncpy (tme->tm_orig_command, tme->tm_command, MAXCOMLEN); tme->tm_orig_command[MAXCOMLEN] = '\0'; } (void)strncpy (tme->tm_command, command, MAXCOMLEN); tme->tm_command[MAXCOMLEN] = '\0'; add_thread_entry_to_list(&thread_reset_list, thread); } else { create_map_entry(thread, command); } } static void record_thread_entry_for_gc(uint64_t thread) { add_thread_entry_to_list(&thread_delete_list, thread); } static void gc_thread_entries(void) { thread_entry_t te; thread_entry_t te_next; int count = 0; for (te = thread_delete_list; te; te = te_next) { delete_thread_entry(te->te_thread); te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; count++; } thread_delete_list = 0; } static void gc_reset_entries(void) { thread_entry_t te; thread_entry_t te_next; int count = 0; for (te = thread_reset_list; te; te = te_next) { te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; count++; } thread_reset_list = 0; } static void reset_thread_names(void) { thread_entry_t te; thread_entry_t te_next; int count = 0; for (te = thread_reset_list; te; te = te_next) { threadmap_t tme; if ((tme = find_thread_entry(te->te_thread))) { if (tme->tm_orig_command[0]) { (void)strncpy (tme->tm_command, tme->tm_orig_command, MAXCOMLEN); tme->tm_command[MAXCOMLEN] = '\0'; tme->tm_orig_command[0] = '\0'; } } te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; count++; } thread_reset_list = 0; } static void delete_all_thread_entries(void) { threadmap_t tme = 0; threadmap_t tme_next = 0; int i; for (i = 0; i < HASH_SIZE; i++) { for (tme = threadmap_hash[i]; tme; tme = tme_next) { tme_next = tme->tm_next; tme->tm_next = threadmap_freelist; threadmap_freelist = tme; } threadmap_hash[i] = 0; } } static void insert_run_event(uint64_t thread, int priority, kd_buf *kd, uint64_t now) { threadrun_t trp; int hashid = thread & HASH_MASK; for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) { if (trp->tr_thread == thread) { break; } } if (trp == NULL) { if ((trp = threadrun_freelist)) { threadrun_freelist = trp->tr_next; } else { trp = (threadrun_t)malloc(sizeof(struct threadrun)); } trp->tr_thread = thread; trp->tr_next = threadrun_hash[hashid]; threadrun_hash[hashid] = trp; add_thread_entry_to_list(&thread_run_list, thread); } trp->tr_entry = kd; trp->tr_timestamp = now; trp->tr_priority = priority; } static threadrun_t find_run_event(uint64_t thread) { threadrun_t trp; int hashid = thread & HASH_MASK; for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) { if (trp->tr_thread == thread) { return trp; } } return 0; } static void delete_run_event(uint64_t thread) { threadrun_t trp = 0; threadrun_t trp_prev; int hashid = thread & HASH_MASK; if ((trp = threadrun_hash[hashid])) { if (trp->tr_thread == thread) { threadrun_hash[hashid] = trp->tr_next; } else { trp_prev = trp; for (trp = trp->tr_next; trp; trp = trp->tr_next) { if (trp->tr_thread == thread) { trp_prev->tr_next = trp->tr_next; break; } trp_prev = trp; } } if (trp) { trp->tr_next = threadrun_freelist; threadrun_freelist = trp; } } } static void gc_run_events(void) { thread_entry_t te; thread_entry_t te_next; threadrun_t trp; threadrun_t trp_next; int count = 0; for (te = thread_run_list; te; te = te_next) { int hashid = te->te_thread & HASH_MASK; for (trp = threadrun_hash[hashid]; trp; trp = trp_next) { trp_next = trp->tr_next; trp->tr_next = threadrun_freelist; threadrun_freelist = trp; count++; } threadrun_hash[hashid] = 0; te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; } thread_run_list = 0; } static void insert_start_event(uint64_t thread, int type, uint64_t now) { event_t evp; int hashid = thread & HASH_MASK; for (evp = event_hash[hashid]; evp; evp = evp->ev_next) { if (evp->ev_thread == thread && evp->ev_type == type) { break; } } if (evp == NULL) { if ((evp = event_freelist)) { event_freelist = evp->ev_next; } else { evp = (event_t)malloc(sizeof(struct event)); } evp->ev_thread = thread; evp->ev_type = type; evp->ev_next = event_hash[hashid]; event_hash[hashid] = evp; add_thread_entry_to_list(&thread_event_list, thread); } evp->ev_timestamp = now; } static uint64_t consume_start_event(uint64_t thread, int type, uint64_t now) { event_t evp; event_t evp_prev; uint64_t elapsed = 0; int hashid = thread & HASH_MASK; if ((evp = event_hash[hashid])) { if (evp->ev_thread == thread && evp->ev_type == type) { event_hash[hashid] = evp->ev_next; } else { evp_prev = evp; for (evp = evp->ev_next; evp; evp = evp->ev_next) { if (evp->ev_thread == thread && evp->ev_type == type) { evp_prev->ev_next = evp->ev_next; break; } evp_prev = evp; } } if (evp) { elapsed = now - evp->ev_timestamp; if (now < evp->ev_timestamp) { printf("consume: now = %qd, timestamp = %qd\n", now, evp->ev_timestamp); elapsed = 0; } evp->ev_next = event_freelist; event_freelist = evp; } } return elapsed; } static void gc_start_events(void) { thread_entry_t te; thread_entry_t te_next; event_t evp; event_t evp_next; int count = 0; int hashid; for (te = thread_event_list; te; te = te_next) { hashid = te->te_thread & HASH_MASK; for (evp = event_hash[hashid]; evp; evp = evp_next) { evp_next = evp->ev_next; evp->ev_next = event_freelist; event_freelist = evp; count++; } event_hash[hashid] = 0; te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; } thread_event_list = 0; } static int thread_in_user_mode(uint64_t thread, char *command) { event_t evp; if (strcmp(command, "kernel_task") == 0) { return 0; } int hashid = thread & HASH_MASK; for (evp = event_hash[hashid]; evp; evp = evp->ev_next) { if (evp->ev_thread == thread) { return 0; } } return 1; } static lookup_t handle_lookup_event(uint64_t thread, int debugid, kd_buf *kdp) { lookup_t lkp; boolean_t first_record = FALSE; int hashid = thread & HASH_MASK; if (debugid & DBG_FUNC_START) { first_record = TRUE; } for (lkp = lookup_hash[hashid]; lkp; lkp = lkp->lk_next) { if (lkp->lk_thread == thread) { break; } } if (lkp == NULL) { if (first_record == FALSE) { return 0; } if ((lkp = lookup_freelist)) { lookup_freelist = lkp->lk_next; } else { lkp = (lookup_t)malloc(sizeof(struct lookup)); } lkp->lk_thread = thread; lkp->lk_next = lookup_hash[hashid]; lookup_hash[hashid] = lkp; add_thread_entry_to_list(&thread_lookup_list, thread); } if (first_record == TRUE) { lkp->lk_pathptr = lkp->lk_pathname; lkp->lk_dvp = kdp->arg1; } else { if (lkp->lk_pathptr > &lkp->lk_pathname[NUMPARMS-4]) { return lkp; } *lkp->lk_pathptr++ = kdp->arg1; } *lkp->lk_pathptr++ = kdp->arg2; *lkp->lk_pathptr++ = kdp->arg3; *lkp->lk_pathptr++ = kdp->arg4; *lkp->lk_pathptr = 0; if (debugid & DBG_FUNC_END) { return lkp; } return 0; } static void delete_lookup_event(uint64_t thread, lookup_t lkp_to_delete) { lookup_t lkp; lookup_t lkp_prev; int hashid; hashid = thread & HASH_MASK; if ((lkp = lookup_hash[hashid])) { if (lkp == lkp_to_delete) { lookup_hash[hashid] = lkp->lk_next; } else { lkp_prev = lkp; for (lkp = lkp->lk_next; lkp; lkp = lkp->lk_next) { if (lkp == lkp_to_delete) { lkp_prev->lk_next = lkp->lk_next; break; } lkp_prev = lkp; } } if (lkp) { lkp->lk_next = lookup_freelist; lookup_freelist = lkp; } } } static void gc_lookup_events(void) { thread_entry_t te; thread_entry_t te_next; lookup_t lkp; lookup_t lkp_next; int count = 0; int hashid; for (te = thread_lookup_list; te; te = te_next) { hashid = te->te_thread & HASH_MASK; for (lkp = lookup_hash[hashid]; lkp; lkp = lkp_next) { lkp_next = lkp->lk_next; lkp->lk_next = lookup_freelist; lookup_freelist = lkp; count++; } lookup_hash[hashid] = 0; te_next = te->te_next; te->te_next = thread_entry_freelist; thread_entry_freelist = te; } thread_lookup_list = 0; } int sample_sc(void) { kd_buf *kd, *end_of_sample; int keep_going = 1; int i; ssize_t count; if (!RAW_flag) { /* * Get kernel buffer information */ get_bufinfo(&bufinfo); } if (need_new_map) { delete_all_thread_entries(); read_command_map(); need_new_map = 0; } if (RAW_flag) { ssize_t bytes_read; bytes_read = read(RAW_fd, my_buffer, num_entries * sizeof(kd_buf)); if (bytes_read == -1) { perror("read failed"); exit(2); } count = bytes_read / sizeof(kd_buf); if (count != num_entries) { keep_going = 0; } if (first_read) { kd = (kd_buf *)my_buffer; first_now = kd->timestamp & KDBG_TIMESTAMP_MASK; first_read = 0; } } else { int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREADTR }; size_t needed = bufinfo.nkdbufs * sizeof(kd_buf); if (sysctl(mib, ARRAYSIZE(mib), my_buffer, &needed, NULL, 0) < 0) { quit("trace facility failure, KERN_KDREADTR\n"); } count = needed; sample_generation++; if (bufinfo.flags & KDBG_WRAPPED) { need_new_map = 1; if (log_fp) { fprintf(log_fp, "\n\n%-19.19s sample = %d <<<<<<< trace buffer wrapped >>>>>>>\n\n", &(ctime(&curr_time)[0]), sample_generation); } set_enable(0); set_enable(1); } } end_of_sample = &((kd_buf *)my_buffer)[count]; /* * Always reinitialize the DECR_TRAP array */ for (i = 0; i < num_cpus; i++) { last_decrementer_kd[i] = (kd_buf *)my_buffer; } for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) { kd_buf *kd_start; uint64_t thread = kd->arg5; int type = kd->debugid & DBG_FUNC_MASK; (void)check_for_thread_update(thread, type, kd, NULL); uint64_t now = kd->timestamp & KDBG_TIMESTAMP_MASK; last_now = now; if (type == DECR_TRAP) { int cpunum = CPU_NUMBER(kd); double i_latency = handle_decrementer(kd, cpunum); if (log_fp) { if (i_thresh_hold && (int)i_latency > i_thresh_hold) { kd_start = last_decrementer_kd[cpunum]; log_decrementer(kd_start, kd, end_of_sample, i_latency); } last_decrementer_kd[cpunum] = kd; } } else { double s_latency; int s_priority; if (check_for_scheduler_latency(type, &thread, now, kd, &kd_start, &s_priority, &s_latency)) { log_scheduler(kd_start, kd, end_of_sample, s_priority, s_latency, thread); } } } if (log_fp) { fflush(log_fp); } gc_thread_entries(); gc_reset_entries(); gc_run_events(); return keep_going; } void enter_syscall(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info) { char *p; double timestamp; double delta; char pcstring[128]; int cpunum = CPU_NUMBER(kd); if (print_info && fp) { timestamp = (double)(now - start_bias) / divisor; delta = (double)idelta / divisor; if ((p = find_code(type))) { if (type == INTERRUPT) { int mode; if (kd->arg3) { mode = USER_MODE; } else { mode = KERNEL_MODE; } pc_to_string(&pcstring[0], kd->arg2, 58, mode); fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2" PRIx64 "] @ %-58.58s %8" PRIx64 " %2d %s\n", timestamp, delta, (uint64_t)kd->arg1, &pcstring[0], thread, cpunum, command); } else if (type == MACH_vmfault) { fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8" PRIx64 " %2d %s\n", timestamp, delta, p, thread, cpunum, command); } else { fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", timestamp, delta, p, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4, thread, cpunum, command); } } else { fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", timestamp, delta, type, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4, thread, cpunum, command); } } if (type != BSC_thread_terminate && type != BSC_exit) { insert_start_event(thread, type, now); } } void exit_syscall(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info) { char *p; uint64_t user_addr; double timestamp; double delta; double elapsed_timestamp; elapsed_timestamp = (double)consume_start_event(thread, type, now) / divisor; if (print_info && fp) { int cpunum = CPU_NUMBER(kd); timestamp = (double)(now - start_bias) / divisor; delta = (double)idelta / divisor; fprintf(fp, "%9.1f %8.1f(%.1f) \t", timestamp, delta, elapsed_timestamp); if ((p = find_code(type))) { if (type == INTERRUPT) { fprintf(fp, "INTERRUPT %8" PRIx64 " %2d %s\n", thread, cpunum, command); } 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 %8" PRIx64 " %2d %s\n", p, fault_name[kd->arg4], user_addr, thread, cpunum, command); } else { fprintf(fp, "%-28.28s %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", p, (uint64_t)kd->arg1, (uint64_t)kd->arg2, thread, cpunum, command); } } else { fprintf(fp, "%-8x %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", type, (uint64_t)kd->arg1, (uint64_t)kd->arg2, thread, cpunum, command); } } } void print_entry(FILE *fp, kd_buf *kd, uint64_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note) { char *p; if (!fp) { return; } int cpunum = CPU_NUMBER(kd); double timestamp = (double)(now - start_bias) / divisor; double delta = (double)idelta / divisor; if ((p = find_code(type))) { if (kd == kd_note) { fprintf(fp, "%9.1f %8.1f\t**\t", timestamp, delta); } else { fprintf(fp, "%9.1f %8.1f\t\t", timestamp, delta); } fprintf(fp, "%-28.28s %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", p, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4, thread, cpunum, command); } else { fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n", timestamp, delta, type, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4, thread, cpunum, command); } } void check_for_thread_update(uint64_t thread, int debugid_base, kd_buf *kbufp, char **command) { if (debugid_base == TRACE_DATA_NEWTHREAD) { /* * Save the create thread data */ create_tmp_map_entry(kbufp->arg1, thread); } else if (debugid_base == TRACE_STRING_NEWTHREAD) { /* * process new map entry */ find_and_insert_tmp_map_entry(thread, (char *)&kbufp->arg1); } else if (debugid_base == TRACE_STRING_EXEC) { exec_thread_entry(thread, (char *)&kbufp->arg1); } else { if (debugid_base == BSC_exit || debugid_base == BSC_thread_terminate) { record_thread_entry_for_gc(thread); } if (command) { find_thread_name(thread, command); } } } void log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note) { lookup_t lkp; int mode; uint64_t reason; char *p; char *command; char *command1; char command_buf[32]; char sched_info[64]; char pcstring[128]; const char *sched_reason; double i_latency; double timestamp; double delta; char joe[32]; uint64_t thread = kd->arg5; int cpunum = CPU_NUMBER(kd); int debugid = kd->debugid; int type = kd->debugid & DBG_FUNC_MASK; (void)check_for_thread_update(thread, type, kd, &command); if ((type >> 24) == DBG_TRACE) { if (((type >> 16) & 0xff) != DBG_TRACE_INFO) { return; } } timestamp = (double)(now - start_bias) / divisor; delta = (double)idelta / divisor; switch (type) { case CQ_action: pc_to_string(&pcstring[0], kd->arg1, 84, KERNEL_MODE); fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-84.84s %8" PRIx64 " %2d %s\n", timestamp, delta, &pcstring[0], thread, cpunum, command); break; case TES_action: pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE); fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-83.83s %8" PRIx64 " %2d %s\n", timestamp, delta, &pcstring[0], thread, cpunum, command); break; case IES_action: pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE); fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-83.83s %8" PRIx64 " %2d %s\n", timestamp, delta, &pcstring[0], thread, cpunum, command); break; case IES_filter: pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE); fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-83.83s %8" PRIx64 " %2d %s\n", timestamp, delta, &pcstring[0], thread, cpunum, command); break; case DECR_TRAP: if ((int)kd->arg1 >= 0) { i_latency = 0; } else { i_latency = (((double)(-1 - kd->arg1)) / divisor); } if (i_thresh_hold && (int)i_latency > i_thresh_hold) { p = "*"; } else { p = " "; } if (kd->arg3) { mode = USER_MODE; } else { mode = KERNEL_MODE; } pc_to_string(&pcstring[0], kd->arg2, 84, mode); fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8" PRIx64 " %2d %s\n", timestamp, delta, i_latency, p, &pcstring[0], thread, cpunum, command); break; case DECR_SET: fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %8" PRIx64 " %2d %s\n", timestamp, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command); break; case MACH_sched: case MACH_stkhandoff: find_thread_name(kd->arg2, &command1); if (command1 == EMPTYSTRING) { command1 = command_buf; sprintf(command1, "%-8" PRIx64, (uint64_t)kd->arg2); } if (thread_in_user_mode(kd->arg2, command1)) { p = "U"; } else { p = "K"; } reason = kd->arg1; if (reason > MAX_REASON) { sched_reason = "?"; } else { sched_reason = sched_reasons[reason]; } if (sched_reason[0] == '?') { sprintf(joe, "%" PRIx64, reason); sched_reason = joe; } sprintf(sched_info, "%16.16s @ pri %3" PRIu64 " --> %16.16s @ pri %3" PRIu64 "%s", command, (uint64_t)kd->arg3, command1, (uint64_t)kd->arg4, p); fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s[%s] %s %8" PRIx64 " %2d\n", timestamp, delta, "MACH_SCHED", sched_reason, sched_info, thread, cpunum); break; case VFS_LOOKUP: if ((lkp = handle_lookup_event(thread, debugid, kd))) { /* * print the tail end of the pathname */ p = (char *)lkp->lk_pathname; size_t clen = strlen(p); if (clen > 45) { clen -= 45; } else { clen = 0; } fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-59s %-16" PRIx64 " %8" PRIx64 " %2d %s\n", timestamp, delta, "VFS_LOOKUP", &p[clen], lkp->lk_dvp, thread, cpunum, command); delete_lookup_event(thread, lkp); } break; default: if (debugid & DBG_FUNC_START) { enter_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1); } else if (debugid & DBG_FUNC_END) { exit_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1); } else { print_entry(log_fp, kd, thread, type, command, now, idelta, start_bias, kd_note); } break; } } static void log_range(kd_buf *kd_buffer, kd_buf *kd_start, kd_buf *kd_stop, kd_buf *kd_note, char *buf1) { uint64_t last_timestamp = 0; uint64_t delta = 0; uint64_t start_bias = 0; uint64_t now; kd_buf *kd; size_t clen; char buf2[128]; clen = strlen(buf1); memset(buf2, '-', clen); buf2[clen] = 0; fprintf(log_fp, "\n\n%s\n", buf2); fprintf(log_fp, "%s\n\n", buf1); fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n"); reset_thread_names(); last_timestamp = kd_start->timestamp & KDBG_TIMESTAMP_MASK; start_bias = last_timestamp; for (kd = kd_buffer; kd <= kd_stop; kd++) { now = kd->timestamp & KDBG_TIMESTAMP_MASK; if (kd >= kd_start) { delta = now - last_timestamp; log_info(now, delta, start_bias, kd, kd_note); last_timestamp = now; } else { int debugid = kd->debugid; uint64_t thread = kd->arg5; int type = kd->debugid & DBG_FUNC_MASK; if ((type >> 24) == DBG_TRACE) { if (((type >> 16) & 0xff) != DBG_TRACE_INFO) { continue; } } if (type == BSC_thread_terminate || type == BSC_exit) { continue; } if (debugid & DBG_FUNC_START) { insert_start_event(thread, type, now); } else if (debugid & DBG_FUNC_END) { (void)consume_start_event(thread, type, now); } } } gc_start_events(); gc_lookup_events(); } kd_buf * log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency) { kd_buf *kd_start, *kd_stop; int kd_count; /* Limit the boundary of kd_start */ uint64_t now; double sample_timestamp; char buf1[128]; uint64_t thread = kd_beg->arg5; int 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) != 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; } thread = kd_end->arg5; for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) { if (CPU_NUMBER(kd_stop) != cpunum) { continue; } if ((kd_stop->debugid & DBG_FUNC_MASK) == INTERRUPT) { break; } if (kd_stop->arg5 != thread) { break; } } if (kd_stop >= end_of_sample) { kd_stop = end_of_sample - 1; } if (RAW_flag) { time_t TOD_secs; uint64_t TOD_usecs; now = kd_start->timestamp & KDBG_TIMESTAMP_MASK; sample_timestamp = (double)(now - first_now) / divisor; TOD_usecs = (uint64_t)sample_timestamp; TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000); sprintf(buf1, "%-19.19s interrupt latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), i_latency, sample_timestamp); } else { sprintf(buf1, "%-19.19s interrupt latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), i_latency, sample_generation); } log_range((kd_buf *)my_buffer, kd_start, kd_stop, 0, buf1); return kd_stop; } void log_scheduler(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, int s_priority, double s_latency, uint64_t thread) { kd_buf *kd_start, *kd_stop; uint64_t now; int count; int cpunum; uint64_t cmask = 0; double sample_timestamp; char buf1[128]; for (count = 0, kd_start = kd_beg; (kd_start >= (kd_buf *)my_buffer); kd_start--) { cpunum = CPU_NUMBER(kd_start); cmask |= ((uint64_t)1 << cpunum); if (cmask == cpu_mask) { if (count++ > 100) 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_stop++) { if (kd_stop->arg5 == thread) { break; } } if (kd_stop >= end_of_sample) { kd_stop = end_of_sample - 1; } if (RAW_flag) { time_t TOD_secs; uint64_t TOD_usecs; now = kd_start->timestamp & KDBG_TIMESTAMP_MASK; sample_timestamp = (double)(now - first_now) / divisor; TOD_usecs = (uint64_t)sample_timestamp; TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000); sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), s_priority, s_latency, sample_timestamp); } else { sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), s_priority, s_latency, sample_generation); } log_range((kd_buf *)my_buffer, kd_start, kd_stop, kd_beg, buf1); } int check_for_scheduler_latency(int type, uint64_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, int *priority, double *latency) { int found_latency = 0; if (type == MACH_makerunnable) { if (watch_priority_min <= kd->arg2 && kd->arg2 <= watch_priority_max) { insert_run_event(kd->arg1, (int)kd->arg2, kd, now); } } else if (type == MACH_sched || type == MACH_stkhandoff) { threadrun_t trp = find_run_event(kd->arg2); if (type == MACH_sched || type == MACH_stkhandoff) { *thread = kd->arg2; } if ((trp = find_run_event(*thread))) { double d_s_latency = (((double)(now - trp->tr_timestamp)) / divisor); int s_latency = (int)d_s_latency; if (s_latency) { if (s_latency < 100) { s_usec_10_bins[s_latency/10]++; } if (s_latency < 1000) { s_usec_100_bins[s_latency/100]++; } else if (s_latency < 10000) { s_msec_1_bins[s_latency/1000]++; } else if (s_latency < 50000) { s_msec_10_bins[s_latency/10000]++; } else { s_too_slow++; } if (s_latency > s_max_latency) { s_max_latency = s_latency; } if (s_latency < s_min_latency || s_total_samples == 0) { s_min_latency = s_latency; } s_total_latency += s_latency; s_total_samples++; if (s_thresh_hold && s_latency > s_thresh_hold) { s_exceeded_threshold++; if (log_fp) { *kd_start = trp->tr_entry; *priority = trp->tr_priority; *latency = d_s_latency; found_latency = 1; } } } delete_run_event(*thread); } } return found_latency; } double handle_decrementer(kd_buf *kd, int cpunum) { struct i_latencies *il; double latency; long elapsed_usecs; if (i_latency_per_cpu == FALSE) { cpunum = 0; } il = &i_lat[cpunum]; if ((long)(kd->arg1) >= 0) { latency = 1; } else { latency = (((double)(-1 - kd->arg1)) / divisor); } elapsed_usecs = (long)latency; if (elapsed_usecs < 100) { il->i_usec_10_bins[elapsed_usecs/10]++; } if (elapsed_usecs < 1000) { il->i_usec_100_bins[elapsed_usecs/100]++; } else if (elapsed_usecs < 10000) { il->i_msec_1_bins[elapsed_usecs/1000]++; } else if (elapsed_usecs < 50000) { il->i_msec_10_bins[elapsed_usecs/10000]++; } else { il->i_too_slow++; } if (use_high_res_bins && elapsed_usecs < N_HIGH_RES_BINS) { i_high_res_bins[elapsed_usecs]++; } if (i_thresh_hold && elapsed_usecs > i_thresh_hold) { il->i_exceeded_threshold++; } if (elapsed_usecs > il->i_max_latency) { il->i_max_latency = elapsed_usecs; } if (elapsed_usecs < il->i_min_latency || il->i_total_samples == 0) { il->i_min_latency = elapsed_usecs; } il->i_total_latency += elapsed_usecs; il->i_total_samples++; return latency; } char * find_code(int type) { int i; for (i = 0; i < num_of_codes; i++) { if (codes_tab[i].type == type) { return codes_tab[i].name; } } return NULL; } void init_code_file(void) { FILE *fp; int i; if ((fp = fopen(code_file, "r")) == NULL) { if (log_fp) { fprintf(log_fp, "open of %s failed\n", code_file); } return; } for (i = 0; i < MAX_ENTRIES; i++) { int code; char name[128]; int n = fscanf(fp, "%x%127s\n", &code, name); if (n == 1 && i == 0) { /* * old code file format, just skip */ continue; } if (n != 2) { break; } strncpy(codes_tab[i].name, name, 32); codes_tab[i].type = code; } num_of_codes = i; fclose(fp); } void do_kernel_nm(void) { int i; size_t len; FILE *fp = NULL; char tmp_nm_file[128]; char tmpstr[1024]; char inchr; bzero(tmp_nm_file, 128); bzero(tmpstr, 1024); /* * Build the temporary nm file path */ 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 -n %s -s __TEXT __text > %s", kernelpath, tmp_nm_file); system(tmpstr); /* * Parse the output from the nm command */ if ((fp = fopen(tmp_nm_file, "r")) == NULL) { /* Hmmm, let's not treat this as fatal */ fprintf(stderr, "Failed to open nm symbol file [%s]\n", tmp_nm_file); return; } /* * Count the number of symbols in the nm symbol table */ kern_sym_count = 0; while ((inchr = getc(fp)) != -1) { if (inchr == '\n') { kern_sym_count++; } } rewind(fp); /* * Malloc the space for symbol table */ if (kern_sym_count > 0) { kern_sym_tbl = malloc(kern_sym_count * sizeof(kern_sym_t)); if (!kern_sym_tbl) { /* * Hmmm, lets not treat this as fatal */ fprintf(stderr, "Can't allocate memory for kernel symbol table\n"); } else { bzero(kern_sym_tbl, kern_sym_count * sizeof(kern_sym_t)); } } else { /* * Hmmm, lets not treat this as fatal */ fprintf(stderr, "No kernel symbol table \n"); } for (i = 0; i < kern_sym_count; i++) { bzero(tmpstr, 1024); if (fscanf(fp, "%p %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3) { break; } else { len = strlen(tmpstr); kern_sym_tbl[i].k_sym_name = malloc(len + 1); if (kern_sym_tbl[i].k_sym_name == NULL) { fprintf(stderr, "Can't allocate memory for symbol name [%s]\n", tmpstr); kern_sym_tbl[i].k_sym_name = NULL; len = 0; } else { strcpy(kern_sym_tbl[i].k_sym_name, tmpstr); } kern_sym_tbl[i].k_sym_len = len; } } if (i != kern_sym_count) { /* * Hmmm, didn't build up entire table from nm * scrap the entire thing */ free(kern_sym_tbl); kern_sym_tbl = NULL; kern_sym_count = 0; } fclose(fp); /* * Remove the temporary nm file */ unlink(tmp_nm_file); #if 0 /* * Dump the kernel symbol table */ for (i = 0; i < kern_sym_count; i++) { if (kern_sym_tbl[i].k_sym_name) { printf ("[%d] %-16p %s\n", i, kern_sym_tbl[i].k_sym_addr, kern_sym_tbl[i].k_sym_name); } else { printf ("[%d] %-16p %s\n", i, kern_sym_tbl[i].k_sym_addr, "No symbol name"); } } #endif } void pc_to_string(char *pcstring, uint64_t pc, int max_len, int mode) { int ret; size_t len; if (mode == USER_MODE) { sprintf(pcstring, "%-16" PRIx64 " [usermode addr]", pc); return; } ret = binary_search(kern_sym_tbl, 0, kern_sym_count-1, pc); if (ret == -1 || kern_sym_tbl[ret].k_sym_name == NULL) { sprintf(pcstring, "%-16" PRIx64, pc); return; } if ((len = kern_sym_tbl[ret].k_sym_len) > (max_len - 8)) { len = max_len - 8; } memcpy(pcstring, kern_sym_tbl[ret].k_sym_name, len); sprintf(&pcstring[len], "+0x%-5" PRIx64, pc - (uint64_t)kern_sym_tbl[ret].k_sym_addr); } /* * Return -1 if not found, else return index */ int binary_search(kern_sym_t *list, int low, int high, uint64_t addr) { int mid; if (kern_sym_count == 0) { return -1; } if (low > high) { return -1; /* failed */ } if (low + 1 == high) { if ((uint64_t)list[low].k_sym_addr <= addr && addr < (uint64_t)list[high].k_sym_addr) { /* * We have a range match */ return low; } if ((uint64_t)list[high].k_sym_addr <= addr) { return high; } /* * Failed */ return -1; } mid = (low + high) / 2; if (addr < (uint64_t)list[mid].k_sym_addr) { return binary_search(list, low, mid, addr); } return binary_search(list, mid, high, addr); } void open_logfile(const char *path) { log_fp = fopen(path, "a"); if (!log_fp) { /* * failed to open path */ fprintf(stderr, "latency: failed to open logfile [%s]\n", path); exit_usage(); } } void open_rawfile(const char *path) { RAW_fd = open(path, O_RDONLY); if (RAW_fd == -1) { /* * failed to open path */ fprintf(stderr, "latency: failed to open RAWfile [%s]\n", path); exit_usage(); } } void getdivisor(void) { mach_timebase_info_data_t info; (void)mach_timebase_info(&info); divisor = ((double)info.denom / (double)info.numer) * 1000; }