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