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