*
* @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 <mach/mach.h>
#include <stdlib.h>
#include <stdio.h>
+#include <unistd.h>
#include <signal.h>
#include <strings.h>
#include <nlist.h>
#include <sys/kdebug.h>
#endif /*KERNEL_PRIVATE*/
+#include <libutil.h>
+
#include <sys/sysctl.h>
#include <errno.h>
#include <err.h>
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;
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
#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
#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();
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;i<N_HIGH_RES_BINS;i++)
+ {
+ fprintf(f,"%d,%d\n", i, i_high_res_bins[i]);
+ }
+ fclose(f);
+ }
+}
void sigwinch()
{
{
void screen_update();
+ write_high_res_latencies();
+
set_enable(0);
set_pidexclude(getpid(), 0);
screen_update(log_fp);
void leave() /* exit under normal conditions -- signal handler */
{
+ write_high_res_latencies();
+
set_enable(0);
set_pidexclude(getpid(), 0);
endwin();
else
printw(tbuf);
+ if (use_high_res_bins) {
+ sprintf(tbuf, "INTERRUPTS(HIGH RESOLUTION)\n");
+ if (fp)
+ fprintf(fp, "%s", tbuf);
+ else
+ printw(tbuf);
+ }
+ if(use_high_res_bins)
+ {
+ for(i=0;i<N_HIGH_RES_BINS;i++) {
+ if(i && !(i%10)) {
+ sprintf(tbuf,"\n");
+ if (fp)
+ fprintf(fp, "%s", tbuf);
+ else
+ printw(tbuf);
+ }
+#define INDEX(i) ((i%10)*50 + (i/10))
+ if(INDEX(i) <= i_highest_latency)
+ sprintf(tbuf,"[%3d]: %6d ", INDEX(i), i_high_res_bins[INDEX(i)]);
+ else
+ tbuf[0] = '\0';
+
+ if (fp)
+ fprintf(fp, "%s", tbuf);
+ else
+ printw(tbuf);
+ }
+ sprintf(tbuf,"\n\n");
+ if (fp)
+ fprintf(fp, "%s", tbuf);
+ else
+ printw(tbuf);
+ }
sprintf(tbuf, " SCHEDULER INTERRUPTS\n");
exit_usage()
{
- fprintf(stderr, "Usage: latency [-rt] [-c codefile] [-l logfile] [-st threshold]\n");
+ fprintf(stderr, "Usage: latency [-rt] [-h] [-c codefile] [-l logfile] [-st threshold]\n");
#if defined (__i386__)
fprintf(stderr, " [-it threshold] [-s sleep_in_usecs] [-n kernel]\n\n");
fprintf(stderr, " -rt Set realtime scheduling policy. Default is timeshare.\n");
+ fprintf(stderr, " -h Display high resolution interrupt latencies and write them to latencies.csv (truncate existing file) upon exit.\n");
fprintf(stderr, " -c specify name of codes file\n");
fprintf(stderr, " -l specify name of file to log trace entries to when threshold is exceeded\n");
fprintf(stderr, " -st set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n");
int
-main(argc, argv)
-int argc;
-char *argv[];
+main(int argc, char *argv[])
{
uint64_t start, stop;
uint64_t timestamp1;
int loop_cnt, sample_sc_now;
int decrementer_usec = 0;
kern_return_t ret;
- int size;
+ unsigned int size;
host_name_port_t host;
void getdivisor();
void sample_sc();
void init_code_file();
void do_kernel_nm();
void open_logfile();
- void mk_wait_until();
+
+ if (0 != reexec_to_match_kernel()) {
+ fprintf(stderr, "Could not re-execute: %d\n", errno);
+ exit(1);
+ }
my_policy = THREAD_STANDARD_POLICY;
policy_name = "TIMESHARE";
kernelpath = argv[1];
else
exit_usage();
+ } else if (strcmp(argv[1], "-h") == 0) {
+ use_high_res_bins = true;
} else
exit_usage();
exit(EXIT_FAILURE);
}
- if ((last_decrementer_kd = (kd_buf **)malloc(hi.avail_cpus * sizeof(kd_buf *))) == (kd_buf **)0)
+ if ((last_decrementer_kd = (kd_buf **)malloc(hi.max_cpus * sizeof(kd_buf *))) == (kd_buf **)0)
quit("can't allocate memory for decrementer tracing info\n");
nanosecs_to_sleep = (double)(num_of_usecs_to_sleep * 1000);
timestamp1 = mach_absolute_time();
adeadline = timestamp1 + adelay;
- mk_wait_until(adeadline);
+ mach_wait_until(adeadline);
timestamp2 = mach_absolute_time();
start = timestamp1;
}
-void create_map_entry(int thread, char *command)
+void create_map_entry(uintptr_t thread, char *command)
{
int i, n;
kd_threadmap *map;
}
-kd_threadmap *find_thread_map(int thread)
+kd_threadmap *find_thread_map(uintptr_t thread)
{
int i;
kd_threadmap *map;
}
void
-kill_thread_map(int thread)
+kill_thread_map(uintptr_t thread)
{
kd_threadmap *map;
}
-struct th_info *find_thread(int thread, int type1, int type2) {
+struct th_info *find_thread(uintptr_t thread, int type1, int type2) {
struct th_info *ti;
for (ti = th_state; ti < &th_state[cur_max]; ti++) {
for (i = 0; i < cur_max; i++) {
th_state[i].thread = 0;
th_state[i].type = -1;
- th_state[i].pathptr = (long *)0;
+ th_state[i].pathptr = (long *)NULL;
th_state[i].pathname[0] = 0;
}
cur_max = 0;
end_of_sample = &((kd_buf *)my_buffer)[count];
/* Always reinitialize the DECR_TRAP array */
- for (i=0; i < hi.avail_cpus; i++)
+ for (i=0; i < hi.max_cpus; i++)
last_decrementer_kd[i] = (kd_buf *)my_buffer;
last_mach_sched = (kd_buf *)0;
void print_entry();
thread = kd->arg5;
- cpunum = CPU_NUMBER(kd->timestamp);
+ cpunum = CPU_NUMBER(kd);
debugid = kd->debugid;
type = kd->debugid & DBG_FUNC_MASK;
}
if ((kd->debugid & DBG_FUNC_MASK) == DECR_TRAP)
{
- cpunum = CPU_NUMBER(kd->timestamp);
+ cpunum = CPU_NUMBER(kd);
last_decrementer_kd[cpunum] = kd;
}
else
}
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 {
handle.
*/
- if ((long *)sargptr >= (long *)&ti->pathname[PATHLENGTH])
+ if (sargptr >= &ti->pathname[NUMPARMS])
{
kd++;
continue;
if (kd->debugid & DBG_FUNC_START)
{
- (long *)ti->pathptr = (long *)&ti->pathname[PATHLENGTH];
+ ti->pathptr = &ti->pathname[NUMPARMS];
}
else
{
*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
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;
int cpunum;
char *p;
- cpunum = CPU_NUMBER(kd->timestamp);
+ cpunum = CPU_NUMBER(kd);
if (print_info && fp) {
if ((p = find_code(type))) {
else
ti->type = -1;
ti->stime = timestamp;
- ti->pathptr = (long *)0;
+ ti->pathptr = (long *)NULL;
#if 0
if (print_info && fp)
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
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",
ti->thread = thread;
ti->child_thread = 0;
- ti->pathptr = (long *)0;
+ ti->pathptr = (long *)NULL;
}
}
ti->type = -1;
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
ti->thread = thread;
ti->type = -1;
- ti->pathptr = (long *)0;
+ ti->pathptr = (long *)NULL;
}
ti->child_thread = kd->arg1;
return (1);
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)
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)
int mode;
thread = kd->arg5;
- cpunum = CPU_NUMBER(kd->timestamp);
+ cpunum = CPU_NUMBER(kd);
debugid = kd->debugid;
type = kd->debugid & DBG_FUNC_MASK;
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 {
handle.
*/
- if ((long *)sargptr >= (long *)&ti->pathname[PATHLENGTH])
+ if (sargptr >= &ti->pathname[NUMPARMS])
{
kd++;
continue;
if (kd->debugid & DBG_FUNC_START)
{
- (long *)ti->pathptr = (long *)&ti->pathname[PATHLENGTH];
+ ti->pathptr = &ti->pathname[NUMPARMS];
}
else
{
*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
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;
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]++;
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)
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) {
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;
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",
projects / apple / system_cmds.git / blobdiff