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