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


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