]> git.saurik.com Git - apple/system_cmds.git/blame - latency.tproj/latency.c
projects / apple / system_cmds.git / blame
? search:
summary | shortlog | log | commit | commitdiff | tree
blob | blame (incremental) | history | HEAD
system_cmds-498.2.tar.gz
[apple/system_cmds.git] / latency.tproj / latency.c
CommitLineData
1815bff5
A		 1/*
2 * Copyright (c) 1999 Apple Computer, Inc. All rights reserved.
3 *
4 * @APPLE_LICENSE_HEADER_START@
5 *
2fc1e207
A		 6 * "Portions Copyright (c) 1999 Apple Computer, Inc. All Rights
7 * Reserved. This file contains Original Code and/or Modifications of
8 * Original Code as defined in and that are subject to the Apple Public
9 * Source License Version 1.0 (the 'License'). You may not use this file
10 * except in compliance with the License. Please obtain a copy of the
11 * License at http://www.apple.com/publicsource and read it before using
12 * this file.
1815bff5
A		 13 *
14 * The Original Code and all software distributed under the License are
15 * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
16 * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
17 * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
2fc1e207
A		 18 * FITNESS FOR A PARTICULAR PURPOSE OR NON-INFRINGEMENT. Please see the
19 * License for the specific language governing rights and limitations
20 * under the License."
1815bff5
A		 21 *
22 * @APPLE_LICENSE_HEADER_END@
23 */
24
25
26/*
09fd88e4 27 cc -I. -DPRIVATE -D__APPLE_PRIVATE -O -o latency latency.c -lncurses
1815bff5
A		 28*/
29
30#include <mach/mach.h>
31#include <stdlib.h>
32#include <stdio.h>
34d340d7 33#include <unistd.h>
1815bff5
A		 34#include <signal.h>
35#include <strings.h>
36#include <nlist.h>
37#include <fcntl.h>
38#include <string.h>
39
40#include <sys/types.h>
41#include <sys/param.h>
42#include <sys/time.h>
43
44#include <libc.h>
45#include <termios.h>
b51d5b5f 46#include <curses.h>
1815bff5
A		 47#include <sys/ioctl.h>
48
49#ifndef KERNEL_PRIVATE
50#define KERNEL_PRIVATE
51#include <sys/kdebug.h>
52#undef KERNEL_PRIVATE
53#else
54#include <sys/kdebug.h>
55#endif /*KERNEL_PRIVATE*/
56
ef8ad44b
A		 57#include <libutil.h>
58
1815bff5
A		 59#include <sys/sysctl.h>
60#include <errno.h>
61#include <err.h>
62
63#include <mach/host_info.h>
64#include <mach/mach_error.h>
65#include <mach/mach_types.h>
66#include <mach/message.h>
67#include <mach/mach_syscalls.h>
1815bff5 68#include <mach/clock_types.h>
1c51fdde 69#include <mach/mach_time.h>
1815bff5
A		 70
71#include <libkern/OSTypes.h>
72
73extern mach_port_t clock_port;
74
75#define KERN_KDPIDEX 14
76
77
78int s_usec_10_bins[10];
79int s_usec_100_bins[10];
80int s_msec_1_bins[10];
81int s_msec_10_bins[5];
82int s_too_slow;
83int s_max_latency;
84int s_min_latency = 0;
85long long s_total_latency = 0;
86int s_total_samples;
87long s_thresh_hold;
88int s_exceeded_threshold = 0;
89
90int i_usec_10_bins[10];
91int i_usec_100_bins[10];
92int i_msec_1_bins[10];
93int i_msec_10_bins[5];
94int i_too_slow;
95int i_max_latency;
96int i_min_latency = 0;
97long long i_total_latency = 0;
98int i_total_samples;
99long i_thresh_hold;
100int i_exceeded_threshold = 0;
101
102long start_time;
103long curr_time;
104long refresh_time;
105
106char *policy_name;
107int my_policy;
108int my_pri = -1;
109int num_of_usecs_to_sleep = 1000;
110
c03df0e9
A		 111#define N_HIGH_RES_BINS 500
112int use_high_res_bins = false;
113int i_high_res_bins[N_HIGH_RES_BINS];
114int i_highest_latency = 0;
115
1815bff5
A		 116char *kernelpath = (char *)0;
117char *code_file = (char *)0;
118
119typedef struct {
120 u_long k_sym_addr; /* kernel symbol address from nm */
121 u_int k_sym_len; /* length of kernel symbol string */
122 char *k_sym_name; /* kernel symbol string from nm */
123} kern_sym_t;
124
125kern_sym_t *kern_sym_tbl; /* pointer to the nm table */
126int kern_sym_count; /* number of entries in nm table */
127char pcstring[128];
128
129#define UNKNOWN "Can't find symbol name"
130
131
132double divisor;
133int gotSIGWINCH = 0;
134int trace_enabled = 0;
b51d5b5f
A		 135struct host_basic_info hi;
136
1815bff5
A		 137
138#define SAMPLE_SIZE 300000
139
140int mib[6];
141size_t needed;
142char *my_buffer;
143
144kbufinfo_t bufinfo = {0, 0, 0};
145
146FILE *log_fp = (FILE *)0;
147int num_of_codes = 0;
148int need_new_map = 0;
149int total_threads = 0;
150kd_threadmap *mapptr = 0;
151
34d340d7 152#define MAX_ENTRIES 4096
1815bff5
A		 153struct ct {
154 int type;
155 char name[32];
156} codes_tab[MAX_ENTRIES];
157
09fd88e4 158
1c51fdde 159#define NUMPARMS 23
1815bff5
A		 160
161struct th_info {
ef8ad44b 162 uintptr_t thread;
1815bff5 163 int type;
ef8ad44b 164 uintptr_t child_thread;
1815bff5
A		 165 int arg1;
166 double stime;
1c51fdde 167 long *pathptr;
09fd88e4 168 long pathname[NUMPARMS + 1];
1815bff5
A		 169};
170
171#define MAX_THREADS 512
172struct th_info th_state[MAX_THREADS];
173
174int cur_max = 0;
175
176#define TRACE_DATA_NEWTHREAD 0x07000004
177#define TRACE_STRING_NEWTHREAD 0x07010004
178#define TRACE_STRING_EXEC 0x07010008
179
180#define INTERRUPT 0x01050000
181#define DECR_TRAP 0x01090000
182#define DECR_SET 0x01090004
34d340d7 183#define MACH_vmfault 0x01300008
1815bff5
A		 184#define MACH_sched 0x01400000
185#define MACH_stkhandoff 0x01400008
186#define VFS_LOOKUP 0x03010090
187#define BSC_exit 0x040C0004
188#define IES_action 0x050b0018
189#define IES_filter 0x050b001c
190#define TES_action 0x050c0010
191#define CQ_action 0x050d0018
192
193
194#define DBG_FUNC_ALL (DBG_FUNC_START | DBG_FUNC_END)
195#define DBG_FUNC_MASK 0xfffffffc
196
ef8ad44b 197#define CPU_NUMBER(kp) kdbg_get_cpu(kp)
83f6dbe8 198
1815bff5 199
ef8ad44b 200char *fault_name[9] = {
1815bff5
A		 201 "",
202 "ZeroFill",
203 "PageIn",
204 "COW",
205 "CacheHit",
ef8ad44b
A		 206 "NoZeroFill",
207 "Guard",
208 "PageInFile",
209 "PageInAnon"
1815bff5
A		 210};
211
212char *pc_to_string();
213static kern_return_t set_time_constraint_policy(void);
214static kern_return_t set_standard_policy(void);
215
216int decrementer_val = 0; /* Value used to reset decrementer */
217int set_remove_flag = 1; /* By default, remove trace buffer */
218
b51d5b5f
A		 219kd_buf **last_decrementer_kd; /* last DECR_TRAP per cpu */
220#define MAX_LOG_COUNT 30 /* limits the number of entries dumped in log_decrementer */
221
1815bff5
A		 222int
223quit(s)
224char *s;
225{
226 void set_enable();
227 void set_rtcdec();
228 void set_remove();
229
230 if (trace_enabled)
231 set_enable(0);
232
233 /*
234 This flag is turned off when calling
235 quit() due to a set_remove() failure.
236 */
237 if (set_remove_flag)
238 set_remove();
239
240 if (decrementer_val)
241 set_rtcdec(0);
242
243 printf("latency: ");
244 if (s)
245 printf("%s", s);
246
247 exit(1);
248}
249
250void
251set_enable(int val)
252{
253 mib[0] = CTL_KERN;
254 mib[1] = KERN_KDEBUG;
255 mib[2] = KERN_KDENABLE; /* protocol */
256 mib[3] = val;
257 mib[4] = 0;
258 mib[5] = 0; /* no flags */
259
260 if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0)
261 quit("trace facility failure, KERN_KDENABLE\n");
262}
263
264void
265set_numbufs(int nbufs)
266{
267 mib[0] = CTL_KERN;
268 mib[1] = KERN_KDEBUG;
269 mib[2] = KERN_KDSETBUF;
270 mib[3] = nbufs;
271 mib[4] = 0;
272 mib[5] = 0; /* no flags */
273 if (sysctl(mib, 4, NULL, &needed, NULL, 0) < 0)
274 quit("trace facility failure, KERN_KDSETBUF\n");
275
276 mib[0] = CTL_KERN;
277 mib[1] = KERN_KDEBUG;
278 mib[2] = KERN_KDSETUP;
279 mib[3] = 0;
280 mib[4] = 0;
281 mib[5] = 0; /* no flags */
282 if (sysctl(mib, 3, NULL, &needed, NULL, 0) < 0)
283 quit("trace facility failure, KERN_KDSETUP\n");
284
285}
286
287void
288set_pidexclude(int pid, int on_off)
289{
290 kd_regtype kr;
291
292 kr.type = KDBG_TYPENONE;
293 kr.value1 = pid;
294 kr.value2 = on_off;
295 needed = sizeof(kd_regtype);
296 mib[0] = CTL_KERN;
297 mib[1] = KERN_KDEBUG;
298 mib[2] = KERN_KDPIDEX;
299 mib[3] = 0;
300 mib[4] = 0;
301 mib[5] = 0;
302
303 sysctl(mib, 3, &kr, &needed, NULL, 0);
304}
305
83f6dbe8 306void set_rtcdec(decval)
1815bff5
A		 307int decval;
308{kd_regtype kr;
309 int ret;
310 extern int errno;
311
312 kr.type = KDBG_TYPENONE;
313 kr.value1 = decval;
314 needed = sizeof(kd_regtype);
315 mib[0] = CTL_KERN;
316 mib[1] = KERN_KDEBUG;
317 mib[2] = KERN_KDSETRTCDEC; /* protocol */
318 mib[3] = 0; /* wildcard address family */
319 mib[4] = 0;
320 mib[5] = 0; /* no flags */
321
322 errno = 0;
1815bff5
A		 323 if ((ret=sysctl(mib, 3, &kr, &needed, NULL, 0)) < 0)
324 {
83f6dbe8
A		 325 decrementer_val = 0;
326 /* ignore this sysctl error if it's not supported */
327 if (errno == ENOENT)
328 return;
329 else
330 quit("trace facility failure, KERN_KDSETRTCDEC\n");
1815bff5
A		 331 }
332}
333
334
335void
336get_bufinfo(kbufinfo_t *val)
337{
338 needed = sizeof (*val);
339 mib[0] = CTL_KERN;
340 mib[1] = KERN_KDEBUG;
341 mib[2] = KERN_KDGETBUF;
342 mib[3] = 0;
343 mib[4] = 0;
344 mib[5] = 0; /* no flags */
345
346 if (sysctl(mib, 3, val, &needed, 0, 0) < 0)
347 quit("trace facility failure, KERN_KDGETBUF\n");
348
349}
350
351void
352set_remove()
353{
354 extern int errno;
355
356 mib[0] = CTL_KERN;
357 mib[1] = KERN_KDEBUG;
358 mib[2] = KERN_KDREMOVE; /* protocol */
359 mib[3] = 0;
360 mib[4] = 0;
361 mib[5] = 0; /* no flags */
362
363 errno = 0;
364
365 if (sysctl(mib, 3, NULL, &needed, NULL, 0) < 0)
366 {
367 set_remove_flag = 0;
368 if(errno == EBUSY)
369 quit("the trace facility is currently in use...\n fs_usage, sc_usage, and latency use this feature.\n\n");
370 else
371 quit("trace facility failure, KERN_KDREMOVE\n");
372 }
373}
374
375void
376set_init_nologging()
377{
378 /* When we aren't logging, only collect the DECR_TRAP trace points */
379 kd_regtype kr;
380 kr.type = KDBG_VALCHECK;
381 kr.value1 = DECR_TRAP;
382 kr.value2 = 0;
383 kr.value3 = 0;
384 kr.value4 = 0;
385 needed = sizeof(kd_regtype);
386 mib[0] = CTL_KERN;
387 mib[1] = KERN_KDEBUG;
388 mib[2] = KERN_KDSETREG;
389 mib[3] = 0;
390 mib[4] = 0;
391 mib[5] = 0; /* no flags */
392 if (sysctl(mib, 3, &kr, &needed, NULL, 0) < 0)
393 quit("trace facility failure, KERN_KDSETREG\n");
394
395 mib[0] = CTL_KERN;
396 mib[1] = KERN_KDEBUG;
397 mib[2] = KERN_KDSETUP;
398 mib[3] = 0;
399 mib[4] = 0;
400 mib[5] = 0; /* no flags */
401
402 if (sysctl(mib, 3, NULL, &needed, NULL, 0) < 0)
403 quit("trace facility failure, KERN_KDSETUP\n");
404}
405
406void
407set_init_logging()
408{ kd_regtype kr;
409
410 kr.type = KDBG_RANGETYPE;
411 kr.value1 = 0;
412 kr.value2 = -1;
413 needed = sizeof(kd_regtype);
414 mib[0] = CTL_KERN;
415 mib[1] = KERN_KDEBUG;
416 mib[2] = KERN_KDSETREG;
417 mib[3] = 0;
418 mib[4] = 0;
419 mib[5] = 0; /* no flags */
420
421 if (sysctl(mib, 3, &kr, &needed, NULL, 0) < 0)
422 quit("trace facility failure, KERN_KDSETREG\n");
423
424 mib[0] = CTL_KERN;
425 mib[1] = KERN_KDEBUG;
426 mib[2] = KERN_KDSETUP;
427 mib[3] = 0;
428 mib[4] = 0;
429 mib[5] = 0; /* no flags */
430
431 if (sysctl(mib, 3, NULL, &needed, NULL, 0) < 0)
432 quit("trace facility failure, KERN_KDSETUP\n");
433}
434
c03df0e9
A		 435void
436write_high_res_latencies()
437{
438 int i;
439 FILE *f;
440 if(use_high_res_bins)
441 {
442 f = fopen("latencies.csv","w");
443 for(i=0;i<N_HIGH_RES_BINS;i++)
444 {
445 fprintf(f,"%d,%d\n", i, i_high_res_bins[i]);
446 }
447 fclose(f);
448 }
449}
1815bff5
A		 450
451void sigwinch()
452{
453 gotSIGWINCH = 1;
454}
455
456void sigintr()
457{
458 void screen_update();
459
c03df0e9
A		 460 write_high_res_latencies();
461
1815bff5
A		 462 set_enable(0);
463 set_pidexclude(getpid(), 0);
464 screen_update(log_fp);
20e66415 465 endwin();
1815bff5
A		 466 set_rtcdec(0);
467 set_remove();
468
469 exit(1);
470}
471
b51d5b5f 472void leave() /* exit under normal conditions -- signal handler */
1815bff5 473{
c03df0e9
A		 474 write_high_res_latencies();
475
1815bff5
A		 476 set_enable(0);
477 set_pidexclude(getpid(), 0);
20e66415 478 endwin();
1815bff5
A		 479 set_rtcdec(0);
480 set_remove();
481
482 exit(1);
483}
484
1815bff5
A		 485void
486screen_update(FILE *fp)
487{
488 int i;
489 int itotal, stotal;
490 int elapsed_secs;
491 int elapsed_mins;
492 int elapsed_hours;
493 unsigned int average_s_latency;
494 unsigned int average_i_latency;
495 char tbuf[256];
496
497 if (fp == (FILE *)0) {
498 erase();
499 move(0, 0);
500 } else
501 fprintf(fp,"\n\n===================================================================================================\n");
502 /*
503 * Display the current time.
504 * "ctime" always returns a string that looks like this:
505 *
506 * Sun Sep 16 01:03:52 1973
507 * 012345678901234567890123
508 * 1 2
509 *
510 * We want indices 11 thru 18 (length 8).
511 */
512 elapsed_secs = curr_time - start_time;
513 elapsed_hours = elapsed_secs / 3600;
514 elapsed_secs -= elapsed_hours * 3600;
515 elapsed_mins = elapsed_secs / 60;
516 elapsed_secs -= elapsed_mins * 60;
517
518 sprintf(tbuf, "%-19.19s %2ld:%02ld:%02ld\n", &(ctime(&curr_time)[0]),
83f6dbe8 519 (long)elapsed_hours, (long)elapsed_mins, (long)elapsed_secs);
1815bff5
A		 520 if (fp)
521 fprintf(fp, "%s", tbuf);
522 else
523 printw(tbuf);
524
c03df0e9
A		 525 if (use_high_res_bins) {
526 sprintf(tbuf, "INTERRUPTS(HIGH RESOLUTION)\n");
1815bff5 527
c03df0e9
A		 528 if (fp)
529 fprintf(fp, "%s", tbuf);
530 else
531 printw(tbuf);
532 }
533 if(use_high_res_bins)
534 {
535 for(i=0;i<N_HIGH_RES_BINS;i++) {
536 if(i && !(i%10)) {
537 sprintf(tbuf,"\n");
538 if (fp)
539 fprintf(fp, "%s", tbuf);
540 else
541 printw(tbuf);
542 }
543#define INDEX(i) ((i%10)*50 + (i/10))
544 if(INDEX(i) <= i_highest_latency)
545 sprintf(tbuf,"[%3d]: %6d ", INDEX(i), i_high_res_bins[INDEX(i)]);
546 else
547 tbuf[0] = '\0';
548
549 if (fp)
550 fprintf(fp, "%s", tbuf);
551 else
552 printw(tbuf);
553 }
554 sprintf(tbuf,"\n\n");
555 if (fp)
556 fprintf(fp, "%s", tbuf);
557 else
558 printw(tbuf);
559 }
1815bff5
A		 560
561 sprintf(tbuf, " SCHEDULER INTERRUPTS\n");
562
563 if (fp)
564 fprintf(fp, "%s", tbuf);
565 else
566 printw(tbuf);
567
568 sprintf(tbuf, "---------------------------------------------\n");
569
570 if (fp)
571 fprintf(fp, "%s", tbuf);
572 else
573 printw(tbuf);
574
575
576
577 sprintf(tbuf, "total_samples %10d %10d\n\n", s_total_samples, i_total_samples);
578
579 if (fp)
580 fprintf(fp, "%s", tbuf);
581 else
582 printw(tbuf);
583
584
585
586 for (itotal = 0, stotal = 0, i = 0; i < 10; i++) {
587 sprintf(tbuf, "delays < %3d usecs %10d %10d\n", (i + 1) * 10, s_usec_10_bins[i], i_usec_10_bins[i]);
588
589 if (fp)
590 fprintf(fp, "%s", tbuf);
591 else
592 printw(tbuf);
593
594 stotal += s_usec_10_bins[i];
595 itotal += i_usec_10_bins[i];
596 }
597 sprintf(tbuf, "total < 100 usecs %10d %10d\n\n", stotal, itotal);
598
599 if (fp)
600 fprintf(fp, "%s", tbuf);
601 else
602 printw(tbuf);
603
604
605
606 for (itotal = 0, stotal = 0, i = 1; i < 10; i++) {
607 if (i < 9)
608 sprintf(tbuf, "delays < %3d usecs %10d %10d\n", (i + 1) * 100, s_usec_100_bins[i], i_usec_100_bins[i]);
609 else
610 sprintf(tbuf, "delays < 1 msec %10d %10d\n", s_usec_100_bins[i], i_usec_100_bins[i]);
611
612 if (fp)
613 fprintf(fp, "%s", tbuf);
614 else
615 printw(tbuf);
616
617 stotal += s_usec_100_bins[i];
618 itotal += i_usec_100_bins[i];
619 }
620 sprintf(tbuf, "total < 1 msec %10d %10d\n\n", stotal, itotal);
621
622 if (fp)
623 fprintf(fp, "%s", tbuf);
624 else
625 printw(tbuf);
626
627
628
629 for (itotal = 0, stotal = 0, i = 1; i < 10; i++) {
630 sprintf(tbuf, "delays < %3d msecs %10d %10d\n", (i + 1), s_msec_1_bins[i], i_msec_1_bins[i]);
631
632 if (fp)
633 fprintf(fp, "%s", tbuf);
634 else
635 printw(tbuf);
636
637 stotal += s_msec_1_bins[i];
638 itotal += i_msec_1_bins[i];
639 }
640 sprintf(tbuf, "total < 10 msecs %10d %10d\n\n", stotal, itotal);
641
642 if (fp)
643 fprintf(fp, "%s", tbuf);
644 else
645 printw(tbuf);
646
647
648
649
650 for (itotal = 0, stotal = 0, i = 1; i < 5; i++) {
651 sprintf(tbuf, "delays < %3d msecs %10d %10d\n", (i + 1)*10, s_msec_10_bins[i], i_msec_10_bins[i]);
652
653 if (fp)
654 fprintf(fp, "%s", tbuf);
655 else
656 printw(tbuf);
657
658 stotal += s_msec_10_bins[i];
659 itotal += i_msec_10_bins[i];
660 }
661 sprintf(tbuf, "total < 50 msecs %10d %10d\n\n", stotal, itotal);
662
663 if (fp)
664 fprintf(fp, "%s", tbuf);
665 else
666 printw(tbuf);
667
668 sprintf(tbuf, "delays > 50 msecs %10d %10d\n", s_too_slow, i_too_slow);
669
670 if (fp)
671 fprintf(fp, "%s", tbuf);
672 else
673 printw(tbuf);
674
675
676
677 sprintf(tbuf, "\nminimum latency(usecs) %7d %7d\n", s_min_latency, i_min_latency);
678
679 if (fp)
680 fprintf(fp, "%s", tbuf);
681 else
682 printw(tbuf);
683
684 sprintf(tbuf, "maximum latency(usecs) %7d %7d\n", s_max_latency, i_max_latency);
685
686 if (fp)
687 fprintf(fp, "%s", tbuf);
688 else
689 printw(tbuf);
690
691 if (s_total_samples)
692 average_s_latency = (unsigned int)(s_total_latency/s_total_samples);
693 else
694 average_s_latency = 0;
695
696 if (i_total_samples)
697 average_i_latency = (unsigned int)(i_total_latency/i_total_samples);
698 else
699 average_i_latency = 0;
700
701 sprintf(tbuf, "average latency(usecs) %7d %7d\n", average_s_latency, average_i_latency);
702
703 if (fp)
704 fprintf(fp, "%s", tbuf);
705 else
706 printw(tbuf);
707
708 sprintf(tbuf, "exceeded threshold %7d %7d\n", s_exceeded_threshold, i_exceeded_threshold);
709
710 if (fp)
711 fprintf(fp, "%s", tbuf);
712 else
713 printw(tbuf);
714
715 if (fp == (FILE *)0)
716 refresh();
717 else
718 fflush(fp);
719}
720
721int
722exit_usage()
723{
724
c03df0e9 725 fprintf(stderr, "Usage: latency [-rt] [-h] [-c codefile] [-l logfile] [-st threshold]\n");
83f6dbe8
A		 726
727#if defined (__i386__)
728 fprintf(stderr, " [-it threshold] [-s sleep_in_usecs] [-n kernel]\n\n");
729#else
730 fprintf(stderr, " [-it threshold] [-s sleep_in_usecs]\n");
1815bff5 731 fprintf(stderr, " [-d decrementer_in_usecs] [-n kernel]\n\n");
83f6dbe8
A		 732#endif
733
1815bff5
A		 734
735 fprintf(stderr, " -rt Set realtime scheduling policy. Default is timeshare.\n");
c03df0e9 736 fprintf(stderr, " -h Display high resolution interrupt latencies and write them to latencies.csv (truncate existing file) upon exit.\n");
1815bff5
A		 737 fprintf(stderr, " -c specify name of codes file\n");
738 fprintf(stderr, " -l specify name of file to log trace entries to when threshold is exceeded\n");
739 fprintf(stderr, " -st set scheduler latency threshold in microseconds... if latency exceeds this, then log trace\n");
740 fprintf(stderr, " -it set interrupt latency threshold in microseconds... if latency exceeds this, then log trace\n");
741 fprintf(stderr, " -s set sleep time in microseconds\n");
83f6dbe8 742#if !defined (__i386__)
1815bff5 743 fprintf(stderr, " -d set decrementer in microseconds.\n");
83f6dbe8 744#endif
1815bff5
A		 745 fprintf(stderr, " -n specify kernel, default is /mach_kernel\n");
746
747 fprintf(stderr, "\nlatency must be run as root\n\n");
748
749 exit(1);
750}
751
752
83f6dbe8 753int
ef8ad44b 754main(int argc, char *argv[])
1815bff5 755{
1c51fdde
A		 756 uint64_t start, stop;
757 uint64_t timestamp1;
758 uint64_t timestamp2;
759 uint64_t adeadline, adelay;
1815bff5
A		 760 double fdelay;
761 int elapsed_usecs;
762 double nanosecs_to_sleep;
763 int loop_cnt, sample_sc_now;
764 int decrementer_usec = 0;
b51d5b5f 765 kern_return_t ret;
09fd88e4 766 unsigned int size;
b51d5b5f 767 host_name_port_t host;
1815bff5
A		 768 void getdivisor();
769 void sample_sc();
770 void init_code_file();
771 void do_kernel_nm();
772 void open_logfile();
773
ef8ad44b
A		 774 if (0 != reexec_to_match_kernel()) {
775 fprintf(stderr, "Could not re-execute: %d\n", errno);
776 exit(1);
777 }
778
1815bff5
A		 779 my_policy = THREAD_STANDARD_POLICY;
780 policy_name = "TIMESHARE";
781
782 while (argc > 1) {
783 if (strcmp(argv[1], "-rt") == 0) {
784 my_policy = THREAD_TIME_CONSTRAINT_POLICY; /* the real time band */
785 policy_name = "REALTIME";
786
787 } else if (strcmp(argv[1], "-st") == 0) {
788 argc--;
789 argv++;
790
791 if (argc > 1)
792 s_thresh_hold = atoi(argv[1]);
793 else
794 exit_usage();
795
796 } else if (strcmp(argv[1], "-it") == 0) {
797 argc--;
798 argv++;
799
800 if (argc > 1)
801 i_thresh_hold = atoi(argv[1]);
802 else
803 exit_usage();
804 } else if (strcmp(argv[1], "-c") == 0) {
805 argc--;
806 argv++;
807
808 if (argc > 1)
809 code_file = argv[1];
810 else
811 exit_usage();
812 } else if (strcmp(argv[1], "-l") == 0) {
813 argc--;
814 argv++;
815
816 if (argc > 1)
817 open_logfile(argv[1]);
818 else
819 exit_usage();
820
821 } else if (strcmp(argv[1], "-s") == 0) {
822 argc--;
823 argv++;
824
825 if (argc > 1)
826 num_of_usecs_to_sleep = atoi(argv[1]);
827 else
828 exit_usage();
83f6dbe8
A		 829 }
830 else if (strcmp(argv[1], "-d") == 0) {
1815bff5
A		 831 argc--;
832 argv++;
833
834 if (argc > 1)
835 decrementer_usec = atoi(argv[1]);
836 else
837 exit_usage();
83f6dbe8
A		 838#if defined(__i386__)
839 /* ignore this option - setting the decrementer has no effect */
840 decrementer_usec = 0;
841#endif
842 }
843 else if (strcmp(argv[1], "-n") == 0) {
1815bff5
A		 844 argc--;
845 argv++;
846
847 if (argc > 1)
848 kernelpath = argv[1];
849 else
850 exit_usage();
c03df0e9
A		 851 } else if (strcmp(argv[1], "-h") == 0) {
852 use_high_res_bins = true;
1815bff5
A		 853 } else
854 exit_usage();
855
856 argc--;
857 argv++;
858 }
859
860 if ( geteuid() != 0 ) {
861 printf("'latency' must be run as root...\n");
862 exit(1);
863 }
864
865 if (kernelpath == (char *) 0)
866 kernelpath = "/mach_kernel";
867
868 if (code_file == (char *) 0)
869 code_file = "/usr/share/misc/trace.codes";
870
871 do_kernel_nm();
872
873 sample_sc_now = 25000 / num_of_usecs_to_sleep;
874
875 getdivisor();
876 decrementer_val = decrementer_usec * divisor;
877
83f6dbe8 878 /* get the cpu countfor the DECR_TRAP array */
b51d5b5f
A		 879 host = mach_host_self();
880 size = sizeof(hi)/sizeof(int);
881 ret = host_info(host, HOST_BASIC_INFO, (host_info_t)&hi, &size);
882 if (ret != KERN_SUCCESS) {
883 mach_error(argv[0], ret);
884 exit(EXIT_FAILURE);
885 }
886
a8daac8f 887 if ((last_decrementer_kd = (kd_buf **)malloc(hi.max_cpus * sizeof(kd_buf *))) == (kd_buf **)0)
b51d5b5f
A		 888 quit("can't allocate memory for decrementer tracing info\n");
889
1815bff5
A		 890 nanosecs_to_sleep = (double)(num_of_usecs_to_sleep * 1000);
891 fdelay = nanosecs_to_sleep * (divisor /1000);
1c51fdde 892 adelay = (uint64_t)fdelay;
1815bff5
A		 893
894 init_code_file();
895
896 /*
897 When the decrementer isn't set in the options,
898 decval will be zero and this call will reset
899 the system default ...
900 */
901 set_rtcdec(decrementer_val);
902
b51d5b5f
A		 903 if (initscr() == (WINDOW *) 0)
904 {
905 printf("Unrecognized TERM type, try vt100\n");
906 exit(1);
907 }
908
1815bff5
A		 909 clear();
910 refresh();
911 signal(SIGWINCH, sigwinch);
912 signal(SIGINT, sigintr);
b51d5b5f
A		 913 signal(SIGQUIT, leave);
914 signal(SIGTERM, leave);
915 signal(SIGHUP, leave);
1815bff5
A		 916
917
918 if ((my_buffer = malloc(SAMPLE_SIZE * sizeof(kd_buf))) == (char *)0)
919 quit("can't allocate memory for tracing info\n");
920 set_remove();
921 set_numbufs(SAMPLE_SIZE);
922 set_enable(0);
923 if(log_fp)
924 set_init_logging();
925 else
926 set_init_nologging();
927 set_pidexclude(getpid(), 1);
928 set_enable(1);
929 trace_enabled = 1;
930 need_new_map = 1;
931
932 loop_cnt = 0;
933 start_time = time((long *)0);
934 refresh_time = start_time;
935
936 if (my_policy == THREAD_TIME_CONSTRAINT_POLICY)
937 {
938 /* the realtime band */
939 if(set_time_constraint_policy() != KERN_SUCCESS)
940 quit("Failed to set realtime policy.\n");
941 }
942
943 for (;;) {
944 curr_time = time((long *)0);
945
946 if (curr_time >= refresh_time) {
947 if (my_policy == THREAD_TIME_CONSTRAINT_POLICY)
948 {
949 /* set standard timeshare policy during screen update */
950 if(set_standard_policy() != KERN_SUCCESS)
951 quit("Failed to set standard policy.\n");
952 }
953 screen_update((FILE *)0);
954 if (my_policy == THREAD_TIME_CONSTRAINT_POLICY)
955 {
956 /* set back to realtime band */
957 if(set_time_constraint_policy() != KERN_SUCCESS)
958 quit("Failed to set time_constraint policy.\n");
959 }
960 refresh_time = curr_time + 1;
961 }
962
1c51fdde
A		 963 timestamp1 = mach_absolute_time();
964 adeadline = timestamp1 + adelay;
2fc1e207 965 mach_wait_until(adeadline);
1c51fdde 966 timestamp2 = mach_absolute_time();
1815bff5 967
1c51fdde 968 start = timestamp1;
1815bff5 969
1c51fdde 970 stop = timestamp2;
1815bff5
A		 971
972 elapsed_usecs = (int)(((double)(stop - start)) / divisor);
973
974 if ((elapsed_usecs -= num_of_usecs_to_sleep) <= 0)
975 continue;
976
977 if (elapsed_usecs < 100)
978 s_usec_10_bins[elapsed_usecs/10]++;
979 if (elapsed_usecs < 1000)
980 s_usec_100_bins[elapsed_usecs/100]++;
981 else if (elapsed_usecs < 10000)
982 s_msec_1_bins[elapsed_usecs/1000]++;
983 else if (elapsed_usecs < 50000)
984 s_msec_10_bins[elapsed_usecs/10000]++;
985 else
986 s_too_slow++;
987
988 if (elapsed_usecs > s_max_latency)
989 s_max_latency = elapsed_usecs;
990 if (elapsed_usecs < s_min_latency || s_total_samples == 0)
991 s_min_latency = elapsed_usecs;
992 s_total_latency += elapsed_usecs;
993 s_total_samples++;
994
995 if (s_thresh_hold && elapsed_usecs > s_thresh_hold)
996 s_exceeded_threshold++;
997 loop_cnt++;
998
999 if (log_fp && s_thresh_hold && elapsed_usecs > s_thresh_hold)
1000 sample_sc(start, stop);
1001 else {
1002 if (loop_cnt >= sample_sc_now) {
1003 sample_sc((long long)0, (long long)0);
1004 loop_cnt = 0;
1005 }
1006 }
1007 if (gotSIGWINCH) {
b51d5b5f
A		 1008 /*
1009 No need to check for initscr error return.
1010 We won't get here if it fails on the first call.
1011 */
1012 endwin();
1815bff5
A		 1013 clear();
1014 refresh();
1015
1016 gotSIGWINCH = 0;
1017 }
1018 }
1c51fdde 1019}
1815bff5
A		 1020
1021
1022void getdivisor()
1023{
1c51fdde 1024 mach_timebase_info_data_t info;
1815bff5 1025
1c51fdde 1026 (void) mach_timebase_info (&info);
1815bff5 1027
1c51fdde 1028 divisor = ( (double)info.denom / (double)info.numer) * 1000;
1815bff5 1029
1815bff5
A		 1030}
1031
1032/* This is the realtime band */
1033static kern_return_t
1034set_time_constraint_policy()
1035{
1036 kern_return_t result;
1037 thread_time_constraint_policy_data_t info;
1038 mach_msg_type_number_t count;
1039 boolean_t get_default;
1040
1041 get_default = TRUE;
1042 count = THREAD_TIME_CONSTRAINT_POLICY_COUNT;
1043 result = thread_policy_get(mach_thread_self(), THREAD_TIME_CONSTRAINT_POLICY,
1044 (thread_policy_t)&info, &count, &get_default);
1045 if (result != KERN_SUCCESS)
1046 return (result);
1047
1048 result = thread_policy_set(mach_thread_self(), THREAD_TIME_CONSTRAINT_POLICY,
1049 (thread_policy_t)&info, THREAD_TIME_CONSTRAINT_POLICY_COUNT);
1050
1051 return (result);
1052}
1053
1054/* This is the timeshare mode */
1055static kern_return_t
1056set_standard_policy()
1057{
1058 kern_return_t result;
1059 thread_standard_policy_data_t info;
1060 mach_msg_type_number_t count;
1061 boolean_t get_default;
1062
1063 get_default = TRUE;
1064 count = THREAD_STANDARD_POLICY_COUNT;
1065 result = thread_policy_get(mach_thread_self(), THREAD_STANDARD_POLICY,
1066 (thread_policy_t)&info, &count, &get_default);
1067 if (result != KERN_SUCCESS)
1068 return (result);
1069
1070 result = thread_policy_set(mach_thread_self(), THREAD_STANDARD_POLICY,
1071 (thread_policy_t)&info, THREAD_STANDARD_POLICY_COUNT);
1072
1073 return (result);
1074}
1075
1076
1077void read_command_map()
1078{
1079 size_t size;
1080 int mib[6];
1081
1082 if (mapptr) {
1083 free(mapptr);
1084 mapptr = 0;
1085 }
1086 total_threads = bufinfo.nkdthreads;
1087 size = bufinfo.nkdthreads * sizeof(kd_threadmap);
1088 if (size)
1089 {
83f6dbe8 1090 if ((mapptr = (kd_threadmap *) malloc(size)))
1815bff5
A		 1091 bzero (mapptr, size);
1092 else
1093 {
1094 printf("Thread map is not initialized -- this is not fatal\n");
1095 return;
1096 }
1097 }
1098
1099 /* Now read the threadmap */
1100 mib[0] = CTL_KERN;
1101 mib[1] = KERN_KDEBUG;
1102 mib[2] = KERN_KDTHRMAP;
1103 mib[3] = 0;
1104 mib[4] = 0;
1105 mib[5] = 0; /* no flags */
1106 if (sysctl(mib, 3, mapptr, &size, NULL, 0) < 0)
1107 {
1108 /* This is not fatal -- just means I cant map command strings */
1109
1110 printf("Can't read the thread map -- this is not fatal\n");
1111 free(mapptr);
1112 mapptr = 0;
1113 return;
1114 }
1115 return;
1116}
1117
1118
ef8ad44b 1119void create_map_entry(uintptr_t thread, char *command)
1815bff5
A		 1120{
1121 int i, n;
1122 kd_threadmap *map;
1123
1124 if (!mapptr)
1125 return;
1126
1127 for (i = 0, map = 0; !map && i < total_threads; i++)
1128 {
1129 if (mapptr[i].thread == thread )
1130 map = &mapptr[i]; /* Reuse this entry, the thread has been reassigned */
1131 }
1132
1133 if (!map) /* look for invalid entries that I can reuse*/
1134 {
1135 for (i = 0, map = 0; !map && i < total_threads; i++)
1136 {
1137 if (mapptr[i].valid == 0 )
1138 map = &mapptr[i]; /* Reuse this invalid entry */
1139 }
1140 }
1141
1142 if (!map)
1143 {
1144 /* If reach here, then this is a new thread and
1145 * there are no invalid entries to reuse
1146 * Double the size of the thread map table.
1147 */
1148
1149 n = total_threads * 2;
1150 mapptr = (kd_threadmap *) realloc(mapptr, n * sizeof(kd_threadmap));
1151 bzero(&mapptr[total_threads], total_threads*sizeof(kd_threadmap));
1152 map = &mapptr[total_threads];
1153 total_threads = n;
1154#if 0
1155 if (log_fp)
1156 fprintf(log_fp, "MAP: increasing thread map to %d entries\n", total_threads);
1157#endif
1158 }
1159#if 0
1160 if (log_fp)
1161 fprintf(log_fp, "MAP: adding thread %x with name %s\n", thread, command);
1162#endif
1163 map->valid = 1;
1164 map->thread = thread;
1c51fdde
A		 1165 /*
1166 The trace entry that returns the command name will hold
1167 at most, MAXCOMLEN chars, and in that case, is not
1168 guaranteed to be null terminated.
1169 */
1170 (void)strncpy (map->command, command, MAXCOMLEN);
1171 map->command[MAXCOMLEN] = '\0';
1815bff5
A		 1172}
1173
1174
ef8ad44b 1175kd_threadmap *find_thread_map(uintptr_t thread)
1815bff5
A		 1176{
1177 int i;
1178 kd_threadmap *map;
1179
1180 if (!mapptr)
1181 return((kd_threadmap *)0);
1182
1183 for (i = 0; i < total_threads; i++)
1184 {
1185 map = &mapptr[i];
1186 if (map->valid && (map->thread == thread))
1187 {
1188 return(map);
1189 }
1190 }
1191 return ((kd_threadmap *)0);
1192}
1193
1194void
ef8ad44b 1195kill_thread_map(uintptr_t thread)
1815bff5
A		 1196{
1197 kd_threadmap *map;
1198
83f6dbe8 1199 if ((map = find_thread_map(thread))) {
1815bff5
A		 1200
1201#if 0
1202 if (log_fp)
1203 fprintf(log_fp, "MAP: deleting thread %x with name %s\n", thread, map->command);
1204#endif
1205 map->valid = 0;
1206 map->thread = 0;
1207 map->command[0] = '\0';
1208 }
1209}
1210
1211
ef8ad44b 1212struct th_info *find_thread(uintptr_t thread, int type1, int type2) {
1815bff5
A		 1213 struct th_info *ti;
1214
1215 for (ti = th_state; ti < &th_state[cur_max]; ti++) {
1216 if (ti->thread == thread) {
1217 if (type1 == 0)
1218 return(ti);
1219 if (type1 == ti->type)
1220 return(ti);
1221 if (type2 == ti->type)
1222 return(ti);
1223 }
1224 }
1225 return ((struct th_info *)0);
1226}
1227
1228
1229char *find_code(type)
1230{
1231 int i;
1232
1233 for (i = 0; i < num_of_codes; i++) {
1234 if (codes_tab[i].type == type)
1235 return(codes_tab[i].name);
1236 }
1237 return ((char *)0);
1238}
1239
1240
1c51fdde 1241void sample_sc(uint64_t start, uint64_t stop)
1815bff5 1242{
b51d5b5f 1243 kd_buf *kd, *last_mach_sched, *start_kd, *end_of_sample;
1c51fdde 1244 uint64_t now;
b51d5b5f 1245 int count, i;
1815bff5 1246 int first_entry = 1;
83f6dbe8
A		 1247 double timestamp = 0.0;
1248 double last_timestamp = 0.0;
1249 double delta = 0.0;
1250 double start_bias = 0.0;
1815bff5 1251 char command[32];
1815bff5
A		 1252 void read_command_map();
1253
1254 if (log_fp && (my_policy == THREAD_TIME_CONSTRAINT_POLICY))
1255 {
1256 /* set standard timeshare policy when logging */
1257 if(set_standard_policy() != KERN_SUCCESS)
1258 quit("Failed to set standard policy.\n");
1259 }
1260
1261 /* Get kernel buffer information */
1262 get_bufinfo(&bufinfo);
1263
1264 if (need_new_map) {
1265 read_command_map();
1266 need_new_map = 0;
1267 }
1268 needed = bufinfo.nkdbufs * sizeof(kd_buf);
1269 mib[0] = CTL_KERN;
1270 mib[1] = KERN_KDEBUG;
1271 mib[2] = KERN_KDREADTR;
1272 mib[3] = 0;
1273 mib[4] = 0;
1274 mib[5] = 0; /* no flags */
1275
1276 if (sysctl(mib, 3, my_buffer, &needed, NULL, 0) < 0)
1277 quit("trace facility failure, KERN_KDREADTR\n");
1278
1279 count = needed;
1280
1281 if (bufinfo.flags & KDBG_WRAPPED) {
1815bff5
A		 1282 for (i = 0; i < cur_max; i++) {
1283 th_state[i].thread = 0;
1284 th_state[i].type = -1;
09fd88e4 1285 th_state[i].pathptr = (long *)NULL;
1815bff5
A		 1286 th_state[i].pathname[0] = 0;
1287 }
1288 cur_max = 0;
1289 need_new_map = 1;
1290
1291 set_enable(0);
1292 set_enable(1);
1293
1294 if (log_fp) {
1295 double latency;
1296
1297 latency = (double)(stop - start) / divisor;
1298 latency -= (double)num_of_usecs_to_sleep;
1299
1300 fprintf(log_fp, "\n\n%-19.19s scheduling latency = %.1fus num_of_traces = %d <<<<<<< trace buffer wrapped >>>>>>>\n\n",
1301 &(ctime(&curr_time)[0]), latency, count);
1302 }
1303 }
1304 end_of_sample = &((kd_buf *)my_buffer)[count];
b51d5b5f
A		 1305
1306 /* Always reinitialize the DECR_TRAP array */
a8daac8f 1307 for (i=0; i < hi.max_cpus; i++)
b51d5b5f
A		 1308 last_decrementer_kd[i] = (kd_buf *)my_buffer;
1309
1815bff5
A		 1310 last_mach_sched = (kd_buf *)0;
1311
1312 for (kd = (kd_buf *)my_buffer; kd < end_of_sample; kd++) {
1313 int debugid, thread, cpunum;
1314 int type, clen, mode;
1c51fdde 1315 int len;
1815bff5
A		 1316 char *p;
1317 long *sargptr;
b51d5b5f 1318 kd_buf *cur_kd;
83f6dbe8 1319 double i_latency = 0.0;
1815bff5
A		 1320 struct th_info *ti;
1321 char command1[32];
1322 char sched_info[64];
1323 kd_threadmap *map;
1324 kd_threadmap *find_thread_map();
1325 double handle_decrementer();
1326 kd_buf *log_decrementer();
1327 int check_for_thread_update();
1328 void enter_syscall();
1329 void exit_syscall();
1330 void print_entry();
1331
83f6dbe8 1332 thread = kd->arg5;
ef8ad44b 1333 cpunum = CPU_NUMBER(kd);
1815bff5
A		 1334 debugid = kd->debugid;
1335 type = kd->debugid & DBG_FUNC_MASK;
1336
1337 if (check_for_thread_update(thread, type, kd))
1338 continue;
1339
1340 if (type == DECR_TRAP)
1341 i_latency = handle_decrementer(kd);
1342
83f6dbe8 1343 now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1815bff5
A		 1344
1345 timestamp = ((double)now) / divisor;
1346
1347 if (now < start || now > stop) {
1348 if (debugid & DBG_FUNC_START)
1349 enter_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 0);
1350 else if (debugid & DBG_FUNC_END)
1351 exit_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 0);
1352 else if (type == DECR_TRAP) {
b51d5b5f 1353 cur_kd = kd;
1815bff5 1354 if (log_fp && i_thresh_hold && (int)i_latency > i_thresh_hold) {
b51d5b5f 1355 start_kd = last_decrementer_kd[cpunum];
1815bff5 1356 kd = log_decrementer(start_kd, kd, end_of_sample, i_latency);
1815bff5
A		 1357 if (kd >= end_of_sample)
1358 break;
1359 }
b51d5b5f
A		 1360 if ((kd->debugid & DBG_FUNC_MASK) == DECR_TRAP)
1361 {
ef8ad44b 1362 cpunum = CPU_NUMBER(kd);
b51d5b5f
A		 1363 last_decrementer_kd[cpunum] = kd;
1364 }
1365 else
1366 last_decrementer_kd[cpunum] = cur_kd;
1815bff5
A		 1367 }
1368 continue;
1369 }
1370 if (first_entry) {
1371 double latency;
b51d5b5f
A		 1372 char buf1[132];
1373 char buf2[132];
1815bff5
A		 1374
1375 latency = (double)(stop - start) / divisor;
1376 latency -= (double)num_of_usecs_to_sleep;
1377
1378 if (my_pri == -1)
1379 sprintf(buf2, "default");
1380 else
1381 sprintf(buf2, "%d", my_pri);
1382 sprintf(buf1, "%-19.19s scheduling latency = %.1fus sleep_request = %dus policy = %s priority = %s",
1383 &(ctime(&curr_time)[0]), latency, num_of_usecs_to_sleep, policy_name, buf2);
1384 clen = strlen(buf1);
1385 memset(buf2, '-', clen);
1386 buf2[clen] = 0;
1387
1388 if (log_fp) {
1389 fprintf(log_fp, "\n\n%s\n", buf2);
1390 fprintf(log_fp, "%s\n\n", buf1);
1391 fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n");
1392 }
1393 start_bias = ((double)start) / divisor;
1394 last_timestamp = timestamp;
1395 first_entry = 0;
1396 }
1397 delta = timestamp - last_timestamp;
1398
83f6dbe8 1399 if ((map = find_thread_map(thread)))
1815bff5
A		 1400 strcpy(command, map->command);
1401 else
1402 command[0] = 0;
1403
1404 switch (type) {
1405
1406 case CQ_action:
1407 if (log_fp) {
1408 fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-59.59s %-8x %d %s\n",
1409 timestamp - start_bias, delta, pc_to_string(kd->arg1, 59, 1) , thread, cpunum, command);
1410 }
1411 last_timestamp = timestamp;
1412 break;
1413
1414 case TES_action:
1415 if (log_fp) {
1416 fprintf(log_fp, "%9.1f %8.1f\t\tTES_action @ %-58.58s %-8x %d %s\n",
1417 timestamp - start_bias, delta, pc_to_string(kd->arg1, 58, 1) , thread, cpunum, command);
1418 }
1419
1420 last_timestamp = timestamp;
1421 break;
1422
1423 case IES_action:
1424 if (log_fp) {
1425 fprintf(log_fp, "%9.1f %8.1f\t\tIES_action @ %-58.58s %-8x %d %s\n",
1426 timestamp - start_bias, delta, pc_to_string(kd->arg1, 58, 1) , thread, cpunum, command);
1427 }
1428
1429 last_timestamp = timestamp;
1430 break;
1431
1432 case IES_filter:
1433 if (log_fp) {
1434 fprintf(log_fp, "%9.1f %8.1f\t\tIES_filter @ %-58.58s %-8x %d %s\n",
1435 timestamp - start_bias, delta, pc_to_string(kd->arg1, 58, 1) , thread, cpunum, command);
1436 }
1437
1438 last_timestamp = timestamp;
1439 break;
1440
1441 case DECR_TRAP:
b51d5b5f 1442 last_decrementer_kd[cpunum] = kd;
1815bff5
A		 1443
1444 if (i_thresh_hold && (int)i_latency > i_thresh_hold)
1445 p = "*";
1446 else
1447 p = " ";
1448
1449 mode = 1;
1450
83f6dbe8 1451 if ((ti = find_thread(kd->arg5, 0, 0))) {
1815bff5
A		 1452 if (ti->type == -1 && strcmp(command, "kernel_task"))
1453 mode = 0;
1454 }
1455
1456 if (log_fp) {
1457 fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-59.59s %-8x %d %s\n",
1458 timestamp - start_bias, delta, i_latency, p, pc_to_string(kd->arg2, 59, mode) , thread, cpunum, command);
1459 }
1460
1461 last_timestamp = timestamp;
1462 break;
1463
1464 case DECR_SET:
1465 if (log_fp) {
1466 fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %-8x %d %s\n",
1467 timestamp - start_bias, delta, (double)kd->arg1/divisor, "DECR_SET", thread, cpunum, command);
1468 }
1469
1470 last_timestamp = timestamp;
1471 break;
1472
1473 case MACH_sched:
1474 case MACH_stkhandoff:
1475 last_mach_sched = kd;
1476
83f6dbe8 1477 if ((map = find_thread_map(kd->arg2)))
1815bff5
A		 1478 strcpy(command1, map->command);
1479 else
1480 sprintf(command1, "%-8x", kd->arg2);
1481
83f6dbe8 1482 if ((ti = find_thread(kd->arg2, 0, 0))) {
1815bff5
A		 1483 if (ti->type == -1 && strcmp(command1, "kernel_task"))
1484 p = "U";
1485 else
1486 p = "K";
1487 } else
1488 p = "*";
1489 memset(sched_info, ' ', sizeof(sched_info));
1490
1491 sprintf(sched_info, "%14.14s", command);
1492 clen = strlen(sched_info);
1493 sched_info[clen] = ' ';
1494
1495 sprintf(&sched_info[14], " @ pri %3d --> %14.14s", kd->arg3, command1);
1496 clen = strlen(sched_info);
1497 sched_info[clen] = ' ';
1498
1499 sprintf(&sched_info[45], " @ pri %3d%s", kd->arg4, p);
1500
1501 if (log_fp) {
1502 fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s %s %-8x %d\n",
1503 timestamp - start_bias, delta, "MACH_SCHED", sched_info, thread, cpunum);
1504 }
1505
1506 last_timestamp = timestamp;
1507 break;
1508
1509 case VFS_LOOKUP:
1510 if ((ti = find_thread(thread, 0, 0)) == (struct th_info *)0) {
1511 if (cur_max >= MAX_THREADS)
1512 continue;
1513 ti = &th_state[cur_max++];
1514
1515 ti->thread = thread;
1516 ti->type = -1;
1c51fdde 1517 ti->pathptr = (long *)0;
1815bff5
A		 1518 ti->child_thread = 0;
1519 }
b51d5b5f
A		 1520 while ( (kd < end_of_sample) && ((kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP))
1521 {
09fd88e4 1522 if (ti->pathptr == NULL) {
1815bff5 1523 ti->arg1 = kd->arg1;
09fd88e4 1524 sargptr = ti->pathname;
1815bff5
A		 1525
1526 *sargptr++ = kd->arg2;
1527 *sargptr++ = kd->arg3;
1528 *sargptr++ = kd->arg4;
09fd88e4
A		 1529 /*
1530 * NULL terminate the 'string'
1531 */
1532 *sargptr = 0;
1c51fdde
A		 1533 ti->pathptr = sargptr;
1534
b51d5b5f 1535 } else {
1c51fdde
A		 1536 sargptr = ti->pathptr;
1537
1538 /*
1539 We don't want to overrun our pathname buffer if the
1540 kernel sends us more VFS_LOOKUP entries than we can
1541 handle.
1542 */
1543
09fd88e4 1544 if (sargptr >= &ti->pathname[NUMPARMS])
b51d5b5f
A		 1545 {
1546 kd++;
1547 continue;
1548 }
1549
1550 /*
1551 We need to detect consecutive vfslookup entries.
1552 So, if we get here and find a START entry,
1553 fake the pathptr so we can bypass all further
1554 vfslookup entries.
1555 */
1556
1557 if (kd->debugid & DBG_FUNC_START)
1558 {
09fd88e4 1559 ti->pathptr = &ti->pathname[NUMPARMS];
b51d5b5f
A		 1560 }
1561 else
1c51fdde
A		 1562 {
1563 *sargptr++ = kd->arg1;
1564 *sargptr++ = kd->arg2;
1565 *sargptr++ = kd->arg3;
1566 *sargptr++ = kd->arg4;
09fd88e4
A		 1567 /*
1568 * NULL terminate the 'string'
1569 */
1570 *sargptr = 0;
1571
1c51fdde 1572 ti->pathptr = sargptr;
b51d5b5f
A		 1573 }
1574 }
1575 kd++;
1576 }
09fd88e4 1577 p = (char *)ti->pathname;
b51d5b5f
A		 1578
1579 kd--;
1c51fdde 1580
09fd88e4
A		 1581 /* print the tail end of the pathname */
1582 len = strlen(p);
b51d5b5f
A		 1583 if (len > 42)
1584 len -= 42;
1585 else
1586 len = 0;
1815bff5 1587
b51d5b5f
A		 1588 if (log_fp) {
1589 fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s %-8x %-8x %d %s\n",
1590 timestamp - start_bias, delta, "VFS_LOOKUP",
09fd88e4 1591 &p[len], ti->arg1, thread, cpunum, command);
1815bff5 1592 }
b51d5b5f 1593
1815bff5
A		 1594 last_timestamp = timestamp;
1595 break;
1596
1597 default:
1598 if (debugid & DBG_FUNC_START)
1599 enter_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 1);
1600 else if (debugid & DBG_FUNC_END)
1601 exit_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 1);
1602 else
1603 print_entry(log_fp, kd, thread, type, command, timestamp, delta, start_bias);
1604
1605 last_timestamp = timestamp;
1606 break;
1607 }
1608 }
1609 if (last_mach_sched && log_fp)
1610 fprintf(log_fp, "\nblocked by %s @ priority %d\n", command, last_mach_sched->arg3);
1611#if 0
1612 if (first_entry == 0 && log_fp)
1613 fprintf(log_fp, "\n start = %qd stop = %qd count = %d now = %qd\n", start, stop, count, now);
1614#endif
1615 if (log_fp)
1616 fflush(log_fp);
1617
1618 if (log_fp && (my_policy == THREAD_TIME_CONSTRAINT_POLICY))
1619 {
1620 /* set back to realtime band */
1621 if(set_time_constraint_policy() != KERN_SUCCESS)
1622 quit("Failed to set time_constraint policy.\n");
1623 }
1624}
1625
1626void
1627enter_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double timestamp, double delta, double bias, int print_info)
1628{
1629 struct th_info *ti;
1630 int i;
1631 int cpunum;
1632 char *p;
1633
ef8ad44b 1634 cpunum = CPU_NUMBER(kd);
1815bff5
A		 1635
1636 if (print_info && fp) {
83f6dbe8 1637 if ((p = find_code(type))) {
1815bff5
A		 1638 if (type == INTERRUPT) {
1639 int mode = 1;
1640
83f6dbe8 1641 if ((ti = find_thread(kd->arg5, 0, 0))) {
1815bff5
A		 1642 if (ti->type == -1 && strcmp(command, "kernel_task"))
1643 mode = 0;
1644 }
1645
1646 fprintf(fp, "%9.1f %8.1f\t\tINTERRUPT @ %-59.59s %-8x %d %s\n",
1647 timestamp - bias, delta, pc_to_string(kd->arg2, 59, mode), thread, cpunum, command);
1648 } else if (type == MACH_vmfault) {
1649 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-8x %d %s\n",
1650 timestamp - bias, delta, p, thread, cpunum, command);
1651 } else {
1652 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-8x %-8x %-8x %-8x %-8x %d %s\n",
1653 timestamp - bias, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1654 thread, cpunum, command);
1655 }
1656 } else {
1657 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-8x %-8x %-8x %-8x %-8x %d %s\n",
1658 timestamp - bias, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1659 thread, cpunum, command);
1660 }
1661 }
1662 if ((ti = find_thread(thread, -1, type)) == (struct th_info *)0) {
1663 if (cur_max >= MAX_THREADS) {
1664 static int do_this_once = 1;
1665
1666 if (do_this_once) {
1667 for (i = 0; i < cur_max; i++) {
1668 if (!fp)
1669 break;
1670 fprintf(fp, "thread = %x, type = %x\n",
1671 th_state[i].thread, th_state[i].type);
1672 }
1673 do_this_once = 0;
1674 }
1675 return;
1676
1677 }
1678 ti = &th_state[cur_max++];
1679
1680 ti->thread = thread;
1681 ti->child_thread = 0;
1682 }
1683 if (type != BSC_exit)
1684 ti->type = type;
1685 else
1686 ti->type = -1;
1687 ti->stime = timestamp;
09fd88e4 1688 ti->pathptr = (long *)NULL;
1c51fdde 1689
1815bff5
A		 1690#if 0
1691 if (print_info && fp)
1692 fprintf(fp, "cur_max = %d, ti = %x, type = %x, thread = %x\n", cur_max, ti, ti->type, ti->thread);
1693#endif
1694}
1695
1696
1697void
1698exit_syscall(FILE *fp, kd_buf *kd, int thread, int type, char *command, double timestamp, double delta, double bias, int print_info)
1699{
1700 struct th_info *ti;
1701 int cpunum;
1702 char *p;
34d340d7 1703 uint64_t user_addr;
1815bff5 1704
ef8ad44b 1705 cpunum = CPU_NUMBER(kd);
83f6dbe8 1706
1815bff5
A		 1707 ti = find_thread(thread, type, type);
1708#if 0
1709 if (print_info && fp)
1710 fprintf(fp, "cur_max = %d, ti = %x, type = %x, thread = %x\n", cur_max, ti, type, thread);
1711#endif
1712 if (print_info && fp) {
1713 if (ti)
1714 fprintf(fp, "%9.1f %8.1f(%.1f) \t", timestamp - bias, delta, timestamp - ti->stime);
1715 else
1716 fprintf(fp, "%9.1f %8.1f() \t", timestamp - bias, delta);
1717
83f6dbe8 1718 if ((p = find_code(type))) {
1815bff5
A		 1719 if (type == INTERRUPT) {
1720 fprintf(fp, "INTERRUPT %-8x %d %s\n", thread, cpunum, command);
ef8ad44b 1721 } else if (type == MACH_vmfault && kd->arg4 <= DBG_PAGEIND_FAULT) {
34d340d7
A		 1722 user_addr = ((uint64_t)kd->arg1 << 32) | (uint32_t)kd->arg2;
1723
ef8ad44b 1724 fprintf(fp, "%-28.28s %-10.10s %-16qx %-8x %d %s\n",
34d340d7 1725 p, fault_name[kd->arg4], user_addr,
1815bff5
A		 1726 thread, cpunum, command);
1727 } else {
1728 fprintf(fp, "%-28.28s %-8x %-8x %-8x %d %s\n",
1729 p, kd->arg1, kd->arg2,
1730 thread, cpunum, command);
1731 }
1732 } else {
1733 fprintf(fp, "%-8x %-8x %-8x %-8x %d %s\n",
1734 type, kd->arg1, kd->arg2,
1735 thread, cpunum, command);
1736 }
1737 }
1738 if (ti == (struct th_info *)0) {
1739 if ((ti = find_thread(thread, -1, -1)) == (struct th_info *)0) {
1740 if (cur_max >= MAX_THREADS)
1741 return;
1742 ti = &th_state[cur_max++];
1743
1744 ti->thread = thread;
1745 ti->child_thread = 0;
09fd88e4 1746 ti->pathptr = (long *)NULL;
1815bff5
A		 1747 }
1748 }
1749 ti->type = -1;
1750}
1751
1752void
1753print_entry(FILE *fp, kd_buf *kd, int thread, int type, char *command, double timestamp, double delta, double bias)
1754{
1755 char *p;
1756 int cpunum;
1757
1758 if (!fp)
1759 return;
1760
ef8ad44b 1761 cpunum = CPU_NUMBER(kd);
1815bff5
A		 1762#if 0
1763 fprintf(fp, "cur_max = %d, type = %x, thread = %x, cpunum = %d\n", cur_max, type, thread, cpunum);
1764#endif
83f6dbe8 1765 if ((p = find_code(type))) {
1815bff5
A		 1766 fprintf(fp, "%9.1f %8.1f\t\t%-28.28s %-8x %-8x %-8x %-8x %-8x %d %s\n",
1767 timestamp - bias, delta, p, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1768 thread, cpunum, command);
1769 } else {
1770 fprintf(fp, "%9.1f %8.1f\t\t%-8x %-8x %-8x %-8x %-8x %-8x %d %s\n",
1771 timestamp - bias, delta, type, kd->arg1, kd->arg2, kd->arg3, kd->arg4,
1772 thread, cpunum, command);
1773 }
1774}
1775
1776int
1777check_for_thread_update(int thread, int type, kd_buf *kd)
1778{
1779 struct th_info *ti;
1780 void create_map_entry();
1781
1782 switch (type) {
1783
1784 case TRACE_DATA_NEWTHREAD:
1785 if ((ti = find_thread(thread, 0, 0)) == (struct th_info *)0) {
1786 if (cur_max >= MAX_THREADS)
1787 return (1);
1788 ti = &th_state[cur_max++];
1789
1790 ti->thread = thread;
1791 ti->type = -1;
09fd88e4 1792 ti->pathptr = (long *)NULL;
1815bff5
A		 1793 }
1794 ti->child_thread = kd->arg1;
1795 return (1);
1796
1797 case TRACE_STRING_NEWTHREAD:
1798 if ((ti = find_thread(thread, 0, 0)) == (struct th_info *)0)
1799 return (1);
1800 if (ti->child_thread == 0)
1801 return (1);
1802 create_map_entry(ti->child_thread, (char *)&kd->arg1);
1803
1804 ti->child_thread = 0;
1805 return (1);
1806
1807 case TRACE_STRING_EXEC:
1808 create_map_entry(thread, (char *)&kd->arg1);
1809 return (1);
1810
1811 }
1812 return (0);
1813}
1814
1815
1816kd_buf *log_decrementer(kd_buf *kd_beg, kd_buf *kd_end, kd_buf *end_of_sample, double i_latency)
1817{
1818 kd_buf *kd, *kd_start, *kd_stop;
b51d5b5f 1819 int kd_count; /* Limit the boundary of kd_start */
83f6dbe8
A		 1820 double timestamp = 0.0;
1821 double last_timestamp = 0.0;
1822 double delta = 0.0;
1823 double start_bias = 0.0;
1815bff5
A		 1824 int thread, cpunum;
1825 int debugid, type, clen;
1c51fdde
A		 1826 int len;
1827 uint64_t now;
1815bff5
A		 1828 struct th_info *ti;
1829 long *sargptr;
1830 char *p;
1831 char command[32];
1832 char command1[32];
1833 char sched_info[64];
1834 char buf1[128];
1835 char buf2[128];
1836 kd_threadmap *map;
1837 kd_threadmap *find_thread_map();
1838
1839 sprintf(buf1, "%-19.19s interrupt latency = %.1fus", &(ctime(&curr_time)[0]), i_latency);
1840 clen = strlen(buf1);
1841 memset(buf2, '-', clen);
1842 buf2[clen] = 0;
1843 fprintf(log_fp, "\n\n%s\n", buf2);
1844 fprintf(log_fp, "%s\n\n", buf1);
1845
1846 fprintf(log_fp, "RelTime(Us) Delta debugid arg1 arg2 arg3 arg4 thread cpu command\n\n");
1847
83f6dbe8 1848 thread = kd_beg->arg5;
ef8ad44b 1849 cpunum = CPU_NUMBER(kd_end);
1815bff5 1850
b51d5b5f
A		 1851 for (kd_count = 0, kd_start = kd_beg - 1; (kd_start >= (kd_buf *)my_buffer); kd_start--, kd_count++) {
1852 if (kd_count == MAX_LOG_COUNT)
1853 break;
1854
ef8ad44b 1855 if (CPU_NUMBER(kd_start) != cpunum)
b51d5b5f
A		 1856 continue;
1857
1858 if ((kd_start->debugid & DBG_FUNC_MASK) == DECR_TRAP)
1859 break;
1860
83f6dbe8 1861 if (kd_start->arg5 != thread)
1815bff5
A		 1862 break;
1863 }
b51d5b5f 1864
1815bff5
A		 1865 if (kd_start < (kd_buf *)my_buffer)
1866 kd_start = (kd_buf *)my_buffer;
1867
83f6dbe8 1868 thread = kd_end->arg5;
b51d5b5f
A		 1869
1870 for (kd_stop = kd_end + 1; kd_stop < end_of_sample; kd_stop++) {
1871
1872 if ((kd_stop->debugid & DBG_FUNC_MASK) == DECR_TRAP)
1873 break;
1874
ef8ad44b 1875 if (CPU_NUMBER(kd_stop) != cpunum)
b51d5b5f
A		 1876 continue;
1877
83f6dbe8 1878 if (kd_stop->arg5 != thread)
1815bff5
A		 1879 break;
1880 }
b51d5b5f 1881
1815bff5
A		 1882 if (kd_stop >= end_of_sample)
1883 kd_stop = end_of_sample - 1;
1884
83f6dbe8 1885 now = kd_start->timestamp & KDBG_TIMESTAMP_MASK;
1815bff5
A		 1886 timestamp = ((double)now) / divisor;
1887
1888 for (kd = kd_start; kd <= kd_stop; kd++) {
1889 type = kd->debugid & DBG_FUNC_MASK;
1890
83f6dbe8 1891 if ((ti = find_thread(kd->arg5, type, type))) {
1815bff5
A		 1892 if (ti->stime >= timestamp)
1893 ti->type = -1;
1894 }
1895 }
1896 for (kd = kd_start; kd <= kd_stop; kd++) {
1897 int mode;
1898
83f6dbe8 1899 thread = kd->arg5;
ef8ad44b 1900 cpunum = CPU_NUMBER(kd);
1815bff5
A		 1901 debugid = kd->debugid;
1902 type = kd->debugid & DBG_FUNC_MASK;
1903
83f6dbe8 1904 now = kd->timestamp & KDBG_TIMESTAMP_MASK;
1815bff5
A		 1905
1906 timestamp = ((double)now) / divisor;
1907
1908 if (kd == kd_start) {
1909 start_bias = timestamp;
1910 last_timestamp = timestamp;
1911 }
1912 delta = timestamp - last_timestamp;
1913
83f6dbe8 1914 if ((map = find_thread_map(thread)))
1815bff5
A		 1915 strcpy(command, map->command);
1916 else
1917 command[0] = 0;
1918
1919
1920 switch (type) {
1921
1922 case CQ_action:
1923 fprintf(log_fp, "%9.1f %8.1f\t\tCQ_action @ %-59.59s %-8x %d %s\n",
1924 timestamp - start_bias, delta, pc_to_string(kd->arg1, 59, 1) , thread, cpunum, command);
1925
1926 last_timestamp = timestamp;
1927 break;
1928
1929 case DECR_TRAP:
1930 if ((int)(kd->arg1) >= 0)
1931 i_latency = 0;
1932 else
1933 i_latency = (((double)(-1 - kd->arg1)) / divisor);
1934
1935 if (i_thresh_hold && (int)i_latency > i_thresh_hold)
1936 p = "*";
1937 else
1938 p = " ";
1939
1940 mode = 1;
1941
83f6dbe8 1942 if ((ti = find_thread(kd->arg5, 0, 0))) {
1815bff5
A		 1943 if (ti->type == -1 && strcmp(command, "kernel_task"))
1944 mode = 0;
1945 }
1946 fprintf(log_fp, "%9.1f %8.1f[%.1f]%s\tDECR_TRAP @ %-59.59s %-8x %d %s\n",
1947 timestamp - start_bias, delta, i_latency, p, pc_to_string(kd->arg2, 59, mode) , thread, cpunum, command);
1948
1949 last_timestamp = timestamp;
1950 break;
1951
1952 case DECR_SET:
1953 fprintf(log_fp, "%9.1f %8.1f[%.1f] \t%-28.28s %-8x %d %s\n",
1954 timestamp - start_bias, delta, (double)kd->arg1/divisor,
1955 "DECR_SET", thread, cpunum, command);
1956
1957 last_timestamp = timestamp;
1958 break;
1959
1960 case MACH_sched:
1961 case MACH_stkhandoff:
83f6dbe8 1962 if ((map = find_thread_map(kd->arg2)))
1815bff5
A		 1963 strcpy(command1, map->command);
1964 else
1965 sprintf(command1, "%-8x", kd->arg2);
1966
83f6dbe8 1967 if ((ti = find_thread(kd->arg2, 0, 0))) {
1815bff5
A		 1968 if (ti->type == -1 && strcmp(command1, "kernel_task"))
1969 p = "U";
1970 else
1971 p = "K";
1972 } else
1973 p = "*";
1974 memset(sched_info, ' ', sizeof(sched_info));
1975
1976 sprintf(sched_info, "%14.14s", command);
1977 clen = strlen(sched_info);
1978 sched_info[clen] = ' ';
1979
1980 sprintf(&sched_info[14], " @ pri %3d --> %14.14s", kd->arg3, command1);
1981 clen = strlen(sched_info);
1982 sched_info[clen] = ' ';
1983
1984 sprintf(&sched_info[45], " @ pri %3d%s", kd->arg4, p);
1985
1986 fprintf(log_fp, "%9.1f %8.1f\t\t%-10.10s %s %-8x %d\n",
1987 timestamp - start_bias, delta, "MACH_SCHED", sched_info, thread, cpunum);
1988
1989 last_timestamp = timestamp;
1990 break;
1991
1992 case VFS_LOOKUP:
1993 if ((ti = find_thread(thread, 0, 0)) == (struct th_info *)0) {
1994 if (cur_max >= MAX_THREADS)
1995 continue;
1996 ti = &th_state[cur_max++];
1997
1998 ti->thread = thread;
1999 ti->type = -1;
09fd88e4 2000 ti->pathptr = (long *)NULL;
1815bff5
A		 2001 ti->child_thread = 0;
2002 }
b51d5b5f
A		 2003
2004 while ( (kd <= kd_stop) && (kd->debugid & DBG_FUNC_MASK) == VFS_LOOKUP)
2005 {
09fd88e4 2006 if (ti->pathptr == NULL) {
1815bff5 2007 ti->arg1 = kd->arg1;
09fd88e4 2008 sargptr = ti->pathname;
1815bff5
A		 2009
2010 *sargptr++ = kd->arg2;
2011 *sargptr++ = kd->arg3;
2012 *sargptr++ = kd->arg4;
09fd88e4
A		 2013 /*
2014 * NULL terminate the 'string'
2015 */
2016 *sargptr = 0;
2017
1c51fdde
A		 2018 ti->pathptr = sargptr;
2019
b51d5b5f 2020 } else {
1c51fdde
A		 2021 sargptr = ti->pathptr;
2022
2023 /*
2024 We don't want to overrun our pathname buffer if the
2025 kernel sends us more VFS_LOOKUP entries than we can
2026 handle.
2027 */
2028
09fd88e4 2029 if (sargptr >= &ti->pathname[NUMPARMS])
b51d5b5f
A		 2030 {
2031 kd++;
2032 continue;
2033 }
2034
2035 /*
2036 We need to detect consecutive vfslookup entries.
2037 So, if we get here and find a START entry,
2038 fake the pathptr so we can bypass all further
2039 vfslookup entries.
2040 */
2041
2042 if (kd->debugid & DBG_FUNC_START)
2043 {
09fd88e4 2044 ti->pathptr = &ti->pathname[NUMPARMS];
b51d5b5f
A		 2045 }
2046 else
1c51fdde
A		 2047 {
2048 *sargptr++ = kd->arg1;
2049 *sargptr++ = kd->arg2;
2050 *sargptr++ = kd->arg3;
2051 *sargptr++ = kd->arg4;
09fd88e4
A		 2052 /*
2053 * NULL terminate the 'string'
2054 */
2055 *sargptr = 0;
2056
b51d5b5f 2057 ti->pathptr = sargptr;
1c51fdde 2058 }
b51d5b5f
A		 2059 }
2060 kd++;
1815bff5 2061 }
09fd88e4 2062 p = (char *)ti->pathname;
b51d5b5f
A		 2063
2064 kd--;
2065 /* print the tail end of the pathname */
09fd88e4 2066 len = strlen(p);
b51d5b5f
A		 2067 if (len > 42)
2068 len -= 42;
2069 else
2070 len = 0;
2071
2072 fprintf(log_fp, "%9.1f %8.1f\t\t%-14.14s %-42s %-8x %-8x %d %s\n",
2073 timestamp - start_bias, delta, "VFS_LOOKUP",
09fd88e4 2074 &p[len], ti->arg1, thread, cpunum, command);
b51d5b5f 2075
1815bff5
A		 2076 last_timestamp = timestamp;
2077 break;
2078
2079 default:
2080 if (debugid & DBG_FUNC_START)
2081 enter_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 1);
2082 else if (debugid & DBG_FUNC_END)
2083 exit_syscall(log_fp, kd, thread, type, command, timestamp, delta, start_bias, 1);
2084 else
2085 print_entry(log_fp, kd, thread, type, command, timestamp, delta, start_bias);
2086
2087 last_timestamp = timestamp;
2088 break;
2089 }
2090 }
2091 return(kd_stop);
2092}
2093
2094
2095double handle_decrementer(kd_buf *kd)
2096{
2097 double latency;
ef8ad44b 2098 long elapsed_usecs;
1815bff5 2099
ef8ad44b 2100 if ((long)(kd->arg1) >= 0)
1815bff5
A		 2101 latency = 1;
2102 else
2103 latency = (((double)(-1 - kd->arg1)) / divisor);
ef8ad44b 2104 elapsed_usecs = (long)latency;
1815bff5
A		 2105
2106 if (elapsed_usecs < 100)
2107 i_usec_10_bins[elapsed_usecs/10]++;
2108 if (elapsed_usecs < 1000)
2109 i_usec_100_bins[elapsed_usecs/100]++;
2110 else if (elapsed_usecs < 10000)
2111 i_msec_1_bins[elapsed_usecs/1000]++;
2112 else if (elapsed_usecs < 50000)
2113 i_msec_10_bins[elapsed_usecs/10000]++;
2114 else
2115 i_too_slow++;
2116
c03df0e9
A		 2117 if(use_high_res_bins && elapsed_usecs < N_HIGH_RES_BINS) {
2118 if(elapsed_usecs > i_highest_latency)
2119 i_highest_latency = elapsed_usecs;
2120 i_high_res_bins[elapsed_usecs]++;
2121 }
2122
1815bff5
A		 2123 if (i_thresh_hold && elapsed_usecs > i_thresh_hold)
2124 i_exceeded_threshold++;
2125 if (elapsed_usecs > i_max_latency)
2126 i_max_latency = elapsed_usecs;
2127 if (elapsed_usecs < i_min_latency || i_total_samples == 0)
2128 i_min_latency = elapsed_usecs;
2129 i_total_latency += elapsed_usecs;
2130 i_total_samples++;
2131
2132 return (latency);
2133}
2134
2135
2136void init_code_file()
2137{
2138 FILE *fp;
c03df0e9 2139 int i, n, code;
1815bff5
A		 2140 char name[128];
2141
2142 if ((fp = fopen(code_file, "r")) == (FILE *)0) {
2143 if (log_fp)
2144 fprintf(log_fp, "open of %s failed\n", code_file);
2145 return;
2146 }
1815bff5 2147 for (i = 0; i < MAX_ENTRIES; i++) {
34d340d7 2148 n = fscanf(fp, "%x%127s\n", &code, name);
1815bff5 2149
c03df0e9
A		 2150 if (n == 1 && i == 0) {
2151 /*
2152 * old code file format, just skip
2153 */
2154 continue;
2155 }
1815bff5
A		 2156 if (n != 2)
2157 break;
2158
2159 strncpy(codes_tab[i].name, name, 32);
2160 codes_tab[i].type = code;
2161 }
2162 num_of_codes = i;
2163
2164 fclose(fp);
2165}
2166
2167
2168void
2169do_kernel_nm()
2170{
2171 int i, len;
2172 FILE *fp = (FILE *)0;
2173 char tmp_nm_file[128];
2174 char tmpstr[1024];
83f6dbe8 2175 char inchr;
1815bff5
A		 2176
2177 bzero(tmp_nm_file, 128);
2178 bzero(tmpstr, 1024);
2179
2180 /* Build the temporary nm file path */
34d340d7
A		 2181 strcpy(tmp_nm_file,"/tmp/knm.out.XXXXXX");
2182 if (!mktemp(tmp_nm_file)) {
2183 fprintf(stderr, "Error in mktemp call\n");
2184 return;
2185 }
1815bff5
A		 2186
2187 /* Build the nm command and create a tmp file with the output*/
2188 sprintf (tmpstr, "/usr/bin/nm -f -n -s __TEXT __text %s > %s",
2189 kernelpath, tmp_nm_file);
2190 system(tmpstr);
2191
2192 /* Parse the output from the nm command */
2193 if ((fp=fopen(tmp_nm_file, "r")) == (FILE *)0)
2194 {
2195 /* Hmmm, let's not treat this as fatal */
2196 fprintf(stderr, "Failed to open nm symbol file [%s]\n", tmp_nm_file);
2197 return;
2198 }
2199
2200 /* Count the number of symbols in the nm symbol table */
2201 kern_sym_count=0;
2202 while ( (inchr = getc(fp)) != -1)
2203 {
2204 if (inchr == '\n')
2205 kern_sym_count++;
2206 }
2207
2208 rewind(fp);
2209
2210 /* Malloc the space for symbol table */
2211 if (kern_sym_count > 0)
2212 {
2213 kern_sym_tbl = (kern_sym_t *)malloc(kern_sym_count * sizeof (kern_sym_t));
2214 if (!kern_sym_tbl)
2215 {
2216 /* Hmmm, lets not treat this as fatal */
2217 fprintf(stderr, "Can't allocate memory for kernel symbol table\n");
2218 }
2219 else
2220 bzero(kern_sym_tbl, (kern_sym_count * sizeof(kern_sym_t)));
2221 }
2222 else
2223 {
2224 /* Hmmm, lets not treat this as fatal */
2225 fprintf(stderr, "No kernel symbol table \n");
2226 }
2227
2228 for (i=0; i<kern_sym_count; i++)
2229 {
2230 bzero(tmpstr, 1024);
83f6dbe8 2231 if (fscanf(fp, "%lx %c %s", &kern_sym_tbl[i].k_sym_addr, &inchr, tmpstr) != 3)
1815bff5
A		 2232 break;
2233 else
2234 {
2235 len = strlen(tmpstr);
2236 kern_sym_tbl[i].k_sym_name = malloc(len + 1);
2237
2238 if (kern_sym_tbl[i].k_sym_name == (char *)0)
2239 {
2240 fprintf(stderr, "Can't allocate memory for symbol name [%s]\n", tmpstr);
2241 kern_sym_tbl[i].k_sym_name = (char *)0;
2242 len = 0;
2243 }
2244 else
2245 strcpy(kern_sym_tbl[i].k_sym_name, tmpstr);
2246
2247 kern_sym_tbl[i].k_sym_len = len;
2248 }
2249 } /* end for */
2250
2251 if (i != kern_sym_count)
2252 {
2253 /* Hmmm, didn't build up entire table from nm */
2254 /* scrap the entire thing */
2255 if (kern_sym_tbl)
2256 free (kern_sym_tbl);
2257 kern_sym_tbl = (kern_sym_t *)0;
2258 kern_sym_count = 0;
2259 }
2260
2261 fclose(fp);
2262
2263 /* Remove the temporary nm file */
2264 unlink(tmp_nm_file);
2265
2266#if 0
2267 /* Dump the kernel symbol table */
2268 for (i=0; i < kern_sym_count; i++)
2269 {
2270 if (kern_sym_tbl[i].k_sym_name)
2271 printf ("[%d] 0x%x %s\n", i,
2272 kern_sym_tbl[i].k_sym_addr, kern_sym_tbl[i].k_sym_name);
2273 else
2274 printf ("[%d] 0x%x %s\n", i,
2275 kern_sym_tbl[i].k_sym_addr, "No symbol name");
2276 }
2277#endif
2278}
2279
2280char *
2281pc_to_string(unsigned int pc, int max_len, int mode)
2282{
2283 int ret;
2284 int len;
2285
2286 int binary_search();
2287
2288 if (mode == 0)
2289 {
2290 sprintf(pcstring, "0x%-8x [usermode addr]", pc);
2291 return(pcstring);
2292 }
2293
2294 ret=0;
2295 ret = binary_search(kern_sym_tbl, 0, kern_sym_count-1, pc);
2296
2297 if (ret == -1)
2298 {
2299 sprintf(pcstring, "0x%x", pc);
2300 return(pcstring);
2301 }
2302 else if (kern_sym_tbl[ret].k_sym_name == (char *)0)
2303 {
2304 sprintf(pcstring, "0x%x", pc);
2305 return(pcstring);
2306 }
2307 else
2308 {
2309 if ((len = kern_sym_tbl[ret].k_sym_len) > (max_len - 8))
2310 len = max_len - 8;
2311
2312 memcpy(pcstring, kern_sym_tbl[ret].k_sym_name, len);
83f6dbe8 2313 sprintf(&pcstring[len], "+0x%-5lx", pc - kern_sym_tbl[ret].k_sym_addr);
1815bff5
A		 2314
2315 return (pcstring);
2316 }
2317}
2318
2319
2320/* Return -1 if not found, else return index */
2321int binary_search(list, low, high, addr)
2322kern_sym_t *list;
2323int low, high;
2324unsigned int addr;
2325{
2326 int mid;
2327
2328 mid = (low + high) / 2;
2329
2330 if (low > high)
2331 return (-1); /* failed */
2332 else if (low + 1 == high)
2333 {
2334 if (list[low].k_sym_addr <= addr &&
2335 addr < list[high].k_sym_addr)
2336 {
2337 /* We have a range match */
2338 return(low);
2339 }
2340 else if (list[high].k_sym_addr <= addr)
2341 {
2342 return(high);
2343 }
2344 else
2345 return(-1); /* Failed */
2346 }
2347 else if (addr < list[mid].k_sym_addr)
2348 {
2349 return(binary_search (list, low, mid, addr));
2350 }
2351 else
2352 {
2353 return(binary_search (list, mid, high, addr));
2354 }
2355}
2356
2357void
2358open_logfile(char *path)
2359{
2360 log_fp = fopen(path, "a");
2361
2362 if (!log_fp)
2363 {
2364 /* failed to open path */
2365 fprintf(stderr, "latency: failed to open logfile [%s]\n", path);
2366 exit_usage();
2367 }
2368}
mirror of system_cmds