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


d8b67e41187f7be4cc38cf0e6db1a30ae67bdab7
[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 int
912 main(int argc, char *argv[])
913 {
914 int i;
915
916 if (0 != reexec_to_match_kernel()) {
917 fprintf(stderr, "Could not re-execute: %d\n", errno);
918 exit(1);
919 }
920 while (argc > 1) {
921
922 if (strcmp(argv[1], "-R") == 0) {
923 argc--;
924 argv++;
925
926 if (argc > 1) {
927 open_rawfile(argv[1]);
928 } else {
929 exit_usage();
930 }
931
932 RAW_flag = 1;
933
934 } else if (strcmp(argv[1], "-p") == 0) {
935 argc--;
936 argv++;
937
938 if (argc > 1) {
939 if (2 == sscanf(argv[1], "%d-%d", &watch_priority_min, &watch_priority_max)) {
940 if (watch_priority_min > watch_priority_max) {
941 exit_usage();
942 } else if (watch_priority_min < 0) {
943 exit_usage();
944 }
945 } else {
946 if (1 == sscanf(argv[1], "%d", &watch_priority_min)) {
947 watch_priority_max = watch_priority_min;
948 } else {
949 exit_usage();
950 }
951 }
952 } else {
953 exit_usage();
954 }
955 } else if (strcmp(argv[1], "-st") == 0) {
956 argc--;
957 argv++;
958
959 if (argc > 1) {
960 s_thresh_hold = atoi(argv[1]);
961 } else {
962 exit_usage();
963 }
964 } else if (strcmp(argv[1], "-it") == 0) {
965 argc--;
966 argv++;
967
968 if (argc > 1) {
969 i_thresh_hold = atoi(argv[1]);
970 } else {
971 exit_usage();
972 }
973 } else if (strcmp(argv[1], "-c") == 0) {
974 argc--;
975 argv++;
976
977 if (argc > 1) {
978 code_file = argv[1];
979 } else {
980 exit_usage();
981 }
982 } else if (strcmp(argv[1], "-l") == 0) {
983 argc--;
984 argv++;
985
986 if (argc > 1) {
987 open_logfile(argv[1]);
988 } else {
989 exit_usage();
990 }
991 } else if (strcmp(argv[1], "-n") == 0) {
992 argc--;
993 argv++;
994
995 if (argc > 1) {
996 kernelpath = argv[1];
997 } else {
998 exit_usage();
999 }
1000 } else if (strcmp(argv[1], "-h") == 0) {
1001 use_high_res_bins = TRUE;
1002
1003 } else if (strcmp(argv[1], "-m") == 0) {
1004 i_latency_per_cpu = TRUE;
1005
1006 } else {
1007 exit_usage();
1008 }
1009
1010 argc--;
1011 argv++;
1012 }
1013 if (!RAW_flag) {
1014 if (geteuid() != 0) {
1015 printf("'latency' must be run as root...\n");
1016 exit(1);
1017 }
1018 }
1019 if (kernelpath == NULL) {
1020 kernelpath = "/System/Library/Kernels/kernel.development";
1021 }
1022
1023 if (code_file == NULL) {
1024 code_file = "/usr/share/misc/trace.codes";
1025 }
1026
1027 do_kernel_nm();
1028
1029 getdivisor();
1030
1031 init_code_file();
1032
1033 if (!RAW_flag) {
1034 if (initscr() == NULL) {
1035 printf("Unrecognized TERM type, try vt100\n");
1036 exit(1);
1037 }
1038 clear();
1039 refresh();
1040
1041 signal(SIGWINCH, sigwinch);
1042 signal(SIGINT, sigintr);
1043 signal(SIGQUIT, leave);
1044 signal(SIGTERM, leave);
1045 signal(SIGHUP, leave);
1046
1047 /*
1048 * grab the number of cpus and scale the buffer size
1049 */
1050 int mib[] = { CTL_HW, HW_NCPU };
1051 size_t len = sizeof(num_cpus);
1052
1053 sysctl(mib, ARRAYSIZE(mib), &num_cpus, &len, NULL, 0);
1054
1055 set_remove();
1056 set_numbufs(SAMPLE_SIZE * num_cpus);
1057
1058 get_bufinfo(&bufinfo);
1059
1060 set_enable(0);
1061
1062 set_pidexclude(getpid(), 1);
1063 set_enable(1);
1064
1065 num_entries = bufinfo.nkdbufs;
1066 } else {
1067 num_entries = 50000;
1068 num_cpus = 128;
1069 }
1070
1071 for (cpu_mask = 0, i = 0; i < num_cpus; i++)
1072 cpu_mask |= ((uint64_t)1 << i);
1073
1074 if ((my_buffer = malloc(num_entries * sizeof(kd_buf))) == NULL) {
1075 quit("can't allocate memory for tracing info\n");
1076 }
1077
1078 if ((last_decrementer_kd = (kd_buf **)malloc(num_cpus * sizeof(kd_buf *))) == NULL) {
1079 quit("can't allocate memory for decrementer tracing info\n");
1080 }
1081
1082 if (i_latency_per_cpu == FALSE) {
1083 num_i_latency_cpus = 1;
1084 } else {
1085 num_i_latency_cpus = num_cpus;
1086 }
1087
1088 if ((i_lat = (struct i_latencies *)malloc(num_i_latency_cpus * sizeof(struct i_latencies))) == NULL) {
1089 quit("can't allocate memory for interrupt latency info\n");
1090 }
1091
1092 bzero((char *)i_lat, num_i_latency_cpus * sizeof(struct i_latencies));
1093
1094 if (RAW_flag) {
1095 while (sample_sc()) {
1096 continue;
1097 }
1098
1099 if (log_fp) {
1100 screen_update(log_fp);
1101 }
1102
1103 screen_update(stdout);
1104
1105 } else {
1106 uint64_t adelay;
1107 double fdelay;
1108 double nanosecs_to_sleep;
1109
1110 nanosecs_to_sleep = (double)(SAMPLE_TIME_USECS * 1000);
1111 fdelay = nanosecs_to_sleep * (divisor /1000);
1112 adelay = (uint64_t)fdelay;
1113
1114 trace_enabled = 1;
1115
1116 start_time = time(NULL);
1117 refresh_time = start_time;
1118
1119 for (;;) {
1120 curr_time = time(NULL);
1121
1122 if (curr_time >= refresh_time) {
1123 screen_update(NULL);
1124 refresh_time = curr_time + 1;
1125 }
1126 mach_wait_until(mach_absolute_time() + adelay);
1127
1128 sample_sc();
1129
1130 if (gotSIGWINCH) {
1131 /*
1132 * No need to check for initscr error return.
1133 * We won't get here if it fails on the first call.
1134 */
1135 endwin();
1136 clear();
1137 refresh();
1138
1139 gotSIGWINCH = 0;
1140 }
1141 }
1142 }
1143 }
1144
1145 void
1146 read_command_map(void)
1147 {
1148 kd_threadmap *mapptr = 0;
1149 int total_threads = 0;
1150 size_t size;
1151 off_t offset;
1152 int i;
1153 RAW_header header = {0};
1154
1155 if (RAW_flag) {
1156 if (read(RAW_fd, &header, sizeof(RAW_header)) != sizeof(RAW_header)) {
1157 perror("read failed");
1158 exit(2);
1159 }
1160 if (header.version_no != RAW_VERSION1) {
1161 header.version_no = RAW_VERSION0;
1162 header.TOD_secs = time(NULL);
1163 header.TOD_usecs = 0;
1164
1165 lseek(RAW_fd, (off_t)0, SEEK_SET);
1166
1167 if (read(RAW_fd, &header.thread_count, sizeof(int)) != sizeof(int)) {
1168 perror("read failed");
1169 exit(2);
1170 }
1171 }
1172 total_threads = header.thread_count;
1173
1174 sample_TOD_secs = header.TOD_secs;
1175 sample_TOD_usecs = header.TOD_usecs;
1176
1177 if (total_threads == 0 && header.version_no != RAW_VERSION0) {
1178 offset = lseek(RAW_fd, (off_t)0, SEEK_CUR);
1179 offset = (offset + (4095)) & ~4095;
1180
1181 lseek(RAW_fd, offset, SEEK_SET);
1182 }
1183 } else {
1184 total_threads = bufinfo.nkdthreads;
1185 }
1186
1187 size = total_threads * sizeof(kd_threadmap);
1188
1189 if (size == 0 || ((mapptr = (kd_threadmap *) malloc(size)) == 0)) {
1190 return;
1191 }
1192 bzero (mapptr, size);
1193
1194 /*
1195 * Now read the threadmap
1196 */
1197 if (RAW_flag) {
1198 if (read(RAW_fd, mapptr, size) != size) {
1199 printf("Can't read the thread map -- this is not fatal\n");
1200 }
1201 if (header.version_no != RAW_VERSION0) {
1202 offset = lseek(RAW_fd, (off_t)0, SEEK_CUR);
1203 offset = (offset + (4095)) & ~4095;
1204
1205 lseek(RAW_fd, offset, SEEK_SET);
1206 }
1207 } else {
1208 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDTHRMAP};
1209 if (sysctl(mib, ARRAYSIZE(mib), mapptr, &size, NULL, 0) < 0) {
1210 /*
1211 * This is not fatal -- just means I cant map command strings
1212 */
1213 printf("Can't read the thread map -- this is not fatal\n");
1214
1215 total_threads = 0;
1216 }
1217 }
1218 for (i = 0; i < total_threads; i++) {
1219 create_map_entry(mapptr[i].thread, &mapptr[i].command[0]);
1220 }
1221 free(mapptr);
1222 }
1223
1224 void
1225 create_map_entry(uint64_t thread, char *command)
1226 {
1227 threadmap_t tme;
1228
1229 if ((tme = threadmap_freelist)) {
1230 threadmap_freelist = tme->tm_next;
1231 } else {
1232 tme = (threadmap_t)malloc(sizeof(struct threadmap));
1233 }
1234
1235 tme->tm_thread = thread;
1236
1237 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1238 tme->tm_command[MAXCOMLEN] = '\0';
1239 tme->tm_orig_command[0] = '\0';
1240
1241 int hashid = thread & HASH_MASK;
1242
1243 tme->tm_next = threadmap_hash[hashid];
1244 threadmap_hash[hashid] = tme;
1245 }
1246
1247 static void
1248 delete_thread_entry(uint64_t thread)
1249 {
1250 threadmap_t tme;
1251
1252 int hashid = thread & HASH_MASK;
1253
1254 if ((tme = threadmap_hash[hashid])) {
1255 if (tme->tm_thread == thread) {
1256 threadmap_hash[hashid] = tme->tm_next;
1257 } else {
1258 threadmap_t tme_prev = tme;
1259
1260 for (tme = tme->tm_next; tme; tme = tme->tm_next) {
1261 if (tme->tm_thread == thread) {
1262 tme_prev->tm_next = tme->tm_next;
1263 break;
1264 }
1265 tme_prev = tme;
1266 }
1267 }
1268 if (tme) {
1269 tme->tm_next = threadmap_freelist;
1270 threadmap_freelist = tme;
1271 }
1272 }
1273 }
1274
1275 static void
1276 find_and_insert_tmp_map_entry(uint64_t pthread, char *command)
1277 {
1278 threadmap_t tme;
1279
1280 if ((tme = threadmap_temp)) {
1281 if (tme->tm_pthread == pthread) {
1282 threadmap_temp = tme->tm_next;
1283 } else {
1284 threadmap_t tme_prev = tme;
1285
1286 for (tme = tme->tm_next; tme; tme = tme->tm_next) {
1287 if (tme->tm_pthread == pthread) {
1288 tme_prev->tm_next = tme->tm_next;
1289 break;
1290 }
1291 tme_prev = tme;
1292 }
1293 }
1294 if (tme) {
1295 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1296 tme->tm_command[MAXCOMLEN] = '\0';
1297 tme->tm_orig_command[0] = '\0';
1298
1299 int hashid = tme->tm_thread & HASH_MASK;
1300 tme->tm_next = threadmap_hash[hashid];
1301 threadmap_hash[hashid] = tme;
1302 }
1303 }
1304 }
1305
1306 static void
1307 create_tmp_map_entry(uint64_t thread, uint64_t pthread)
1308 {
1309 threadmap_t tme;
1310
1311 if ((tme = threadmap_freelist)) {
1312 threadmap_freelist = tme->tm_next;
1313 } else {
1314 tme = malloc(sizeof(struct threadmap));
1315 }
1316
1317 tme->tm_thread = thread;
1318 tme->tm_pthread = pthread;
1319 tme->tm_command[0] = '\0';
1320 tme->tm_orig_command[0] = '\0';
1321
1322 tme->tm_next = threadmap_temp;
1323 threadmap_temp = tme;
1324 }
1325
1326 static threadmap_t
1327 find_thread_entry(uint64_t thread)
1328 {
1329 threadmap_t tme;
1330
1331 int hashid = thread & HASH_MASK;
1332
1333 for (tme = threadmap_hash[hashid]; tme; tme = tme->tm_next) {
1334 if (tme->tm_thread == thread) {
1335 return tme;
1336 }
1337 }
1338 return 0;
1339 }
1340
1341 static void
1342 find_thread_name(uint64_t thread, char **command)
1343 {
1344 threadmap_t tme;
1345
1346 if ((tme = find_thread_entry(thread))) {
1347 *command = tme->tm_command;
1348 } else {
1349 *command = EMPTYSTRING;
1350 }
1351 }
1352
1353 static void
1354 add_thread_entry_to_list(thread_entry_t *list, uint64_t thread)
1355 {
1356 thread_entry_t te;
1357
1358 if ((te = thread_entry_freelist)) {
1359 thread_entry_freelist = te->te_next;
1360 } else {
1361 te = (thread_entry_t)malloc(sizeof(struct thread_entry));
1362 }
1363
1364 te->te_thread = thread;
1365 te->te_next = *list;
1366 *list = te;
1367 }
1368
1369 static void
1370 exec_thread_entry(uint64_t thread, char *command)
1371 {
1372 threadmap_t tme;
1373
1374 if ((tme = find_thread_entry(thread))) {
1375 if (tme->tm_orig_command[0] == '\0') {
1376 (void)strncpy (tme->tm_orig_command, tme->tm_command, MAXCOMLEN);
1377 tme->tm_orig_command[MAXCOMLEN] = '\0';
1378 }
1379 (void)strncpy (tme->tm_command, command, MAXCOMLEN);
1380 tme->tm_command[MAXCOMLEN] = '\0';
1381
1382 add_thread_entry_to_list(&thread_reset_list, thread);
1383 } else {
1384 create_map_entry(thread, command);
1385 }
1386 }
1387
1388 static void
1389 record_thread_entry_for_gc(uint64_t thread)
1390 {
1391 add_thread_entry_to_list(&thread_delete_list, thread);
1392 }
1393
1394 static void
1395 gc_thread_entries(void)
1396 {
1397 thread_entry_t te;
1398 thread_entry_t te_next;
1399 int count = 0;
1400
1401 for (te = thread_delete_list; te; te = te_next) {
1402 delete_thread_entry(te->te_thread);
1403
1404 te_next = te->te_next;
1405 te->te_next = thread_entry_freelist;
1406 thread_entry_freelist = te;
1407
1408 count++;
1409 }
1410 thread_delete_list = 0;
1411 }
1412
1413 static void
1414 gc_reset_entries(void)
1415 {
1416 thread_entry_t te;
1417 thread_entry_t te_next;
1418 int count = 0;
1419
1420 for (te = thread_reset_list; te; te = te_next) {
1421 te_next = te->te_next;
1422 te->te_next = thread_entry_freelist;
1423 thread_entry_freelist = te;
1424
1425 count++;
1426 }
1427 thread_reset_list = 0;
1428 }
1429
1430 static void
1431 reset_thread_names(void)
1432 {
1433 thread_entry_t te;
1434 thread_entry_t te_next;
1435 int count = 0;
1436
1437 for (te = thread_reset_list; te; te = te_next) {
1438 threadmap_t tme;
1439
1440 if ((tme = find_thread_entry(te->te_thread))) {
1441 if (tme->tm_orig_command[0]) {
1442 (void)strncpy (tme->tm_command, tme->tm_orig_command, MAXCOMLEN);
1443 tme->tm_command[MAXCOMLEN] = '\0';
1444 tme->tm_orig_command[0] = '\0';
1445 }
1446 }
1447 te_next = te->te_next;
1448 te->te_next = thread_entry_freelist;
1449 thread_entry_freelist = te;
1450
1451 count++;
1452 }
1453 thread_reset_list = 0;
1454 }
1455
1456 static void
1457 delete_all_thread_entries(void)
1458 {
1459 threadmap_t tme = 0;
1460 threadmap_t tme_next = 0;
1461 int i;
1462
1463 for (i = 0; i < HASH_SIZE; i++) {
1464 for (tme = threadmap_hash[i]; tme; tme = tme_next) {
1465 tme_next = tme->tm_next;
1466 tme->tm_next = threadmap_freelist;
1467 threadmap_freelist = tme;
1468 }
1469 threadmap_hash[i] = 0;
1470 }
1471 }
1472
1473 static void
1474 insert_run_event(uint64_t thread, int priority, kd_buf *kd, uint64_t now)
1475 {
1476 threadrun_t trp;
1477
1478 int hashid = thread & HASH_MASK;
1479
1480 for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) {
1481 if (trp->tr_thread == thread) {
1482 break;
1483 }
1484 }
1485 if (trp == NULL) {
1486 if ((trp = threadrun_freelist)) {
1487 threadrun_freelist = trp->tr_next;
1488 } else {
1489 trp = (threadrun_t)malloc(sizeof(struct threadrun));
1490 }
1491
1492 trp->tr_thread = thread;
1493
1494 trp->tr_next = threadrun_hash[hashid];
1495 threadrun_hash[hashid] = trp;
1496
1497 add_thread_entry_to_list(&thread_run_list, thread);
1498 }
1499 trp->tr_entry = kd;
1500 trp->tr_timestamp = now;
1501 trp->tr_priority = priority;
1502 }
1503
1504 static threadrun_t
1505 find_run_event(uint64_t thread)
1506 {
1507 threadrun_t trp;
1508 int hashid = thread & HASH_MASK;
1509
1510 for (trp = threadrun_hash[hashid]; trp; trp = trp->tr_next) {
1511 if (trp->tr_thread == thread) {
1512 return trp;
1513 }
1514 }
1515 return 0;
1516 }
1517
1518 static void
1519 delete_run_event(uint64_t thread)
1520 {
1521 threadrun_t trp = 0;
1522 threadrun_t trp_prev;
1523
1524 int hashid = thread & HASH_MASK;
1525
1526 if ((trp = threadrun_hash[hashid])) {
1527 if (trp->tr_thread == thread) {
1528 threadrun_hash[hashid] = trp->tr_next;
1529 } else {
1530 trp_prev = trp;
1531
1532 for (trp = trp->tr_next; trp; trp = trp->tr_next) {
1533 if (trp->tr_thread == thread) {
1534 trp_prev->tr_next = trp->tr_next;
1535 break;
1536 }
1537 trp_prev = trp;
1538 }
1539 }
1540 if (trp) {
1541 trp->tr_next = threadrun_freelist;
1542 threadrun_freelist = trp;
1543 }
1544 }
1545 }
1546
1547 static void
1548 gc_run_events(void)
1549 {
1550 thread_entry_t te;
1551 thread_entry_t te_next;
1552 threadrun_t trp;
1553 threadrun_t trp_next;
1554 int count = 0;
1555
1556 for (te = thread_run_list; te; te = te_next) {
1557 int hashid = te->te_thread & HASH_MASK;
1558
1559 for (trp = threadrun_hash[hashid]; trp; trp = trp_next) {
1560 trp_next = trp->tr_next;
1561 trp->tr_next = threadrun_freelist;
1562 threadrun_freelist = trp;
1563 count++;
1564 }
1565 threadrun_hash[hashid] = 0;
1566
1567 te_next = te->te_next;
1568 te->te_next = thread_entry_freelist;
1569 thread_entry_freelist = te;
1570 }
1571 thread_run_list = 0;
1572 }
1573
1574
1575
1576 static void
1577 insert_start_event(uint64_t thread, int type, uint64_t now)
1578 {
1579 event_t evp;
1580
1581 int hashid = thread & HASH_MASK;
1582
1583 for (evp = event_hash[hashid]; evp; evp = evp->ev_next) {
1584 if (evp->ev_thread == thread && evp->ev_type == type) {
1585 break;
1586 }
1587 }
1588 if (evp == NULL) {
1589 if ((evp = event_freelist)) {
1590 event_freelist = evp->ev_next;
1591 } else {
1592 evp = (event_t)malloc(sizeof(struct event));
1593 }
1594
1595 evp->ev_thread = thread;
1596 evp->ev_type = type;
1597
1598 evp->ev_next = event_hash[hashid];
1599 event_hash[hashid] = evp;
1600
1601 add_thread_entry_to_list(&thread_event_list, thread);
1602 }
1603 evp->ev_timestamp = now;
1604 }
1605
1606
1607 static uint64_t
1608 consume_start_event(uint64_t thread, int type, uint64_t now)
1609 {
1610 event_t evp;
1611 event_t evp_prev;
1612 uint64_t elapsed = 0;
1613
1614 int hashid = thread & HASH_MASK;
1615
1616 if ((evp = event_hash[hashid])) {
1617 if (evp->ev_thread == thread && evp->ev_type == type) {
1618 event_hash[hashid] = evp->ev_next;
1619 } else {
1620 evp_prev = evp;
1621
1622 for (evp = evp->ev_next; evp; evp = evp->ev_next) {
1623 if (evp->ev_thread == thread && evp->ev_type == type) {
1624 evp_prev->ev_next = evp->ev_next;
1625 break;
1626 }
1627 evp_prev = evp;
1628 }
1629 }
1630 if (evp) {
1631 elapsed = now - evp->ev_timestamp;
1632
1633 if (now < evp->ev_timestamp) {
1634 printf("consume: now = %qd, timestamp = %qd\n", now, evp->ev_timestamp);
1635 elapsed = 0;
1636 }
1637 evp->ev_next = event_freelist;
1638 event_freelist = evp;
1639 }
1640 }
1641 return elapsed;
1642 }
1643
1644 static void
1645 gc_start_events(void)
1646 {
1647 thread_entry_t te;
1648 thread_entry_t te_next;
1649 event_t evp;
1650 event_t evp_next;
1651 int count = 0;
1652 int hashid;
1653
1654 for (te = thread_event_list; te; te = te_next) {
1655
1656 hashid = te->te_thread & HASH_MASK;
1657
1658 for (evp = event_hash[hashid]; evp; evp = evp_next) {
1659 evp_next = evp->ev_next;
1660 evp->ev_next = event_freelist;
1661 event_freelist = evp;
1662 count++;
1663 }
1664 event_hash[hashid] = 0;
1665
1666 te_next = te->te_next;
1667 te->te_next = thread_entry_freelist;
1668 thread_entry_freelist = te;
1669 }
1670 thread_event_list = 0;
1671 }
1672
1673 static int
1674 thread_in_user_mode(uint64_t thread, char *command)
1675 {
1676 event_t evp;
1677
1678 if (strcmp(command, "kernel_task") == 0) {
1679 return 0;
1680 }
1681
1682 int hashid = thread & HASH_MASK;
1683
1684 for (evp = event_hash[hashid]; evp; evp = evp->ev_next) {
1685 if (evp->ev_thread == thread) {
1686 return 0;
1687 }
1688 }
1689 return 1;
1690 }
1691
1692 static lookup_t
1693 handle_lookup_event(uint64_t thread, int debugid, kd_buf *kdp)
1694 {
1695 lookup_t lkp;
1696 boolean_t first_record = FALSE;
1697
1698 int hashid = thread & HASH_MASK;
1699
1700 if (debugid & DBG_FUNC_START) {
1701 first_record = TRUE;
1702 }
1703
1704 for (lkp = lookup_hash[hashid]; lkp; lkp = lkp->lk_next) {
1705 if (lkp->lk_thread == thread) {
1706 break;
1707 }
1708 }
1709 if (lkp == NULL) {
1710 if (first_record == FALSE) {
1711 return 0;
1712 }
1713
1714 if ((lkp = lookup_freelist)) {
1715 lookup_freelist = lkp->lk_next;
1716 } else {
1717 lkp = (lookup_t)malloc(sizeof(struct lookup));
1718 }
1719
1720 lkp->lk_thread = thread;
1721
1722 lkp->lk_next = lookup_hash[hashid];
1723 lookup_hash[hashid] = lkp;
1724
1725 add_thread_entry_to_list(&thread_lookup_list, thread);
1726 }
1727
1728 if (first_record == TRUE) {
1729 lkp->lk_pathptr = lkp->lk_pathname;
1730 lkp->lk_dvp = kdp->arg1;
1731 } else {
1732 if (lkp->lk_pathptr > &lkp->lk_pathname[NUMPARMS-4]) {
1733 return lkp;
1734 }
1735 *lkp->lk_pathptr++ = kdp->arg1;
1736 }
1737 *lkp->lk_pathptr++ = kdp->arg2;
1738 *lkp->lk_pathptr++ = kdp->arg3;
1739 *lkp->lk_pathptr++ = kdp->arg4;
1740 *lkp->lk_pathptr = 0;
1741
1742 if (debugid & DBG_FUNC_END) {
1743 return lkp;
1744 }
1745
1746 return 0;
1747 }
1748
1749 static void
1750 delete_lookup_event(uint64_t thread, lookup_t lkp_to_delete)
1751 {
1752 lookup_t lkp;
1753 lookup_t lkp_prev;
1754 int hashid;
1755
1756 hashid = thread & HASH_MASK;
1757
1758 if ((lkp = lookup_hash[hashid])) {
1759 if (lkp == lkp_to_delete) {
1760 lookup_hash[hashid] = lkp->lk_next;
1761 } else {
1762 lkp_prev = lkp;
1763
1764 for (lkp = lkp->lk_next; lkp; lkp = lkp->lk_next) {
1765 if (lkp == lkp_to_delete) {
1766 lkp_prev->lk_next = lkp->lk_next;
1767 break;
1768 }
1769 lkp_prev = lkp;
1770 }
1771 }
1772 if (lkp) {
1773 lkp->lk_next = lookup_freelist;
1774 lookup_freelist = lkp;
1775 }
1776 }
1777 }
1778
1779 static void
1780 gc_lookup_events(void)
1781 {
1782 thread_entry_t te;
1783 thread_entry_t te_next;
1784 lookup_t lkp;
1785 lookup_t lkp_next;
1786 int count = 0;
1787 int hashid;
1788
1789 for (te = thread_lookup_list; te; te = te_next) {
1790 hashid = te->te_thread & HASH_MASK;
1791
1792 for (lkp = lookup_hash[hashid]; lkp; lkp = lkp_next) {
1793 lkp_next = lkp->lk_next;
1794 lkp->lk_next = lookup_freelist;
1795 lookup_freelist = lkp;
1796 count++;
1797 }
1798 lookup_hash[hashid] = 0;
1799
1800 te_next = te->te_next;
1801 te->te_next = thread_entry_freelist;
1802 thread_entry_freelist = te;
1803 }
1804 thread_lookup_list = 0;
1805 }
1806
1807 int
1808 sample_sc(void)
1809 {
1810 kd_buf *kd, *end_of_sample;
1811 int keep_going = 1;
1812 int i;
1813 ssize_t count;
1814
1815 if (!RAW_flag) {
1816 /*
1817 * Get kernel buffer information
1818 */
1819 get_bufinfo(&bufinfo);
1820 }
1821 if (need_new_map) {
1822 delete_all_thread_entries();
1823 read_command_map();
1824 need_new_map = 0;
1825 }
1826 if (RAW_flag) {
1827 ssize_t bytes_read;
1828
1829 bytes_read = read(RAW_fd, my_buffer, num_entries * sizeof(kd_buf));
1830
1831 if (bytes_read == -1) {
1832 perror("read failed");
1833 exit(2);
1834 }
1835 count = bytes_read / sizeof(kd_buf);
1836
1837 if (count != num_entries) {
1838 keep_going = 0;
1839 }
1840
1841 if (first_read) {
1842 kd = (kd_buf *)my_buffer;
1843 first_now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1844 first_read = 0;
1845 }
1846
1847 } else {
1848 int mib[] = { CTL_KERN, KERN_KDEBUG, KERN_KDREADTR };
1849 size_t needed = bufinfo.nkdbufs * sizeof(kd_buf);
1850
1851 if (sysctl(mib, ARRAYSIZE(mib), my_buffer, &needed, NULL, 0) < 0) {
1852 quit("trace facility failure, KERN_KDREADTR\n");
1853 }
1854
1855 count = needed;
1856 sample_generation++;
1857
1858 if (bufinfo.flags & KDBG_WRAPPED) {
1859 need_new_map = 1;
1860
1861 if (log_fp) {
1862 fprintf(log_fp, "\n\n%-19.19s sample = %d <<<<<<< trace buffer wrapped >>>>>>>\n\n",
1863 &(ctime(&curr_time)[0]), sample_generation);
1864 }
1865 set_enable(0);
1866 set_enable(1);
1867 }
1868 }
1869 end_of_sample = &((kd_buf *)my_buffer)[count];
1870
1871 /*
1872 * Always reinitialize the DECR_TRAP array
1873 */
1874 for (i = 0; i < num_cpus; i++) {
1875 last_decrementer_kd[i] = (kd_buf *)my_buffer;
1876 }
1877
1878 for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) {
1879 kd_buf *kd_start;
1880 uint64_t thread = kd->arg5;
1881 int type = kd->debugid & DBG_FUNC_MASK;
1882
1883 (void)check_for_thread_update(thread, type, kd, NULL);
1884
1885 uint64_t now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1886 last_now = now;
1887
1888 if (type == DECR_TRAP) {
1889 int cpunum = CPU_NUMBER(kd);
1890 double i_latency = handle_decrementer(kd, cpunum);
1891
1892 if (log_fp) {
1893 if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
1894 kd_start = last_decrementer_kd[cpunum];
1895
1896 log_decrementer(kd_start, kd, end_of_sample, i_latency);
1897 }
1898 last_decrementer_kd[cpunum] = kd;
1899 }
1900 } else {
1901 double s_latency;
1902 int s_priority;
1903 if (check_for_scheduler_latency(type, &thread, now, kd, &kd_start, &s_priority, &s_latency)) {
1904 log_scheduler(kd_start, kd, end_of_sample, s_priority, s_latency, thread);
1905 }
1906 }
1907 }
1908 if (log_fp) {
1909 fflush(log_fp);
1910 }
1911
1912 gc_thread_entries();
1913 gc_reset_entries();
1914 gc_run_events();
1915
1916 return keep_going;
1917 }
1918
1919 void
1920 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)
1921 {
1922 char *p;
1923 double timestamp;
1924 double delta;
1925 char pcstring[128];
1926
1927 int cpunum = CPU_NUMBER(kd);
1928
1929 if (print_info && fp) {
1930 timestamp = (double)(now - start_bias) / divisor;
1931 delta = (double)idelta / divisor;
1932
1933 if ((p = find_code(type))) {
1934 if (type == INTERRUPT) {
1935 int mode;
1936
1937 if (kd->arg3) {
1938 mode = USER_MODE;
1939 } else {
1940 mode = KERNEL_MODE;
1941 }
1942
1943 pc_to_string(&pcstring[0], kd->arg2, 58, mode);
1944
1945 fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT[%2" PRIx64 "] @ %-58.58s %8" PRIx64 " %2d %s\n",
1946 timestamp, delta, (uint64_t)kd->arg1, &pcstring[0], thread, cpunum, command);
1947 } else if (type == MACH_vmfault) {
1948 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %8" PRIx64 " %2d %s\n",
1949 timestamp, delta, p, thread, cpunum, command);
1950 } else {
1951 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
1952 timestamp, delta, p, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4,
1953 thread, cpunum, command);
1954 }
1955 } else {
1956 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
1957 timestamp, delta, type, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4,
1958 thread, cpunum, command);
1959 }
1960 }
1961 if (type != BSC_thread_terminate && type != BSC_exit) {
1962 insert_start_event(thread, type, now);
1963 }
1964 }
1965
1966 void
1967 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)
1968 {
1969 char *p;
1970 uint64_t user_addr;
1971 double timestamp;
1972 double delta;
1973 double elapsed_timestamp;
1974
1975 elapsed_timestamp = (double)consume_start_event(thread, type, now) / divisor;
1976
1977 if (print_info && fp) {
1978 int cpunum = CPU_NUMBER(kd);
1979
1980 timestamp = (double)(now - start_bias) / divisor;
1981 delta = (double)idelta / divisor;
1982
1983 fprintf(fp, "%9.1f %8.1f(%.1f) \t", timestamp, delta, elapsed_timestamp);
1984
1985 if ((p = find_code(type))) {
1986 if (type == INTERRUPT) {
1987 fprintf(fp, "INTERRUPT %8" PRIx64 " %2d %s\n", thread, cpunum, command);
1988 } else if (type == MACH_vmfault && kd->arg4 <= DBG_PAGEIND_FAULT) {
1989 user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2;
1990
1991 fprintf(fp, "%-28.28s %-10.10s %-16qx %8" PRIx64 " %2d %s\n",
1992 p, fault_name[kd->arg4], user_addr,
1993 thread, cpunum, command);
1994 } else {
1995 fprintf(fp, "%-28.28s %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
1996 p, (uint64_t)kd->arg1, (uint64_t)kd->arg2,
1997 thread, cpunum, command);
1998 }
1999 } else {
2000 fprintf(fp, "%-8x %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
2001 type, (uint64_t)kd->arg1, (uint64_t)kd->arg2,
2002 thread, cpunum, command);
2003 }
2004 }
2005 }
2006
2007 void
2008 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)
2009 {
2010 char *p;
2011
2012 if (!fp) {
2013 return;
2014 }
2015
2016 int cpunum = CPU_NUMBER(kd);
2017
2018 double timestamp = (double)(now - start_bias) / divisor;
2019 double delta = (double)idelta / divisor;
2020
2021 if ((p = find_code(type))) {
2022 if (kd == kd_note) {
2023 fprintf(fp, "%9.1f %8.1f\t**\t", timestamp, delta);
2024 } else {
2025 fprintf(fp, "%9.1f %8.1f\t\t", timestamp, delta);
2026 }
2027 fprintf(fp, "%-28.28s %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
2028 p, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4, thread, cpunum, command);
2029 } else {
2030 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
2031 timestamp, delta, type, (uint64_t)kd->arg1, (uint64_t)kd->arg2, (uint64_t)kd->arg3, (uint64_t)kd->arg4,
2032 thread, cpunum, command);
2033 }
2034 }
2035
2036 void
2037 check_for_thread_update(uint64_t thread, int debugid_base, kd_buf *kbufp, char **command)
2038 {
2039 if (debugid_base == TRACE_DATA_NEWTHREAD) {
2040 /*
2041 * Save the create thread data
2042 */
2043 create_tmp_map_entry(kbufp->arg1, thread);
2044 } else if (debugid_base == TRACE_STRING_NEWTHREAD) {
2045 /*
2046 * process new map entry
2047 */
2048 find_and_insert_tmp_map_entry(thread, (char *)&kbufp->arg1);
2049 } else if (debugid_base == TRACE_STRING_EXEC) {
2050 exec_thread_entry(thread, (char *)&kbufp->arg1);
2051 } else {
2052 if (debugid_base == BSC_exit || debugid_base == BSC_thread_terminate) {
2053 record_thread_entry_for_gc(thread);
2054 }
2055 if (command) {
2056 find_thread_name(thread, command);
2057 }
2058 }
2059 }
2060
2061 void
2062 log_info(uint64_t now, uint64_t idelta, uint64_t start_bias, kd_buf *kd, kd_buf *kd_note)
2063 {
2064 lookup_t lkp;
2065 int mode;
2066 uint64_t reason;
2067 char *p;
2068 char *command;
2069 char *command1;
2070 char command_buf[32];
2071 char sched_info[64];
2072 char pcstring[128];
2073 const char *sched_reason;
2074 double i_latency;
2075 double timestamp;
2076 double delta;
2077 char joe[32];
2078
2079 uint64_t thread = kd->arg5;
2080 int cpunum = CPU_NUMBER(kd);
2081 int debugid = kd->debugid;
2082 int type = kd->debugid & DBG_FUNC_MASK;
2083
2084 (void)check_for_thread_update(thread, type, kd, &command);
2085
2086 if ((type >> 24) == DBG_TRACE) {
2087 if (((type >> 16) & 0xff) != DBG_TRACE_INFO) {
2088 return;
2089 }
2090 }
2091 timestamp = (double)(now - start_bias) / divisor;
2092 delta = (double)idelta / divisor;
2093
2094 switch (type) {
2095
2096 case CQ_action:
2097 pc_to_string(&pcstring[0], kd->arg1, 84, KERNEL_MODE);
2098
2099 fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-84.84s %8" PRIx64 " %2d %s\n",
2100 timestamp, delta, &pcstring[0], thread, cpunum, command);
2101 break;
2102
2103 case TES_action:
2104 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2105
2106 fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-83.83s %8" PRIx64 " %2d %s\n",
2107 timestamp, delta, &pcstring[0], thread, cpunum, command);
2108 break;
2109
2110 case IES_action:
2111 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2112
2113 fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-83.83s %8" PRIx64 " %2d %s\n",
2114 timestamp, delta, &pcstring[0], thread, cpunum, command);
2115 break;
2116
2117 case IES_filter:
2118 pc_to_string(&pcstring[0], kd->arg1, 83, KERNEL_MODE);
2119
2120 fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-83.83s %8" PRIx64 " %2d %s\n",
2121 timestamp, delta, &pcstring[0], thread, cpunum, command);
2122 break;
2123
2124 case DECR_TRAP:
2125 if ((int)kd->arg1 >= 0) {
2126 i_latency = 0;
2127 } else {
2128 i_latency = (((double)(-1 - kd->arg1)) / divisor);
2129 }
2130
2131 if (i_thresh_hold && (int)i_latency > i_thresh_hold) {
2132 p = "*";
2133 } else {
2134 p = " ";
2135 }
2136
2137 if (kd->arg3) {
2138 mode = USER_MODE;
2139 } else {
2140 mode = KERNEL_MODE;
2141 }
2142
2143 pc_to_string(&pcstring[0], kd->arg2, 84, mode);
2144
2145 fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-84.84s %8" PRIx64 " %2d %s\n",
2146 timestamp, delta, i_latency, p, &pcstring[0], thread, cpunum, command);
2147 break;
2148
2149 case DECR_SET:
2150 fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %8" PRIx64 " %2d %s\n",
2151 timestamp, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command);
2152 break;
2153
2154 case MACH_sched:
2155 case MACH_stkhandoff:
2156
2157 find_thread_name(kd->arg2, &command1);
2158
2159 if (command1 == EMPTYSTRING) {
2160 command1 = command_buf;
2161 sprintf(command1, "%-8" PRIx64, (uint64_t)kd->arg2);
2162 }
2163 if (thread_in_user_mode(kd->arg2, command1)) {
2164 p = "U";
2165 } else {
2166 p = "K";
2167 }
2168
2169 reason = kd->arg1;
2170
2171 if (reason > MAX_REASON) {
2172 sched_reason = "?";
2173 } else {
2174 sched_reason = sched_reasons[reason];
2175 }
2176
2177 if (sched_reason[0] == '?') {
2178 sprintf(joe, "%" PRIx64, reason);
2179 sched_reason = joe;
2180 }
2181 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);
2182
2183 fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s[%s] %s %8" PRIx64 " %2d\n",
2184 timestamp, delta, "MACH_SCHED", sched_reason, sched_info, thread, cpunum);
2185 break;
2186
2187 case VFS_LOOKUP:
2188 if ((lkp = handle_lookup_event(thread, debugid, kd))) {
2189 /*
2190 * print the tail end of the pathname
2191 */
2192 p = (char *)lkp->lk_pathname;
2193 size_t clen = strlen(p);
2194
2195 if (clen > 45) {
2196 clen -= 45;
2197 } else {
2198 clen = 0;
2199 }
2200
2201 fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-59s %-16" PRIx64 " %8" PRIx64 " %2d %s\n",
2202 timestamp, delta, "VFS_LOOKUP",
2203 &p[clen], lkp->lk_dvp, thread, cpunum, command);
2204
2205 delete_lookup_event(thread, lkp);
2206 }
2207 break;
2208
2209 default:
2210 if (debugid & DBG_FUNC_START) {
2211 enter_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1);
2212 } else if (debugid & DBG_FUNC_END) {
2213 exit_syscall(log_fp, kd, thread, type, command, now, idelta, start_bias, 1);
2214 } else {
2215 print_entry(log_fp, kd, thread, type, command, now, idelta, start_bias, kd_note);
2216 }
2217 break;
2218 }
2219 }
2220
2221 static void
2222 log_range(kd_buf *kd_buffer, kd_buf *kd_start, kd_buf *kd_stop, kd_buf *kd_note, char *buf1)
2223 {
2224 uint64_t last_timestamp = 0;
2225 uint64_t delta = 0;
2226 uint64_t start_bias = 0;
2227 uint64_t now;
2228 kd_buf *kd;
2229 size_t clen;
2230 char buf2[128];
2231
2232 clen = strlen(buf1);
2233 memset(buf2, '-', clen);
2234 buf2[clen] = 0;
2235 fprintf(log_fp, "\n\n%s\n", buf2);
2236 fprintf(log_fp, "%s\n\n", buf1);
2237
2238 fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n");
2239
2240 reset_thread_names();
2241
2242 last_timestamp = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2243 start_bias = last_timestamp;
2244
2245 for (kd = kd_buffer; kd <= kd_stop; kd++) {
2246 now = kd->timestamp & KDBG_TIMESTAMP_MASK;
2247
2248 if (kd >= kd_start) {
2249 delta = now - last_timestamp;
2250
2251 log_info(now, delta, start_bias, kd, kd_note);
2252
2253 last_timestamp = now;
2254 } else {
2255 int debugid = kd->debugid;
2256 uint64_t thread = kd->arg5;
2257 int type = kd->debugid & DBG_FUNC_MASK;
2258
2259 if ((type >> 24) == DBG_TRACE) {
2260 if (((type >> 16) & 0xff) != DBG_TRACE_INFO) {
2261 continue;
2262 }
2263 }
2264 if (type == BSC_thread_terminate || type == BSC_exit) {
2265 continue;
2266 }
2267
2268 if (debugid & DBG_FUNC_START) {
2269 insert_start_event(thread, type, now);
2270 } else if (debugid & DBG_FUNC_END) {
2271 (void)consume_start_event(thread, type, now);
2272 }
2273 }
2274 }
2275 gc_start_events();
2276 gc_lookup_events();
2277 }
2278
2279 kd_buf *
2280 log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency)
2281 {
2282 kd_buf *kd_start, *kd_stop;
2283 int kd_count; /* Limit the boundary of kd_start */
2284 uint64_t now;
2285 double sample_timestamp;
2286 char buf1[128];
2287
2288 uint64_t thread = kd_beg->arg5;
2289 int cpunum = CPU_NUMBER(kd_end);
2290
2291 for (kd_count = 0, kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer); kd_start--, kd_count++) {
2292 if (kd_count == MAX_LOG_COUNT) {
2293 break;
2294 }
2295
2296 if (CPU_NUMBER(kd_start) != cpunum) {
2297 continue;
2298 }
2299
2300 if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP) {
2301 break;
2302 }
2303
2304 if (kd_start->arg5 != thread) {
2305 break;
2306 }
2307 }
2308 if (kd_start < (kd_buf *)my_buffer) {
2309 kd_start = (kd_buf *)my_buffer;
2310 }
2311
2312 thread = kd_end->arg5;
2313
2314 for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
2315 if (CPU_NUMBER(kd_stop) != cpunum) {
2316 continue;
2317 }
2318
2319 if ((kd_stop->debugid & DBG_FUNC_MASK) == INTERRUPT) {
2320 break;
2321 }
2322
2323 if (kd_stop->arg5 != thread) {
2324 break;
2325 }
2326 }
2327 if (kd_stop >= end_of_sample) {
2328 kd_stop = end_of_sample - 1;
2329 }
2330
2331 if (RAW_flag) {
2332 time_t TOD_secs;
2333 uint64_t TOD_usecs;
2334
2335 now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2336 sample_timestamp = (double)(now - first_now) / divisor;
2337
2338 TOD_usecs = (uint64_t)sample_timestamp;
2339 TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000);
2340
2341 sprintf(buf1, "%-19.19s interrupt latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), i_latency, sample_timestamp);
2342 } else {
2343 sprintf(buf1, "%-19.19s interrupt latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), i_latency, sample_generation);
2344 }
2345
2346 log_range((kd_buf *)my_buffer, kd_start, kd_stop, 0, buf1);
2347
2348 return kd_stop;
2349 }
2350
2351
2352 void
2353 log_scheduler(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, int s_priority, double s_latency, uint64_t thread)
2354 {
2355 kd_buf *kd_start, *kd_stop;
2356 uint64_t now;
2357 int count;
2358 int cpunum;
2359 uint64_t cmask = 0;
2360 double sample_timestamp;
2361 char buf1[128];
2362
2363 for (count = 0, kd_start = kd_beg; (kd_start >= (kd_buf *)my_buffer); kd_start--) {
2364 cpunum = CPU_NUMBER(kd_start);
2365
2366 cmask |= ((uint64_t)1 << cpunum);
2367
2368 if (cmask == cpu_mask) {
2369 if (count++ > 100)
2370 break;
2371 }
2372 }
2373 if (kd_start < (kd_buf *)my_buffer) {
2374 kd_start = (kd_buf *)my_buffer;
2375 }
2376
2377 for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
2378 if (kd_stop->arg5 == thread) {
2379 break;
2380 }
2381 }
2382 if (kd_stop >= end_of_sample) {
2383 kd_stop = end_of_sample - 1;
2384 }
2385
2386 if (RAW_flag) {
2387 time_t TOD_secs;
2388 uint64_t TOD_usecs;
2389
2390 now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
2391 sample_timestamp = (double)(now - first_now) / divisor;
2392
2393 TOD_usecs = (uint64_t)sample_timestamp;
2394 TOD_secs = (unsigned long)sample_TOD_secs + (unsigned long)((sample_TOD_usecs + TOD_usecs) / 1000000);
2395
2396 sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [timestamp %.1f]", ctime(&TOD_secs), s_priority, s_latency, sample_timestamp);
2397 } else {
2398 sprintf(buf1, "%-19.19s priority = %d, scheduling latency = %.1fus [sample %d]", &(ctime(&curr_time)[0]), s_priority, s_latency, sample_generation);
2399 }
2400
2401 log_range((kd_buf *)my_buffer, kd_start, kd_stop, kd_beg, buf1);
2402 }
2403
2404 int
2405 check_for_scheduler_latency(int type, uint64_t *thread, uint64_t now, kd_buf *kd, kd_buf **kd_start, int *priority, double *latency)
2406 {
2407 int found_latency = 0;
2408
2409 if (type == MACH_makerunnable) {
2410 if (watch_priority_min <= kd->arg2 && kd->arg2 <= watch_priority_max) {
2411 insert_run_event(kd->arg1, (int)kd->arg2, kd, now);
2412 }
2413 } else if (type == MACH_sched || type == MACH_stkhandoff) {
2414 threadrun_t trp = find_run_event(kd->arg2);
2415
2416 if (type == MACH_sched || type == MACH_stkhandoff) {
2417 *thread = kd->arg2;
2418 }
2419
2420 if ((trp = find_run_event(*thread))) {
2421 double d_s_latency = (((double)(now - trp->tr_timestamp)) / divisor);
2422 int s_latency = (int)d_s_latency;
2423
2424 if (s_latency) {
2425 if (s_latency < 100) {
2426 s_usec_10_bins[s_latency/10]++;
2427 }
2428 if (s_latency < 1000) {
2429 s_usec_100_bins[s_latency/100]++;
2430 } else if (s_latency < 10000) {
2431 s_msec_1_bins[s_latency/1000]++;
2432 } else if (s_latency < 50000) {
2433 s_msec_10_bins[s_latency/10000]++;
2434 } else {
2435 s_too_slow++;
2436 }
2437
2438 if (s_latency > s_max_latency) {
2439 s_max_latency = s_latency;
2440 }
2441 if (s_latency < s_min_latency || s_total_samples == 0) {
2442 s_min_latency = s_latency;
2443 }
2444 s_total_latency += s_latency;
2445 s_total_samples++;
2446
2447 if (s_thresh_hold && s_latency > s_thresh_hold) {
2448 s_exceeded_threshold++;
2449
2450 if (log_fp) {
2451 *kd_start = trp->tr_entry;
2452 *priority = trp->tr_priority;
2453 *latency = d_s_latency;
2454 found_latency = 1;
2455 }
2456 }
2457 }
2458 delete_run_event(*thread);
2459 }
2460 }
2461 return found_latency;
2462 }
2463
2464 double
2465 handle_decrementer(kd_buf *kd, int cpunum)
2466 {
2467 struct i_latencies *il;
2468 double latency;
2469 long elapsed_usecs;
2470
2471 if (i_latency_per_cpu == FALSE) {
2472 cpunum = 0;
2473 }
2474
2475 il = &i_lat[cpunum];
2476
2477 if ((long)(kd->arg1) >= 0) {
2478 latency = 1;
2479 } else {
2480 latency = (((double)(-1 - kd->arg1)) / divisor);
2481 }
2482 elapsed_usecs = (long)latency;
2483
2484 if (elapsed_usecs < 100) {
2485 il->i_usec_10_bins[elapsed_usecs/10]++;
2486 }
2487
2488 if (elapsed_usecs < 1000) {
2489 il->i_usec_100_bins[elapsed_usecs/100]++;
2490 } else if (elapsed_usecs < 10000) {
2491 il->i_msec_1_bins[elapsed_usecs/1000]++;
2492 } else if (elapsed_usecs < 50000) {
2493 il->i_msec_10_bins[elapsed_usecs/10000]++;
2494 } else {
2495 il->i_too_slow++;
2496 }
2497
2498 if (use_high_res_bins && elapsed_usecs < N_HIGH_RES_BINS) {
2499 i_high_res_bins[elapsed_usecs]++;
2500 }
2501 if (i_thresh_hold && elapsed_usecs > i_thresh_hold) {
2502 il->i_exceeded_threshold++;
2503 }
2504 if (elapsed_usecs > il->i_max_latency) {
2505 il->i_max_latency = elapsed_usecs;
2506 }
2507 if (elapsed_usecs < il->i_min_latency || il->i_total_samples == 0) {
2508 il->i_min_latency = elapsed_usecs;
2509 }
2510 il->i_total_latency += elapsed_usecs;
2511 il->i_total_samples++;
2512
2513 return latency;
2514 }
2515
2516 char *
2517 find_code(int type)
2518 {
2519 int i;
2520 for (i = 0; i < num_of_codes; i++) {
2521 if (codes_tab[i].type == type) {
2522 return codes_tab[i].name;
2523 }
2524 }
2525 return NULL;
2526 }
2527
2528 void
2529 init_code_file(void)
2530 {
2531 FILE *fp;
2532 int i;
2533
2534 if ((fp = fopen(code_file, "r")) == NULL) {
2535 if (log_fp) {
2536 fprintf(log_fp, "open of %s failed\n", code_file);
2537 }
2538 return;
2539 }
2540 for (i = 0; i < MAX_ENTRIES; i++) {
2541 int code;
2542 char name[128];
2543 int n = fscanf(fp, "%x%127s\n", &code, name);
2544
2545 if (n == 1 && i == 0) {
2546 /*
2547 * old code file format, just skip
2548 */
2549 continue;
2550 }
2551 if (n != 2) {
2552 break;
2553 }
2554
2555 strncpy(codes_tab[i].name, name, 32);
2556 codes_tab[i].type = code;
2557 }
2558 num_of_codes = i;
2559
2560 fclose(fp);
2561 }
2562
2563 void
2564 do_kernel_nm(void)
2565 {
2566 int i;
2567 size_t len;
2568 FILE *fp = NULL;
2569 char tmp_nm_file[128];
2570 char tmpstr[1024];
2571 char inchr;
2572
2573 bzero(tmp_nm_file, 128);
2574 bzero(tmpstr, 1024);
2575
2576 /*
2577 * Build the temporary nm file path
2578 */
2579 strcpy(tmp_nm_file,"/tmp/knm.out.XXXXXX");
2580
2581 if (!mktemp(tmp_nm_file)) {
2582 fprintf(stderr, "Error in mktemp call\n");
2583 return;
2584 }
2585
2586 /*
2587 * Build the nm command and create a tmp file with the output
2588 */
2589 sprintf (tmpstr, "/usr/bin/nm -n %s -s __TEXT __text > %s",
2590 kernelpath, tmp_nm_file);
2591 system(tmpstr);
2592
2593 /*
2594 * Parse the output from the nm command
2595 */
2596 if ((fp = fopen(tmp_nm_file, "r")) == NULL) {
2597 /* Hmmm, let's not treat this as fatal */
2598 fprintf(stderr, "Failed to open nm symbol file [%s]\n", tmp_nm_file);
2599 return;
2600 }
2601 /*
2602 * Count the number of symbols in the nm symbol table
2603 */
2604 kern_sym_count = 0;
2605
2606 while ((inchr = getc(fp)) != -1) {
2607 if (inchr == '\n') {
2608 kern_sym_count++;
2609 }
2610 }
2611 rewind(fp);
2612
2613 /*
2614 * Malloc the space for symbol table
2615 */
2616 if (kern_sym_count > 0) {
2617 kern_sym_tbl = malloc(kern_sym_count * sizeof(kern_sym_t));
2618
2619 if (!kern_sym_tbl) {
2620 /*
2621 * Hmmm, lets not treat this as fatal
2622 */
2623 fprintf(stderr, "Can't allocate memory for kernel symbol table\n");
2624 } else {
2625 bzero(kern_sym_tbl, kern_sym_count * sizeof(kern_sym_t));
2626 }
2627 } else {
2628 /*
2629 * Hmmm, lets not treat this as fatal
2630 */
2631 fprintf(stderr, "No kernel symbol table \n");
2632 }
2633 for (i = 0; i < kern_sym_count; i++) {
2634 bzero(tmpstr, 1024);
2635
2636 if (fscanf(fp, "%p %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3) {
2637 break;
2638 } else {
2639 len = strlen(tmpstr);
2640 kern_sym_tbl[i].k_sym_name = malloc(len + 1);
2641
2642 if (kern_sym_tbl[i].k_sym_name == NULL) {
2643 fprintf(stderr, "Can't allocate memory for symbol name [%s]\n", tmpstr);
2644 kern_sym_tbl[i].k_sym_name = NULL;
2645 len = 0;
2646 } else {
2647 strcpy(kern_sym_tbl[i].k_sym_name, tmpstr);
2648 }
2649
2650 kern_sym_tbl[i].k_sym_len = len;
2651 }
2652 }
2653 if (i != kern_sym_count) {
2654 /*
2655 * Hmmm, didn't build up entire table from nm
2656 * scrap the entire thing
2657 */
2658 free(kern_sym_tbl);
2659 kern_sym_tbl = NULL;
2660 kern_sym_count = 0;
2661 }
2662 fclose(fp);
2663
2664 /*
2665 * Remove the temporary nm file
2666 */
2667 unlink(tmp_nm_file);
2668 #if 0
2669 /*
2670 * Dump the kernel symbol table
2671 */
2672 for (i = 0; i < kern_sym_count; i++) {
2673 if (kern_sym_tbl[i].k_sym_name) {
2674 printf ("[%d] %-16p %s\n", i,
2675 kern_sym_tbl[i].k_sym_addr, kern_sym_tbl[i].k_sym_name);
2676 } else {
2677 printf ("[%d] %-16p %s\n", i,
2678 kern_sym_tbl[i].k_sym_addr, "No symbol name");
2679 }
2680 }
2681 #endif
2682 }
2683
2684 void
2685 pc_to_string(char *pcstring, uint64_t pc, int max_len, int mode)
2686 {
2687 int ret;
2688 size_t len;
2689
2690 if (mode == USER_MODE) {
2691 sprintf(pcstring, "%-16" PRIx64 " [usermode addr]", pc);
2692 return;
2693 }
2694 ret = binary_search(kern_sym_tbl, 0, kern_sym_count-1, pc);
2695
2696 if (ret == -1 || kern_sym_tbl[ret].k_sym_name == NULL) {
2697 sprintf(pcstring, "%-16" PRIx64, pc);
2698 return;
2699 }
2700 if ((len = kern_sym_tbl[ret].k_sym_len) > (max_len - 8)) {
2701 len = max_len - 8;
2702 }
2703
2704 memcpy(pcstring, kern_sym_tbl[ret].k_sym_name, len);
2705
2706 sprintf(&pcstring[len], "+0x%-5" PRIx64, pc - (uint64_t)kern_sym_tbl[ret].k_sym_addr);
2707 }
2708
2709
2710 /*
2711 * Return -1 if not found, else return index
2712 */
2713 int
2714 binary_search(kern_sym_t *list, int low, int high, uint64_t addr)
2715 {
2716 int mid;
2717
2718 if (kern_sym_count == 0) {
2719 return -1;
2720 }
2721
2722 if (low > high) {
2723 return -1; /* failed */
2724 }
2725
2726 if (low + 1 == high) {
2727 if ((uint64_t)list[low].k_sym_addr <= addr && addr < (uint64_t)list[high].k_sym_addr) {
2728 /*
2729 * We have a range match
2730 */
2731 return low;
2732 }
2733 if ((uint64_t)list[high].k_sym_addr <= addr) {
2734 return high;
2735 }
2736 /*
2737 * Failed
2738 */
2739 return -1;
2740 }
2741 mid = (low + high) / 2;
2742
2743 if (addr < (uint64_t)list[mid].k_sym_addr) {
2744 return binary_search(list, low, mid, addr);
2745 }
2746
2747 return binary_search(list, mid, high, addr);
2748 }
2749
2750 void
2751 open_logfile(const char *path)
2752 {
2753 log_fp = fopen(path, "a");
2754
2755 if (!log_fp) {
2756 /*
2757 * failed to open path
2758 */
2759 fprintf(stderr, "latency: failed to open logfile [%s]\n", path);
2760 exit_usage();
2761 }
2762 }
2763
2764 void
2765 open_rawfile(const char *path)
2766 {
2767 RAW_fd = open(path, O_RDONLY);
2768
2769 if (RAW_fd == -1) {
2770 /*
2771 * failed to open path
2772 */
2773 fprintf(stderr, "latency: failed to open RAWfile [%s]\n", path);
2774 exit_usage();
2775 }
2776 }
2777
2778 void
2779 getdivisor(void)
2780 {
2781 mach_timebase_info_data_t info;
2782
2783 (void)mach_timebase_info(&info);
2784
2785 divisor = ((double)info.denom / (double)info.numer) * 1000;
2786 }
mirror of system_cmds