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