]> git.saurik.com Git - apple/system_cmds.git/blobdiff - latency.tproj/latency.c
system_cmds-433.1.tar.gz
[apple/system_cmds.git] / latency.tproj / latency.c
index fc2cf35c93cde70583d297b1ea7c63776b6c844a..d24fb577eff1f813198897abaf9c4ca6f1e67cee 100644 (file)
 
 
 /* 
-   cc -I. -DKERNEL_PRIVATE -O -o latency latency.c
+   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>
@@ -42,7 +43,7 @@
 
 #include <libc.h>
 #include <termios.h>
-#include <bsd/curses.h>
+#include <curses.h>
 #include <sys/ioctl.h>
 
 #ifndef KERNEL_PRIVATE
@@ -124,6 +125,8 @@ char       pcstring[128];
 double   divisor;
 int      gotSIGWINCH = 0;
 int      trace_enabled = 0;
+struct host_basic_info  hi;
+
 
 #define SAMPLE_SIZE 300000
 
@@ -139,15 +142,14 @@ int need_new_map = 0;
 int total_threads = 0;
 kd_threadmap *mapptr = 0;
 
-#define MAX_ENTRIES 1024
+#define MAX_ENTRIES 4096
 struct ct {
         int type;
         char name[32];
 } codes_tab[MAX_ENTRIES];
 
-/* If NUMPARMS changes from the kernel, then PATHLENGTH will also reflect the change */
+
 #define NUMPARMS 23
-#define PATHLENGTH (NUMPARMS*sizeof(long))
 
 struct th_info {
         int  thread;
@@ -156,7 +158,7 @@ struct th_info {
         int  arg1;
         double stime;
         long *pathptr;
-        char pathname[PATHLENGTH + 1];
+        long pathname[NUMPARMS + 1];
 };
 
 #define MAX_THREADS 512
@@ -171,7 +173,7 @@ int  cur_max = 0;
 #define INTERRUPT         0x01050000
 #define DECR_TRAP         0x01090000
 #define DECR_SET          0x01090004
-#define MACH_vmfault      0x01300000
+#define MACH_vmfault      0x01300008
 #define MACH_sched        0x01400000
 #define MACH_stkhandoff   0x01400008
 #define VFS_LOOKUP        0x03010090
@@ -185,6 +187,8 @@ int  cur_max = 0;
 #define DBG_FUNC_ALL   (DBG_FUNC_START | DBG_FUNC_END)
 #define DBG_FUNC_MASK  0xfffffffc
 
+#define CPU_NUMBER(ts) ((ts & KDBG_CPU_MASK) >> KDBG_CPU_SHIFT)
+
 #define DBG_ZERO_FILL_FAULT   1
 #define DBG_PAGEIN_FAULT      2
 #define DBG_COW_FAULT         3
@@ -205,6 +209,9 @@ static kern_return_t        set_standard_policy(void);
 int decrementer_val = 0;     /* Value used to reset decrementer */
 int set_remove_flag = 1;     /* By default, remove trace buffer */
 
+kd_buf **last_decrementer_kd;   /* last DECR_TRAP per cpu */
+#define MAX_LOG_COUNT  30       /* limits the number of entries dumped in log_decrementer */
+
 int
 quit(s)
 char *s;
@@ -289,7 +296,7 @@ set_pidexclude(int pid, int on_off)
        sysctl(mib, 3, &kr, &needed, NULL, 0);
 }
 
-set_rtcdec(decval)
+void set_rtcdec(decval)
 int decval;
 {kd_regtype kr;
  int ret;
@@ -306,11 +313,14 @@ int decval;
        mib[5] = 0;             /* no flags */
 
        errno = 0;
-
        if ((ret=sysctl(mib, 3, &kr, &needed, NULL, 0)) < 0)
          {
-           decrementer_val = 0;
-           quit("trace facility failure, KERN_KDSETRTCDEC\n");
+             decrementer_val = 0;
+             /* ignore this sysctl error if it's not supported */
+             if (errno == ENOENT) 
+                 return;
+             else
+                 quit("trace facility failure, KERN_KDSETRTCDEC\n");
          }
 }
 
