1 /* 2 * CDDL HEADER START 3 * 4 * The contents of this file are subject to the terms of the 5 * Common Development and Distribution License (the "License"). 6 * You may not use this file except in compliance with the License. 7 * 8 * You can obtain a copy of the license at usr/src/OPENSOLARIS.LICENSE 9 * or http://www.opensolaris.org/os/licensing. 10 * See the License for the specific language governing permissions 11 * and limitations under the License. 12 * 13 * When distributing Covered Code, include this CDDL HEADER in each 14 * file and include the License file at usr/src/OPENSOLARIS.LICENSE. 15 * If applicable, add the following below this CDDL HEADER, with the 16 * fields enclosed by brackets "[]" replaced with your own identifying 17 * information: Portions Copyright [yyyy] [name of copyright owner] 18 * 19 * CDDL HEADER END 20 */ 21 /* 22 * Copyright 2008 Sun Microsystems, Inc. All rights reserved. 23 * Use is subject to license terms. 24 */ 25 26 #include <stdio.h> 27 #include <stddef.h> 28 #include <stdlib.h> 29 #include <stdarg.h> 30 #include <string.h> 31 #include <strings.h> 32 #include <ctype.h> 33 #include <fcntl.h> 34 #include <unistd.h> 35 #include <errno.h> 36 #include <limits.h> 37 #include <sys/types.h> 38 #include <sys/modctl.h> 39 #include <sys/stat.h> 40 #include <sys/wait.h> 41 #include <dtrace.h> 42 #include <sys/lockstat.h> 43 #include <alloca.h> 44 #include <signal.h> 45 #include <assert.h> 46 47 #define LOCKSTAT_OPTSTR "x:bths:n:d:i:l:f:e:ckwWgCHEATID:RpPo:V" 48 49 #define LS_MAX_STACK_DEPTH 50 50 #define LS_MAX_EVENTS 64 51 52 typedef struct lsrec { 53 struct lsrec *ls_next; /* next in hash chain */ 54 uintptr_t ls_lock; /* lock address */ 55 uintptr_t ls_caller; /* caller address */ 56 uint32_t ls_count; /* cumulative event count */ 57 uint32_t ls_event; /* type of event */ 58 uintptr_t ls_refcnt; /* cumulative reference count */ 59 uint64_t ls_time; /* cumulative event duration */ 60 uint32_t ls_hist[64]; /* log2(duration) histogram */ 61 uintptr_t ls_stack[LS_MAX_STACK_DEPTH]; 62 } lsrec_t; 63 64 typedef struct lsdata { 65 struct lsrec *lsd_next; /* next available */ 66 int lsd_count; /* number of records */ 67 } lsdata_t; 68 69 /* 70 * Definitions for the types of experiments which can be run. They are 71 * listed in increasing order of memory cost and processing time cost. 72 * The numerical value of each type is the number of bytes needed per record. 73 */ 74 #define LS_BASIC offsetof(lsrec_t, ls_time) 75 #define LS_TIME offsetof(lsrec_t, ls_hist[0]) 76 #define LS_HIST offsetof(lsrec_t, ls_stack[0]) 77 #define LS_STACK(depth) offsetof(lsrec_t, ls_stack[depth]) 78 79 static void report_stats(FILE *, lsrec_t **, size_t, uint64_t, uint64_t); 80 static void report_trace(FILE *, lsrec_t **); 81 82 extern int symtab_init(void); 83 extern char *addr_to_sym(uintptr_t, uintptr_t *, size_t *); 84 extern uintptr_t sym_to_addr(char *name); 85 extern size_t sym_size(char *name); 86 extern char *strtok_r(char *, const char *, char **); 87 88 #define DEFAULT_NRECS 10000 89 #define DEFAULT_HZ 97 90 #define MAX_HZ 1000 91 #define MIN_AGGSIZE (16 * 1024) 92 #define MAX_AGGSIZE (32 * 1024 * 1024) 93 94 static int g_stkdepth; 95 static int g_topn = INT_MAX; 96 static hrtime_t g_elapsed; 97 static int g_rates = 0; 98 static int g_pflag = 0; 99 static int g_Pflag = 0; 100 static int g_wflag = 0; 101 static int g_Wflag = 0; 102 static int g_cflag = 0; 103 static int g_kflag = 0; 104 static int g_gflag = 0; 105 static int g_Vflag = 0; 106 static int g_tracing = 0; 107 static size_t g_recsize; 108 static size_t g_nrecs; 109 static int g_nrecs_used; 110 static uchar_t g_enabled[LS_MAX_EVENTS]; 111 static hrtime_t g_min_duration[LS_MAX_EVENTS]; 112 static dtrace_hdl_t *g_dtp; 113 static char *g_predicate; 114 static char *g_ipredicate; 115 static char *g_prog; 116 static int g_proglen; 117 static int g_dropped; 118 119 typedef struct ls_event_info { 120 char ev_type; 121 char ev_lhdr[20]; 122 char ev_desc[80]; 123 char ev_units[10]; 124 char ev_name[DTRACE_NAMELEN]; 125 char *ev_predicate; 126 char *ev_acquire; 127 } ls_event_info_t; 128 129 static ls_event_info_t g_event_info[LS_MAX_EVENTS] = { 130 { 'C', "Lock", "Adaptive mutex spin", "nsec", 131 "lockstat:::adaptive-spin" }, 132 { 'C', "Lock", "Adaptive mutex block", "nsec", 133 "lockstat:::adaptive-block" }, 134 { 'C', "Lock", "Spin lock spin", "nsec", 135 "lockstat:::spin-spin" }, 136 { 'C', "Lock", "Thread lock spin", "nsec", 137 "lockstat:::thread-spin" }, 138 { 'C', "Lock", "R/W writer blocked by writer", "nsec", 139 "lockstat:::rw-block", "arg2 == 0 && arg3 == 1" }, 140 { 'C', "Lock", "R/W writer blocked by readers", "nsec", 141 "lockstat:::rw-block", "arg2 == 0 && arg3 == 0 && arg4" }, 142 { 'C', "Lock", "R/W reader blocked by writer", "nsec", 143 "lockstat:::rw-block", "arg2 != 0 && arg3 == 1" }, 144 { 'C', "Lock", "R/W reader blocked by write wanted", "nsec", 145 "lockstat:::rw-block", "arg2 != 0 && arg3 == 0 && arg4" }, 146 { 'C', "Lock", "Unknown event (type 8)", "units" }, 147 { 'C', "Lock", "Unknown event (type 9)", "units" }, 148 { 'C', "Lock", "Unknown event (type 10)", "units" }, 149 { 'C', "Lock", "Unknown event (type 11)", "units" }, 150 { 'C', "Lock", "Unknown event (type 12)", "units" }, 151 { 'C', "Lock", "Unknown event (type 13)", "units" }, 152 { 'C', "Lock", "Unknown event (type 14)", "units" }, 153 { 'C', "Lock", "Unknown event (type 15)", "units" }, 154 { 'C', "Lock", "Unknown event (type 16)", "units" }, 155 { 'C', "Lock", "Unknown event (type 17)", "units" }, 156 { 'C', "Lock", "Unknown event (type 18)", "units" }, 157 { 'C', "Lock", "Unknown event (type 19)", "units" }, 158 { 'C', "Lock", "Unknown event (type 20)", "units" }, 159 { 'C', "Lock", "Unknown event (type 21)", "units" }, 160 { 'C', "Lock", "Unknown event (type 22)", "units" }, 161 { 'C', "Lock", "Unknown event (type 23)", "units" }, 162 { 'C', "Lock", "Unknown event (type 24)", "units" }, 163 { 'C', "Lock", "Unknown event (type 25)", "units" }, 164 { 'C', "Lock", "Unknown event (type 26)", "units" }, 165 { 'C', "Lock", "Unknown event (type 27)", "units" }, 166 { 'C', "Lock", "Unknown event (type 28)", "units" }, 167 { 'C', "Lock", "Unknown event (type 29)", "units" }, 168 { 'C', "Lock", "Unknown event (type 30)", "units" }, 169 { 'C', "Lock", "Unknown event (type 31)", "units" }, 170 { 'H', "Lock", "Adaptive mutex hold", "nsec", 171 "lockstat:::adaptive-release", NULL, 172 "lockstat:::adaptive-acquire" }, 173 { 'H', "Lock", "Spin lock hold", "nsec", 174 "lockstat:::spin-release", NULL, 175 "lockstat:::spin-acquire" }, 176 { 'H', "Lock", "R/W writer hold", "nsec", 177 "lockstat:::rw-release", "arg1 == 0", 178 "lockstat:::rw-acquire" }, 179 { 'H', "Lock", "R/W reader hold", "nsec", 180 "lockstat:::rw-release", "arg1 != 0", 181 "lockstat:::rw-acquire" }, 182 { 'H', "Lock", "Unknown event (type 36)", "units" }, 183 { 'H', "Lock", "Unknown event (type 37)", "units" }, 184 { 'H', "Lock", "Unknown event (type 38)", "units" }, 185 { 'H', "Lock", "Unknown event (type 39)", "units" }, 186 { 'H', "Lock", "Unknown event (type 40)", "units" }, 187 { 'H', "Lock", "Unknown event (type 41)", "units" }, 188 { 'H', "Lock", "Unknown event (type 42)", "units" }, 189 { 'H', "Lock", "Unknown event (type 43)", "units" }, 190 { 'H', "Lock", "Unknown event (type 44)", "units" }, 191 { 'H', "Lock", "Unknown event (type 45)", "units" }, 192 { 'H', "Lock", "Unknown event (type 46)", "units" }, 193 { 'H', "Lock", "Unknown event (type 47)", "units" }, 194 { 'H', "Lock", "Unknown event (type 48)", "units" }, 195 { 'H', "Lock", "Unknown event (type 49)", "units" }, 196 { 'H', "Lock", "Unknown event (type 50)", "units" }, 197 { 'H', "Lock", "Unknown event (type 51)", "units" }, 198 { 'H', "Lock", "Unknown event (type 52)", "units" }, 199 { 'H', "Lock", "Unknown event (type 53)", "units" }, 200 { 'H', "Lock", "Unknown event (type 54)", "units" }, 201 { 'H', "Lock", "Unknown event (type 55)", "units" }, 202 { 'I', "CPU+PIL", "Profiling interrupt", "nsec", 203 "profile:::profile-97", NULL }, 204 { 'I', "Lock", "Unknown event (type 57)", "units" }, 205 { 'I', "Lock", "Unknown event (type 58)", "units" }, 206 { 'I', "Lock", "Unknown event (type 59)", "units" }, 207 { 'E', "Lock", "Recursive lock entry detected", "(N/A)", 208 "lockstat:::rw-release", NULL, "lockstat:::rw-acquire" }, 209 { 'E', "Lock", "Lockstat enter failure", "(N/A)" }, 210 { 'E', "Lock", "Lockstat exit failure", "nsec" }, 211 { 'E', "Lock", "Lockstat record failure", "(N/A)" }, 212 }; 213 214 static void 215 fail(int do_perror, const char *message, ...) 216 { 217 va_list args; 218 int save_errno = errno; 219 220 va_start(args, message); 221 (void) fprintf(stderr, "lockstat: "); 222 (void) vfprintf(stderr, message, args); 223 va_end(args); 224 if (do_perror) 225 (void) fprintf(stderr, ": %s", strerror(save_errno)); 226 (void) fprintf(stderr, "\n"); 227 exit(2); 228 } 229 230 static void 231 dfail(const char *message, ...) 232 { 233 va_list args; 234 235 va_start(args, message); 236 (void) fprintf(stderr, "lockstat: "); 237 (void) vfprintf(stderr, message, args); 238 va_end(args); 239 (void) fprintf(stderr, ": %s\n", 240 dtrace_errmsg(g_dtp, dtrace_errno(g_dtp))); 241 242 exit(2); 243 } 244 245 static void 246 show_events(char event_type, char *desc) 247 { 248 int i, first = -1, last; 249 250 for (i = 0; i < LS_MAX_EVENTS; i++) { 251 ls_event_info_t *evp = &g_event_info[i]; 252 if (evp->ev_type != event_type || 253 strncmp(evp->ev_desc, "Unknown event", 13) == 0) 254 continue; 255 if (first == -1) 256 first = i; 257 last = i; 258 } 259 260 (void) fprintf(stderr, 261 "\n%s events (lockstat -%c or lockstat -e %d-%d):\n\n", 262 desc, event_type, first, last); 263 264 for (i = first; i <= last; i++) 265 (void) fprintf(stderr, 266 "%4d = %s\n", i, g_event_info[i].ev_desc); 267 } 268 269 static void 270 usage(void) 271 { 272 (void) fprintf(stderr, 273 "Usage: lockstat [options] command [args]\n" 274 "\nEvent selection options:\n\n" 275 " -C watch contention events [on by default]\n" 276 " -E watch error events [off by default]\n" 277 " -H watch hold events [off by default]\n" 278 " -I watch interrupt events [off by default]\n" 279 " -A watch all lock events [equivalent to -CH]\n" 280 " -e event_list only watch the specified events (shown below);\n" 281 " <event_list> is a comma-separated list of\n" 282 " events or ranges of events, e.g. 1,4-7,35\n" 283 " -i rate interrupt rate for -I [default: %d Hz]\n" 284 "\nData gathering options:\n\n" 285 " -b basic statistics (lock, caller, event count)\n" 286 " -t timing for all events [default]\n" 287 " -h histograms for event times\n" 288 " -s depth stack traces <depth> deep\n" 289 " -x opt[=val] enable or modify DTrace options\n" 290 "\nData filtering options:\n\n" 291 " -n nrecords maximum number of data records [default: %d]\n" 292 " -l lock[,size] only watch <lock>, which can be specified as a\n" 293 " symbolic name or hex address; <size> defaults\n" 294 " to the ELF symbol size if available, 1 if not\n" 295 " -f func[,size] only watch events generated by <func>\n" 296 " -d duration only watch events longer than <duration>\n" 297 " -T trace (rather than sample) events\n" 298 "\nData reporting options:\n\n" 299 " -c coalesce lock data for arrays like pse_mutex[]\n" 300 " -k coalesce PCs within functions\n" 301 " -g show total events generated by function\n" 302 " -w wherever: don't distinguish events by caller\n" 303 " -W whichever: don't distinguish events by lock\n" 304 " -R display rates rather than counts\n" 305 " -p parsable output format (awk(1)-friendly)\n" 306 " -P sort lock data by (count * avg_time) product\n" 307 " -D n only display top <n> events of each type\n" 308 " -o filename send output to <filename>\n", 309 DEFAULT_HZ, DEFAULT_NRECS); 310 311 show_events('C', "Contention"); 312 show_events('H', "Hold-time"); 313 show_events('I', "Interrupt"); 314 show_events('E', "Error"); 315 (void) fprintf(stderr, "\n"); 316 317 exit(1); 318 } 319 320 static int 321 lockcmp(lsrec_t *a, lsrec_t *b) 322 { 323 int i; 324 325 if (a->ls_event < b->ls_event) 326 return (-1); 327 if (a->ls_event > b->ls_event) 328 return (1); 329 330 for (i = g_stkdepth - 1; i >= 0; i--) { 331 if (a->ls_stack[i] < b->ls_stack[i]) 332 return (-1); 333 if (a->ls_stack[i] > b->ls_stack[i]) 334 return (1); 335 } 336 337 if (a->ls_caller < b->ls_caller) 338 return (-1); 339 if (a->ls_caller > b->ls_caller) 340 return (1); 341 342 if (a->ls_lock < b->ls_lock) 343 return (-1); 344 if (a->ls_lock > b->ls_lock) 345 return (1); 346 347 return (0); 348 } 349 350 static int 351 countcmp(lsrec_t *a, lsrec_t *b) 352 { 353 if (a->ls_event < b->ls_event) 354 return (-1); 355 if (a->ls_event > b->ls_event) 356 return (1); 357 358 return (b->ls_count - a->ls_count); 359 } 360 361 static int 362 timecmp(lsrec_t *a, lsrec_t *b) 363 { 364 if (a->ls_event < b->ls_event) 365 return (-1); 366 if (a->ls_event > b->ls_event) 367 return (1); 368 369 if (a->ls_time < b->ls_time) 370 return (1); 371 if (a->ls_time > b->ls_time) 372 return (-1); 373 374 return (0); 375 } 376 377 static int 378 lockcmp_anywhere(lsrec_t *a, lsrec_t *b) 379 { 380 if (a->ls_event < b->ls_event) 381 return (-1); 382 if (a->ls_event > b->ls_event) 383 return (1); 384 385 if (a->ls_lock < b->ls_lock) 386 return (-1); 387 if (a->ls_lock > b->ls_lock) 388 return (1); 389 390 return (0); 391 } 392 393 static int 394 lock_and_count_cmp_anywhere(lsrec_t *a, lsrec_t *b) 395 { 396 if (a->ls_event < b->ls_event) 397 return (-1); 398 if (a->ls_event > b->ls_event) 399 return (1); 400 401 if (a->ls_lock < b->ls_lock) 402 return (-1); 403 if (a->ls_lock > b->ls_lock) 404 return (1); 405 406 return (b->ls_count - a->ls_count); 407 } 408 409 static int 410 sitecmp_anylock(lsrec_t *a, lsrec_t *b) 411 { 412 int i; 413 414 if (a->ls_event < b->ls_event) 415 return (-1); 416 if (a->ls_event > b->ls_event) 417 return (1); 418 419 for (i = g_stkdepth - 1; i >= 0; i--) { 420 if (a->ls_stack[i] < b->ls_stack[i]) 421 return (-1); 422 if (a->ls_stack[i] > b->ls_stack[i]) 423 return (1); 424 } 425 426 if (a->ls_caller < b->ls_caller) 427 return (-1); 428 if (a->ls_caller > b->ls_caller) 429 return (1); 430 431 return (0); 432 } 433 434 static int 435 site_and_count_cmp_anylock(lsrec_t *a, lsrec_t *b) 436 { 437 int i; 438 439 if (a->ls_event < b->ls_event) 440 return (-1); 441 if (a->ls_event > b->ls_event) 442 return (1); 443 444 for (i = g_stkdepth - 1; i >= 0; i--) { 445 if (a->ls_stack[i] < b->ls_stack[i]) 446 return (-1); 447 if (a->ls_stack[i] > b->ls_stack[i]) 448 return (1); 449 } 450 451 if (a->ls_caller < b->ls_caller) 452 return (-1); 453 if (a->ls_caller > b->ls_caller) 454 return (1); 455 456 return (b->ls_count - a->ls_count); 457 } 458 459 static void 460 mergesort(int (*cmp)(lsrec_t *, lsrec_t *), lsrec_t **a, lsrec_t **b, int n) 461 { 462 int m = n / 2; 463 int i, j; 464 465 if (m > 1) 466 mergesort(cmp, a, b, m); 467 if (n - m > 1) 468 mergesort(cmp, a + m, b + m, n - m); 469 for (i = m; i > 0; i--) 470 b[i - 1] = a[i - 1]; 471 for (j = m - 1; j < n - 1; j++) 472 b[n + m - j - 2] = a[j + 1]; 473 while (i < j) 474 *a++ = cmp(b[i], b[j]) < 0 ? b[i++] : b[j--]; 475 *a = b[i]; 476 } 477 478 static void 479 coalesce(int (*cmp)(lsrec_t *, lsrec_t *), lsrec_t **lock, int n) 480 { 481 int i, j; 482 lsrec_t *target, *current; 483 484 target = lock[0]; 485 486 for (i = 1; i < n; i++) { 487 current = lock[i]; 488 if (cmp(current, target) != 0) { 489 target = current; 490 continue; 491 } 492 current->ls_event = LS_MAX_EVENTS; 493 target->ls_count += current->ls_count; 494 target->ls_refcnt += current->ls_refcnt; 495 if (g_recsize < LS_TIME) 496 continue; 497 target->ls_time += current->ls_time; 498 if (g_recsize < LS_HIST) 499 continue; 500 for (j = 0; j < 64; j++) 501 target->ls_hist[j] += current->ls_hist[j]; 502 } 503 } 504 505 static void 506 coalesce_symbol(uintptr_t *addrp) 507 { 508 uintptr_t symoff; 509 size_t symsize; 510 511 if (addr_to_sym(*addrp, &symoff, &symsize) != NULL && symoff < symsize) 512 *addrp -= symoff; 513 } 514 515 static void 516 predicate_add(char **pred, char *what, char *cmp, uintptr_t value) 517 { 518 char *new; 519 int len, newlen; 520 521 if (what == NULL) 522 return; 523 524 if (*pred == NULL) { 525 *pred = malloc(1); 526 *pred[0] = '\0'; 527 } 528 529 len = strlen(*pred); 530 newlen = len + strlen(what) + 32 + strlen("( && )"); 531 new = malloc(newlen); 532 533 if (*pred[0] != '\0') { 534 if (cmp != NULL) { 535 (void) sprintf(new, "(%s) && (%s %s 0x%p)", 536 *pred, what, cmp, (void *)value); 537 } else { 538 (void) sprintf(new, "(%s) && (%s)", *pred, what); 539 } 540 } else { 541 if (cmp != NULL) { 542 (void) sprintf(new, "%s %s 0x%p", 543 what, cmp, (void *)value); 544 } else { 545 (void) sprintf(new, "%s", what); 546 } 547 } 548 549 free(*pred); 550 *pred = new; 551 } 552 553 static void 554 predicate_destroy(char **pred) 555 { 556 free(*pred); 557 *pred = NULL; 558 } 559 560 static void 561 filter_add(char **filt, char *what, uintptr_t base, uintptr_t size) 562 { 563 char buf[256], *c = buf, *new; 564 int len, newlen; 565 566 if (*filt == NULL) { 567 *filt = malloc(1); 568 *filt[0] = '\0'; 569 } 570 571 (void) sprintf(c, "%s(%s >= 0x%p && %s < 0x%p)", *filt[0] != '\0' ? 572 " || " : "", what, (void *)base, what, (void *)(base + size)); 573 574 newlen = (len = strlen(*filt) + 1) + strlen(c); 575 new = malloc(newlen); 576 bcopy(*filt, new, len); 577 (void) strcat(new, c); 578 free(*filt); 579 *filt = new; 580 } 581 582 static void 583 filter_destroy(char **filt) 584 { 585 free(*filt); 586 *filt = NULL; 587 } 588 589 static void 590 dprog_add(const char *fmt, ...) 591 { 592 va_list args; 593 int size, offs; 594 char c; 595 596 va_start(args, fmt); 597 size = vsnprintf(&c, 1, fmt, args) + 1; 598 599 if (g_proglen == 0) { 600 offs = 0; 601 } else { 602 offs = g_proglen - 1; 603 } 604 605 g_proglen = offs + size; 606 607 if ((g_prog = realloc(g_prog, g_proglen)) == NULL) 608 fail(1, "failed to reallocate program text"); 609 610 (void) vsnprintf(&g_prog[offs], size, fmt, args); 611 } 612 613 /* 614 * This function may read like an open sewer, but keep in mind that programs 615 * that generate other programs are rarely pretty. If one has the unenviable 616 * task of maintaining or -- worse -- extending this code, use the -V option 617 * to examine the D program as generated by this function. 618 */ 619 static void 620 dprog_addevent(int event) 621 { 622 ls_event_info_t *info = &g_event_info[event]; 623 char *pred = NULL; 624 char stack[20]; 625 const char *arg0, *caller; 626 char *arg1 = "arg1"; 627 char buf[80]; 628 hrtime_t dur; 629 int depth; 630 631 if (info->ev_name[0] == '\0') 632 return; 633 634 if (info->ev_type == 'I') { 635 /* 636 * For interrupt events, arg0 (normally the lock pointer) is 637 * the CPU address plus the current pil, and arg1 (normally 638 * the number of nanoseconds) is the number of nanoseconds 639 * late -- and it's stored in arg2. 640 */ 641 arg0 = "(uintptr_t)curthread->t_cpu + \n" 642 "\t curthread->t_cpu->cpu_profile_pil"; 643 caller = "(uintptr_t)arg0"; 644 arg1 = "arg2"; 645 } else { 646 arg0 = "(uintptr_t)arg0"; 647 caller = "caller"; 648 } 649 650 if (g_recsize > LS_HIST) { 651 for (depth = 0; g_recsize > LS_STACK(depth); depth++) 652 continue; 653 654 if (g_tracing) { 655 (void) sprintf(stack, "\tstack(%d);\n", depth); 656 } else { 657 (void) sprintf(stack, ", stack(%d)", depth); 658 } 659 } else { 660 (void) sprintf(stack, ""); 661 } 662 663 if (info->ev_acquire != NULL) { 664 /* 665 * If this is a hold event, we need to generate an additional 666 * clause for the acquire; the clause for the release will be 667 * generated with the aggregating statement, below. 668 */ 669 dprog_add("%s\n", info->ev_acquire); 670 predicate_add(&pred, info->ev_predicate, NULL, 0); 671 predicate_add(&pred, g_predicate, NULL, 0); 672 if (pred != NULL) 673 dprog_add("/%s/\n", pred); 674 675 dprog_add("{\n"); 676 (void) sprintf(buf, "self->ev%d[(uintptr_t)arg0]", event); 677 678 if (info->ev_type == 'H') { 679 dprog_add("\t%s = timestamp;\n", buf); 680 } else { 681 /* 682 * If this isn't a hold event, it's the recursive 683 * error event. For this, we simply bump the 684 * thread-local, per-lock count. 685 */ 686 dprog_add("\t%s++;\n", buf); 687 } 688 689 dprog_add("}\n\n"); 690 predicate_destroy(&pred); 691 pred = NULL; 692 693 if (info->ev_type == 'E') { 694 /* 695 * If this is the recursive lock error event, we need 696 * to generate an additional clause to decrement the 697 * thread-local, per-lock count. This assures that we 698 * only execute the aggregating clause if we have 699 * recursive entry. 700 */ 701 dprog_add("%s\n", info->ev_name); 702 dprog_add("/%s/\n{\n\t%s--;\n}\n\n", buf, buf); 703 } 704 705 predicate_add(&pred, buf, NULL, 0); 706 707 if (info->ev_type == 'H') { 708 (void) sprintf(buf, "timestamp -\n\t " 709 "self->ev%d[(uintptr_t)arg0]", event); 710 } 711 712 arg1 = buf; 713 } else { 714 predicate_add(&pred, info->ev_predicate, NULL, 0); 715 if (info->ev_type != 'I') 716 predicate_add(&pred, g_predicate, NULL, 0); 717 else 718 predicate_add(&pred, g_ipredicate, NULL, 0); 719 } 720 721 if ((dur = g_min_duration[event]) != 0) 722 predicate_add(&pred, arg1, ">=", dur); 723 724 dprog_add("%s\n", info->ev_name); 725 726 if (pred != NULL) 727 dprog_add("/%s/\n", pred); 728 predicate_destroy(&pred); 729 730 dprog_add("{\n"); 731 732 if (g_tracing) { 733 dprog_add("\ttrace(%dULL);\n", event); 734 dprog_add("\ttrace(%s);\n", arg0); 735 dprog_add("\ttrace(%s);\n", caller); 736 dprog_add(stack); 737 } else { 738 /* 739 * The ordering here is important: when we process the 740 * aggregate, we count on the fact that @avg appears before 741 * @hist in program order to assure that @avg is assigned the 742 * first aggregation variable ID and @hist assigned the 743 * second; see the comment in process_aggregate() for details. 744 */ 745 dprog_add("\t@avg[%dULL, %s, %s%s] = avg(%s);\n", 746 event, arg0, caller, stack, arg1); 747 748 if (g_recsize >= LS_HIST) { 749 dprog_add("\t@hist[%dULL, %s, %s%s] = quantize" 750 "(%s);\n", event, arg0, caller, stack, arg1); 751 } 752 } 753 754 if (info->ev_acquire != NULL) 755 dprog_add("\tself->ev%d[arg0] = 0;\n", event); 756 757 dprog_add("}\n\n"); 758 } 759 760 static void 761 dprog_compile() 762 { 763 dtrace_prog_t *prog; 764 dtrace_proginfo_t info; 765 766 if (g_Vflag) { 767 (void) fprintf(stderr, "lockstat: vvvv D program vvvv\n"); 768 (void) fputs(g_prog, stderr); 769 (void) fprintf(stderr, "lockstat: ^^^^ D program ^^^^\n"); 770 } 771 772 if ((prog = dtrace_program_strcompile(g_dtp, g_prog, 773 DTRACE_PROBESPEC_NAME, 0, 0, NULL)) == NULL) 774 dfail("failed to compile program"); 775 776 if (dtrace_program_exec(g_dtp, prog, &info) == -1) 777 dfail("failed to enable probes"); 778 779 if (dtrace_go(g_dtp) != 0) 780 dfail("couldn't start tracing"); 781 } 782 783 static void 784 status_fire(void) 785 {} 786 787 static void 788 status_init(void) 789 { 790 dtrace_optval_t val, status, agg; 791 struct sigaction act; 792 struct itimerspec ts; 793 struct sigevent ev; 794 timer_t tid; 795 796 if (dtrace_getopt(g_dtp, "statusrate", &status) == -1) 797 dfail("failed to get 'statusrate'"); 798 799 if (dtrace_getopt(g_dtp, "aggrate", &agg) == -1) 800 dfail("failed to get 'statusrate'"); 801 802 /* 803 * We would want to awaken at a rate that is the GCD of the statusrate 804 * and the aggrate -- but that seems a bit absurd. Instead, we'll 805 * simply awaken at a rate that is the more frequent of the two, which 806 * assures that we're never later than the interval implied by the 807 * more frequent rate. 808 */ 809 val = status < agg ? status : agg; 810 811 (void) sigemptyset(&act.sa_mask); 812 act.sa_flags = 0; 813 act.sa_handler = status_fire; 814 (void) sigaction(SIGUSR1, &act, NULL); 815 816 ev.sigev_notify = SIGEV_SIGNAL; 817 ev.sigev_signo = SIGUSR1; 818 819 if (timer_create(CLOCK_REALTIME, &ev, &tid) == -1) 820 dfail("cannot create CLOCK_REALTIME timer"); 821 822 ts.it_value.tv_sec = val / NANOSEC; 823 ts.it_value.tv_nsec = val % NANOSEC; 824 ts.it_interval = ts.it_value; 825 826 if (timer_settime(tid, TIMER_RELTIME, &ts, NULL) == -1) 827 dfail("cannot set time on CLOCK_REALTIME timer"); 828 } 829 830 static void 831 status_check(void) 832 { 833 if (!g_tracing && dtrace_aggregate_snap(g_dtp) != 0) 834 dfail("failed to snap aggregate"); 835 836 if (dtrace_status(g_dtp) == -1) 837 dfail("dtrace_status()"); 838 } 839 840 static void 841 lsrec_fill(lsrec_t *lsrec, const dtrace_recdesc_t *rec, int nrecs, caddr_t data) 842 { 843 bzero(lsrec, g_recsize); 844 lsrec->ls_count = 1; 845 846 if ((g_recsize > LS_HIST && nrecs < 4) || (nrecs < 3)) 847 fail(0, "truncated DTrace record"); 848 849 if (rec->dtrd_size != sizeof (uint64_t)) 850 fail(0, "bad event size in first record"); 851 852 /* LINTED - alignment */ 853 lsrec->ls_event = (uint32_t)*((uint64_t *)(data + rec->dtrd_offset)); 854 rec++; 855 856 if (rec->dtrd_size != sizeof (uintptr_t)) 857 fail(0, "bad lock address size in second record"); 858 859 /* LINTED - alignment */ 860 lsrec->ls_lock = *((uintptr_t *)(data + rec->dtrd_offset)); 861 rec++; 862 863 if (rec->dtrd_size != sizeof (uintptr_t)) 864 fail(0, "bad caller size in third record"); 865 866 /* LINTED - alignment */ 867 lsrec->ls_caller = *((uintptr_t *)(data + rec->dtrd_offset)); 868 rec++; 869 870 if (g_recsize > LS_HIST) { 871 int frames, i; 872 pc_t *stack; 873 874 frames = rec->dtrd_size / sizeof (pc_t); 875 /* LINTED - alignment */ 876 stack = (pc_t *)(data + rec->dtrd_offset); 877 878 for (i = 1; i < frames; i++) 879 lsrec->ls_stack[i - 1] = stack[i]; 880 } 881 } 882 883 /*ARGSUSED*/ 884 static int 885 count_aggregate(const dtrace_aggdata_t *agg, void *arg) 886 { 887 *((size_t *)arg) += 1; 888 889 return (DTRACE_AGGWALK_NEXT); 890 } 891 892 static int 893 process_aggregate(const dtrace_aggdata_t *agg, void *arg) 894 { 895 const dtrace_aggdesc_t *aggdesc = agg->dtada_desc; 896 caddr_t data = agg->dtada_data; 897 lsdata_t *lsdata = arg; 898 lsrec_t *lsrec = lsdata->lsd_next; 899 const dtrace_recdesc_t *rec; 900 uint64_t *avg, *quantized; 901 int i, j; 902 903 assert(lsdata->lsd_count < g_nrecs); 904 905 /* 906 * Aggregation variable IDs are guaranteed to be generated in program 907 * order, and they are guaranteed to start from DTRACE_AGGVARIDNONE 908 * plus one. As "avg" appears before "hist" in program order, we know 909 * that "avg" will be allocated the first aggregation variable ID, and 910 * "hist" will be allocated the second aggregation variable ID -- and 911 * we therefore use the aggregation variable ID to differentiate the 912 * cases. 913 */ 914 if (aggdesc->dtagd_varid > DTRACE_AGGVARIDNONE + 1) { 915 /* 916 * If this is the histogram entry. We'll copy the quantized 917 * data into lc_hist, and jump over the rest. 918 */ 919 rec = &aggdesc->dtagd_rec[aggdesc->dtagd_nrecs - 1]; 920 921 if (aggdesc->dtagd_varid != DTRACE_AGGVARIDNONE + 2) 922 fail(0, "bad variable ID in aggregation record"); 923 924 if (rec->dtrd_size != 925 DTRACE_QUANTIZE_NBUCKETS * sizeof (uint64_t)) 926 fail(0, "bad quantize size in aggregation record"); 927 928 /* LINTED - alignment */ 929 quantized = (uint64_t *)(data + rec->dtrd_offset); 930 931 for (i = DTRACE_QUANTIZE_ZEROBUCKET, j = 0; 932 i < DTRACE_QUANTIZE_NBUCKETS; i++, j++) 933 lsrec->ls_hist[j] = quantized[i]; 934 935 goto out; 936 } 937 938 lsrec_fill(lsrec, &aggdesc->dtagd_rec[1], 939 aggdesc->dtagd_nrecs - 1, data); 940 941 rec = &aggdesc->dtagd_rec[aggdesc->dtagd_nrecs - 1]; 942 943 if (rec->dtrd_size != 2 * sizeof (uint64_t)) 944 fail(0, "bad avg size in aggregation record"); 945 946 /* LINTED - alignment */ 947 avg = (uint64_t *)(data + rec->dtrd_offset); 948 lsrec->ls_count = (uint32_t)avg[0]; 949 lsrec->ls_time = (uintptr_t)avg[1]; 950 951 if (g_recsize >= LS_HIST) 952 return (DTRACE_AGGWALK_NEXT); 953 954 out: 955 lsdata->lsd_next = (lsrec_t *)((uintptr_t)lsrec + g_recsize); 956 lsdata->lsd_count++; 957 958 return (DTRACE_AGGWALK_NEXT); 959 } 960 961 static int 962 process_trace(const dtrace_probedata_t *pdata, void *arg) 963 { 964 lsdata_t *lsdata = arg; 965 lsrec_t *lsrec = lsdata->lsd_next; 966 dtrace_eprobedesc_t *edesc = pdata->dtpda_edesc; 967 caddr_t data = pdata->dtpda_data; 968 969 if (lsdata->lsd_count >= g_nrecs) 970 return (DTRACE_CONSUME_NEXT); 971 972 lsrec_fill(lsrec, edesc->dtepd_rec, edesc->dtepd_nrecs, data); 973 974 lsdata->lsd_next = (lsrec_t *)((uintptr_t)lsrec + g_recsize); 975 lsdata->lsd_count++; 976 977 return (DTRACE_CONSUME_NEXT); 978 } 979 980 static int 981 process_data(FILE *out, char *data) 982 { 983 lsdata_t lsdata; 984 985 /* LINTED - alignment */ 986 lsdata.lsd_next = (lsrec_t *)data; 987 lsdata.lsd_count = 0; 988 989 if (g_tracing) { 990 if (dtrace_consume(g_dtp, out, 991 process_trace, NULL, &lsdata) != 0) 992 dfail("failed to consume buffer"); 993 994 return (lsdata.lsd_count); 995 } 996 997 if (dtrace_aggregate_walk_keyvarsorted(g_dtp, 998 process_aggregate, &lsdata) != 0) 999 dfail("failed to walk aggregate"); 1000 1001 return (lsdata.lsd_count); 1002 } 1003 1004 /*ARGSUSED*/ 1005 static int 1006 drophandler(const dtrace_dropdata_t *data, void *arg) 1007 { 1008 g_dropped++; 1009 (void) fprintf(stderr, "lockstat: warning: %s", data->dtdda_msg); 1010 return (DTRACE_HANDLE_OK); 1011 } 1012 1013 int 1014 main(int argc, char **argv) 1015 { 1016 char *data_buf; 1017 lsrec_t *lsp, **current, **first, **sort_buf, **merge_buf; 1018 FILE *out = stdout; 1019 char c; 1020 pid_t child; 1021 int status; 1022 int i, j; 1023 hrtime_t duration; 1024 char *addrp, *offp, *sizep, *evp, *lastp, *p; 1025 uintptr_t addr; 1026 size_t size, off; 1027 int events_specified = 0; 1028 int exec_errno = 0; 1029 uint32_t event; 1030 char *filt = NULL, *ifilt = NULL; 1031 static uint64_t ev_count[LS_MAX_EVENTS + 1]; 1032 static uint64_t ev_time[LS_MAX_EVENTS + 1]; 1033 dtrace_optval_t aggsize; 1034 char aggstr[10]; 1035 long ncpus; 1036 int dynvar = 0; 1037 int err; 1038 1039 if ((g_dtp = dtrace_open(DTRACE_VERSION, 0, &err)) == NULL) { 1040 fail(0, "cannot open dtrace library: %s", 1041 dtrace_errmsg(NULL, err)); 1042 } 1043 1044 if (dtrace_handle_drop(g_dtp, &drophandler, NULL) == -1) 1045 dfail("couldn't establish drop handler"); 1046 1047 if (symtab_init() == -1) 1048 fail(1, "can't load kernel symbols"); 1049 1050 g_nrecs = DEFAULT_NRECS; 1051 1052 while ((c = getopt(argc, argv, LOCKSTAT_OPTSTR)) != EOF) { 1053 switch (c) { 1054 case 'b': 1055 g_recsize = LS_BASIC; 1056 break; 1057 1058 case 't': 1059 g_recsize = LS_TIME; 1060 break; 1061 1062 case 'h': 1063 g_recsize = LS_HIST; 1064 break; 1065 1066 case 's': 1067 if (!isdigit(optarg[0])) 1068 usage(); 1069 g_stkdepth = atoi(optarg); 1070 if (g_stkdepth > LS_MAX_STACK_DEPTH) 1071 fail(0, "max stack depth is %d", 1072 LS_MAX_STACK_DEPTH); 1073 g_recsize = LS_STACK(g_stkdepth); 1074 break; 1075 1076 case 'n': 1077 if (!isdigit(optarg[0])) 1078 usage(); 1079 g_nrecs = atoi(optarg); 1080 break; 1081 1082 case 'd': 1083 if (!isdigit(optarg[0])) 1084 usage(); 1085 duration = atoll(optarg); 1086 1087 /* 1088 * XXX -- durations really should be per event 1089 * since the units are different, but it's hard 1090 * to express this nicely in the interface. 1091 * Not clear yet what the cleanest solution is. 1092 */ 1093 for (i = 0; i < LS_MAX_EVENTS; i++) 1094 if (g_event_info[i].ev_type != 'E') 1095 g_min_duration[i] = duration; 1096 1097 break; 1098 1099 case 'i': 1100 if (!isdigit(optarg[0])) 1101 usage(); 1102 i = atoi(optarg); 1103 if (i <= 0) 1104 usage(); 1105 if (i > MAX_HZ) 1106 fail(0, "max interrupt rate is %d Hz", MAX_HZ); 1107 1108 for (j = 0; j < LS_MAX_EVENTS; j++) 1109 if (strcmp(g_event_info[j].ev_desc, 1110 "Profiling interrupt") == 0) 1111 break; 1112 1113 (void) sprintf(g_event_info[j].ev_name, 1114 "profile:::profile-%d", i); 1115 break; 1116 1117 case 'l': 1118 case 'f': 1119 addrp = strtok(optarg, ","); 1120 sizep = strtok(NULL, ","); 1121 addrp = strtok(optarg, ",+"); 1122 offp = strtok(NULL, ","); 1123 1124 size = sizep ? strtoul(sizep, NULL, 0) : 1; 1125 off = offp ? strtoul(offp, NULL, 0) : 0; 1126 1127 if (addrp[0] == '0') { 1128 addr = strtoul(addrp, NULL, 16) + off; 1129 } else { 1130 addr = sym_to_addr(addrp) + off; 1131 if (sizep == NULL) 1132 size = sym_size(addrp) - off; 1133 if (addr - off == 0) 1134 fail(0, "symbol '%s' not found", addrp); 1135 if (size == 0) 1136 size = 1; 1137 } 1138 1139 1140 if (c == 'l') { 1141 filter_add(&filt, "arg0", addr, size); 1142 } else { 1143 filter_add(&filt, "caller", addr, size); 1144 filter_add(&ifilt, "arg0", addr, size); 1145 } 1146 break; 1147 1148 case 'e': 1149 evp = strtok_r(optarg, ",", &lastp); 1150 while (evp) { 1151 int ev1, ev2; 1152 char *evp2; 1153 1154 (void) strtok(evp, "-"); 1155 evp2 = strtok(NULL, "-"); 1156 ev1 = atoi(evp); 1157 ev2 = evp2 ? atoi(evp2) : ev1; 1158 if ((uint_t)ev1 >= LS_MAX_EVENTS || 1159 (uint_t)ev2 >= LS_MAX_EVENTS || ev1 > ev2) 1160 fail(0, "-e events out of range"); 1161 for (i = ev1; i <= ev2; i++) 1162 g_enabled[i] = 1; 1163 evp = strtok_r(NULL, ",", &lastp); 1164 } 1165 events_specified = 1; 1166 break; 1167 1168 case 'c': 1169 g_cflag = 1; 1170 break; 1171 1172 case 'k': 1173 g_kflag = 1; 1174 break; 1175 1176 case 'w': 1177 g_wflag = 1; 1178 break; 1179 1180 case 'W': 1181 g_Wflag = 1; 1182 break; 1183 1184 case 'g': 1185 g_gflag = 1; 1186 break; 1187 1188 case 'C': 1189 case 'E': 1190 case 'H': 1191 case 'I': 1192 for (i = 0; i < LS_MAX_EVENTS; i++) 1193 if (g_event_info[i].ev_type == c) 1194 g_enabled[i] = 1; 1195 events_specified = 1; 1196 break; 1197 1198 case 'A': 1199 for (i = 0; i < LS_MAX_EVENTS; i++) 1200 if (strchr("CH", g_event_info[i].ev_type)) 1201 g_enabled[i] = 1; 1202 events_specified = 1; 1203 break; 1204 1205 case 'T': 1206 g_tracing = 1; 1207 break; 1208 1209 case 'D': 1210 if (!isdigit(optarg[0])) 1211 usage(); 1212 g_topn = atoi(optarg); 1213 break; 1214 1215 case 'R': 1216 g_rates = 1; 1217 break; 1218 1219 case 'p': 1220 g_pflag = 1; 1221 break; 1222 1223 case 'P': 1224 g_Pflag = 1; 1225 break; 1226 1227 case 'o': 1228 if ((out = fopen(optarg, "w")) == NULL) 1229 fail(1, "error opening file"); 1230 break; 1231 1232 case 'V': 1233 g_Vflag = 1; 1234 break; 1235 1236 default: 1237 if (strchr(LOCKSTAT_OPTSTR, c) == NULL) 1238 usage(); 1239 } 1240 } 1241 1242 if (filt != NULL) { 1243 predicate_add(&g_predicate, filt, NULL, 0); 1244 filter_destroy(&filt); 1245 } 1246 1247 if (ifilt != NULL) { 1248 predicate_add(&g_ipredicate, ifilt, NULL, 0); 1249 filter_destroy(&ifilt); 1250 } 1251 1252 if (g_recsize == 0) { 1253 if (g_gflag) { 1254 g_stkdepth = LS_MAX_STACK_DEPTH; 1255 g_recsize = LS_STACK(g_stkdepth); 1256 } else { 1257 g_recsize = LS_TIME; 1258 } 1259 } 1260 1261 if (g_gflag && g_recsize <= LS_STACK(0)) 1262 fail(0, "'-g' requires at least '-s 1' data gathering"); 1263 1264 /* 1265 * Make sure the alignment is reasonable 1266 */ 1267 g_recsize = -(-g_recsize & -sizeof (uint64_t)); 1268 1269 for (i = 0; i < LS_MAX_EVENTS; i++) { 1270 /* 1271 * If no events were specified, enable -C. 1272 */ 1273 if (!events_specified && g_event_info[i].ev_type == 'C') 1274 g_enabled[i] = 1; 1275 } 1276 1277 for (i = 0; i < LS_MAX_EVENTS; i++) { 1278 if (!g_enabled[i]) 1279 continue; 1280 1281 if (g_event_info[i].ev_acquire != NULL) { 1282 /* 1283 * If we've enabled a hold event, we must explicitly 1284 * allocate dynamic variable space. 1285 */ 1286 dynvar = 1; 1287 } 1288 1289 dprog_addevent(i); 1290 } 1291 1292 /* 1293 * Make sure there are remaining arguments to specify a child command 1294 * to execute. 1295 */ 1296 if (argc <= optind) 1297 usage(); 1298 1299 if ((ncpus = sysconf(_SC_NPROCESSORS_ONLN)) == -1) 1300 dfail("couldn't determine number of online CPUs"); 1301 1302 /* 1303 * By default, we set our data buffer size to be the number of records 1304 * multiplied by the size of the record, doubled to account for some 1305 * DTrace slop and divided by the number of CPUs. We silently clamp 1306 * the aggregation size at both a minimum and a maximum to prevent 1307 * absurdly low or high values. 1308 */ 1309 if ((aggsize = (g_nrecs * g_recsize * 2) / ncpus) < MIN_AGGSIZE) 1310 aggsize = MIN_AGGSIZE; 1311 1312 if (aggsize > MAX_AGGSIZE) 1313 aggsize = MAX_AGGSIZE; 1314 1315 (void) sprintf(aggstr, "%lld", (long long)aggsize); 1316 1317 if (!g_tracing) { 1318 if (dtrace_setopt(g_dtp, "bufsize", "4k") == -1) 1319 dfail("failed to set 'bufsize'"); 1320 1321 if (dtrace_setopt(g_dtp, "aggsize", aggstr) == -1) 1322 dfail("failed to set 'aggsize'"); 1323 1324 if (dynvar) { 1325 /* 1326 * If we're using dynamic variables, we set our 1327 * dynamic variable size to be one megabyte per CPU, 1328 * with a hard-limit of 32 megabytes. This may still 1329 * be too small in some cases, but it can be tuned 1330 * manually via -x if need be. 1331 */ 1332 (void) sprintf(aggstr, "%ldm", ncpus < 32 ? ncpus : 32); 1333 1334 if (dtrace_setopt(g_dtp, "dynvarsize", aggstr) == -1) 1335 dfail("failed to set 'dynvarsize'"); 1336 } 1337 } else { 1338 if (dtrace_setopt(g_dtp, "bufsize", aggstr) == -1) 1339 dfail("failed to set 'bufsize'"); 1340 } 1341 1342 if (dtrace_setopt(g_dtp, "statusrate", "10sec") == -1) 1343 dfail("failed to set 'statusrate'"); 1344 1345 optind = 1; 1346 while ((c = getopt(argc, argv, LOCKSTAT_OPTSTR)) != EOF) { 1347 switch (c) { 1348 case 'x': 1349 if ((p = strchr(optarg, '=')) != NULL) 1350 *p++ = '\0'; 1351 1352 if (dtrace_setopt(g_dtp, optarg, p) != 0) 1353 dfail("failed to set -x %s", optarg); 1354 break; 1355 } 1356 } 1357 1358 argc -= optind; 1359 argv += optind; 1360 1361 dprog_compile(); 1362 status_init(); 1363 1364 g_elapsed = -gethrtime(); 1365 1366 /* 1367 * Spawn the specified command and wait for it to complete. 1368 */ 1369 child = fork(); 1370 if (child == -1) 1371 fail(1, "cannot fork"); 1372 if (child == 0) { 1373 (void) dtrace_close(g_dtp); 1374 (void) execvp(argv[0], &argv[0]); 1375 exec_errno = errno; 1376 exit(127); 1377 } 1378 1379 while (waitpid(child, &status, WEXITED) != child) 1380 status_check(); 1381 1382 g_elapsed += gethrtime(); 1383 1384 if (WIFEXITED(status)) { 1385 if (WEXITSTATUS(status) != 0) { 1386 if (exec_errno != 0) { 1387 errno = exec_errno; 1388 fail(1, "could not execute %s", argv[0]); 1389 } 1390 (void) fprintf(stderr, 1391 "lockstat: warning: %s exited with code %d\n", 1392 argv[0], WEXITSTATUS(status)); 1393 } 1394 } else { 1395 (void) fprintf(stderr, 1396 "lockstat: warning: %s died on signal %d\n", 1397 argv[0], WTERMSIG(status)); 1398 } 1399 1400 if (dtrace_stop(g_dtp) == -1) 1401 dfail("failed to stop dtrace"); 1402 1403 /* 1404 * Before we read out the results, we need to allocate our buffer. 1405 * If we're tracing, then we'll just use the precalculated size. If 1406 * we're not, then we'll take a snapshot of the aggregate, and walk 1407 * it to count the number of records. 1408 */ 1409 if (!g_tracing) { 1410 if (dtrace_aggregate_snap(g_dtp) != 0) 1411 dfail("failed to snap aggregate"); 1412 1413 g_nrecs = 0; 1414 1415 if (dtrace_aggregate_walk(g_dtp, 1416 count_aggregate, &g_nrecs) != 0) 1417 dfail("failed to walk aggregate"); 1418 } 1419 1420 if ((data_buf = memalign(sizeof (uint64_t), 1421 (g_nrecs + 1) * g_recsize)) == NULL) 1422 fail(1, "Memory allocation failed"); 1423 1424 /* 1425 * Read out the DTrace data. 1426 */ 1427 g_nrecs_used = process_data(out, data_buf); 1428 1429 if (g_nrecs_used > g_nrecs || g_dropped) 1430 (void) fprintf(stderr, "lockstat: warning: " 1431 "ran out of data records (use -n for more)\n"); 1432 1433 /* LINTED - alignment */ 1434 for (i = 0, lsp = (lsrec_t *)data_buf; i < g_nrecs_used; i++, 1435 /* LINTED - alignment */ 1436 lsp = (lsrec_t *)((char *)lsp + g_recsize)) { 1437 ev_count[lsp->ls_event] += lsp->ls_count; 1438 ev_time[lsp->ls_event] += lsp->ls_time; 1439 } 1440 1441 /* 1442 * If -g was specified, convert stacks into individual records. 1443 */ 1444 if (g_gflag) { 1445 lsrec_t *newlsp, *oldlsp; 1446 1447 newlsp = memalign(sizeof (uint64_t), 1448 g_nrecs_used * LS_TIME * (g_stkdepth + 1)); 1449 if (newlsp == NULL) 1450 fail(1, "Cannot allocate space for -g processing"); 1451 lsp = newlsp; 1452 /* LINTED - alignment */ 1453 for (i = 0, oldlsp = (lsrec_t *)data_buf; i < g_nrecs_used; i++, 1454 /* LINTED - alignment */ 1455 oldlsp = (lsrec_t *)((char *)oldlsp + g_recsize)) { 1456 int fr; 1457 int caller_in_stack = 0; 1458 1459 if (oldlsp->ls_count == 0) 1460 continue; 1461 1462 for (fr = 0; fr < g_stkdepth; fr++) { 1463 if (oldlsp->ls_stack[fr] == 0) 1464 break; 1465 if (oldlsp->ls_stack[fr] == oldlsp->ls_caller) 1466 caller_in_stack = 1; 1467 bcopy(oldlsp, lsp, LS_TIME); 1468 lsp->ls_caller = oldlsp->ls_stack[fr]; 1469 /* LINTED - alignment */ 1470 lsp = (lsrec_t *)((char *)lsp + LS_TIME); 1471 } 1472 if (!caller_in_stack) { 1473 bcopy(oldlsp, lsp, LS_TIME); 1474 /* LINTED - alignment */ 1475 lsp = (lsrec_t *)((char *)lsp + LS_TIME); 1476 } 1477 } 1478 g_nrecs = g_nrecs_used = 1479 ((uintptr_t)lsp - (uintptr_t)newlsp) / LS_TIME; 1480 g_recsize = LS_TIME; 1481 g_stkdepth = 0; 1482 free(data_buf); 1483 data_buf = (char *)newlsp; 1484 } 1485 1486 if ((sort_buf = calloc(2 * (g_nrecs + 1), 1487 sizeof (void *))) == NULL) 1488 fail(1, "Sort buffer allocation failed"); 1489 merge_buf = sort_buf + (g_nrecs + 1); 1490 1491 /* 1492 * Build the sort buffer, discarding zero-count records along the way. 1493 */ 1494 /* LINTED - alignment */ 1495 for (i = 0, lsp = (lsrec_t *)data_buf; i < g_nrecs_used; i++, 1496 /* LINTED - alignment */ 1497 lsp = (lsrec_t *)((char *)lsp + g_recsize)) { 1498 if (lsp->ls_count == 0) 1499 lsp->ls_event = LS_MAX_EVENTS; 1500 sort_buf[i] = lsp; 1501 } 1502 1503 if (g_nrecs_used == 0) 1504 exit(0); 1505 1506 /* 1507 * Add a sentinel after the last record 1508 */ 1509 sort_buf[i] = lsp; 1510 lsp->ls_event = LS_MAX_EVENTS; 1511 1512 if (g_tracing) { 1513 report_trace(out, sort_buf); 1514 return (0); 1515 } 1516 1517 /* 1518 * Application of -g may have resulted in multiple records 1519 * with the same signature; coalesce them. 1520 */ 1521 if (g_gflag) { 1522 mergesort(lockcmp, sort_buf, merge_buf, g_nrecs_used); 1523 coalesce(lockcmp, sort_buf, g_nrecs_used); 1524 } 1525 1526 /* 1527 * Coalesce locks within the same symbol if -c option specified. 1528 * Coalesce PCs within the same function if -k option specified. 1529 */ 1530 if (g_cflag || g_kflag) { 1531 for (i = 0; i < g_nrecs_used; i++) { 1532 int fr; 1533 lsp = sort_buf[i]; 1534 if (g_cflag) 1535 coalesce_symbol(&lsp->ls_lock); 1536 if (g_kflag) { 1537 for (fr = 0; fr < g_stkdepth; fr++) 1538 coalesce_symbol(&lsp->ls_stack[fr]); 1539 coalesce_symbol(&lsp->ls_caller); 1540 } 1541 } 1542 mergesort(lockcmp, sort_buf, merge_buf, g_nrecs_used); 1543 coalesce(lockcmp, sort_buf, g_nrecs_used); 1544 } 1545 1546 /* 1547 * Coalesce callers if -w option specified 1548 */ 1549 if (g_wflag) { 1550 mergesort(lock_and_count_cmp_anywhere, 1551 sort_buf, merge_buf, g_nrecs_used); 1552 coalesce(lockcmp_anywhere, sort_buf, g_nrecs_used); 1553 } 1554 1555 /* 1556 * Coalesce locks if -W option specified 1557 */ 1558 if (g_Wflag) { 1559 mergesort(site_and_count_cmp_anylock, 1560 sort_buf, merge_buf, g_nrecs_used); 1561 coalesce(sitecmp_anylock, sort_buf, g_nrecs_used); 1562 } 1563 1564 /* 1565 * Sort data by contention count (ls_count) or total time (ls_time), 1566 * depending on g_Pflag. Override g_Pflag if time wasn't measured. 1567 */ 1568 if (g_recsize < LS_TIME) 1569 g_Pflag = 0; 1570 1571 if (g_Pflag) 1572 mergesort(timecmp, sort_buf, merge_buf, g_nrecs_used); 1573 else 1574 mergesort(countcmp, sort_buf, merge_buf, g_nrecs_used); 1575 1576 /* 1577 * Display data by event type 1578 */ 1579 first = &sort_buf[0]; 1580 while ((event = (*first)->ls_event) < LS_MAX_EVENTS) { 1581 current = first; 1582 while ((lsp = *current)->ls_event == event) 1583 current++; 1584 report_stats(out, first, current - first, ev_count[event], 1585 ev_time[event]); 1586 first = current; 1587 } 1588 1589 return (0); 1590 } 1591 1592 static char * 1593 format_symbol(char *buf, uintptr_t addr, int show_size) 1594 { 1595 uintptr_t symoff; 1596 char *symname; 1597 size_t symsize; 1598 1599 symname = addr_to_sym(addr, &symoff, &symsize); 1600 1601 if (show_size && symoff == 0) 1602 (void) sprintf(buf, "%s[%ld]", symname, (long)symsize); 1603 else if (symoff == 0) 1604 (void) sprintf(buf, "%s", symname); 1605 else if (symoff < 16 && bcmp(symname, "cpu[", 4) == 0) /* CPU+PIL */ 1606 (void) sprintf(buf, "%s+%ld", symname, (long)symoff); 1607 else if (symoff <= symsize || (symoff < 256 && addr != symoff)) 1608 (void) sprintf(buf, "%s+0x%llx", symname, 1609 (unsigned long long)symoff); 1610 else 1611 (void) sprintf(buf, "0x%llx", (unsigned long long)addr); 1612 return (buf); 1613 } 1614 1615 static void 1616 report_stats(FILE *out, lsrec_t **sort_buf, size_t nrecs, uint64_t total_count, 1617 uint64_t total_time) 1618 { 1619 uint32_t event = sort_buf[0]->ls_event; 1620 lsrec_t *lsp; 1621 double ptotal = 0.0; 1622 double percent; 1623 int i, j, fr; 1624 int displayed; 1625 int first_bin, last_bin, max_bin_count, total_bin_count; 1626 int rectype; 1627 char buf[256]; 1628 char lhdr[80], chdr[80]; 1629 1630 rectype = g_recsize; 1631 1632 if (g_topn == 0) { 1633 (void) fprintf(out, "%20llu %s\n", 1634 g_rates == 0 ? total_count : 1635 ((unsigned long long)total_count * NANOSEC) / g_elapsed, 1636 g_event_info[event].ev_desc); 1637 return; 1638 } 1639 1640 (void) sprintf(lhdr, "%s%s", 1641 g_Wflag ? "Hottest " : "", g_event_info[event].ev_lhdr); 1642 (void) sprintf(chdr, "%s%s", 1643 g_wflag ? "Hottest " : "", "Caller"); 1644 1645 if (!g_pflag) 1646 (void) fprintf(out, 1647 "\n%s: %.0f events in %.3f seconds (%.0f events/sec)\n\n", 1648 g_event_info[event].ev_desc, (double)total_count, 1649 (double)g_elapsed / NANOSEC, 1650 (double)total_count * NANOSEC / g_elapsed); 1651 1652 if (!g_pflag && rectype < LS_HIST) { 1653 (void) sprintf(buf, "%s", g_event_info[event].ev_units); 1654 (void) fprintf(out, "%5s %4s %4s %4s %8s %-22s %-24s\n", 1655 g_rates ? "ops/s" : "Count", 1656 g_gflag ? "genr" : "indv", 1657 "cuml", "rcnt", rectype >= LS_TIME ? buf : "", lhdr, chdr); 1658 (void) fprintf(out, "---------------------------------" 1659 "----------------------------------------------\n"); 1660 } 1661 1662 displayed = 0; 1663 for (i = 0; i < nrecs; i++) { 1664 lsp = sort_buf[i]; 1665 1666 if (displayed++ >= g_topn) 1667 break; 1668 1669 if (g_pflag) { 1670 int j; 1671 1672 (void) fprintf(out, "%u %u", 1673 lsp->ls_event, lsp->ls_count); 1674 (void) fprintf(out, " %s", 1675 format_symbol(buf, lsp->ls_lock, g_cflag)); 1676 (void) fprintf(out, " %s", 1677 format_symbol(buf, lsp->ls_caller, 0)); 1678 (void) fprintf(out, " %f", 1679 (double)lsp->ls_refcnt / lsp->ls_count); 1680 if (rectype >= LS_TIME) 1681 (void) fprintf(out, " %llu", 1682 (unsigned long long)lsp->ls_time); 1683 if (rectype >= LS_HIST) { 1684 for (j = 0; j < 64; j++) 1685 (void) fprintf(out, " %u", 1686 lsp->ls_hist[j]); 1687 } 1688 for (j = 0; j < LS_MAX_STACK_DEPTH; j++) { 1689 if (rectype <= LS_STACK(j) || 1690 lsp->ls_stack[j] == 0) 1691 break; 1692 (void) fprintf(out, " %s", 1693 format_symbol(buf, lsp->ls_stack[j], 0)); 1694 } 1695 (void) fprintf(out, "\n"); 1696 continue; 1697 } 1698 1699 if (rectype >= LS_HIST) { 1700 (void) fprintf(out, "---------------------------------" 1701 "----------------------------------------------\n"); 1702 (void) sprintf(buf, "%s", 1703 g_event_info[event].ev_units); 1704 (void) fprintf(out, "%5s %4s %4s %4s %8s %-22s %-24s\n", 1705 g_rates ? "ops/s" : "Count", 1706 g_gflag ? "genr" : "indv", 1707 "cuml", "rcnt", buf, lhdr, chdr); 1708 } 1709 1710 if (g_Pflag && total_time != 0) 1711 percent = (lsp->ls_time * 100.00) / total_time; 1712 else 1713 percent = (lsp->ls_count * 100.00) / total_count; 1714 1715 ptotal += percent; 1716 1717 if (rectype >= LS_TIME) 1718 (void) sprintf(buf, "%llu", 1719 (unsigned long long)(lsp->ls_time / lsp->ls_count)); 1720 else 1721 buf[0] = '\0'; 1722 1723 (void) fprintf(out, "%5llu ", 1724 g_rates == 0 ? lsp->ls_count : 1725 ((uint64_t)lsp->ls_count * NANOSEC) / g_elapsed); 1726 1727 (void) fprintf(out, "%3.0f%% ", percent); 1728 1729 if (g_gflag) 1730 (void) fprintf(out, "---- "); 1731 else 1732 (void) fprintf(out, "%3.0f%% ", ptotal); 1733 1734 (void) fprintf(out, "%4.2f %8s ", 1735 (double)lsp->ls_refcnt / lsp->ls_count, buf); 1736 1737 (void) fprintf(out, "%-22s ", 1738 format_symbol(buf, lsp->ls_lock, g_cflag)); 1739 1740 (void) fprintf(out, "%-24s\n", 1741 format_symbol(buf, lsp->ls_caller, 0)); 1742 1743 if (rectype < LS_HIST) 1744 continue; 1745 1746 (void) fprintf(out, "\n"); 1747 (void) fprintf(out, "%10s %31s %-9s %-24s\n", 1748 g_event_info[event].ev_units, 1749 "------ Time Distribution ------", 1750 g_rates ? "ops/s" : "count", 1751 rectype > LS_STACK(0) ? "Stack" : ""); 1752 1753 first_bin = 0; 1754 while (lsp->ls_hist[first_bin] == 0) 1755 first_bin++; 1756 1757 last_bin = 63; 1758 while (lsp->ls_hist[last_bin] == 0) 1759 last_bin--; 1760 1761 max_bin_count = 0; 1762 total_bin_count = 0; 1763 for (j = first_bin; j <= last_bin; j++) { 1764 total_bin_count += lsp->ls_hist[j]; 1765 if (lsp->ls_hist[j] > max_bin_count) 1766 max_bin_count = lsp->ls_hist[j]; 1767 } 1768 1769 /* 1770 * If we went a few frames below the caller, ignore them 1771 */ 1772 for (fr = 3; fr > 0; fr--) 1773 if (lsp->ls_stack[fr] == lsp->ls_caller) 1774 break; 1775 1776 for (j = first_bin; j <= last_bin; j++) { 1777 uint_t depth = (lsp->ls_hist[j] * 30) / total_bin_count; 1778 (void) fprintf(out, "%10llu |%s%s %-9u ", 1779 1ULL << j, 1780 "@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@" + 30 - depth, 1781 " " + depth, 1782 g_rates == 0 ? lsp->ls_hist[j] : 1783 (uint_t)(((uint64_t)lsp->ls_hist[j] * NANOSEC) / 1784 g_elapsed)); 1785 if (rectype <= LS_STACK(fr) || lsp->ls_stack[fr] == 0) { 1786 (void) fprintf(out, "\n"); 1787 continue; 1788 } 1789 (void) fprintf(out, "%-24s\n", 1790 format_symbol(buf, lsp->ls_stack[fr], 0)); 1791 fr++; 1792 } 1793 while (rectype > LS_STACK(fr) && lsp->ls_stack[fr] != 0) { 1794 (void) fprintf(out, "%15s %-36s %-24s\n", "", "", 1795 format_symbol(buf, lsp->ls_stack[fr], 0)); 1796 fr++; 1797 } 1798 } 1799 1800 if (!g_pflag) 1801 (void) fprintf(out, "---------------------------------" 1802 "----------------------------------------------\n"); 1803 1804 (void) fflush(out); 1805 } 1806 1807 static void 1808 report_trace(FILE *out, lsrec_t **sort_buf) 1809 { 1810 lsrec_t *lsp; 1811 int i, fr; 1812 int rectype; 1813 char buf[256], buf2[256]; 1814 1815 rectype = g_recsize; 1816 1817 if (!g_pflag) { 1818 (void) fprintf(out, "%5s %7s %11s %-24s %-24s\n", 1819 "Event", "Time", "Owner", "Lock", "Caller"); 1820 (void) fprintf(out, "---------------------------------" 1821 "----------------------------------------------\n"); 1822 } 1823 1824 for (i = 0; i < g_nrecs_used; i++) { 1825 1826 lsp = sort_buf[i]; 1827 1828 if (lsp->ls_event >= LS_MAX_EVENTS || lsp->ls_count == 0) 1829 continue; 1830 1831 (void) fprintf(out, "%2d %10llu %11p %-24s %-24s\n", 1832 lsp->ls_event, (unsigned long long)lsp->ls_time, 1833 (void *)lsp->ls_next, 1834 format_symbol(buf, lsp->ls_lock, 0), 1835 format_symbol(buf2, lsp->ls_caller, 0)); 1836 1837 if (rectype <= LS_STACK(0)) 1838 continue; 1839 1840 /* 1841 * If we went a few frames below the caller, ignore them 1842 */ 1843 for (fr = 3; fr > 0; fr--) 1844 if (lsp->ls_stack[fr] == lsp->ls_caller) 1845 break; 1846 1847 while (rectype > LS_STACK(fr) && lsp->ls_stack[fr] != 0) { 1848 (void) fprintf(out, "%53s %-24s\n", "", 1849 format_symbol(buf, lsp->ls_stack[fr], 0)); 1850 fr++; 1851 } 1852 (void) fprintf(out, "\n"); 1853 } 1854 1855 (void) fflush(out); 1856 } 1857