/*
- * Copyright (c) 1999-2010 Apple Inc. All rights reserved.
+ * 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,
* 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
*/
int i_msec_1_bins[10];
int i_msec_10_bins[5];
int i_too_slow;
- int i_max_latency;
- int i_min_latency;
+ long i_max_latency;
+ long i_min_latency;
int i_total_samples;
int i_total;
int i_exceeded_threshold;
long i_thresh_hold;
-int watch_priority = 97;
+int watch_priority_min = 97;
+int watch_priority_max = 97;
long start_time;
long curr_time;
typedef struct {
void *k_sym_addr; /* kernel symbol address from nm */
- u_int k_sym_len; /* length of kernel symbol string */
+ size_t k_sym_len; /* length of kernel symbol string */
char *k_sym_name; /* kernel symbol string from nm */
} kern_sym_t;
int sample_generation = 0;
int num_i_latency_cpus = 1;
int num_cpus;
-char *my_buffer;
+void *my_buffer;
int num_entries;
kd_buf **last_decrementer_kd; /* last DECR_TRAP per cpu */
struct lookup {
lookup_t lk_next;
-
+
uintptr_t lk_thread;
uintptr_t lk_dvp;
long *lk_pathptr;
struct threadmap {
threadmap_t tm_next;
-
+
uintptr_t tm_thread;
uintptr_t tm_pthread;
char tm_command[MAXCOMLEN + 1];
struct threadrun {
threadrun_t tr_next;
-
+
uintptr_t tr_thread;
kd_buf *tr_entry;
uint64_t tr_timestamp;
+ int tr_priority;
};
uintptr_t te_thread;
};
-
#define HASH_SIZE 1024
#define HASH_MASK 1023
#define KERNEL_MODE 1
-#define TRACE_DATA_NEWTHREAD 0x07000004
-#define TRACE_STRING_NEWTHREAD 0x07010004
-#define TRACE_STRING_EXEC 0x07010008
-
-#define INTERRUPT 0x01050000
-#define DECR_TRAP 0x01090000
-#define DECR_SET 0x01090004
-#define MACH_vmfault 0x01300008
-#define MACH_sched 0x01400000
-#define MACH_stkhandoff 0x01400008
+#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 VFS_LOOKUP 0x03010090
-#define IES_action 0x050b0018
-#define IES_filter 0x050b001c
-#define TES_action 0x050c0010
-#define CQ_action 0x050d0018
+#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_exit 0x040C0004
#define BSC_thread_terminate 0x040c05a4
#define DBG_FUNC_MASK ~(DBG_FUNC_START | DBG_FUNC_END)
#define EMPTYSTRING ""
-
const char *fault_name[] = {
"",
"ZeroFill",
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, int 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, int 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, int thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note);
+static void enter_syscall(FILE *fp, kd_buf *kd, uintptr_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, uintptr_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, uintptr_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, uintptr_t pc, int max_len, int mode);
static void create_map_entry(uintptr_t, char *);
static void check_for_thread_update(uintptr_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, double s_latency, uintptr_t thread);
-static int check_for_scheduler_latency(int type, uintptr_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, double *latency);
+static void log_scheduler(kd_buf *kd_start, kd_buf *kd_stop, kd_buf *end_of_sample, int s_priority, double s_latency, uintptr_t thread);
+static int check_for_scheduler_latency(int type, uintptr_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 *);
if (trace_enabled) {
set_enable(0);
}
- /*
+ /*
* This flag is turned off when calling
* quit() due to a set_remove() failure.
*/
set_remove();
}
}
+ endwin();
+
printf("latency: ");
if (s) {
printf("%s", s);
}
void
-set_enable(int val)
+set_enable(int val)
{
int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDENABLE, val };
size_t needed;
}
}
-void
-set_numbufs(int nbufs)
+static void
+set_numbufs(int nbufs)
{
int mib1[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETBUF, nbufs };
int mib2[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETUP };
}
}
-void
-set_pidexclude(int pid, int on_off)
+static void
+set_pidexclude(int pid, int on_off)
{
int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDPIDEX };
size_t needed = sizeof(kd_regtype);
sysctl(mib, ARRAYSIZE(mib), &kr, &needed, NULL, 0);
}
-void
+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
+static void
write_high_res_latencies(void)
{
int i;
}
}
-void
+static void
sigintr(int signo __attribute__((unused)))
{
write_high_res_latencies();
}
/* exit under normal conditions -- signal handler */
-void
+static void
leave(int signo __attribute__((unused)))
{
write_high_res_latencies();
set_pidexclude(getpid(), 0);
endwin();
set_remove();
-
+
exit(1);
}
-void
+static void
sigwinch(int signo __attribute__((unused)))
{
gotSIGWINCH = 1;
}
-void
+static void
print_total(FILE *fp, char *s, int total)
{
int cpu;
int cpu;
int clen;
int itotal, stotal;
- int elapsed_secs;
- int elapsed_mins;
- int elapsed_hours;
- int min_lat, max_lat;
+ 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;
/*
* 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 = sample_TOD_secs;
+ curr_time = (unsigned long)sample_TOD_secs;
elapsed_secs = ((last_now - first_now) / divisor) / 1000000;
} else {
elapsed_secs = curr_time - start_time;
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 (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);
}
}
min_lat = il->i_min_latency;
}
}
- clen = sprintf(tbuf, "\n\nminimum latency(usecs) %7d %9d", s_min_latency, min_lat);
+ 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], " %9d", il->i_min_latency);
+
+ clen += sprintf(&tbuf[clen], " %9ld", il->i_min_latency);
}
}
if (fp) {
max_lat = il->i_max_latency;
}
}
- clen = sprintf(tbuf, "\nmaximum latency(usecs) %7d %9d", s_max_latency, max_lat);
+ 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], " %9d", il->i_max_latency);
+
+ clen += sprintf(&tbuf[clen], " %9ld", il->i_max_latency);
}
}
if (fp) {
} else {
printw(tbuf);
}
-
+
if (s_total_samples) {
average_s_latency = (unsigned int)(s_total_latency/s_total_samples);
} else {
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 (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 {
} 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);
}
}
fprintf(fp, "%s", tbuf);
} else {
printw(tbuf);
- }
+ }
if (fp == NULL) {
refresh();
}
}
-int
+static int
exit_usage(void)
{
- fprintf(stderr, "Usage: latency [-p priority] [-h] [-m] [-st threshold] [-it threshold]\n");
- fprintf(stderr, " [-c codefile] [-l logfile] [-R rawfile] [-n kernel]\n\n");
-
- fprintf(stderr, " -p specify scheduling priority to watch... default is realtime\n");
+ fprintf(stderr, "Usage: latency [-p <priority>] [-h] [-m] [-st <threshold>] [-it <threshold>]\n");
+ fprintf(stderr, " [-c <codefile>] [-l <logfile>] [-R <rawfile>] [-n <kernel>]\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, " -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 /mach_kernel\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);
}
-
int
main(int argc, char *argv[])
{
argv++;
if (argc > 1) {
- watch_priority = atoi(argv[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], "-it") == 0) {
argc--;
argv++;
-
+
if (argc > 1) {
i_thresh_hold = atoi(argv[1]);
} else {
} else if (strcmp(argv[1], "-c") == 0) {
argc--;
argv++;
-
+
if (argc > 1) {
code_file = argv[1];
} else {
} else if (strcmp(argv[1], "-l") == 0) {
argc--;
argv++;
-
+
if (argc > 1) {
open_logfile(argv[1]);
} else {
}
}
if (kernelpath == NULL) {
- kernelpath = "/mach_kernel";
+ kernelpath = "/System/Library/Kernels/kernel.development";
}
if (code_file == NULL) {
}
}
-
-
void
read_command_map(void)
{
}
}
total_threads = header.thread_count;
-
+
sample_TOD_secs = header.TOD_secs;
sample_TOD_usecs = header.TOD_usecs;
} 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
*/
threadmap_hash[hashid] = tme;
}
-void
+static void
delete_thread_entry(uintptr_t thread)
{
threadmap_t tme;
}
}
-void
+static void
find_and_insert_tmp_map_entry(uintptr_t pthread, char *command)
{
threadmap_t tme;
}
}
-void
+static void
create_tmp_map_entry(uintptr_t thread, uintptr_t pthread)
{
threadmap_t tme;
threadmap_temp = tme;
}
-threadmap_t
+static threadmap_t
find_thread_entry(uintptr_t thread)
{
threadmap_t tme;
return 0;
}
-void
+static void
find_thread_name(uintptr_t thread, char **command)
{
threadmap_t tme;
}
}
-void
+static void
add_thread_entry_to_list(thread_entry_t *list, uintptr_t thread)
{
thread_entry_t te;
*list = te;
}
-void
+static void
exec_thread_entry(uintptr_t thread, char *command)
{
threadmap_t tme;
}
}
-void
+static void
record_thread_entry_for_gc(uintptr_t thread)
{
add_thread_entry_to_list(&thread_delete_list, thread);
}
-void
+static void
gc_thread_entries(void)
{
thread_entry_t te;
thread_delete_list = 0;
}
-void
+static void
gc_reset_entries(void)
{
thread_entry_t te;
thread_reset_list = 0;
}
-void
+static void
reset_thread_names(void)
{
thread_entry_t te;
thread_reset_list = 0;
}
-void
+static void
delete_all_thread_entries(void)
{
threadmap_t tme = 0;
}
}
-
-
-
static void
-insert_run_event(uintptr_t thread, kd_buf *kd, uint64_t now)
+insert_run_event(uintptr_t thread, int priority, kd_buf *kd, uint64_t now)
{
threadrun_t trp;
}
trp->tr_entry = kd;
trp->tr_timestamp = now;
+ trp->tr_priority = priority;
}
static threadrun_t
}
static void
-gc_run_events(void) {
+gc_run_events(void)
+{
thread_entry_t te;
thread_entry_t te_next;
threadrun_t trp;
thread_event_list = 0;
}
-int
+static int
thread_in_user_mode(uintptr_t thread, char *command)
{
event_t evp;
return 1;
}
-
-
static lookup_t
handle_lookup_event(uintptr_t thread, int debugid, kd_buf *kdp)
{
}
static void
-gc_lookup_events(void) {
+gc_lookup_events(void)
+{
thread_entry_t te;
thread_entry_t te_next;
lookup_t lkp;
{
kd_buf *kd, *end_of_sample;
int keep_going = 1;
- int count, i;
+ int i;
+ ssize_t count;
if (!RAW_flag) {
/*
need_new_map = 0;
}
if (RAW_flag) {
- uint32_t bytes_read;
+ ssize_t bytes_read;
bytes_read = read(RAW_fd, my_buffer, num_entries * sizeof(kd_buf));
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 (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);
}
} else {
double s_latency;
- if (check_for_scheduler_latency(type, &thread, now, kd, &kd_start, &s_latency)) {
- log_scheduler(kd_start, kd, end_of_sample, s_latency, thread);
+ 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);
}
}
}
return keep_going;
}
-
-
void
-enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info)
+enter_syscall(FILE *fp, kd_buf *kd, uintptr_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info)
{
char *p;
double timestamp;
pc_to_string(&pcstring[0], kd->arg2, 58, mode);
- fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2lx] @ %-58.58s %8x %2d %s\n",
+ fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2lx] @ %-58.58s %8lx %2d %s\n",
timestamp, delta, kd->arg1, &pcstring[0], thread, cpunum, command);
} else if (type == MACH_vmfault) {
- fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8x %2d %s\n",
+ fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8lx %2d %s\n",
timestamp, delta, p, thread, cpunum, command);
} else {
- fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16lx %-16lx %-16lx %-16lx %8x %2d %s\n",
- timestamp, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
thread, cpunum, command);
}
} else {
- fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8x %2d %s\n",
- timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
thread, cpunum, command);
}
}
}
}
-
void
-exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, int print_info)
+exit_syscall(FILE *fp, kd_buf *kd, uintptr_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;
if ((p = find_code(type))) {
if (type == INTERRUPT) {
- fprintf(fp, "INTERRUPT %8x %2d %s\n", thread, cpunum, command);
+ fprintf(fp, "INTERRUPT %8lx %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 %8x %2d %s\n",
+ fprintf(fp, "%-28.28s %-10.10s %-16qx %8lx %2d %s\n",
p, fault_name[kd->arg4], user_addr,
thread, cpunum, command);
} else {
- fprintf(fp, "%-28.28s %-16lx %-16lx %8x %2d %s\n",
+ fprintf(fp, "%-28.28s %-16lx %-16lx %8lx %2d %s\n",
p, kd->arg1, kd->arg2,
thread, cpunum, command);
}
} else {
- fprintf(fp, "%-8x %-16lx %-16lx %8x %2d %s\n",
+ fprintf(fp, "%-8x %-16lx %-16lx %8lx %2d %s\n",
type, kd->arg1, kd->arg2,
thread, cpunum, command);
}
}
}
-
void
-print_entry(FILE *fp, kd_buf *kd, int thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note)
+print_entry(FILE *fp, kd_buf *kd, uintptr_t thread, int type, char *command, uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd_note)
{
char *p;
} else {
fprintf(fp, "%9.1f %8.1f\t\t", timestamp, delta);
}
- fprintf(fp, "%-28.28s %-16lx %-16lx %-16lx %-16lx %8x %2d %s\n",
+ fprintf(fp, "%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
p, kd->arg1, kd->arg2, kd->arg3, kd->arg4, thread, cpunum, command);
} else {
- fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8x %2d %s\n",
- timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
+ fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
+ timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
thread, cpunum, command);
}
}
-
void
check_for_thread_update(uintptr_t thread, int debugid_base, kd_buf *kbufp, char **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;
- int reason;
+ uintptr_t reason;
char *p;
char *command;
char *command1;
double delta;
char joe[32];
- int thread = kd->arg5;
+ uintptr_t thread = kd->arg5;
int cpunum = CPU_NUMBER(kd);
int debugid = kd->debugid;
int type = kd->debugid & DBG_FUNC_MASK;
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 %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-84.84s %8lx %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 %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-83.83s %8lx %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 %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-83.83s %8lx %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 %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-83.83s %8lx %2d %s\n",
timestamp, delta, &pcstring[0], thread, cpunum, command);
break;
pc_to_string(&pcstring[0], kd->arg2, 84, mode);
- fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8lx %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 %8x %2d %s\n",
+ fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %8lx %2d %s\n",
timestamp, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command);
break;
case MACH_stkhandoff:
find_thread_name(kd->arg2, &command1);
-
+
if (command1 == EMPTYSTRING) {
command1 = command_buf;
sprintf(command1, "%-8lx", kd->arg2);
}
if (sched_reason[0] == '?') {
- sprintf(joe, "%x", reason);
+ sprintf(joe, "%lx", reason);
sched_reason = joe;
}
sprintf(sched_info, "%16.16s @ pri %3lu --> %16.16s @ pri %3lu%s", command, kd->arg3, command1, kd->arg4, p);
- fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s[%s] %s %8x %2d\n",
+ fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s[%s] %s %8lx %2d\n",
timestamp, delta, "MACH_SCHED", sched_reason, sched_info, thread, cpunum);
break;
* print the tail end of the pathname
*/
p = (char *)lkp->lk_pathname;
- int clen = strlen(p);
+ 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 %-16lx %8x %2d %s\n",
- timestamp, delta, "VFS_LOOKUP",
+
+ fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-59s %-16lx %8lx %2d %s\n",
+ timestamp, delta, "VFS_LOOKUP",
&p[clen], lkp->lk_dvp, thread, cpunum, command);
delete_lookup_event(thread, lkp);
}
}
-
-
-void
+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 start_bias = 0;
uint64_t now;
kd_buf *kd;
- int clen;
+ size_t clen;
char buf2[128];
clen = strlen(buf1);
last_timestamp = now;
} else {
int debugid = kd->debugid;
- int thread = kd->arg5;
+ uintptr_t thread = kd->arg5;
int type = kd->debugid & DBG_FUNC_MASK;
if ((type >> 24) == DBG_TRACE) {
gc_lookup_events();
}
-
kd_buf *
log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency)
{
double sample_timestamp;
char buf1[128];
- int thread = kd_beg->arg5;
+ uintptr_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 (CPU_NUMBER(kd_start) != cpunum) {
continue;
}
-
+
if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) {
break;
}
sample_timestamp = (double)(now - first_now) / divisor;
TOD_usecs = (uint64_t)sample_timestamp;
- TOD_secs = sample_TOD_secs + ((sample_TOD_usecs + TOD_usecs) / 1000000);
+ 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 {
void
-log_scheduler(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double s_latency, uintptr_t thread)
+log_scheduler(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, int s_priority, double s_latency, uintptr_t thread)
{
kd_buf *kd_start, *kd_stop;
uint64_t now;
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;
sample_timestamp = (double)(now - first_now) / divisor;
TOD_usecs = (uint64_t)sample_timestamp;
- TOD_secs = sample_TOD_secs + ((sample_TOD_usecs + TOD_usecs) / 1000000);
+ 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), watch_priority, s_latency, sample_timestamp);
+ 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]), watch_priority, s_latency, sample_generation);
+ 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, uintptr_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, double *latency)
+check_for_scheduler_latency(int type, uintptr_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 == kd->arg2) {
- insert_run_event(kd->arg1, kd, now);
+ 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;
+ threadrun_t trp = find_run_event(kd->arg2);
if (type == MACH_sched || type == MACH_stkhandoff) {
*thread = kd->arg2;
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;
}
return found_latency;
}
-
double
handle_decrementer(kd_buf *kd, int cpunum)
{
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) {
return latency;
}
-
-
char *
find_code(int type)
{
return NULL;
}
-
void
init_code_file(void)
{
fclose(fp);
}
-
void
do_kernel_nm(void)
{
- int i, len;
+ int i;
+ size_t len;
FILE *fp = NULL;
char tmp_nm_file[128];
char tmpstr[1024];
/*
* Build the nm command and create a tmp file with the output
*/
- sprintf (tmpstr, "/usr/bin/nm -f -n -s __TEXT __text %s > %s",
+ sprintf (tmpstr, "/usr/bin/nm -n %s -s __TEXT __text > %s",
kernelpath, tmp_nm_file);
system(tmpstr);
-
+
/*
* Parse the output from the nm command
*/
*/
for (i = 0; i < kern_sym_count; i++) {
if (kern_sym_tbl[i].k_sym_name) {
- printf ("[%d] %-16p %s\n", i,
+ 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,
+ printf ("[%d] %-16p %s\n", i,
kern_sym_tbl[i].k_sym_addr, "No symbol name");
}
}
pc_to_string(char *pcstring, uintptr_t pc, int max_len, int mode)
{
int ret;
- int len;
+ size_t len;
if (mode == USER_MODE) {
sprintf(pcstring, "%-16lx [usermode addr]", pc);
binary_search(kern_sym_t *list, int low, int high, uintptr_t addr)
{
int mid;
-
+
if (kern_sym_count == 0) {
return -1;
}
return -1; /* failed */
}
- if (low + 1 == high) {
+ if (low + 1 == high) {
if ((uintptr_t)list[low].k_sym_addr <= addr && addr < (uintptr_t)list[high].k_sym_addr) {
/*
* We have a range match
* Failed
*/
return -1;
- }
+ }
mid = (low + high) / 2;
if (addr < (uintptr_t)list[mid].k_sym_addr) {
return binary_search(list, mid, high, addr);
}
-
void
open_logfile(const char *path)
{
}
}
-
void
open_rawfile(const char *path)
{
}
}
-
void
getdivisor(void)
{
mach_timebase_info_data_t info;
-
+
(void)mach_timebase_info(&info);
divisor = ((double)info.denom / (double)info.numer) * 1000;
projects / apple / system_cmds.git / blobdiff