]> git.saurik.com Git - apple/system_cmds.git/blob - latency.tproj/latency.c
projects / apple / system_cmds.git / blob
? search:


8047b2d84d46e651dd3bccaa060517b0d61c4175
[apple/system_cmds.git] / latency.tproj / latency.c
1 /*
2 * Copyright (c) 1999-2016 Apple Inc. All rights reserved.
3 *
4 * @APPLE_LICENSE_HEADER_START@
5 *
6 * This file contains Original Code and/or Modifications of Original Code
7 * as defined in and that are subject to the Apple Public Source License
8 * Version 2.0 (the 'License'). You may not use this file except in
9 * compliance with the License. Please obtain a copy of the License at
10 * http://www.opensource.apple.com/apsl/ and read it before using this
11 * file.
12 *
13 * The Original Code and all software distributed under the License are
14 * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
15 * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
16 * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
17 * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
18 * Please see the License for the specific language governing rights and
19 * limitations under the License.
20 *
21 * @APPLE_LICENSE_HEADER_END@
22 */
23
24 /*
25 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
26 */
27
28 #include <mach/mach.h>
29 #include <stdlib.h>
30 #include <stdio.h>
31 #include <unistd.h>
32 #include <signal.h>
33 #include <strings.h>
34 #include <nlist.h>
35 #include <fcntl.h>
36 #include <string.h>
37 #include <libc.h>
38 #include <termios.h>
39 #include <curses.h>
40 #include <libutil.h>
41 #include <errno.h>
42 #include <err.h>
43
44 #include <sys/types.h>
45 #include <sys/param.h>
46 #include <sys/time.h>
47 #include <sys/sysctl.h>
48 #include <sys/ioctl.h>
49
50 #ifndef KERNEL_PRIVATE
51 #define KERNEL_PRIVATE
52 #include <sys/kdebug.h>
53 #undef KERNEL_PRIVATE
54 #else
55 #include <sys/kdebug.h>
56 #endif /*KERNEL_PRIVATE*/
57
58 #include <mach/mach_error.h>
59 #include <mach/mach_types.h>
60 #include <mach/message.h>
61 #include <mach/mach_syscalls.h>
62 #include <mach/clock_types.h>
63 #include <mach/mach_time.h>
64
65 #include <libkern/OSTypes.h>
66
67
68 int s_usec_10_bins[10];
69 int s_usec_100_bins[10];
70 int s_msec_1_bins[10];
71 int s_msec_10_bins[5];
72 int s_too_slow;
73 int s_max_latency;
74 int s_min_latency = 0;
75 long long s_total_latency = 0;
76 int s_total_samples = 0;
77 long s_thresh_hold;
78 int s_exceeded_threshold = 0;
79
80
81 #define N_HIGH_RES_BINS 500
82 int use_high_res_bins = false;
83
84 struct i_latencies {
85 int i_usec_10_bins[10];
86 int i_usec_100_bins[10];
87 int i_msec_1_bins[10];
88 int i_msec_10_bins[5];
89 int i_too_slow;
90 long i_max_latency;
91 long i_min_latency;
92 int i_total_samples;
93 int i_total;
94 int i_exceeded_threshold;
95 uint64_t i_total_latency;
96 };
97
98 struct i_latencies *i_lat;
99 boolean_t i_latency_per_cpu = FALSE;
100
101 int i_high_res_bins[N_HIGH_RES_BINS];
102
103 long i_thresh_hold;
104
105 int watch_priority_min = 97;
106 int watch_priority_max = 97;
107
108 long start_time;
109 long curr_time;
110 long refresh_time;
111
112
113 char *kernelpath = NULL;
114
115 typedef struct {
116 void *k_sym_addr; /* kernel symbol address from nm */
117 size_t k_sym_len; /* length of kernel symbol string */
118 char *k_sym_name; /* kernel symbol string from nm */
119 } kern_sym_t;
120
121 kern_sym_t *kern_sym_tbl; /* pointer to the nm table */
122 int kern_sym_count; /* number of entries in nm table */
123
124
125
126 #define MAX_ENTRIES 4096
127 struct ct {
128 int type;
129 char name[32];
130 } codes_tab[MAX_ENTRIES];
131
132 char *code_file = NULL;
133 int num_of_codes = 0;
134
135
136 double divisor;
137 sig_atomic_t gotSIGWINCH = 0;
138 int trace_enabled = 0;
139 int need_new_map = 1;
140 int set_remove_flag = 1; /* By default, remove trace buffer */
141
142 int RAW_flag = 0;
143 int RAW_fd = 0;
144
145 uint64_t first_now = 0;
146 uint64_t last_now = 0;
147 int first_read = 1;
148
149
150 #define SAMPLE_TIME_USECS 50000
151 #define SAMPLE_SIZE 300000
152 #define MAX_LOG_COUNT 30 /* limits the number of entries dumped in log_decrementer */
153
154 kbufinfo_t bufinfo = {0, 0, 0};
155
156 FILE *log_fp = NULL;
157
158 uint64_t sample_TOD_secs;
159 uint32_t sample_TOD_usecs;
160
161 uint64_t cpu_mask;
162
163 int sample_generation = 0;
164 int num_i_latency_cpus = 1;
165 int num_cpus;
166 void *my_buffer;
167 int num_entries;
168
169 kd_buf **last_decrementer_kd; /* last DECR_TRAP per cpu */
170
171
172 #define NUMPARMS 23
173
174 typedef struct event *event_t;
175
176 struct event {
177 event_t ev_next;
178
179 uintptr_t ev_thread;
180 uint32_t ev_type;
181 uint64_t ev_timestamp;
182 };
183
184
185 typedef struct lookup *lookup_t;
186
187 struct lookup {
188 lookup_t lk_next;
189
190 uintptr_t lk_thread;
191 uintptr_t lk_dvp;
192 long *lk_pathptr;
193 long lk_pathname[NUMPARMS + 1];
194 };
195
196
197 typedef struct threadmap *threadmap_t;
198
199 struct threadmap {
200 threadmap_t tm_next;
201
202 uintptr_t tm_thread;
203 uintptr_t tm_pthread;
204 char tm_command[MAXCOMLEN + 1];
205 char tm_orig_command[MAXCOMLEN + 1];
206 };
207
208
209 typedef struct threadrun *threadrun_t;
210
211 struct threadrun {
212 threadrun_t tr_next;
213
214 uintptr_t tr_thread;
215 kd_buf *tr_entry;
216 uint64_t tr_timestamp;
217 int tr_priority;
218 };
219
220
221 typedef struct thread_entry *thread_entry_t;
222
223 struct thread_entry {
224 thread_entry_t te_next;
225
226 uintptr_t te_thread;
227 };
228
229 #define HASH_SIZE 1024
230 #define HASH_MASK 1023
231
232 event_t event_hash[HASH_SIZE];
233 lookup_t lookup_hash[HASH_SIZE];
234 threadmap_t threadmap_hash[HASH_SIZE];
235 threadrun_t threadrun_hash[HASH_SIZE];
236
237 event_t event_freelist;
238 lookup_t lookup_freelist;
239 threadrun_t threadrun_freelist;
240 threadmap_t threadmap_freelist;
241 threadmap_t threadmap_temp;
242
243 thread_entry_t thread_entry_freelist;
244 thread_entry_t thread_delete_list;
245 thread_entry_t thread_reset_list;
246 thread_entry_t thread_event_list;
247 thread_entry_t thread_lookup_list;
248 thread_entry_t thread_run_list;
249
250
251 #ifndef RAW_VERSION1
252 typedef struct {
253 int version_no;
254 int thread_count;
255 uint64_t TOD_secs;
256 uint32_t TOD_usecs;
257 } RAW_header;
258
259 #define RAW_VERSION0 0x55aa0000
260 #define RAW_VERSION1 0x55aa0101
261 #endif
262
263
264 #define USER_MODE 0
265 #define KERNEL_MODE 1
266
267
268 #define INTERRUPT 0x01050000
269 #define DECR_TRAP 0x01090000
270 #define DECR_SET 0x01090004
271 #define MACH_vmfault 0x01300008
272 #define MACH_sched 0x01400000
273 #define MACH_stkhandoff 0x01400008
274 #define MACH_makerunnable 0x01400018
275 #define MACH_idle 0x01400024
276 #define IES_action 0x050b0018
277 #define IES_filter 0x050b001c
278 #define TES_action 0x050c0010
279 #define CQ_action 0x050d0018
280 #define CPUPM_CPUSTER_RUNCOUNT 0x05310144
281
282 #define BSC_exit 0x040C0004
283 #define BSC_thread_terminate 0x040c05a4
284
285 #define DBG_FUNC_MASK ~(DBG_FUNC_START | DBG_FUNC_END)
286
287 #define CPU_NUMBER(kp) kdbg_get_cpu(kp)
288
289 #define EMPTYSTRING ""
290
291 const char *fault_name[] = {
292 "",
293 "ZeroFill",
294 "PageIn",
295 "COW",
296 "CacheHit",
297 "NoZeroFill",
298 "Guard",
299 "PageInFile",
300 "PageInAnon"
301 };
302
303 const char *sched_reasons[] = {
304 "N",
305 "P",
306 "Q",
307 "?",
308 "u",
309 "U",
310 "?",
311 "?",
312 "H",
313 "?",
314 "?",
315 "?",
316 "?",
317 "?",
318 "?",
319 "?",
320 "Y"
321 };
322
323 #define ARRAYSIZE(x) ((int)(sizeof(x) / sizeof(*x)))
324 #define MAX_REASON ARRAYSIZE(sched_reasons)
325
326 static double handle_decrementer(kd_buf *, int);
327 static kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency);
328 static void read_command_map(void);
329 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);
330 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);
331 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);
332 static void log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note);
333 static char *find_code(int);
334 static void pc_to_string(char *pcstring, uintptr_t pc, int max_len, int mode);
335 static void getdivisor(void);
336 static int sample_sc(void);
337 static void init_code_file(void);
338 static void do_kernel_nm(void);
339 static void open_logfile(const char*);
340 static int binary_search(kern_sym_t *list, int low, int high, uintptr_t addr);
341
342 static void create_map_entry(uintptr_t, char *);
343 static void check_for_thread_update(uintptr_t thread, int debugid_base, kd_buf *kbufp, char **command);
344 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);
345 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);
346 static void open_rawfile(const char *path);
347
348 static void screen_update(FILE *);
349
350 static void set_enable(int);
351 static void set_remove(void);
352
353 static int
354 quit(char *s)
355 {
356 if (!RAW_flag) {
357 if (trace_enabled) {
358 set_enable(0);
359 }
360 /*
361 * This flag is turned off when calling
362 * quit() due to a set_remove() failure.
363 */
364 if (set_remove_flag) {
365 set_remove();
366 }
367 }
368 printf("latency: ");
369 if (s) {
370 printf("%s", s);
371 }
372 exit(1);
373 }
374
375 void
376 set_enable(int val)
377 {
378 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDENABLE, val };
379 size_t needed;
380
381 if (sysctl(mib, ARRAYSIZE(mib), NULL, &needed, NULL, 0) < 0) {
382 quit("trace facility failure, KERN_KDENABLE\n");
383 }
384 }
385
386 static void
387 set_numbufs(int nbufs)
388 {
389 int mib1[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETBUF, nbufs };
390 int mib2[] = { CTL_KERN, KERN_KDEBUG, KERN_KDSETUP };
391 size_t needed;
392
393 if (sysctl(mib1, ARRAYSIZE(mib1), NULL, &needed, NULL, 0) < 0) {
394 quit("trace facility failure, KERN_KDSETBUF\n");
395 }
396 if (sysctl(mib2, ARRAYSIZE(mib2), NULL, &needed, NULL, 0) < 0) {
397 quit("trace facility failure, KERN_KDSETUP\n");
398 }
399 }
400
401 static void
402 set_pidexclude(int pid, int on_off)
403 {
404 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDPIDEX };
405 size_t needed = sizeof(kd_regtype);
406
407 kd_regtype kr = {
408 .type = KDBG_TYPENONE,
409 .value1 = pid,
410 .value2 = on_off
411 };
412
413 sysctl(mib, ARRAYSIZE(mib), &kr, &needed, NULL, 0);
414 }
415
416 static void
417 get_bufinfo(kbufinfo_t *val)
418 {
419 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDGETBUF };
420 size_t needed = sizeof (*val);
421
422 if (sysctl(mib, ARRAYSIZE(mib), val, &needed, 0, 0) < 0) {
423 quit("trace facility failure, KERN_KDGETBUF\n");
424 }
425 }
426
427 void
428 set_remove(void)
429 {
430 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREMOVE };
431 size_t needed;
432
433 errno = 0;
434
435 if (sysctl(mib, ARRAYSIZE(mib), NULL, &needed, NULL, 0) < 0) {
436 set_remove_flag = 0;
437 if (errno == EBUSY) {
438 quit("the trace facility is currently in use...\n fs_usage, sc_usage, and latency use this feature.\n\n");
439 } else {
440 quit("trace facility failure, KERN_KDREMOVE\n");
441 }
442 }
443 }
444
445
446 static void
447 write_high_res_latencies(void)
448 {
449 int i;
450 FILE *f;
451
452 if (use_high_res_bins) {
453 if ((f = fopen("latencies.csv","w"))) {
454 for (i = 0; i < N_HIGH_RES_BINS; i++) {
455 fprintf(f, "%d,%d\n", i, i_high_res_bins[i]);
456 }
457 fclose(f);
458 }
459 }
460 }
461
462 static void
463 sigintr(int signo __attribute__((unused)))
464 {
465 write_high_res_latencies();
466
467 set_enable(0);
468 set_pidexclude(getpid(), 0);
469 screen_update(log_fp);
470 endwin();
471 set_remove();
472
473 exit(1);
474 }
475
476 /* exit under normal conditions -- signal handler */
477 static void
478 leave(int signo __attribute__((unused)))
479 {
480 write_high_res_latencies();
481
482 set_enable(0);
483 set_pidexclude(getpid(), 0);
484 endwin();
485 set_remove();
486
487 exit(1);
488 }
489
490 static void
491 sigwinch(int signo __attribute__((unused)))
492 {
493 gotSIGWINCH = 1;
494 }
495
496 static void
497 print_total(FILE *fp, char *s, int total)
498 {
499 int cpu;
500 int clen;
501 int itotal;
502 struct i_latencies *il;
503 char tbuf[512];
504
505 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
506 il = &i_lat[cpu];
507 itotal += il->i_total;
508 }
509 clen = sprintf(tbuf, "%s %10d %9d", s, total, itotal);
510
511 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
512 il = &i_lat[cpu];
513
514 if (i_latency_per_cpu == TRUE) {
515 clen += sprintf(&tbuf[clen], " %9d", il->i_total);
516 }
517
518 il->i_total = 0;
519 }
520 sprintf(&tbuf[clen], "\n");
521 if (fp) {
522 fprintf(fp, "%s", tbuf);
523 } else {
524 printw(tbuf);
525 }
526 }
527
528
529
530 void
531 screen_update(FILE *fp)
532 {
533 int i;
534 int cpu;
535 int clen;
536 int itotal, stotal;
537 long elapsed_secs;
538 long elapsed_mins;
539 long elapsed_hours;
540 long min_lat, max_lat;
541 uint64_t tot_lat;
542 unsigned int average_s_latency;
543 unsigned int average_i_latency;
544 struct i_latencies *il;
545 char tbuf[1024];
546
547 if (fp == NULL) {
548 erase();
549 move(0, 0);
550 } else {
551 fprintf(fp,"\n\n===================================================================================================\n");
552 }
553 /*
554 * Display the current time.
555 * "ctime" always returns a string that looks like this:
556 *
557 * Sun Sep 16 01:03:52 1973
558 * 012345678901234567890123
559 * 1 2
560 *
561 * We want indices 11 thru 18 (length 8).
562 */
563 if (RAW_flag) {
564 curr_time = (unsigned long)sample_TOD_secs;
565 elapsed_secs = ((last_now - first_now) / divisor) / 1000000;
566 } else {
567 elapsed_secs = curr_time - start_time;
568 }
569
570 elapsed_hours = elapsed_secs / 3600;
571 elapsed_secs -= elapsed_hours * 3600;
572 elapsed_mins = elapsed_secs / 60;
573 elapsed_secs -= elapsed_mins * 60;
574
575 sprintf(tbuf, "%-19.19s %2ld:%02ld:%02ld\n", &(ctime(&curr_time)[0]),
576 (long)elapsed_hours, (long)elapsed_mins, (long)elapsed_secs);
577 if (fp) {
578 fprintf(fp, "%s", tbuf);
579 } else {
580 printw(tbuf);
581 }
582
583 sprintf(tbuf, " SCHEDULER INTERRUPTS\n");
584 if (fp) {
585 fprintf(fp, "%s", tbuf);
586 } else {
587 printw(tbuf);
588 }
589
590 if (i_latency_per_cpu == TRUE) {
591 clen = sprintf(tbuf, " Total");
592
593 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
594 if (cpu <= 9) {
595 clen += sprintf(&tbuf[clen], " CPU %d", cpu);
596 } else {
597 clen += sprintf(&tbuf[clen], " CPU %d", cpu);
598 }
599 }
600 if (fp) {
601 fprintf(fp, "%s", tbuf);
602 } else {
603 printw(tbuf);
604 }
605
606 clen = sprintf(tbuf, "\n-------------------------------------------------------");
607
608 for (cpu = 1; cpu < num_i_latency_cpus; cpu++) {
609 clen += sprintf(&tbuf[clen], "----------");
610 }
611 if (fp) {
612 fprintf(fp, "%s", tbuf);
613 } else {
614 printw(tbuf);
615 }
616 } else {
617 sprintf(tbuf, "---------------------------------------------");
618 if (fp) {
619 fprintf(fp, "%s", tbuf);
620 } else {
621 printw(tbuf);
622 }
623 }
624 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
625 il = &i_lat[cpu];
626 itotal += il->i_total_samples;
627 }
628 clen = sprintf(tbuf, "\ntotal_samples %10d %9d", s_total_samples, itotal);
629
630 if (i_latency_per_cpu == TRUE) {
631 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
632 il = &i_lat[cpu];
633
634 clen += sprintf(&tbuf[clen], " %9d", il->i_total_samples);
635 }
636 }
637 sprintf(&tbuf[clen], "\n");
638 if (fp) {
639 fprintf(fp, "%s", tbuf);
640 } else {
641 printw(tbuf);
642 }
643
644
645 for (stotal = 0, i = 0; i < 10; i++) {
646 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
647 il = &i_lat[cpu];
648
649 itotal += il->i_usec_10_bins[i];
650 il->i_total += il->i_usec_10_bins[i];
651 }
652 clen = sprintf(tbuf, "\ndelays < %3d usecs %10d %9d", (i + 1) * 10, s_usec_10_bins[i], itotal);
653
654 stotal += s_usec_10_bins[i];
655
656 if (i_latency_per_cpu == TRUE) {
657 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
658 il = &i_lat[cpu];
659
660 clen += sprintf(&tbuf[clen], " %9d", il->i_usec_10_bins[i]);
661 }
662 }
663 if (fp) {
664 fprintf(fp, "%s", tbuf);
665 } else {
666 printw(tbuf);
667 }
668 }
669 print_total(fp, "\ntotal < 100 usecs", stotal);
670
671 for (stotal = 0, i = 1; i < 10; i++) {
672 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
673 il = &i_lat[cpu];
674
675 itotal += il->i_usec_100_bins[i];
676 il->i_total += il->i_usec_100_bins[i];
677 }
678 if (i < 9) {
679 clen = sprintf(tbuf, "\ndelays < %3d usecs %10d %9d", (i + 1) * 100, s_usec_100_bins[i], itotal);
680 } else {
681 clen = sprintf(tbuf, "\ndelays < 1 msec %10d %9d", s_usec_100_bins[i], itotal);
682 }
683
684 stotal += s_usec_100_bins[i];
685
686 if (i_latency_per_cpu == TRUE) {
687 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
688 il = &i_lat[cpu];
689
690 clen += sprintf(&tbuf[clen], " %9d", il->i_usec_100_bins[i]);
691 }
692 }
693 if (fp) {
694 fprintf(fp, "%s", tbuf);
695 } else {
696 printw(tbuf);
697 }
698 }
699 print_total(fp, "\ntotal < 1 msec ", stotal);
700
701
702 for (stotal = 0, i = 1; i < 10; i++) {
703 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
704 il = &i_lat[cpu];
705
706 itotal += il->i_msec_1_bins[i];
707 il->i_total += il->i_msec_1_bins[i];
708 }
709 clen = sprintf(tbuf, "\ndelays < %3d msecs %10d %9d", (i + 1), s_msec_1_bins[i], itotal);
710
711 stotal += s_msec_1_bins[i];
712
713 if (i_latency_per_cpu == TRUE) {
714 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
715 il = &i_lat[cpu];
716
717 clen += sprintf(&tbuf[clen], " %9d", il->i_msec_1_bins[i]);
718 }
719 }
720 if (fp) {
721 fprintf(fp, "%s", tbuf);
722 } else {
723 printw(tbuf);
724 }
725 }
726 print_total(fp, "\ntotal < 10 msecs", stotal);
727
728 for (stotal = 0, i = 1; i < 5; i++) {
729 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
730 il = &i_lat[cpu];
731
732 itotal += il->i_msec_10_bins[i];
733 il->i_total += il->i_msec_10_bins[i];
734 }
735 clen = sprintf(tbuf, "\ndelays < %3d msecs %10d %9d", (i + 1)*10, s_msec_10_bins[i], itotal);
736
737 stotal += s_msec_10_bins[i];
738
739 if (i_latency_per_cpu == TRUE) {
740 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
741 il = &i_lat[cpu];
742
743 clen += sprintf(&tbuf[clen], " %9d", il->i_msec_10_bins[i]);
744 }
745 }
746 if (fp) {
747 fprintf(fp, "%s", tbuf);
748 } else {
749 printw(tbuf);
750 }
751 }
752 print_total(fp, "\ntotal < 50 msecs", stotal);
753
754
755 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
756 il = &i_lat[cpu];
757 itotal += il->i_too_slow;
758 }
759 clen = sprintf(tbuf, "\ndelays > 50 msecs %10d %9d", s_too_slow, itotal);
760
761 if (i_latency_per_cpu == TRUE) {
762 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
763 il = &i_lat[cpu];
764
765 clen += sprintf(&tbuf[clen], " %9d", il->i_too_slow);
766 }
767 }
768 if (fp) {
769 fprintf(fp, "%s", tbuf);
770 } else {
771 printw(tbuf);
772 }
773
774 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
775 il = &i_lat[cpu];
776
777 if (cpu == 0 || (il->i_min_latency < min_lat)) {
778 min_lat = il->i_min_latency;
779 }
780 }
781 clen = sprintf(tbuf, "\n\nminimum latency(usecs) %7d %9ld", s_min_latency, min_lat);
782
783 if (i_latency_per_cpu == TRUE) {
784 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
785 il = &i_lat[cpu];
786
787 clen += sprintf(&tbuf[clen], " %9ld", il->i_min_latency);
788 }
789 }
790 if (fp) {
791 fprintf(fp, "%s", tbuf);
792 } else {
793 printw(tbuf);
794 }
795
796
797 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
798 il = &i_lat[cpu];
799
800 if (cpu == 0 || (il->i_max_latency > max_lat)) {
801 max_lat = il->i_max_latency;
802 }
803 }
804 clen = sprintf(tbuf, "\nmaximum latency(usecs) %7d %9ld", s_max_latency, max_lat);
805
806 if (i_latency_per_cpu == TRUE) {
807 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
808 il = &i_lat[cpu];
809
810 clen += sprintf(&tbuf[clen], " %9ld", il->i_max_latency);
811 }
812 }
813 if (fp) {
814 fprintf(fp, "%s", tbuf);
815 } else {
816 printw(tbuf);
817 }
818
819 if (s_total_samples) {
820 average_s_latency = (unsigned int)(s_total_latency/s_total_samples);
821 } else {
822 average_s_latency = 0;
823 }
824
825 for (itotal = 0, tot_lat = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
826 il = &i_lat[cpu];
827
828 itotal += il->i_total_samples;
829 tot_lat += il->i_total_latency;
830 }
831 if (itotal) {
832 average_i_latency = (unsigned)(tot_lat/itotal);
833 } else {
834 average_i_latency = 0;
835 }
836
837 clen = sprintf(tbuf, "\naverage latency(usecs) %7d %9d", average_s_latency, average_i_latency);
838
839 if (i_latency_per_cpu == TRUE) {
840 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
841 il = &i_lat[cpu];
842
843 if (il->i_total_samples) {
844 average_i_latency = (unsigned int)(il->i_total_latency/il->i_total_samples);
845 } else {
846 average_i_latency = 0;
847 }
848
849 clen += sprintf(&tbuf[clen], " %9d", average_i_latency);
850 }
851 }
852 if (fp) {
853 fprintf(fp, "%s", tbuf);
854 } else {
855 printw(tbuf);
856 }
857
858 for (itotal = 0, cpu = 0; cpu < num_i_latency_cpus; cpu++) {
859 il = &i_lat[cpu];
860
861 itotal += il->i_exceeded_threshold;
862 }
863 clen = sprintf(tbuf, "\nexceeded threshold %7d %9d", s_exceeded_threshold, itotal);
864
865 if (i_latency_per_cpu == TRUE) {
866 for (cpu = 0; cpu < num_i_latency_cpus; cpu++) {
867 il = &i_lat[cpu];
868
869 clen += sprintf(&tbuf[clen], " %9d", il->i_exceeded_threshold);
870 }
871 }
872 sprintf(&tbuf[clen], "\n");
873
874 if (fp) {
875 fprintf(fp, "%s", tbuf);
876 } else {
877 printw(tbuf);
878 }
879
880 if (fp == NULL) {
881 refresh();
882 } else {
883 fflush(fp);
884 }
885 }
886
887 static int
888 exit_usage(void)
889 {
890 fprintf(stderr, "Usage: latency [-p <priority>] [-h] [-m] [-st <threshold>] [-it <threshold>]\n");
891 fprintf(stderr, " [-c <codefile>] [-l <logfile>] [-R <rawfile>] [-n <kernel>]\n\n");
892
893 fprintf(stderr, " -p specify scheduling priority to watch... default is realtime. Can also be a range, e.g. \"31-47\".\n");
894 fprintf(stderr, " -h Display high resolution interrupt latencies and write them to latencies.csv (truncate existing file) upon exit.\n");
895 fprintf(stderr, " -st set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n");
896 fprintf(stderr, " -m specify per-CPU interrupt latency reporting\n");
897 fprintf(stderr, " -it set interrupt latency threshold in microseconds... if latency exceeds this, then log trace\n");
898 fprintf(stderr, " -c specify name of codes file... default is /usr/share/misc/trace.codes\n");
899 fprintf(stderr, " -l specify name of file to log trace entries to when the specified threshold is exceeded\n");
900 fprintf(stderr, " -R specify name of raw trace file to process\n");
901 fprintf(stderr, " -n specify kernel... default is /System/Library/Kernels/kernel.development\n");
902
903 fprintf(stderr, "\nlatency must be run as root\n\n");
904
905 exit(1);
906 }
907
908 int
909 main(int argc, char *argv[])
910 {
911 int i;
912
913 if (0 != reexec_to_match_kernel()) {
914 fprintf(stderr, "Could not re-execute: %d\n", errno);
915 exit(1);
916 }
917 while (argc > 1) {
918
919 if (strcmp(argv[1], "-R") == 0) {
920 argc--;
921 argv++;
922
923 if (argc > 1) {
924 open_rawfile(argv[1]);
925 } else {
926 exit_usage();
927 }
928
929 RAW_flag = 1;
930
931 } else if (strcmp(argv[1], "-p") == 0) {
932 argc--;
933 argv++;
934
935 if (argc > 1) {
936 if (2 == sscanf(argv[1], "%d-%d", &watch_priority_min, &watch_priority_max)) {
937 if (watch_priority_min > watch_priority_max) {
938 exit_usage();
939 } else if (watch_priority_min < 0) {
940 exit_usage();
941 }
942 } else {
943 if (1 == sscanf(argv[1], "%d", &watch_priority_min)) {
944 watch_priority_max = watch_priority_min;
945 } else {
946 exit_usage();
947 }
948 }
949 } else {
950 exit_usage();
951 }
952 } else if (strcmp(argv[1], "-st") == 0) {
953 argc--;
954 argv++;
955
956 if (argc > 1) {
957 s_thresh_hold = atoi(argv[1]);
958 } else {
959 exit_usage();
960 }
961 } else if (strcmp(argv[1], "-it") == 0) {
962 argc--;
963 argv++;
964
965 if (argc > 1) {
966 i_thresh_hold = atoi(argv[1]);
967 } else {
968 exit_usage();
969 }
970 } else if (strcmp(argv[1], "-c") == 0) {
971 argc--;
972 argv++;
973
974 if (argc > 1) {
975 code_file = argv[1];
976 } else {
977 exit_usage();
978 }
979 } else if (strcmp(argv[1], "-l") == 0) {
980 argc--;
981 argv++;
982
983 if (argc > 1) {
984 open_logfile(argv[1]);
985 } else {
986 exit_usage();
987 }
988 } else if (strcmp(argv[1], "-n") == 0) {
989 argc--;
990 argv++;
991
992 if (argc > 1) {
993 kernelpath = argv[1];
994 } else {
995 exit_usage();
996 }
997 } else if (strcmp(argv[1], "-h") == 0) {
998 use_high_res_bins = TRUE;
999
1000 } else if (strcmp(argv[1], "-m") == 0) {
1001 i_latency_per_cpu = TRUE;
1002
1003 } else {
1004 exit_usage();
1005 }
1006
1007 argc--;
1008 argv++;
1009 }
1010 if (!RAW_flag) {
1011 if (geteuid() != 0) {
1012 printf("'latency' must be run as root...\n");
1013 exit(1);
1014 }
1015 }
1016 if (kernelpath == NULL) {
1017 kernelpath = "/System/Library/Kernels/kernel.development";
1018 }
1019
1020 if (code_file == NULL) {
1021 code_file = "/usr/share/misc/trace.codes";
1022 }
1023
1024 do_kernel_nm();
1025
1026 getdivisor();
1027
1028 init_code_file();
1029
1030 if (!RAW_flag) {
1031 if (initscr() == NULL) {
1032 printf("Unrecognized TERM type, try vt100\n");
1033 exit(1);
1034 }
1035 clear();
1036 refresh();
1037
1038 signal(SIGWINCH, sigwinch);
1039 signal(SIGINT, sigintr);
1040 signal(SIGQUIT, leave);
1041 signal(SIGTERM, leave);
1042 signal(SIGHUP, leave);
1043
1044 /*
1045 * grab the number of cpus and scale the buffer size
1046 */
1047 int mib[] = { CTL_HW, HW_NCPU };
1048 size_t len = sizeof(num_cpus);
1049
1050 sysctl(mib, ARRAYSIZE(mib), &num_cpus, &len, NULL, 0);
1051
1052 set_remove();
1053 set_numbufs(SAMPLE_SIZE * num_cpus);
1054
1055 get_bufinfo(&bufinfo);
1056
1057 set_enable(0);
1058
1059 set_pidexclude(getpid(), 1);
1060 set_enable(1);
1061
1062 num_entries = bufinfo.nkdbufs;
1063 } else {
1064 num_entries = 50000;
1065 num_cpus = 128;
1066 }
1067
1068 for (cpu_mask = 0, i = 0; i < num_cpus; i++)
1069 cpu_mask |= ((uint64_t)1 << i);
1070
1071 if ((my_buffer = malloc(num_entries * sizeof(kd_buf))) == NULL) {
1072 quit("can't allocate memory for tracing info\n");
1073 }
1074
1075 if ((last_decrementer_kd = (kd_buf **)malloc(num_cpus * sizeof(kd_buf *))) == NULL) {
1076 quit("can't allocate memory for decrementer tracing info\n");
1077 }
1078
1079 if (i_latency_per_cpu == FALSE) {
1080 num_i_latency_cpus = 1;
1081 } else {
1082 num_i_latency_cpus = num_cpus;
1083 }
1084
1085 if ((i_lat = (struct i_latencies *)malloc(num_i_latency_cpus * sizeof(struct i_latencies))) == NULL) {
1086 quit("can't allocate memory for interrupt latency info\n");
1087 }
1088
1089 bzero((char *)i_lat, num_i_latency_cpus * sizeof(struct i_latencies));
1090
1091 if (RAW_flag) {
1092 while (sample_sc()) {
1093 continue;
1094 }
1095
1096 if (log_fp) {
1097 screen_update(log_fp);
1098 }
1099
1100 screen_update(stdout);
1101
1102 } else {
1103 uint64_t adelay;
1104 double fdelay;
1105 double nanosecs_to_sleep;
1106
1107 nanosecs_to_sleep = (double)(SAMPLE_TIME_USECS * 1000);
1108 fdelay = nanosecs_to_sleep * (divisor /1000);
1109 adelay = (uint64_t)fdelay;
1110
1111 trace_enabled = 1;
1112
1113 start_time = time(NULL);
1114 refresh_time = start_time;
1115
1116 for (;;) {
1117 curr_time = time(NULL);
1118
1119 if (curr_time >= refresh_time) {
1120 screen_update(NULL);
1121 refresh_time = curr_time + 1;
1122 }
1123 mach_wait_until(mach_absolute_time() + adelay);
1124
1125 sample_sc();
1126
1127 if (gotSIGWINCH) {
1128 /*
1129 * No need to check for initscr error return.
1130 * We won't get here if it fails on the first call.
1131 */
1132 endwin();
1133 clear();
1134 refresh();
1135
1136 gotSIGWINCH = 0;
1137 }
1138 }
1139 }
1140 }
1141
1142 void
1143 read_command_map(void)
1144 {
1145 kd_threadmap *mapptr = 0;
1146 int total_threads = 0;
1147 size_t size;
1148 off_t offset;
1149 int i;
1150 RAW_header header = {0};
1151
1152 if (RAW_flag) {
1153 if (read(RAW_fd, &header, sizeof(RAW_header)) != sizeof(RAW_header)) {
1154 perror("read failed");
1155 exit(2);
1156 }
1157 if (header.version_no != RAW_VERSION1) {
1158 header.version_no = RAW_VERSION0;
1159 header.TOD_secs = time(NULL);
1160 header.TOD_usecs = 0;
1161
1162 lseek(RAW_fd, (off_t)0, SEEK_SET);
1163
1164 if (read(RAW_fd, &header.thread_count, sizeof(int)) != sizeof(int)) {
1165 perror("read failed");
1166 exit(2);
1167 }
1168 }
1169 total_threads = header.thread_count;
1170
1171 sample_TOD_secs = header.TOD_secs;
1172 sample_TOD_usecs = header.TOD_usecs;
1173
1174 if (total_threads == 0 && header.version_no != RAW_VERSION0) {
1175 offset = lseek(RAW_fd, (off_t)0, SEEK_CUR);
1176 offset = (offset + (4095)) & ~4095;
1177
1178 lseek(RAW_fd, offset, SEEK_SET);
1179 }
1180 } else {
1181 total_threads = bufinfo.nkdthreads;
1182 }
1183
1184 size = total_threads * sizeof(kd_threadmap);
1185
1186 if (size == 0 || ((mapptr = (kd_threadmap *) malloc(size)) == 0)) {
1187 return;
1188 }
1189 bzero (mapptr, size);
1190
1191 /*
1192 * Now read the threadmap
1193 */
1194 if (RAW_flag) {
1195 if (read(RAW_fd, mapptr, size) != size) {
1196 printf("Can't read the thread map -- this is not fatal\n");
1197 }
1198 if (header.version_no != RAW_VERSION0) {
1199 offset = lseek(RAW_fd, (off_t)0, SEEK_CUR);
1200 offset = (offset + (4095)) & ~4095;
1201
1202 lseek(RAW_fd, offset, SEEK_SET);
1203 }
1204 } else {
1205 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDTHRMAP};
1206 if (sysctl(mib, ARRAYSIZE(mib), mapptr, &size, NULL, 0) < 0) {
1207 /*
1208 * This is not fatal -- just means I cant map command strings
1209 */
1210 printf("Can't read the thread map -- this is not fatal\n");
1211
1212 total_threads = 0;
1213 }
1214 }
1215 for (i = 0; i < total_threads; i++) {
1216 create_map_entry(mapptr[i].thread, &mapptr[i].command[0]);
1217 }
1218 free(mapptr);
1219 }
1220
1221 void
1222 create_map_entry(uintptr_t thread, char *command)
1223 {
1224 threadmap_t tme;
1225
1226 if ((tme = threadmap_freelist)) {
1227 threadmap_freelist = tme->tm_next;
1228 } else {
1229 tme = (threadmap_t)malloc(sizeof(struct threadmap));
1230 }
1231
1232 tme->tm_thread = thread;
1233
1234 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1235 tme->tm_command[MAXCOMLEN] = '\0';
1236 tme->tm_orig_command[0] = '\0';
1237
1238 int hashid = thread & HASH_MASK;
1239
1240 tme->tm_next = threadmap_hash[hashid];
1241 threadmap_hash[hashid] = tme;
1242 }
1243
1244 static void
1245 delete_thread_entry(uintptr_t thread)
1246 {
1247 threadmap_t tme;
1248
1249 int hashid = thread & HASH_MASK;
1250
1251 if ((tme = threadmap_hash[hashid])) {
1252 if (tme->tm_thread == thread) {
1253 threadmap_hash[hashid] = tme->tm_next;
1254 } else {
1255 threadmap_t tme_prev = tme;
1256
1257 for (tme = tme->tm_next; tme; tme = tme->tm_next) {
1258 if (tme->tm_thread == thread) {
1259 tme_prev->tm_next = tme->tm_next;
1260 break;
1261 }
1262 tme_prev = tme;
1263 }
1264 }
1265 if (tme) {
1266 tme->tm_next = threadmap_freelist;
1267 threadmap_freelist = tme;
1268 }
1269 }
1270 }
1271
1272 static void
1273 find_and_insert_tmp_map_entry(uintptr_t pthread, char *command)
1274 {
1275 threadmap_t tme;
1276
1277 if ((tme = threadmap_temp)) {
1278 if (tme->tm_pthread == pthread) {
1279 threadmap_temp = tme->tm_next;
1280 } else {
1281 threadmap_t tme_prev = tme;
1282
1283 for (tme = tme->tm_next; tme; tme = tme->tm_next) {
1284 if (tme->tm_pthread == pthread) {
1285 tme_prev->tm_next = tme->tm_next;
1286 break;
1287 }
1288 tme_prev = tme;
1289 }
1290 }
1291 if (tme) {
1292 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1293 tme->tm_command[MAXCOMLEN] = '\0';
1294 tme->tm_orig_command[0] = '\0';
1295
1296 int hashid = tme->tm_thread & HASH_MASK;
1297 tme->tm_next = threadmap_hash[hashid];
1298 threadmap_hash[hashid] = tme;
1299 }
1300 }
1301 }
1302
1303 static void
1304 create_tmp_map_entry(uintptr_t thread, uintptr_t pthread)
1305 {
1306 threadmap_t tme;
1307
1308 if ((tme = threadmap_freelist)) {
1309 threadmap_freelist = tme->tm_next;
1310 } else {
1311 tme = malloc(sizeof(struct threadmap));
1312 }
1313
1314 tme->tm_thread = thread;
1315 tme->tm_pthread = pthread;
1316 tme->tm_command[0] = '\0';
1317 tme->tm_orig_command[0] = '\0';
1318
1319 tme->tm_next = threadmap_temp;
1320 threadmap_temp = tme;
1321 }
1322
1323 static threadmap_t
1324 find_thread_entry(uintptr_t thread)
1325 {
1326 threadmap_t tme;
1327
1328 int hashid = thread & HASH_MASK;
1329
1330 for (tme = threadmap_hash[hashid]; tme; tme = tme->tm_next) {
1331 if (tme->tm_thread == thread) {
1332 return tme;
1333 }
1334 }
1335 return 0;
1336 }
1337
1338 static void
1339 find_thread_name(uintptr_t thread, char **command)
1340 {
1341 threadmap_t tme;
1342
1343 if ((tme = find_thread_entry(thread))) {
1344 *command = tme->tm_command;
1345 } else {
1346 *command = EMPTYSTRING;
1347 }
1348 }
1349
1350 static void
1351 add_thread_entry_to_list(thread_entry_t *list, uintptr_t thread)
1352 {
1353 thread_entry_t te;
1354
1355 if ((te = thread_entry_freelist)) {
1356 thread_entry_freelist = te->te_next;
1357 } else {
1358 te = (thread_entry_t)malloc(sizeof(struct thread_entry));
1359 }
1360
1361 te->te_thread = thread;
1362 te->te_next = *list;
1363 *list = te;
1364 }
1365
1366 static void
1367 exec_thread_entry(uintptr_t thread, char *command)
1368 {
1369 threadmap_t tme;
1370
1371 if ((tme = find_thread_entry(thread))) {
1372 if (tme->tm_orig_command[0] == '\0') {
1373 (void)strncpy (tme->tm_orig_command, tme->tm_command, MAXCOMLEN);
1374 tme->tm_orig_command[MAXCOMLEN] = '\0';
1375 }
1376 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1377 tme->tm_command[MAXCOMLEN] = '\0';
1378
1379 add_thread_entry_to_list(&thread_reset_list, thread);
1380 } else {
1381 create_map_entry(thread, command);
1382 }
1383 }
1384
1385 static void
1386 record_thread_entry_for_gc(uintptr_t thread)
1387 {
1388 add_thread_entry_to_list(&thread_delete_list, thread);
1389 }
1390
1391 static void
1392 gc_thread_entries(void)
1393 {
1394 thread_entry_t te;
1395 thread_entry_t te_next;
1396 int count = 0;
1397
1398 for (te = thread_delete_list; te; te = te_next) {
1399 delete_thread_entry(te->te_thread);
1400
1401 te_next = te->te_next;
1402 te->te_next = thread_entry_freelist;
1403 thread_entry_freelist = te;
1404
1405 count++;
1406 }
1407 thread_delete_list = 0;
1408 }
1409
1410 static void
1411 gc_reset_entries(void)
1412 {
1413 thread_entry_t te;
1414 thread_entry_t te_next;
1415 int count = 0;
1416
1417 for (te = thread_reset_list; te; te = te_next) {
1418 te_next = te->te_next;
1419 te->te_next = thread_entry_freelist;
1420 thread_entry_freelist = te;
1421
1422 count++;
1423 }
1424 thread_reset_list = 0;
1425 }
1426
1427 static void
1428 reset_thread_names(void)
1429 {
1430 thread_entry_t te;
1431 thread_entry_t te_next;
1432 int count = 0;
1433
1434 for (te = thread_reset_list; te; te = te_next) {
1435 threadmap_t tme;
1436
1437 if ((tme = find_thread_entry(te->te_thread))) {
1438 if (tme->tm_orig_command[0]) {
1439 (void)strncpy (tme->tm_command, tme->tm_orig_command, MAXCOMLEN);
1440 tme->tm_command[MAXCOMLEN] = '\0';
1441 tme->tm_orig_command[0] = '\0';
1442 }
1443 }
1444 te_next = te->te_next;
1445 te->te_next = thread_entry_freelist;
1446 thread_entry_freelist = te;
1447
1448 count++;
1449 }
1450 thread_reset_list = 0;
1451 }
1452
1453 static void
1454 delete_all_thread_entries(void)
1455 {
1456 threadmap_t tme = 0;
1457 threadmap_t tme_next = 0;
1458 int i;
1459
1460 for (i = 0; i < HASH_SIZE; i++) {
1461 for (tme = threadmap_hash[i]; tme; tme = tme_next) {
1462 tme_next = tme->tm_next;
1463 tme->tm_next = threadmap_freelist;
1464 threadmap_freelist = tme;
1465 }
1466 threadmap_hash[i] = 0;
1467 }
1468 }
1469
1470 static void
1471 insert_run_event(uintptr_t thread, int priority, kd_buf *kd, uint64_t now)
1472 {
1473 threadrun_t trp;
1474
1475 int hashid = thread & HASH_MASK;
1476
1477 for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) {
1478 if (trp->tr_thread == thread) {
1479 break;
1480 }
1481 }
1482 if (trp == NULL) {
1483 if ((trp = threadrun_freelist)) {
1484 threadrun_freelist = trp->tr_next;
1485 } else {
1486 trp = (threadrun_t)malloc(sizeof(struct threadrun));
1487 }
1488
1489 trp->tr_thread = thread;
1490
1491 trp->tr_next = threadrun_hash[hashid];
1492 threadrun_hash[hashid] = trp;
1493
1494 add_thread_entry_to_list(&thread_run_list, thread);
1495 }
1496 trp->tr_entry = kd;
1497 trp->tr_timestamp = now;
1498 trp->tr_priority = priority;
1499 }
1500
1501 static threadrun_t
1502 find_run_event(uintptr_t thread)
1503 {
1504 threadrun_t trp;
1505 int hashid = thread & HASH_MASK;
1506
1507 for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) {
1508 if (trp->tr_thread == thread) {
1509 return trp;
1510 }
1511 }
1512 return 0;
1513 }
1514
1515 static void
1516 delete_run_event(uintptr_t thread)
1517 {
1518 threadrun_t trp = 0;
1519 threadrun_t trp_prev;
1520
1521 int hashid = thread & HASH_MASK;
1522
1523 if ((trp = threadrun_hash[hashid])) {
1524 if (trp->tr_thread == thread) {
1525 threadrun_hash[hashid] = trp->tr_next;
1526 } else {
1527 trp_prev = trp;
1528
1529 for (trp = trp->tr_next; trp; trp = trp->tr_next) {
1530 if (trp->tr_thread == thread) {
1531 trp_prev->tr_next = trp->tr_next;
1532 break;
1533 }
1534 trp_prev = trp;
1535 }
1536 }
1537 if (trp) {
1538 trp->tr_next = threadrun_freelist;
1539 threadrun_freelist = trp;
1540 }
1541 }
1542 }
1543
1544 static void
1545 gc_run_events(void)
1546 {
1547 thread_entry_t te;
1548 thread_entry_t te_next;
1549 threadrun_t trp;
1550 threadrun_t trp_next;
1551 int count = 0;
1552
1553 for (te = thread_run_list; te; te = te_next) {
1554 int hashid = te->te_thread & HASH_MASK;
1555
1556 for (trp = threadrun_hash[hashid]; trp; trp = trp_next) {
1557 trp_next = trp->tr_next;
1558 trp->tr_next = threadrun_freelist;
1559 threadrun_freelist = trp;
1560 count++;
1561 }
1562 threadrun_hash[hashid] = 0;
1563
1564 te_next = te->te_next;
1565 te->te_next = thread_entry_freelist;
1566 thread_entry_freelist = te;
1567 }
1568 thread_run_list = 0;
1569 }
1570
1571
1572
1573 static void
1574 insert_start_event(uintptr_t thread, int type, uint64_t now)
1575 {
1576 event_t evp;
1577
1578 int hashid = thread & HASH_MASK;
1579
1580 for (evp = event_hash[hashid]; evp; evp = evp->ev_next) {
1581 if (evp->ev_thread == thread && evp->ev_type == type) {
1582 break;
1583 }
1584 }
1585 if (evp == NULL) {
1586 if ((evp = event_freelist)) {
1587 event_freelist = evp->ev_next;
1588 } else {
1589 evp = (event_t)malloc(sizeof(struct event));
1590 }
1591
1592 evp->ev_thread = thread;
1593 evp->ev_type = type;
1594
1595 evp->ev_next = event_hash[hashid];
1596 event_hash[hashid] = evp;
1597
1598 add_thread_entry_to_list(&thread_event_list, thread);
1599 }
1600 evp->ev_timestamp = now;
1601 }
1602
1603
1604 static uint64_t
1605 consume_start_event(uintptr_t thread, int type, uint64_t now)
1606 {
1607 event_t evp;
1608 event_t evp_prev;
1609 uint64_t elapsed = 0;
1610
1611 int hashid = thread & HASH_MASK;
1612
1613 if ((evp = event_hash[hashid])) {
1614 if (evp->ev_thread == thread && evp->ev_type == type) {
1615 event_hash[hashid] = evp->ev_next;
1616 } else {
1617 evp_prev = evp;
1618
1619 for (evp = evp->ev_next; evp; evp = evp->ev_next) {
1620 if (evp->ev_thread == thread && evp->ev_type == type) {
1621 evp_prev->ev_next = evp->ev_next;
1622 break;
1623 }
1624 evp_prev = evp;
1625 }
1626 }
1627 if (evp) {
1628 elapsed = now - evp->ev_timestamp;
1629
1630 if (now < evp->ev_timestamp) {
1631 printf("consume: now = %qd, timestamp = %qd\n", now, evp->ev_timestamp);
1632 elapsed = 0;
1633 }
1634 evp->ev_next = event_freelist;
1635 event_freelist = evp;
1636 }
1637 }
1638 return elapsed;
1639 }
1640
1641 static void
1642 gc_start_events(void)
1643 {
1644 thread_entry_t te;
1645 thread_entry_t te_next;
1646 event_t evp;
1647 event_t evp_next;
1648 int count = 0;
1649 int hashid;
1650
1651 for (te = thread_event_list; te; te = te_next) {
1652
1653 hashid = te->te_thread & HASH_MASK;
1654
1655 for (evp = event_hash[hashid]; evp; evp = evp_next) {
1656 evp_next = evp->ev_next;
1657 evp->ev_next = event_freelist;
1658 event_freelist = evp;
1659 count++;
1660 }
1661 event_hash[hashid] = 0;
1662
1663 te_next = te->te_next;
1664 te->te_next = thread_entry_freelist;
1665 thread_entry_freelist = te;
1666 }
1667 thread_event_list = 0;
1668 }
1669
1670 static int
1671 thread_in_user_mode(uintptr_t thread, char *command)
1672 {
1673 event_t evp;
1674
1675 if (strcmp(command, "kernel_task") == 0) {
1676 return 0;
1677 }
1678
1679 int hashid = thread & HASH_MASK;
1680
1681 for (evp = event_hash[hashid]; evp; evp = evp->ev_next) {
1682 if (evp->ev_thread == thread) {
1683 return 0;
1684 }
1685 }
1686 return 1;
1687 }
1688
1689 static lookup_t
1690 handle_lookup_event(uintptr_t thread, int debugid, kd_buf *kdp)
1691 {
1692 lookup_t lkp;
1693 boolean_t first_record = FALSE;
1694
1695 int hashid = thread & HASH_MASK;
1696
1697 if (debugid & DBG_FUNC_START) {
1698 first_record = TRUE;
1699 }
1700
1701 for (lkp = lookup_hash[hashid]; lkp; lkp = lkp->lk_next) {
1702 if (lkp->lk_thread == thread) {
1703 break;
1704 }
1705 }
1706 if (lkp == NULL) {
1707 if (first_record == FALSE) {
1708 return 0;
1709 }
1710
1711 if ((lkp = lookup_freelist)) {
1712 lookup_freelist = lkp->lk_next;
1713 } else {
1714 lkp = (lookup_t)malloc(sizeof(struct lookup));
1715 }
1716
1717 lkp->lk_thread = thread;
1718
1719 lkp->lk_next = lookup_hash[hashid];
1720 lookup_hash[hashid] = lkp;
1721
1722 add_thread_entry_to_list(&thread_lookup_list, thread);
1723 }
1724
1725 if (first_record == TRUE) {
1726 lkp->lk_pathptr = lkp->lk_pathname;
1727 lkp->lk_dvp = kdp->arg1;
1728 } else {
1729 if (lkp->lk_pathptr > &lkp->lk_pathname[NUMPARMS-4]) {
1730 return lkp;
1731 }
1732 *lkp->lk_pathptr++ = kdp->arg1;
1733 }
1734 *lkp->lk_pathptr++ = kdp->arg2;
1735 *lkp->lk_pathptr++ = kdp->arg3;
1736 *lkp->lk_pathptr++ = kdp->arg4;
1737 *lkp->lk_pathptr = 0;
1738
1739 if (debugid & DBG_FUNC_END) {
1740 return lkp;
1741 }
1742
1743 return 0;
1744 }
1745
1746 static void
1747 delete_lookup_event(uintptr_t thread, lookup_t lkp_to_delete)
1748 {
1749 lookup_t lkp;
1750 lookup_t lkp_prev;
1751 int hashid;
1752
1753 hashid = thread & HASH_MASK;
1754
1755 if ((lkp = lookup_hash[hashid])) {
1756 if (lkp == lkp_to_delete) {
1757 lookup_hash[hashid] = lkp->lk_next;
1758 } else {
1759 lkp_prev = lkp;
1760
1761 for (lkp = lkp->lk_next; lkp; lkp = lkp->lk_next) {
1762 if (lkp == lkp_to_delete) {
1763 lkp_prev->lk_next = lkp->lk_next;
1764 break;
1765 }
1766 lkp_prev = lkp;
1767 }
1768 }
1769 if (lkp) {
1770 lkp->lk_next = lookup_freelist;
1771 lookup_freelist = lkp;
1772 }
1773 }
1774 }
1775
1776 static void
1777 gc_lookup_events(void)
1778 {
1779 thread_entry_t te;
1780 thread_entry_t te_next;
1781 lookup_t lkp;
1782 lookup_t lkp_next;
1783 int count = 0;
1784 int hashid;
1785
1786 for (te = thread_lookup_list; te; te = te_next) {
1787 hashid = te->te_thread & HASH_MASK;
1788
1789 for (lkp = lookup_hash[hashid]; lkp; lkp = lkp_next) {
1790 lkp_next = lkp->lk_next;
1791 lkp->lk_next = lookup_freelist;
1792 lookup_freelist = lkp;
1793 count++;
1794 }
1795 lookup_hash[hashid] = 0;
1796
1797 te_next = te->te_next;
1798 te->te_next = thread_entry_freelist;
1799 thread_entry_freelist = te;
1800 }
1801 thread_lookup_list = 0;
1802 }
1803
1804 int
1805 sample_sc(void)
1806 {
1807 kd_buf *kd, *end_of_sample;
1808 int keep_going = 1;
1809 int i;
1810 ssize_t count;
1811
1812 if (!RAW_flag) {
1813 /*
1814 * Get kernel buffer information
1815 */
1816 get_bufinfo(&bufinfo);
1817 }
1818 if (need_new_map) {
1819 delete_all_thread_entries();
1820 read_command_map();
1821 need_new_map = 0;
1822 }
1823 if (RAW_flag) {
1824 ssize_t bytes_read;
1825
1826 bytes_read = read(RAW_fd, my_buffer, num_entries * sizeof(kd_buf));
1827
1828 if (bytes_read == -1) {
1829 perror("read failed");
1830 exit(2);
1831 }
1832 count = bytes_read / sizeof(kd_buf);
1833
1834 if (count != num_entries) {
1835 keep_going = 0;
1836 }
1837
1838 if (first_read) {
1839 kd = (kd_buf *)my_buffer;
1840 first_now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1841 first_read = 0;
1842 }
1843
1844 } else {
1845 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREADTR };
1846 size_t needed = bufinfo.nkdbufs * sizeof(kd_buf);
1847
1848 if (sysctl(mib, ARRAYSIZE(mib), my_buffer, &needed, NULL, 0) < 0) {
1849 quit("trace facility failure, KERN_KDREADTR\n");
1850 }
1851
1852 count = needed;
1853 sample_generation++;
1854
1855 if (bufinfo.flags & KDBG_WRAPPED) {
1856 need_new_map = 1;
1857
1858 if (log_fp) {
1859 fprintf(log_fp, "\n\n%-19.19s sample = %d <<<<<<< trace buffer wrapped >>>>>>>\n\n",
1860 &(ctime(&curr_time)[0]), sample_generation);
1861 }
1862 set_enable(0);
1863 set_enable(1);
1864 }
1865 }
1866 end_of_sample = &((kd_buf *)my_buffer)[count];
1867
1868 /*
1869 * Always reinitialize the DECR_TRAP array
1870 */
1871 for (i = 0; i < num_cpus; i++) {
1872 last_decrementer_kd[i] = (kd_buf *)my_buffer;
1873 }
1874
1875 for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) {
1876 kd_buf *kd_start;
1877 uintptr_t thread = kd->arg5;
1878 int type = kd->debugid & DBG_FUNC_MASK;
1879
1880 (void)check_for_thread_update(thread, type, kd, NULL);
1881
1882 uint64_t now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1883 last_now = now;
1884
1885 if (type == DECR_TRAP) {
1886 int cpunum = CPU_NUMBER(kd);
1887 double i_latency = handle_decrementer(kd, cpunum);
1888
1889 if (log_fp) {
1890 if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
1891 kd_start = last_decrementer_kd[cpunum];
1892
1893 log_decrementer(kd_start, kd, end_of_sample, i_latency);
1894 }
1895 last_decrementer_kd[cpunum] = kd;
1896 }
1897 } else {
1898 double s_latency;
1899 int s_priority;
1900 if (check_for_scheduler_latency(type, &thread, now, kd, &kd_start, &s_priority, &s_latency)) {
1901 log_scheduler(kd_start, kd, end_of_sample, s_priority, s_latency, thread);
1902 }
1903 }
1904 }
1905 if (log_fp) {
1906 fflush(log_fp);
1907 }
1908
1909 gc_thread_entries();
1910 gc_reset_entries();
1911 gc_run_events();
1912
1913 return keep_going;
1914 }
1915
1916 void
1917 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)
1918 {
1919 char *p;
1920 double timestamp;
1921 double delta;
1922 char pcstring[128];
1923
1924 int cpunum = CPU_NUMBER(kd);
1925
1926 if (print_info && fp) {
1927 timestamp = (double)(now - start_bias) / divisor;
1928 delta = (double)idelta / divisor;
1929
1930 if ((p = find_code(type))) {
1931 if (type == INTERRUPT) {
1932 int mode;
1933
1934 if (kd->arg3) {
1935 mode = USER_MODE;
1936 } else {
1937 mode = KERNEL_MODE;
1938 }
1939
1940 pc_to_string(&pcstring[0], kd->arg2, 58, mode);
1941
1942 fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2lx] @ %-58.58s %8lx %2d %s\n",
1943 timestamp, delta, kd->arg1, &pcstring[0], thread, cpunum, command);
1944 } else if (type == MACH_vmfault) {
1945 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8lx %2d %s\n",
1946 timestamp, delta, p, thread, cpunum, command);
1947 } else {
1948 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
1949 timestamp, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1950 thread, cpunum, command);
1951 }
1952 } else {
1953 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
1954 timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1955 thread, cpunum, command);
1956 }
1957 }
1958 if (type != BSC_thread_terminate && type != BSC_exit) {
1959 insert_start_event(thread, type, now);
1960 }
1961 }
1962
1963 void
1964 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)
1965 {
1966 char *p;
1967 uint64_t user_addr;
1968 double timestamp;
1969 double delta;
1970 double elapsed_timestamp;
1971
1972 elapsed_timestamp = (double)consume_start_event(thread, type, now) / divisor;
1973
1974 if (print_info && fp) {
1975 int cpunum = CPU_NUMBER(kd);
1976
1977 timestamp = (double)(now - start_bias) / divisor;
1978 delta = (double)idelta / divisor;
1979
1980 fprintf(fp, "%9.1f %8.1f(%.1f) \t", timestamp, delta, elapsed_timestamp);
1981
1982 if ((p = find_code(type))) {
1983 if (type == INTERRUPT) {
1984 fprintf(fp, "INTERRUPT %8lx %2d %s\n", thread, cpunum, command);
1985 } else if (type == MACH_vmfault && kd->arg4 <= DBG_PAGEIND_FAULT) {
1986 user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2;
1987
1988 fprintf(fp, "%-28.28s %-10.10s %-16qx %8lx %2d %s\n",
1989 p, fault_name[kd->arg4], user_addr,
1990 thread, cpunum, command);
1991 } else {
1992 fprintf(fp, "%-28.28s %-16lx %-16lx %8lx %2d %s\n",
1993 p, kd->arg1, kd->arg2,
1994 thread, cpunum, command);
1995 }
1996 } else {
1997 fprintf(fp, "%-8x %-16lx %-16lx %8lx %2d %s\n",
1998 type, kd->arg1, kd->arg2,
1999 thread, cpunum, command);
2000 }
2001 }
2002 }
2003
2004 void
2005 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)
2006 {
2007 char *p;
2008
2009 if (!fp) {
2010 return;
2011 }
2012
2013 int cpunum = CPU_NUMBER(kd);
2014
2015 double timestamp = (double)(now - start_bias) / divisor;
2016 double delta = (double)idelta / divisor;
2017
2018 if ((p = find_code(type))) {
2019 if (kd == kd_note) {
2020 fprintf(fp, "%9.1f %8.1f\t**\t", timestamp, delta);
2021 } else {
2022 fprintf(fp, "%9.1f %8.1f\t\t", timestamp, delta);
2023 }
2024 fprintf(fp, "%-28.28s %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
2025 p, kd->arg1, kd->arg2, kd->arg3, kd->arg4, thread, cpunum, command);
2026 } else {
2027 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16lx %-16lx %-16lx %-16lx %8lx %2d %s\n",
2028 timestamp, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
2029 thread, cpunum, command);
2030 }
2031 }
2032
2033 void
2034 check_for_thread_update(uintptr_t thread, int debugid_base, kd_buf *kbufp, char **command)
2035 {
2036 if (debugid_base == TRACE_DATA_NEWTHREAD) {
2037 /*
2038 * Save the create thread data
2039 */
2040 create_tmp_map_entry(kbufp->arg1, thread);
2041 } else if (debugid_base == TRACE_STRING_NEWTHREAD) {
2042 /*
2043 * process new map entry
2044 */
2045 find_and_insert_tmp_map_entry(thread, (char *)&kbufp->arg1);
2046 } else if (debugid_base == TRACE_STRING_EXEC) {
2047 exec_thread_entry(thread, (char *)&kbufp->arg1);
2048 } else {
2049 if (debugid_base == BSC_exit || debugid_base == BSC_thread_terminate) {
2050 record_thread_entry_for_gc(thread);
2051 }
2052 if (command) {
2053 find_thread_name(thread, command);
2054 }
2055 }
2056 }
2057
2058 void
2059 log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note)
2060 {
2061 lookup_t lkp;
2062 int mode;
2063 uintptr_t reason;
2064 char *p;
2065 char *command;
2066 char *command1;
2067 char command_buf[32];
2068 char sched_info[64];
2069 char pcstring[128];
2070 const char *sched_reason;
2071 double i_latency;
2072 double timestamp;
2073 double delta;
2074 char joe[32];
2075
2076 uintptr_t thread = kd->arg5;
2077 int cpunum = CPU_NUMBER(kd);
2078 int debugid = kd->debugid;
2079 int type = kd->debugid & DBG_FUNC_MASK;
2080
2081 (void)check_for_thread_update(thread, type, kd, &command);
2082
2083 if ((type >> 24) == DBG_TRACE) {
2084 if (((type >> 16) & 0xff) != DBG_TRACE_INFO) {
2085 return;
2086 }
2087 }
2088 timestamp = (double)(now - start_bias) / divisor;
2089 delta = (double)idelta / divisor;
2090
2091 switch (type) {
2092
2093 case CQ_action:
2094 pc_to_string(&pcstring[0], kd->arg1, 84, KERNEL_MODE);
2095
2096 fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-84.84s %8lx %2d %s\n",
2097 timestamp, delta, &pcstring[0], thread, cpunum, command);
2098 break;
2099
2100 case TES_action:
2101 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2102
2103 fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-83.83s %8lx %2d %s\n",
2104 timestamp, delta, &pcstring[0], thread, cpunum, command);
2105 break;
2106
2107 case IES_action:
2108 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2109
2110 fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-83.83s %8lx %2d %s\n",
2111 timestamp, delta, &pcstring[0], thread, cpunum, command);
2112 break;
2113
2114 case IES_filter:
2115 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2116
2117 fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-83.83s %8lx %2d %s\n",
2118 timestamp, delta, &pcstring[0], thread, cpunum, command);
2119 break;
2120
2121 case DECR_TRAP:
2122 if ((int)kd->arg1 >= 0) {
2123 i_latency = 0;
2124 } else {
2125 i_latency = (((double)(-1 - kd->arg1)) / divisor);
2126 }
2127
2128 if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
2129 p = "*";
2130 } else {
2131 p = " ";
2132 }
2133
2134 if (kd->arg3) {
2135 mode = USER_MODE;
2136 } else {
2137 mode = KERNEL_MODE;
2138 }
2139
2140 pc_to_string(&pcstring[0], kd->arg2, 84, mode);
2141
2142 fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8lx %2d %s\n",
2143 timestamp, delta, i_latency, p, &pcstring[0], thread, cpunum, command);
2144 break;
2145
2146 case DECR_SET:
2147 fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %8lx %2d %s\n",
2148 timestamp, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command);
2149 break;
2150
2151 case MACH_sched:
2152 case MACH_stkhandoff:
2153
2154 find_thread_name(kd->arg2, &command1);
2155
2156 if (command1 == EMPTYSTRING) {
2157 command1 = command_buf;
2158 sprintf(command1, "%-8lx", kd->arg2);
2159 }
2160 if (thread_in_user_mode(kd->arg2, command1)) {
2161 p = "U";
2162 } else {
2163 p = "K";
2164 }
2165
2166 reason = kd->arg1;
2167
2168 if (reason > MAX_REASON) {
2169 sched_reason = "?";
2170 } else {
2171 sched_reason = sched_reasons[reason];
2172 }
2173
2174 if (sched_reason[0] == '?') {
2175 sprintf(joe, "%lx", reason);
2176 sched_reason = joe;
2177 }
2178 sprintf(sched_info, "%16.16s @ pri %3lu --> %16.16s @ pri %3lu%s", command, kd->arg3, command1, kd->arg4, p);
2179
2180 fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s[%s] %s %8lx %2d\n",
2181 timestamp, delta, "MACH_SCHED", sched_reason, sched_info, thread, cpunum);
2182 break;
2183
2184 case VFS_LOOKUP:
2185 if ((lkp = handle_lookup_event(thread, debugid, kd))) {
2186 /*
2187 * print the tail end of the pathname
2188 */
2189 p = (char *)lkp->lk_pathname;
2190 size_t clen = strlen(p);
2191
2192 if (clen > 45) {
2193 clen -= 45;
2194 } else {
2195 clen = 0;
2196 }
2197
2198 fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-59s %-16lx %8lx %2d %s\n",
2199 timestamp, delta, "VFS_LOOKUP",
2200 &p[clen], lkp->lk_dvp, thread, cpunum, command);
2201
2202 delete_lookup_event(thread, lkp);
2203 }
2204 break;
2205
2206 default:
2207 if (debugid & DBG_FUNC_START) {
2208 enter_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1);
2209 } else if (debugid & DBG_FUNC_END) {
2210 exit_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1);
2211 } else {
2212 print_entry(log_fp, kd, thread, type, command, now, idelta, start_bias, kd_note);
2213 }
2214 break;
2215 }
2216 }
2217
2218 static void
2219 log_range(kd_buf *kd_buffer, kd_buf *kd_start, kd_buf *kd_stop, kd_buf *kd_note, char *buf1)
2220 {
2221 uint64_t last_timestamp = 0;
2222 uint64_t delta = 0;
2223 uint64_t start_bias = 0;
2224 uint64_t now;
2225 kd_buf *kd;
2226 size_t clen;
2227 char buf2[128];
2228
2229 clen = strlen(buf1);
2230 memset(buf2, '-', clen);
2231 buf2[clen] = 0;
2232 fprintf(log_fp, "\n\n%s\n", buf2);
2233 fprintf(log_fp, "%s\n\n", buf1);
2234
2235 fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n");
2236
2237 reset_thread_names();
2238
2239 last_timestamp = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2240 start_bias = last_timestamp;
2241
2242 for (kd = kd_buffer; kd <= kd_stop; kd++) {
2243 now = kd->timestamp & KDBG_TIMESTAMP_MASK;
2244
2245 if (kd >= kd_start) {
2246 delta = now - last_timestamp;
2247
2248 log_info(now, delta, start_bias, kd, kd_note);
2249
2250 last_timestamp = now;
2251 } else {
2252 int debugid = kd->debugid;
2253 uintptr_t thread = kd->arg5;
2254 int type = kd->debugid & DBG_FUNC_MASK;
2255
2256 if ((type >> 24) == DBG_TRACE) {
2257 if (((type >> 16) & 0xff) != DBG_TRACE_INFO) {
2258 continue;
2259 }
2260 }
2261 if (type == BSC_thread_terminate || type == BSC_exit) {
2262 continue;
2263 }
2264
2265 if (debugid & DBG_FUNC_START) {
2266 insert_start_event(thread, type, now);
2267 } else if (debugid & DBG_FUNC_END) {
2268 (void)consume_start_event(thread, type, now);
2269 }
2270 }
2271 }
2272 gc_start_events();
2273 gc_lookup_events();
2274 }
2275
2276 kd_buf *
2277 log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency)
2278 {
2279 kd_buf *kd_start, *kd_stop;
2280 int kd_count; /* Limit the boundary of kd_start */
2281 uint64_t now;
2282 double sample_timestamp;
2283 char buf1[128];
2284
2285 uintptr_t thread = kd_beg->arg5;
2286 int cpunum = CPU_NUMBER(kd_end);
2287
2288 for (kd_count = 0, kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer); kd_start--, kd_count++) {
2289 if (kd_count == MAX_LOG_COUNT) {
2290 break;
2291 }
2292
2293 if (CPU_NUMBER(kd_start) != cpunum) {
2294 continue;
2295 }
2296
2297 if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) {
2298 break;
2299 }
2300
2301 if (kd_start->arg5 != thread) {
2302 break;
2303 }
2304 }
2305 if (kd_start < (kd_buf *)my_buffer) {
2306 kd_start = (kd_buf *)my_buffer;
2307 }
2308
2309 thread = kd_end->arg5;
2310
2311 for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
2312 if (CPU_NUMBER(kd_stop) != cpunum) {
2313 continue;
2314 }
2315
2316 if ((kd_stop->debugid & DBG_FUNC_MASK) == INTERRUPT) {
2317 break;
2318 }
2319
2320 if (kd_stop->arg5 != thread) {
2321 break;
2322 }
2323 }
2324 if (kd_stop >= end_of_sample) {
2325 kd_stop = end_of_sample - 1;
2326 }
2327
2328 if (RAW_flag) {
2329 time_t TOD_secs;
2330 uint64_t TOD_usecs;
2331
2332 now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2333 sample_timestamp = (double)(now - first_now) / divisor;
2334
2335 TOD_usecs = (uint64_t)sample_timestamp;
2336 TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000);
2337
2338 sprintf(buf1, "%-19.19s interrupt latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), i_latency, sample_timestamp);
2339 } else {
2340 sprintf(buf1, "%-19.19s interrupt latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), i_latency, sample_generation);
2341 }
2342
2343 log_range((kd_buf *)my_buffer, kd_start, kd_stop, 0, buf1);
2344
2345 return kd_stop;
2346 }
2347
2348
2349 void
2350 log_scheduler(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, int s_priority, double s_latency, uintptr_t thread)
2351 {
2352 kd_buf *kd_start, *kd_stop;
2353 uint64_t now;
2354 int count;
2355 int cpunum;
2356 uint64_t cmask = 0;
2357 double sample_timestamp;
2358 char buf1[128];
2359
2360 for (count = 0, kd_start = kd_beg; (kd_start >= (kd_buf *)my_buffer); kd_start--) {
2361 cpunum = CPU_NUMBER(kd_start);
2362
2363 cmask |= ((uint64_t)1 << cpunum);
2364
2365 if (cmask == cpu_mask) {
2366 if (count++ > 100)
2367 break;
2368 }
2369 }
2370 if (kd_start < (kd_buf *)my_buffer) {
2371 kd_start = (kd_buf *)my_buffer;
2372 }
2373
2374 for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
2375 if (kd_stop->arg5 == thread) {
2376 break;
2377 }
2378 }
2379 if (kd_stop >= end_of_sample) {
2380 kd_stop = end_of_sample - 1;
2381 }
2382
2383 if (RAW_flag) {
2384 time_t TOD_secs;
2385 uint64_t TOD_usecs;
2386
2387 now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2388 sample_timestamp = (double)(now - first_now) / divisor;
2389
2390 TOD_usecs = (uint64_t)sample_timestamp;
2391 TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000);
2392
2393 sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), s_priority, s_latency, sample_timestamp);
2394 } else {
2395 sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), s_priority, s_latency, sample_generation);
2396 }
2397
2398 log_range((kd_buf *)my_buffer, kd_start, kd_stop, kd_beg, buf1);
2399 }
2400
2401 int
2402 check_for_scheduler_latency(int type, uintptr_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, int *priority, double *latency)
2403 {
2404 int found_latency = 0;
2405
2406 if (type == MACH_makerunnable) {
2407 if (watch_priority_min <= kd->arg2 && kd->arg2 <= watch_priority_max) {
2408 insert_run_event(kd->arg1, (int)kd->arg2, kd, now);
2409 }
2410 } else if (type == MACH_sched || type == MACH_stkhandoff) {
2411 threadrun_t trp = find_run_event(kd->arg2);
2412
2413 if (type == MACH_sched || type == MACH_stkhandoff) {
2414 *thread = kd->arg2;
2415 }
2416
2417 if ((trp = find_run_event(*thread))) {
2418 double d_s_latency = (((double)(now - trp->tr_timestamp)) / divisor);
2419 int s_latency = (int)d_s_latency;
2420
2421 if (s_latency) {
2422 if (s_latency < 100) {
2423 s_usec_10_bins[s_latency/10]++;
2424 }
2425 if (s_latency < 1000) {
2426 s_usec_100_bins[s_latency/100]++;
2427 } else if (s_latency < 10000) {
2428 s_msec_1_bins[s_latency/1000]++;
2429 } else if (s_latency < 50000) {
2430 s_msec_10_bins[s_latency/10000]++;
2431 } else {
2432 s_too_slow++;
2433 }
2434
2435 if (s_latency > s_max_latency) {
2436 s_max_latency = s_latency;
2437 }
2438 if (s_latency < s_min_latency || s_total_samples == 0) {
2439 s_min_latency = s_latency;
2440 }
2441 s_total_latency += s_latency;
2442 s_total_samples++;
2443
2444 if (s_thresh_hold && s_latency > s_thresh_hold) {
2445 s_exceeded_threshold++;
2446
2447 if (log_fp) {
2448 *kd_start = trp->tr_entry;
2449 *priority = trp->tr_priority;
2450 *latency = d_s_latency;
2451 found_latency = 1;
2452 }
2453 }
2454 }
2455 delete_run_event(*thread);
2456 }
2457 }
2458 return found_latency;
2459 }
2460
2461 double
2462 handle_decrementer(kd_buf *kd, int cpunum)
2463 {
2464 struct i_latencies *il;
2465 double latency;
2466 long elapsed_usecs;
2467
2468 if (i_latency_per_cpu == FALSE) {
2469 cpunum = 0;
2470 }
2471
2472 il = &i_lat[cpunum];
2473
2474 if ((long)(kd->arg1) >= 0) {
2475 latency = 1;
2476 } else {
2477 latency = (((double)(-1 - kd->arg1)) / divisor);
2478 }
2479 elapsed_usecs = (long)latency;
2480
2481 if (elapsed_usecs < 100) {
2482 il->i_usec_10_bins[elapsed_usecs/10]++;
2483 }
2484
2485 if (elapsed_usecs < 1000) {
2486 il->i_usec_100_bins[elapsed_usecs/100]++;
2487 } else if (elapsed_usecs < 10000) {
2488 il->i_msec_1_bins[elapsed_usecs/1000]++;
2489 } else if (elapsed_usecs < 50000) {
2490 il->i_msec_10_bins[elapsed_usecs/10000]++;
2491 } else {
2492 il->i_too_slow++;
2493 }
2494
2495 if (use_high_res_bins && elapsed_usecs < N_HIGH_RES_BINS) {
2496 i_high_res_bins[elapsed_usecs]++;
2497 }
2498 if (i_thresh_hold && elapsed_usecs > i_thresh_hold) {
2499 il->i_exceeded_threshold++;
2500 }
2501 if (elapsed_usecs > il->i_max_latency) {
2502 il->i_max_latency = elapsed_usecs;
2503 }
2504 if (elapsed_usecs < il->i_min_latency || il->i_total_samples == 0) {
2505 il->i_min_latency = elapsed_usecs;
2506 }
2507 il->i_total_latency += elapsed_usecs;
2508 il->i_total_samples++;
2509
2510 return latency;
2511 }
2512
2513 char *
2514 find_code(int type)
2515 {
2516 int i;
2517 for (i = 0; i < num_of_codes; i++) {
2518 if (codes_tab[i].type == type) {
2519 return codes_tab[i].name;
2520 }
2521 }
2522 return NULL;
2523 }
2524
2525 void
2526 init_code_file(void)
2527 {
2528 FILE *fp;
2529 int i;
2530
2531 if ((fp = fopen(code_file, "r")) == NULL) {
2532 if (log_fp) {
2533 fprintf(log_fp, "open of %s failed\n", code_file);
2534 }
2535 return;
2536 }
2537 for (i = 0; i < MAX_ENTRIES; i++) {
2538 int code;
2539 char name[128];
2540 int n = fscanf(fp, "%x%127s\n", &code, name);
2541
2542 if (n == 1 && i == 0) {
2543 /*
2544 * old code file format, just skip
2545 */
2546 continue;
2547 }
2548 if (n != 2) {
2549 break;
2550 }
2551
2552 strncpy(codes_tab[i].name, name, 32);
2553 codes_tab[i].type = code;
2554 }
2555 num_of_codes = i;
2556
2557 fclose(fp);
2558 }
2559
2560 void
2561 do_kernel_nm(void)
2562 {
2563 int i;
2564 size_t len;
2565 FILE *fp = NULL;
2566 char tmp_nm_file[128];
2567 char tmpstr[1024];
2568 char inchr;
2569
2570 bzero(tmp_nm_file, 128);
2571 bzero(tmpstr, 1024);
2572
2573 /*
2574 * Build the temporary nm file path
2575 */
2576 strcpy(tmp_nm_file,"/tmp/knm.out.XXXXXX");
2577
2578 if (!mktemp(tmp_nm_file)) {
2579 fprintf(stderr, "Error in mktemp call\n");
2580 return;
2581 }
2582
2583 /*
2584 * Build the nm command and create a tmp file with the output
2585 */
2586 sprintf (tmpstr, "/usr/bin/nm -f -n -s __TEXT __text %s > %s",
2587 kernelpath, tmp_nm_file);
2588 system(tmpstr);
2589
2590 /*
2591 * Parse the output from the nm command
2592 */
2593 if ((fp = fopen(tmp_nm_file, "r")) == NULL) {
2594 /* Hmmm, let's not treat this as fatal */
2595 fprintf(stderr, "Failed to open nm symbol file [%s]\n", tmp_nm_file);
2596 return;
2597 }
2598 /*
2599 * Count the number of symbols in the nm symbol table
2600 */
2601 kern_sym_count = 0;
2602
2603 while ((inchr = getc(fp)) != -1) {
2604 if (inchr == '\n') {
2605 kern_sym_count++;
2606 }
2607 }
2608 rewind(fp);
2609
2610 /*
2611 * Malloc the space for symbol table
2612 */
2613 if (kern_sym_count > 0) {
2614 kern_sym_tbl = malloc(kern_sym_count * sizeof(kern_sym_t));
2615
2616 if (!kern_sym_tbl) {
2617 /*
2618 * Hmmm, lets not treat this as fatal
2619 */
2620 fprintf(stderr, "Can't allocate memory for kernel symbol table\n");
2621 } else {
2622 bzero(kern_sym_tbl, kern_sym_count * sizeof(kern_sym_t));
2623 }
2624 } else {
2625 /*
2626 * Hmmm, lets not treat this as fatal
2627 */
2628 fprintf(stderr, "No kernel symbol table \n");
2629 }
2630 for (i = 0; i < kern_sym_count; i++) {
2631 bzero(tmpstr, 1024);
2632
2633 if (fscanf(fp, "%p %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3) {
2634 break;
2635 } else {
2636 len = strlen(tmpstr);
2637 kern_sym_tbl[i].k_sym_name = malloc(len + 1);
2638
2639 if (kern_sym_tbl[i].k_sym_name == NULL) {
2640 fprintf(stderr, "Can't allocate memory for symbol name [%s]\n", tmpstr);
2641 kern_sym_tbl[i].k_sym_name = NULL;
2642 len = 0;
2643 } else {
2644 strcpy(kern_sym_tbl[i].k_sym_name, tmpstr);
2645 }
2646
2647 kern_sym_tbl[i].k_sym_len = len;
2648 }
2649 }
2650 if (i != kern_sym_count) {
2651 /*
2652 * Hmmm, didn't build up entire table from nm
2653 * scrap the entire thing
2654 */
2655 free(kern_sym_tbl);
2656 kern_sym_tbl = NULL;
2657 kern_sym_count = 0;
2658 }
2659 fclose(fp);
2660
2661 /*
2662 * Remove the temporary nm file
2663 */
2664 unlink(tmp_nm_file);
2665 #if 0
2666 /*
2667 * Dump the kernel symbol table
2668 */
2669 for (i = 0; i < kern_sym_count; i++) {
2670 if (kern_sym_tbl[i].k_sym_name) {
2671 printf ("[%d] %-16p %s\n", i,
2672 kern_sym_tbl[i].k_sym_addr, kern_sym_tbl[i].k_sym_name);
2673 } else {
2674 printf ("[%d] %-16p %s\n", i,
2675 kern_sym_tbl[i].k_sym_addr, "No symbol name");
2676 }
2677 }
2678 #endif
2679 }
2680
2681 void
2682 pc_to_string(char *pcstring, uintptr_t pc, int max_len, int mode)
2683 {
2684 int ret;
2685 size_t len;
2686
2687 if (mode == USER_MODE) {
2688 sprintf(pcstring, "%-16lx [usermode addr]", pc);
2689 return;
2690 }
2691 ret = binary_search(kern_sym_tbl, 0, kern_sym_count-1, pc);
2692
2693 if (ret == -1 || kern_sym_tbl[ret].k_sym_name == NULL) {
2694 sprintf(pcstring, "%-16lx", pc);
2695 return;
2696 }
2697 if ((len = kern_sym_tbl[ret].k_sym_len) > (max_len - 8)) {
2698 len = max_len - 8;
2699 }
2700
2701 memcpy(pcstring, kern_sym_tbl[ret].k_sym_name, len);
2702
2703 sprintf(&pcstring[len], "+0x%-5lx", pc - (uintptr_t)kern_sym_tbl[ret].k_sym_addr);
2704 }
2705
2706
2707 /*
2708 * Return -1 if not found, else return index
2709 */
2710 int
2711 binary_search(kern_sym_t *list, int low, int high, uintptr_t addr)
2712 {
2713 int mid;
2714
2715 if (kern_sym_count == 0) {
2716 return -1;
2717 }
2718
2719 if (low > high) {
2720 return -1; /* failed */
2721 }
2722
2723 if (low + 1 == high) {
2724 if ((uintptr_t)list[low].k_sym_addr <= addr && addr < (uintptr_t)list[high].k_sym_addr) {
2725 /*
2726 * We have a range match
2727 */
2728 return low;
2729 }
2730 if ((uintptr_t)list[high].k_sym_addr <= addr) {
2731 return high;
2732 }
2733 /*
2734 * Failed
2735 */
2736 return -1;
2737 }
2738 mid = (low + high) / 2;
2739
2740 if (addr < (uintptr_t)list[mid].k_sym_addr) {
2741 return binary_search(list, low, mid, addr);
2742 }
2743
2744 return binary_search(list, mid, high, addr);
2745 }
2746
2747 void
2748 open_logfile(const char *path)
2749 {
2750 log_fp = fopen(path, "a");
2751
2752 if (!log_fp) {
2753 /*
2754 * failed to open path
2755 */
2756 fprintf(stderr, "latency: failed to open logfile [%s]\n", path);
2757 exit_usage();
2758 }
2759 }
2760
2761 void
2762 open_rawfile(const char *path)
2763 {
2764 RAW_fd = open(path, O_RDONLY);
2765
2766 if (RAW_fd == -1) {
2767 /*
2768 * failed to open path
2769 */
2770 fprintf(stderr, "latency: failed to open RAWfile [%s]\n", path);
2771 exit_usage();
2772 }
2773 }
2774
2775 void
2776 getdivisor(void)
2777 {
2778 mach_timebase_info_data_t info;
2779
2780 (void)mach_timebase_info(&info);
2781
2782 divisor = ((double)info.denom / (double)info.numer) * 1000;
2783 }
mirror of system_cmds