1'\" te 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.\" Copyright (c) 2008, Sun Microsystems, Inc. All Rights Reserved. 21.\" 22.\" $FreeBSD$ 23.\" 24.Dd October 24, 2013 25.Dt LOCKSTAT 1 26.Os 27.Sh NAME 28.Nm lockstat 29.Nd report kernel lock and profiling statistics 30.Sh SYNOPSIS 31.Nm 32.Op Fl ACEHI 33.Op Fl e Ar event-list 34.Op Fl i Ar rate 35.Op Fl b | t | h | s Ar depth 36.Op Fl n Ar num-records 37.Op Fl l Ar lock Oo Ns , Ns Ar size Oc 38.Op Fl d Ar duration 39.Op Fl f Ar function Oo Ns , Ns Ar size Oc 40.Op Fl T 41.Op Fl ckgwWRpP 42.Op Fl D Ar count 43.Op Fl o filename 44.Op Fl x Ar opt Oo Ns = Ns Ar val Oc 45.Ar command 46.Op Oo Ar args Oc 47.Sh DESCRIPTION 48The 49.Nm 50utility gathers and displays kernel locking and profiling statistics. 51.Nm 52allows you to specify which events to watch (for example, spin on adaptive 53mutex, block on read access to rwlock due to waiting writers, and so forth), how 54much data to gather for each event, and how to display the data. 55By default, 56.Nm 57monitors all lock contention events, gathers frequency and timing data about 58those events, and displays the data in decreasing frequency order, so that the 59most common events appear first. 60.Pp 61.Nm 62gathers data until the specified command completes. 63For example, to gather statistics for a fixed-time interval, use 64.Xr sleep 1 65as the command, as follows: 66.Pp 67.Dl # lockstat sleep 5 68.Pp 69When the 70.Fl I 71option is specified, 72.Nm lockstat 73establishes a per-processor high-level periodic interrupt source to gather 74profiling data. 75The interrupt handler simply generates a 76.Nm 77event whose caller is the interrupted PC (program counter). 78The profiling event is just like any other 79.Nm lockstat 80event, so all of the normal 81.Nm lockstat 82options are applicable. 83.Pp 84.Nm 85relies on DTrace to modify the running kernel's text to intercept events of 86interest. 87This imposes a small but measurable overhead on all system activity, so access 88to 89.Nm 90is restricted to super-user by default. 91.Sh OPTIONS 92The following options are supported: 93.Ss Event Selection 94If no event selection options are specified, the default is 95.Fl C . 96.Bl -tag -width indent 97.It Fl A 98Watch all lock events. 99.Fl A 100is equivalent to 101.Fl CH . 102.It Fl C 103Watch contention events. 104.It Fl E 105Watch error events. 106.It Fl e Ar event-list 107Only watch the specified events. 108.Ar event-list 109is a comma-separated list of events or ranges of events such as 1,4-7,35. 110Run 111.Nm 112with no arguments to get a brief description of all events. 113.It Fl H 114Watch hold events. 115.It Fl I 116Watch profiling interrupt events. 117.It Fl i Ar rate 118Interrupt rate (per second) for 119.Fl I . 120The default is 97 Hz, so that profiling doesn't run in lockstep with the clock 121interrupt (which runs at 100 Hz). 122.El 123.Ss Data Gathering 124.Bl -tag -width indent 125.It Fl x Ar arg Oo Ns = Ns Ar val Oc 126Enable or modify a 127.Xr dtrace 1 128runtime option or D compiler option. 129Boolean options are enabled by specifying their name. 130Options with values are set by separating the option name and value with an 131equals sign. 132.El 133.Ss "Data Gathering (Mutually Exclusive)" 134.Bl -tag -width indent 135.It Fl b 136Basic statistics: lock, caller, number of events. 137.It Fl h 138Histogram: timing plus time-distribution histograms. 139.It Fl s Ar depth 140Stack trace: histogram plus stack traces up to 141.Ar depth 142frames deep. 143.It Fl t 144Timing: Basic plus timing for all events (default). 145.El 146.Ss "Data Filtering" 147.Bl -tag -width indent 148.It Fl d Ar duration 149Only watch events longer than 150.Ar duration . 151.It Fl f Ar func Ns Oo Ns , Ns Ar size Oc Ns 152Only watch events generated by 153.Ar func , 154which can be specified as a symbolic name or hex address. 155.Ar size 156defaults to the ELF symbol size if available, or 1 if not. 157.It Fl l Ar lock Ns Oo Ns , Ns Ar size Oc Ns 158Only watch 159.Ar lock , 160which can be specified as a symbolic name or hex address. 161.Ar size 162defaults to the ELF symbol size or 1 if the symbol size is not available. 163.It Fl n Ar num-records 164Maximum number of data records. 165.It Fl T 166Trace (rather than sample) events. 167This is off by default. 168.El 169.Ss Data Reporting 170.Bl -tag -width indent 171.It Fl c 172Coalesce lock data for lock arrays. 173.It Fl D Ar count 174Only display the top 175.Ar count 176events of each type. 177.It Fl g 178Show total events generated by function. 179For example, if 180.Fn foo 181calls 182.Fn bar 183in a loop, the work done by 184.Fn bar 185counts as work generated by 186.Fn foo 187(along with any work done by 188.Fn foo 189itself). 190The 191.Fl g 192option works by counting the total number of stack frames in which each function 193appears. 194This implies two things: (1) the data reported by 195.Fl g 196can be misleading if the stack traces are not deep enough, and (2) functions 197that are called recursively might show greater than 100% activity. 198In light of issue (1), the default data gathering mode when using 199.Fl g 200is 201.Fl s 50 . 202.It Fl k 203Coalesce PCs within functions. 204.It Fl o Ar filename 205Direct output to 206.Ar filename . 207.It Fl P 208Sort data by (\fIcount * time\fR) product. 209.It Fl p 210Parsable output format. 211.It Fl R 212Display rates (events per second) rather than counts. 213.It Fl W 214Whichever: distinguish events only by caller, not by lock. 215.It Fl w 216Wherever: distinguish events only by lock, not by caller. 217.El 218.Sh DISPLAY FORMATS 219The following headers appear over various columns of data. 220.Bl -tag -width indent 221.It Count or ops/s 222Number of times this event occurred, or the rate (times per second) if 223.Fl R 224was specified. 225.It indv 226Percentage of all events represented by this individual event. 227.It genr 228Percentage of all events generated by this function. 229.It cuml 230Cumulative percentage; a running total of the individuals. 231.It rcnt 232Average reference count. 233This will always be 1 for exclusive locks (mutexes, 234spin locks, rwlocks held as writer) but can be greater than 1 for shared locks 235(rwlocks held as reader). 236.It nsec 237Average duration of the events in nanoseconds, as appropriate for the event. 238For the profiling event, duration means interrupt latency. 239.It Lock 240Address of the lock; displayed symbolically if possible. 241.It CPU+PIL 242CPU plus processor interrupt level (PIL). 243For example, if CPU 4 is interrupted while at PIL 6, this will be reported as 244cpu[4]+6. 245.It Caller 246Address of the caller; displayed symbolically if possible. 247.El 248.Sh EXAMPLES 249.Bl -tag -width 0n 250.It Example 1 Measuring Kernel Lock Contention 251.Pp 252.Li # lockstat sleep 5 253.Bd -literal 254Adaptive mutex spin: 41411 events in 5.011 seconds (8263 events/sec) 255 256Count indv cuml rcnt nsec Lock Caller 257------------------------------------------------------------------------------- 25813750 33% 33% 0.00 72 vm_page_queue_free_mtx vm_page_free_toq+0x12e 25913648 33% 66% 0.00 66 vm_page_queue_free_mtx vm_page_alloc+0x138 260 4023 10% 76% 0.00 51 vm_dom+0x80 vm_page_dequeue+0x68 261 2672 6% 82% 0.00 186 vm_dom+0x80 vm_page_enqueue+0x63 262 618 1% 84% 0.00 31 0xfffff8000cd83a88 qsyncvp+0x37 263 506 1% 85% 0.00 164 0xfffff8000cb3f098 vputx+0x5a 264 477 1% 86% 0.00 69 0xfffff8000c7eb180 uma_dbg_getslab+0x5b 265 288 1% 87% 0.00 77 0xfffff8000cd8b000 vn_finished_write+0x29 266 263 1% 88% 0.00 103 0xfffff8000cbad448 vinactive+0xdc 267 259 1% 88% 0.00 53 0xfffff8000cd8b000 vfs_ref+0x24 268 237 1% 89% 0.00 20 0xfffff8000cbad448 vfs_hash_get+0xcc 269 233 1% 89% 0.00 22 0xfffff8000bfd9480 uma_dbg_getslab+0x5b 270 223 1% 90% 0.00 20 0xfffff8000cb3f098 cache_lookup+0x561 271 193 0% 90% 0.00 16 0xfffff8000cb40ba8 vref+0x27 272 175 0% 91% 0.00 34 0xfffff8000cbad448 vputx+0x5a 273 169 0% 91% 0.00 51 0xfffff8000cd8b000 vfs_unbusy+0x27 274 164 0% 92% 0.00 31 0xfffff8000cb40ba8 vputx+0x5a 275[...] 276 277Adaptive mutex block: 10 events in 5.011 seconds (2 events/sec) 278 279Count indv cuml rcnt nsec Lock Caller 280------------------------------------------------------------------------------- 281 3 30% 30% 0.00 17592 vm_page_queue_free_mtx vm_page_alloc+0x138 282 2 20% 50% 0.00 20528 vm_dom+0x80 vm_page_enqueue+0x63 283 2 20% 70% 0.00 55502 0xfffff8000cb40ba8 vputx+0x5a 284 1 10% 80% 0.00 12007 vm_page_queue_free_mtx vm_page_free_toq+0x12e 285 1 10% 90% 0.00 9125 0xfffff8000cbad448 vfs_hash_get+0xcc 286 1 10% 100% 0.00 7864 0xfffff8000cd83a88 qsyncvp+0x37 287------------------------------------------------------------------------------- 288[...] 289.Ed 290.It Example 2 Measuring Hold Times 291.Pp 292.Li # lockstat -H -D 10 sleep 1 293.Bd -literal 294Adaptive mutex hold: 109589 events in 1.039 seconds (105526 events/sec) 295 296Count indv cuml rcnt nsec Lock Caller 297------------------------------------------------------------------------------- 298 8998 8% 8% 0.00 617 0xfffff8000c7eb180 uma_dbg_getslab+0xd4 299 5901 5% 14% 0.00 917 vm_page_queue_free_mtx vm_object_terminate+0x16a 300 5040 5% 18% 0.00 902 vm_dom+0x80 vm_page_free_toq+0x88 301 4884 4% 23% 0.00 1056 vm_page_queue_free_mtx vm_page_alloc+0x44e 302 4664 4% 27% 0.00 759 vm_dom+0x80 vm_fault_hold+0x1a13 303 4011 4% 31% 0.00 888 vm_dom vm_page_advise+0x11b 304 4010 4% 34% 0.00 957 vm_dom+0x80 _vm_page_deactivate+0x5c 305 3743 3% 38% 0.00 582 0xfffff8000cf04838 pmap_is_prefaultable+0x158 306 2254 2% 40% 0.00 952 vm_dom vm_page_free_toq+0x88 307 1639 1% 41% 0.00 591 0xfffff800d60065b8 trap_pfault+0x1f7 308------------------------------------------------------------------------------- 309[...] 310 311R/W writer hold: 64314 events in 1.039 seconds (61929 events/sec) 312 313Count indv cuml rcnt nsec Lock Caller 314------------------------------------------------------------------------------- 315 7421 12% 12% 0.00 2994 pvh_global_lock pmap_page_is_mapped+0xb6 316 4668 7% 19% 0.00 3313 pvh_global_lock pmap_enter+0x9ae 317 1639 3% 21% 0.00 733 0xfffff80168d10200 vm_object_deallocate+0x683 318 1639 3% 24% 0.00 3061 0xfffff80168d10200 unlock_and_deallocate+0x2b 319 1639 3% 26% 0.00 2966 0xfffff80168d10200 vm_fault_hold+0x16ee 320 1567 2% 29% 0.00 733 0xfffff80168d10200 vm_fault_hold+0x19bc 321 821 1% 30% 0.00 786 0xfffff801eb0cc000 vm_object_madvise+0x32d 322 649 1% 31% 0.00 4918 0xfffff80191105300 vm_fault_hold+0x16ee 323 648 1% 32% 0.00 8112 0xfffff80191105300 unlock_and_deallocate+0x2b 324 647 1% 33% 0.00 1261 0xfffff80191105300 vm_object_deallocate+0x683 325------------------------------------------------------------------------------- 326.Ed 327.It Example 3 Measuring Hold Times for Stack Traces Containing a Specific Function 328.Pp 329.Li # lockstat -H -f tcp_input -s 50 -D 10 sleep 1 330.Bd -literal 331Adaptive mutex hold: 68 events in 1.026 seconds (66 events/sec) 332 333------------------------------------------------------------------------------- 334Count indv cuml rcnt nsec Lock Caller 335 32 47% 47% 0.00 1631 0xfffff800686f50d8 tcp_do_segment+0x284b 336 337 nsec ------ Time Distribution ------ count Stack 338 1024 |@@@@@@@@@@ 11 tcp_input+0xf54 339 2048 |@@@@@@@@@@@@@ 14 ip_input+0xc8 340 4096 |@@@@@ 6 swi_net+0x192 341 8192 | 1 intr_event_execute_handlers+0x93 342 ithread_loop+0xa6 343 fork_exit+0x84 344 0xffffffff808cf9ee 345------------------------------------------------------------------------------- 346Count indv cuml rcnt nsec Lock Caller 347 29 43% 90% 0.00 4851 0xfffff800686f50d8 sowakeup+0xf8 348 349 nsec ------ Time Distribution ------ count Stack 350 4096 |@@@@@@@@@@@@@@@ 15 tcp_do_segment+0x2423 351 8192 |@@@@@@@@@@@@ 12 tcp_input+0xf54 352 16384 |@@ 2 ip_input+0xc8 353 swi_net+0x192 354 intr_event_execute_handlers+0x93 355 ithread_loop+0xa6 356 fork_exit+0x84 357 0xffffffff808cf9ee 358------------------------------------------------------------------------------- 359[...] 360.Ed 361.El 362.Sh SEE ALSO 363.Xr dtrace 1 , 364.Xr ksyms 4 , 365.Xr locking 9 366.Sh NOTES 367Tail-call elimination can affect call sites. 368For example, if 369.Fn foo Ns +0x50 370calls 371.Fn bar 372and the last thing 373.Fn bar 374does is call 375.Fn mtx_unlock , 376the compiler can arrange for 377.Fn bar 378to branch to 379.Fn mtx_unlock 380with a return address of 381.Fn foo Ns +0x58. 382Thus, the 383.Fn mtx_unlock 384in 385.Fn bar 386will appear as though it occurred at 387.Fn foo Ns +0x58. 388.Pp 389The PC in the stack frame in which an interrupt occurs can be bogus because, 390between function calls, the compiler is free to use the return address register 391for local storage. 392.Pp 393When using the 394.Fl I 395and 396.Fl s 397options together, the interrupted PC will usually not appear anywhere in the 398stack since the interrupt handler is entered asynchronously, not by a function 399call from that PC. 400