@@ -428,33 +438,24 @@ void sigintr()
         set_enable(0);
        set_pidexclude(getpid(), 0);
         screen_update(log_fp);
+       endwin();
        set_rtcdec(0);
        set_remove();
        
         exit(1);
 }
 
-void sigquit()
-{
-        set_enable(0);
-       set_pidexclude(getpid(), 0);
-       set_rtcdec(0);
-       set_remove();
-       
-        exit(1);
-}
-
-void sigterm()
+void leave()    /* exit under normal conditions -- signal handler */
 {
         set_enable(0);
        set_pidexclude(getpid(), 0);
+       endwin();
        set_rtcdec(0);
        set_remove();
        
         exit(1);
 }
 
-
 void
 screen_update(FILE *fp)
 {
@@ -489,7 +490,7 @@ screen_update(FILE *fp)
        elapsed_secs -= elapsed_mins * 60;
 
        sprintf(tbuf, "%-19.19s                            %2ld:%02ld:%02ld\n", &(ctime(&curr_time)[0]),
-               elapsed_hours, elapsed_mins, elapsed_secs);
+               (long)elapsed_hours, (long)elapsed_mins, (long)elapsed_secs);
        if (fp)
                fprintf(fp, "%s", tbuf);
        else
@@ -662,8 +663,14 @@ exit_usage()
 {
 
         fprintf(stderr, "Usage: latency [-rt] [-c codefile] [-l logfile] [-st threshold]\n");
-       fprintf(stderr, "               [-it threshold] [-s sleep_in_usecs]\n");
+
+#if defined (__i386__)
+       fprintf(stderr, "               [-it threshold] [-s sleep_in_usecs] [-n kernel]\n\n");  
+#else
+       fprintf(stderr, "               [-it threshold] [-s sleep_in_usecs]\n");        
        fprintf(stderr, "               [-d decrementer_in_usecs] [-n kernel]\n\n");
+#endif
+
 
        fprintf(stderr, "  -rt   Set realtime scheduling policy.  Default is timeshare.\n");
        fprintf(stderr, "  -c    specify name of codes file\n");
@@ -671,7 +678,9 @@ exit_usage()
        fprintf(stderr, "  -st   set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n");
        fprintf(stderr, "  -it   set interrupt latency threshold in microseconds... if latency exceeds this, then log trace\n");
        fprintf(stderr, "  -s    set sleep time in microseconds\n");
+#if !defined (__i386__)        
        fprintf(stderr, "  -d    set decrementer in microseconds.\n");
+#endif
        fprintf(stderr, "  -n    specify kernel, default is /mach_kernel\n");   
 
        fprintf(stderr, "\nlatency must be run as root\n\n");
@@ -680,12 +689,11 @@ exit_usage()
 }
 
 
