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