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