-
+int
 main(argc, argv)
 int  argc;
 char *argv[];
 {
-        mach_timespec_t remain;
        uint64_t start, stop;
        uint64_t timestamp1;
        uint64_t timestamp2;
@@ -695,6 +703,9 @@ char *argv[];
        double   nanosecs_to_sleep;
        int      loop_cnt, sample_sc_now;
        int      decrementer_usec = 0;
+        kern_return_t           ret;
+        unsigned int            size;
+        host_name_port_t        host;
        void     getdivisor();
        void     sample_sc();
        void     init_code_file();
@@ -751,7 +762,8 @@ char *argv[];
                          num_of_usecs_to_sleep = atoi(argv[1]);
                        else
                          exit_usage();
-               } else if (strcmp(argv[1], "-d") == 0) {
+               }
+               else if (strcmp(argv[1], "-d") == 0) {
                        argc--;
                        argv++;
 
@@ -759,7 +771,12 @@ char *argv[];
                          decrementer_usec = atoi(argv[1]);
                        else
                          exit_usage();
-               } else if (strcmp(argv[1], "-n") == 0) {
+#if defined(__i386__)
+                       /* ignore this option - setting the decrementer has no effect */
+                       decrementer_usec = 0;
+#endif                 
+               }
+               else if (strcmp(argv[1], "-n") == 0) {
                        argc--;
                        argv++;
 
@@ -792,6 +809,18 @@ char *argv[];
        getdivisor();
        decrementer_val = decrementer_usec * divisor;
 
+       /* get the cpu countfor the DECR_TRAP array */
+        host = mach_host_self();
+       size = sizeof(hi)/sizeof(int);
+        ret = host_info(host, HOST_BASIC_INFO, (host_info_t)&hi, &size);
+        if (ret != KERN_SUCCESS) {
+            mach_error(argv[0], ret);
+            exit(EXIT_FAILURE);
+       }
+
+       if ((last_decrementer_kd = (kd_buf **)malloc(hi.avail_cpus * sizeof(kd_buf *))) == (kd_buf **)0)
+               quit("can't allocate memory for decrementer tracing info\n");
+
        nanosecs_to_sleep = (double)(num_of_usecs_to_sleep * 1000);
        fdelay = nanosecs_to_sleep * (divisor /1000);
        adelay = (uint64_t)fdelay;
@@ -805,13 +834,19 @@ char *argv[];
        */
        set_rtcdec(decrementer_val);
 
-       initscr();
+       if (initscr() == (WINDOW *) 0)
+         {
+           printf("Unrecognized TERM type, try vt100\n");
+           exit(1);
+         }
+
        clear();
        refresh();
        signal(SIGWINCH, sigwinch);
        signal(SIGINT, sigintr);
-       signal(SIGQUIT, sigquit);
-       signal(SIGTERM, sigterm);
+       signal(SIGQUIT, leave);
+       signal(SIGTERM, leave);
+       signal(SIGHUP, leave);
 
 
        if ((my_buffer = malloc(SAMPLE_SIZE * sizeof(kd_buf))) == (char *)0)
@@ -861,7 +896,7 @@ char *argv[];
 
                timestamp1 = mach_absolute_time();
                adeadline = timestamp1 + adelay;
-               mk_wait_until(adeadline);
+               mach_wait_until(adeadline);
                timestamp2 = mach_absolute_time();
 
                start = timestamp1;
@@ -904,7 +939,11 @@ char *argv[];
                        }
                }
                if (gotSIGWINCH) {
-                       initscr();
+                       /*
+                         No need to check for initscr error return.
+                         We won't get here if it fails on the first call.
+                       */
+                       endwin();
                        clear();
                        refresh();
 
@@ -982,7 +1021,7 @@ void read_command_map()
     size = bufinfo.nkdthreads * sizeof(kd_threadmap);
     if (size)
     {
-        if (mapptr = (kd_threadmap *) malloc(size))
+        if ((mapptr = (kd_threadmap *) malloc(size)))
             bzero (mapptr, size);
        else
        {
@@ -1091,7 +1130,7 @@ kill_thread_map(int thread)
 {
     kd_threadmap *map;
 
-    if (map = find_thread_map(thread)) {
+    if ((map = find_thread_map(thread))) {
 
 #if 0
       if (log_fp)
@@ -1135,12 +1174,15 @@ char *find_code(type)
 
 void sample_sc(uint64_t start, uint64_t stop)
 {
-       kd_buf   *kd, *last_mach_sched, *last_decrementer_kd, *start_kd, *end_of_sample;
+       kd_buf   *kd, *last_mach_sched, *start_kd, *end_of_sample;
        uint64_t now;
-       int count;
+       int count, i;
        int first_entry = 1;
+       double timestamp = 0.0;
+       double last_timestamp = 0.0;
+       double delta = 0.0;
+       double start_bias = 0.0;        
        char   command[32];
-       double timestamp, last_timestamp, delta, start_bias;
        void read_command_map();
 
        if (log_fp && (my_policy == THREAD_TIME_CONSTRAINT_POLICY))
@@ -1171,12 +1213,10 @@ void sample_sc(uint64_t start, uint64_t stop)
        count = needed;
 
        if (bufinfo.flags & KDBG_WRAPPED) {
-               int i;
-
                for (i = 0; i < cur_max; i++) {
                        th_state[i].thread = 0;
                        th_state[i].type = -1;
-                       th_state[i].pathptr = (long *)0;
+                       th_state[i].pathptr = (long *)NULL;
                        th_state[i].pathname[0] = 0;
                }
                cur_max = 0;
@@ -1196,7 +1236,11 @@ void sample_sc(uint64_t start, uint64_t stop)
                }
        }
        end_of_sample = &((kd_buf *)my_buffer)[count];
-       last_decrementer_kd = (kd_buf *)my_buffer;
+
+       /* Always reinitialize the DECR_TRAP array */
+       for (i=0; i < hi.avail_cpus; i++)
+             last_decrementer_kd[i] = (kd_buf *)my_buffer;
+
        last_mach_sched = (kd_buf *)0;
 
        for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) {
@@ -1205,7 +1249,8 @@ void sample_sc(uint64_t start, uint64_t stop)
                int len;
                char *p;
                long *sargptr;
-               double i_latency;
+               kd_buf *cur_kd;
+               double i_latency = 0.0;
                struct th_info *ti;
                char   command1[32];
                char   sched_info[64];
@@ -1218,8 +1263,8 @@ void sample_sc(uint64_t start, uint64_t stop)
                void exit_syscall();
                void print_entry();
 
-               thread  = kd->arg5 & KDBG_THREAD_MASK;
-               cpunum =  (kd->arg5 & KDBG_CPU_MASK) ? 1: 0;
+               thread  = kd->arg5;
+               cpunum  = CPU_NUMBER(kd->timestamp);
                debugid = kd->debugid;
                type    = kd->debugid & DBG_FUNC_MASK;
 
@@ -1229,8 +1274,7 @@ void sample_sc(uint64_t start, uint64_t stop)
                if (type == DECR_TRAP)
                        i_latency = handle_decrementer(kd);
 
-               now = (((uint64_t)kd->timestamp.tv_sec) << 32) |
-                       (uint64_t)((unsigned int)(kd->timestamp.tv_nsec));
+               now = kd->timestamp & KDBG_TIMESTAMP_MASK;
 
                timestamp = ((double)now) / divisor;
 
@@ -1240,21 +1284,27 @@ void sample_sc(uint64_t start, uint64_t stop)
                        else if (debugid & DBG_FUNC_END)
                                exit_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 0);
                        else if (type == DECR_TRAP) {
+                               cur_kd = kd;
                                if (log_fp && i_thresh_hold && (int)i_latency > i_thresh_hold) {
-                                       start_kd = last_decrementer_kd;
+                                       start_kd = last_decrementer_kd[cpunum];
                                        kd = log_decrementer(start_kd, kd, end_of_sample, i_latency);
-
                                        if (kd >= end_of_sample)
                                                break;
                                }
-                               last_decrementer_kd = kd;
+                               if ((kd->debugid & DBG_FUNC_MASK) == DECR_TRAP)
+                                 {
+                                   cpunum = CPU_NUMBER(kd->timestamp);
+                                   last_decrementer_kd[cpunum] = kd;
+                                 }
+                               else
+                                 last_decrementer_kd[cpunum] = cur_kd;
                        }
                        continue;
                }
                if (first_entry) {
                        double latency;
-                       char buf1[128];
-                       char buf2[128];
+                       char buf1[132];
+                       char buf2[132];
 
                        latency = (double)(stop - start) / divisor;
                        latency -= (double)num_of_usecs_to_sleep;
@@ -1280,7 +1330,7 @@ void sample_sc(uint64_t start, uint64_t stop)
                }
                delta = timestamp - last_timestamp;
 
-               if (map = find_thread_map(thread))
+               if ((map = find_thread_map(thread)))
                        strcpy(command, map->command);
                else
                        command[0] = 0;
@@ -1323,7 +1373,7 @@ void sample_sc(uint64_t start, uint64_t stop)
                    break;
 
                case DECR_TRAP:
-                   last_decrementer_kd = kd;
+                   last_decrementer_kd[cpunum] = kd;
 
                    if (i_thresh_hold && (int)i_latency > i_thresh_hold)
                            p = "*";
@@ -1332,7 +1382,7 @@ void sample_sc(uint64_t start, uint64_t stop)
 
                    mode = 1;
 
-                   if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) {
+                   if ((ti = find_thread(kd->arg5, 0, 0))) {
                            if (ti->type == -1 && strcmp(command, "kernel_task"))
                                    mode = 0;
                    }
@@ -1358,12 +1408,12 @@ void sample_sc(uint64_t start, uint64_t stop)
                case MACH_stkhandoff:
                    last_mach_sched = kd;
 
-                   if (map = find_thread_map(kd->arg2))
+                   if ((map = find_thread_map(kd->arg2)))
                            strcpy(command1, map->command);
                    else
                            sprintf(command1, "%-8x", kd->arg2);
 
-                   if (ti = find_thread(kd->arg2, 0, 0)) {
+                   if ((ti = find_thread(kd->arg2, 0, 0))) {
                            if (ti->type == -1 && strcmp(command1, "kernel_task"))
                                    p = "U";
                            else
@@ -1401,17 +1451,22 @@ void sample_sc(uint64_t start, uint64_t stop)
                            ti->pathptr = (long *)0;
                            ti->child_thread = 0;
                    }
-                   if (!ti->pathptr) {
+                   while ( (kd < end_of_sample) && ((kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP))
+                     {
+                       if (ti->pathptr == NULL) {
                            ti->arg1 = kd->arg1;
-                           memset(&ti->pathname[0], 0, (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 {
+                       } else {
                            sargptr = ti->pathptr;
 
                            /*
@@ -1420,28 +1475,56 @@ void sample_sc(uint64_t start, uint64_t stop)
                                handle.
                            */
 
-                            if ((long *)sargptr < (long *)&ti->pathname[PATHLENGTH])
+                            if (sargptr >= &ti->pathname[NUMPARMS])
+                             {
+                               kd++;
+                               continue;
+                             }
+
+                            /*
+                              We need to detect consecutive vfslookup entries.
+                              So, if we get here and find a START entry,
+                              fake the pathptr so we can bypass all further
+                              vfslookup entries.
+                           */
+
+                            if (kd->debugid & DBG_FUNC_START)
+                              {
+                                ti->pathptr = &ti->pathname[NUMPARMS];
+                              }
+                           else
                              {
                                *sargptr++ = kd->arg1;
                                *sargptr++ = kd->arg2;
                                *sargptr++ = kd->arg3;
                                *sargptr++ = kd->arg4;
+                               /*
+                                * NULL terminate the 'string'
+                                */
+                               *sargptr = 0;
+
                                ti->pathptr = sargptr;
+                             }
+                       }
+                       kd++;
+                   }
+                   p = (char *)ti->pathname;
 
-                               /* print the tail end of the pathname */
-                               len = strlen(ti->pathname);
-                               if (len > 28)
-                                 len -= 28;
-                               else
-                                 len = 0;
+                   kd--;
+
+                   /* print the tail end of the pathname */
+                   len = strlen(p);
+                   if (len > 42)
+                     len -= 42;
+                   else
+                     len = 0;
                            
-                               if (log_fp) {
-                                 fprintf(log_fp, "%9.1f %8.1f\t\t%-28.28s %-28s    %-8x   %-8x  %d  %s\n",
-                                         timestamp - start_bias, delta, "VFS_LOOKUP", 
-                                         &ti->pathname[len], ti->arg1, thread, cpunum, command);
-                               }
-                           }
+                   if (log_fp) {
+                     fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s    %-8x   %-8x  %d  %s\n",
+                             timestamp - start_bias, delta, "VFS_LOOKUP", 
+                             &p[len], ti->arg1, thread, cpunum, command);
                    }
+
                    last_timestamp = timestamp;
                    break;
 
@@ -1482,14 +1565,14 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double
        int    cpunum;
        char  *p;
 
-       cpunum =  (kd->arg5 & KDBG_CPU_MASK) ? 1: 0;
+       cpunum = CPU_NUMBER(kd->timestamp);
 
        if (print_info && fp) {
-              if (p = find_code(type)) {
+              if ((p = find_code(type))) {
                       if (type == INTERRUPT) {
                               int mode = 1;
 
-                              if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) {
+                              if ((ti = find_thread(kd->arg5, 0, 0))) {
                                       if (ti->type == -1 && strcmp(command, "kernel_task"))
                                               mode = 0;
                               }
@@ -1536,7 +1619,7 @@ enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double
        else
               ti->type = -1;
        ti->stime  = timestamp;
-       ti->pathptr = (long *)0;
+       ti->pathptr = (long *)NULL;
 
 #if 0
        if (print_info && fp)
@@ -1551,8 +1634,10 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t
        struct th_info *ti;
        int    cpunum;
        char   *p;
+       uint64_t user_addr;
+
+       cpunum = CPU_NUMBER(kd->timestamp);
 
-       cpunum =  (kd->arg5 & KDBG_CPU_MASK) ? 1: 0;
        ti = find_thread(thread, type, type);
 #if 0
        if (print_info && fp)
@@ -1564,12 +1649,14 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t
               else
                       fprintf(fp, "%9.1f %8.1f()      \t", timestamp - bias, delta);
 
-              if (p = find_code(type)) {
+              if ((p = find_code(type))) {
                       if (type == INTERRUPT) {
                               fprintf(fp, "INTERRUPT                                                               %-8x  %d  %s\n", thread, cpunum, command);
-                      } else if (type == MACH_vmfault && kd->arg2 <= DBG_CACHE_HIT_FAULT) {
-                              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_CACHE_HIT_FAULT) {
+                              user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2;
+
+                              fprintf(fp, "%-28.28s %-8.8s   %-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",
@@ -1590,7 +1677,7 @@ exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double t
 
                       ti->thread = thread;
                       ti->child_thread = 0;
-                      ti->pathptr = (long *)0;
+                      ti->pathptr = (long *)NULL;
               }
        }
        ti->type = -1;
@@ -1605,12 +1692,11 @@ print_entry(FILE *fp, kd_buf *kd, int thread, int type, char *command, double ti
        if (!fp)
         return;
 
-       cpunum =  (kd->arg5 & KDBG_CPU_MASK) ? 1: 0;
-
+       cpunum = CPU_NUMBER(kd->timestamp);
 #if 0
        fprintf(fp, "cur_max = %d, type = %x,  thread = %x, cpunum = %d\n", cur_max, type, thread, cpunum);
 #endif
-       if (p = find_code(type)) {
+       if ((p = find_code(type))) {
               fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-8x   %-8x   %-8x  %-8x   %-8x  %d  %s\n",
                       timestamp - bias, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4, 
                       thread, cpunum, command);
@@ -1637,7 +1723,7 @@ check_for_thread_update(int thread, int type, kd_buf *kd)
 
                    ti->thread = thread;
                    ti->type   = -1;
-                   ti->pathptr = (long *)0;
+                   ti->pathptr = (long *)NULL;
            }
            ti->child_thread = kd->arg1;
            return (1);
@@ -1664,7 +1750,11 @@ check_for_thread_update(int thread, int type, kd_buf *kd)
 kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency)
 {
         kd_buf *kd, *kd_start, *kd_stop;
-       double timestamp, last_timestamp, delta, start_bias;
+       int kd_count;     /* Limit the boundary of kd_start */
+       double timestamp = 0.0;
+       double last_timestamp = 0.0;
+       double delta = 0.0;
+       double start_bias = 0.0;
        int thread, cpunum;
        int debugid, type, clen;
        int len;
@@ -1689,30 +1779,50 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
 
        fprintf(log_fp, "RelTime(Us)  Delta              debugid                      arg1       arg2       arg3      arg4       thread   cpu   command\n\n");
 
-       thread = kd_beg->arg5 & KDBG_THREAD_MASK;
+       thread = kd_beg->arg5;
+       cpunum = CPU_NUMBER(kd_end->timestamp);
+
+       for (kd_count = 0, kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer); kd_start--, kd_count++) {
+               if (kd_count == MAX_LOG_COUNT)
+                       break;
 
-       for (kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer) && (kd_start->arg5 & KDBG_THREAD_MASK) == thread; kd_start--) {
-               if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP)
+               if (CPU_NUMBER(kd_start->timestamp) != cpunum)
+                       continue;
+                                                                                    
+               if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP)
+                       break;
+
+               if (kd_start->arg5 != thread)
                        break;
        }
+
        if (kd_start < (kd_buf *)my_buffer)
                kd_start = (kd_buf *)my_buffer;
 
-       for (kd_stop = kd_end + 1; kd_stop < end_of_sample && (kd_start->arg5 & KDBG_THREAD_MASK) == thread; kd_stop++) {
-               if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP)
+       thread = kd_end->arg5;
+
+       for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
+                                                                                    
+               if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP)
+                       break;
+
+               if (CPU_NUMBER(kd_stop->timestamp) != cpunum)
+                       continue;
+
+               if (kd_stop->arg5 != thread)
                        break;
        }
+
        if (kd_stop >= end_of_sample)
                kd_stop = end_of_sample - 1;
 
-       now = (((uint64_t)kd_start->timestamp.tv_sec) << 32) |
-               (uint64_t)((unsigned int)(kd_start->timestamp.tv_nsec));
+       now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
        timestamp = ((double)now) / divisor;
 
        for (kd = kd_start; kd <= kd_stop; kd++) {
                type = kd->debugid & DBG_FUNC_MASK;
 
-               if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), type, type)) {
+               if ((ti = find_thread(kd->arg5, type, type))) {
                        if (ti->stime >= timestamp)
                                ti->type = -1;
                }
@@ -1720,13 +1830,12 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
        for (kd = kd_start; kd <= kd_stop; kd++) {
                int    mode;
 
-               thread  = kd->arg5 & KDBG_THREAD_MASK;
-               cpunum =  (kd->arg5 & KDBG_CPU_MASK) ? 1: 0;
+               thread  = kd->arg5;
+               cpunum  = CPU_NUMBER(kd->timestamp);
                debugid = kd->debugid;
                type    = kd->debugid & DBG_FUNC_MASK;
 
-               now = (((uint64_t)kd->timestamp.tv_sec) << 32) |
-                       (uint64_t)((unsigned int)(kd->timestamp.tv_nsec));
+               now = kd->timestamp & KDBG_TIMESTAMP_MASK;
 
                timestamp = ((double)now) / divisor;
 
@@ -1736,7 +1845,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
                }
                delta = timestamp - last_timestamp;
 
-               if (map = find_thread_map(thread))
+               if ((map = find_thread_map(thread)))
                        strcpy(command, map->command);
                else
                        command[0] = 0;
@@ -1764,7 +1873,7 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
 
                    mode = 1;
 
-                   if (ti = find_thread((kd->arg5 & KDBG_THREAD_MASK), 0, 0)) {
+                   if ((ti = find_thread(kd->arg5, 0, 0))) {
                            if (ti->type == -1 && strcmp(command, "kernel_task"))
                                    mode = 0;
                    }
@@ -1784,12 +1893,12 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
 
                case MACH_sched:
                case MACH_stkhandoff:
-                   if (map = find_thread_map(kd->arg2))
+                   if ((map = find_thread_map(kd->arg2)))
                            strcpy(command1, map->command);
                    else
                            sprintf(command1, "%-8x", kd->arg2);
 
-                   if (ti = find_thread(kd->arg2, 0, 0)) {
+                   if ((ti = find_thread(kd->arg2, 0, 0))) {
                            if (ti->type == -1 && strcmp(command1, "kernel_task"))
                                    p = "U";
                            else
@@ -1822,20 +1931,27 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
 
                            ti->thread = thread;
                            ti->type   = -1;
-                           ti->pathptr = (long *)0;
+                           ti->pathptr = (long *)NULL;
                            ti->child_thread = 0;
                    }
-                   if (!ti->pathptr) {
+
+                   while ( (kd <= kd_stop) && (kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP)
+                     {
+                       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 {
+                       } else {
                            sargptr = ti->pathptr;
 
                            /*
@@ -1844,25 +1960,53 @@ kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, d
                                handle.
                            */
 
-                            if ((long *)sargptr < (long *)&ti->pathname[PATHLENGTH])
+                            if (sargptr >= &ti->pathname[NUMPARMS])
+                             {
+                               kd++;
+                               continue;
+                             }
+
+                            /*
+                              We need to detect consecutive vfslookup entries.
+                              So, if we get here and find a START entry,
+                              fake the pathptr so we can bypass all further
+                              vfslookup entries.
+                           */
+
+                            if (kd->debugid & DBG_FUNC_START)
+                              {
+                                ti->pathptr = &ti->pathname[NUMPARMS];
+                              }
+                           else
                              {
                                *sargptr++ = kd->arg1;
                                *sargptr++ = kd->arg2;
                                *sargptr++ = kd->arg3;
                                *sargptr++ = kd->arg4;
+                               /*
+                                * NULL terminate the 'string'
+                                */
+                               *sargptr = 0;
 
-                               /* print the tail end of the pathname */
-                               len = strlen(ti->pathname);
-                               if (len > 28)
-                                 len -= 28;
-                               else
-                                 len = 0;
-                           
-                               fprintf(log_fp, "%9.1f %8.1f\t\t%-28.28s %-28s    %-8x   %-8x  %d  %s\n",
-                                       timestamp - start_bias, delta, "VFS_LOOKUP", 
-                                       &ti->pathname[len], ti->arg1, thread, cpunum, command);
+                               ti->pathptr = sargptr;
                              }
+                       }
+                       kd++;
                    }
+                   p = (char *)ti->pathname;
+
+                   kd--;
+                   /* print the tail end of the pathname */
+                   len = strlen(p);
+                   if (len > 42)
+                     len -= 42;
+                   else
+                     len = 0;
+                   
+                   fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s    %-8x   %-8x  %d  %s\n",
+                           timestamp - start_bias, delta, "VFS_LOOKUP", 
+                           &p[len], ti->arg1, thread, cpunum, command);
+
                    last_timestamp = timestamp;
                    break;
 
@@ -1936,7 +2080,7 @@ void init_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 != 2)
                        break;
@@ -1957,13 +2101,17 @@ do_kernel_nm()
   FILE *fp = (FILE *)0;
   char tmp_nm_file[128];
   char tmpstr[1024];
-  int inchr;
+  char inchr;
 
   bzero(tmp_nm_file, 128);
   bzero(tmpstr, 1024);
 
   /* 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",
@@ -2009,7 +2157,7 @@ do_kernel_nm()
   for (i=0; i<kern_sym_count; i++)
     {
       bzero(tmpstr, 1024);
-      if (fscanf(fp, "%x %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3)
+      if (fscanf(fp, "%lx %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3)
        break;
       else
        {
@@ -2091,7 +2239,7 @@ pc_to_string(unsigned int pc, int max_len, int mode)
            len = max_len - 8;
 
       memcpy(pcstring, kern_sym_tbl[ret].k_sym_name, len);
-      sprintf(&pcstring[len], "+0x%-5x", pc - kern_sym_tbl[ret].k_sym_addr);
+      sprintf(&pcstring[len], "+0x%-5lx", pc - kern_sym_tbl[ret].k_sym_addr);
 
       return (pcstring);
     }