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 8, 2014 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+Pri_Class 242CPU plus the priority class of the interrupted thread. 243For example, if CPU 4 is interrupted while running a timeshare thread, this 244will be reported as 245.Ql cpu[4]+TShar . 246.It Caller 247Address of the caller; displayed symbolically if possible. 248.El 249.Sh EXAMPLES 250.Bl -tag -width 0n 251.It Example 1 Measuring Kernel Lock Contention 252.Pp 253.Li # lockstat sleep 5 254.Bd -literal 255Adaptive mutex spin: 41411 events in 5.011 seconds (8263 events/sec) 256 257Count indv cuml rcnt nsec Lock Caller 258------------------------------------------------------------------------------- 25913750 33% 33% 0.00 72 vm_page_queue_free_mtx vm_page_free_toq+0x12e 26013648 33% 66% 0.00 66 vm_page_queue_free_mtx vm_page_alloc+0x138 261 4023 10% 76% 0.00 51 vm_dom+0x80 vm_page_dequeue+0x68 262 2672 6% 82% 0.00 186 vm_dom+0x80 vm_page_enqueue+0x63 263 618 1% 84% 0.00 31 0xfffff8000cd83a88 qsyncvp+0x37 264 506 1% 85% 0.00 164 0xfffff8000cb3f098 vputx+0x5a 265 477 1% 86% 0.00 69 0xfffff8000c7eb180 uma_dbg_getslab+0x5b 266 288 1% 87% 0.00 77 0xfffff8000cd8b000 vn_finished_write+0x29 267 263 1% 88% 0.00 103 0xfffff8000cbad448 vinactive+0xdc 268 259 1% 88% 0.00 53 0xfffff8000cd8b000 vfs_ref+0x24 269 237 1% 89% 0.00 20 0xfffff8000cbad448 vfs_hash_get+0xcc 270 233 1% 89% 0.00 22 0xfffff8000bfd9480 uma_dbg_getslab+0x5b 271 223 1% 90% 0.00 20 0xfffff8000cb3f098 cache_lookup+0x561 272 193 0% 90% 0.00 16 0xfffff8000cb40ba8 vref+0x27 273 175 0% 91% 0.00 34 0xfffff8000cbad448 vputx+0x5a 274 169 0% 91% 0.00 51 0xfffff8000cd8b000 vfs_unbusy+0x27 275 164 0% 92% 0.00 31 0xfffff8000cb40ba8 vputx+0x5a 276[...] 277 278Adaptive mutex block: 10 events in 5.011 seconds (2 events/sec) 279 280Count indv cuml rcnt nsec Lock Caller 281------------------------------------------------------------------------------- 282 3 30% 30% 0.00 17592 vm_page_queue_free_mtx vm_page_alloc+0x138 283 2 20% 50% 0.00 20528 vm_dom+0x80 vm_page_enqueue+0x63 284 2 20% 70% 0.00 55502 0xfffff8000cb40ba8 vputx+0x5a 285 1 10% 80% 0.00 12007 vm_page_queue_free_mtx vm_page_free_toq+0x12e 286 1 10% 90% 0.00 9125 0xfffff8000cbad448 vfs_hash_get+0xcc 287 1 10% 100% 0.00 7864 0xfffff8000cd83a88 qsyncvp+0x37 288------------------------------------------------------------------------------- 289[...] 290.Ed 291.It Example 2 Measuring Hold Times 292.Pp 293.Li # lockstat -H -D 10 sleep 1 294.Bd -literal 295Adaptive mutex hold: 109589 events in 1.039 seconds (105526 events/sec) 296 297Count indv cuml rcnt nsec Lock Caller 298------------------------------------------------------------------------------- 299 8998 8% 8% 0.00 617 0xfffff8000c7eb180 uma_dbg_getslab+0xd4 300 5901 5% 14% 0.00 917 vm_page_queue_free_mtx vm_object_terminate+0x16a 301 5040 5% 18% 0.00 902 vm_dom+0x80 vm_page_free_toq+0x88 302 4884 4% 23% 0.00 1056 vm_page_queue_free_mtx vm_page_alloc+0x44e 303 4664 4% 27% 0.00 759 vm_dom+0x80 vm_fault_hold+0x1a13 304 4011 4% 31% 0.00 888 vm_dom vm_page_advise+0x11b 305 4010 4% 34% 0.00 957 vm_dom+0x80 _vm_page_deactivate+0x5c 306 3743 3% 38% 0.00 582 0xfffff8000cf04838 pmap_is_prefaultable+0x158 307 2254 2% 40% 0.00 952 vm_dom vm_page_free_toq+0x88 308 1639 1% 41% 0.00 591 0xfffff800d60065b8 trap_pfault+0x1f7 309------------------------------------------------------------------------------- 310[...] 311 312R/W writer hold: 64314 events in 1.039 seconds (61929 events/sec) 313 314Count indv cuml rcnt nsec Lock Caller 315------------------------------------------------------------------------------- 316 7421 12% 12% 0.00 2994 pvh_global_lock pmap_page_is_mapped+0xb6 317 4668 7% 19% 0.00 3313 pvh_global_lock pmap_enter+0x9ae 318 1639 3% 21% 0.00 733 0xfffff80168d10200 vm_object_deallocate+0x683 319 1639 3% 24% 0.00 3061 0xfffff80168d10200 unlock_and_deallocate+0x2b 320 1639 3% 26% 0.00 2966 0xfffff80168d10200 vm_fault_hold+0x16ee 321 1567 2% 29% 0.00 733 0xfffff80168d10200 vm_fault_hold+0x19bc 322 821 1% 30% 0.00 786 0xfffff801eb0cc000 vm_object_madvise+0x32d 323 649 1% 31% 0.00 4918 0xfffff80191105300 vm_fault_hold+0x16ee 324 648 1% 32% 0.00 8112 0xfffff80191105300 unlock_and_deallocate+0x2b 325 647 1% 33% 0.00 1261 0xfffff80191105300 vm_object_deallocate+0x683 326------------------------------------------------------------------------------- 327.Ed 328.It Example 3 Measuring Hold Times for Stack Traces Containing a Specific Function 329.Pp 330.Li # lockstat -H -f tcp_input -s 50 -D 10 sleep 1 331.Bd -literal 332Adaptive mutex hold: 68 events in 1.026 seconds (66 events/sec) 333 334------------------------------------------------------------------------------- 335Count indv cuml rcnt nsec Lock Caller 336 32 47% 47% 0.00 1631 0xfffff800686f50d8 tcp_do_segment+0x284b 337 338 nsec ------ Time Distribution ------ count Stack 339 1024 |@@@@@@@@@@ 11 tcp_input+0xf54 340 2048 |@@@@@@@@@@@@@ 14 ip_input+0xc8 341 4096 |@@@@@ 6 swi_net+0x192 342 8192 | 1 intr_event_execute_handlers+0x93 343 ithread_loop+0xa6 344 fork_exit+0x84 345 0xffffffff808cf9ee 346------------------------------------------------------------------------------- 347Count indv cuml rcnt nsec Lock Caller 348 29 43% 90% 0.00 4851 0xfffff800686f50d8 sowakeup+0xf8 349 350 nsec ------ Time Distribution ------ count Stack 351 4096 |@@@@@@@@@@@@@@@ 15 tcp_do_segment+0x2423 352 8192 |@@@@@@@@@@@@ 12 tcp_input+0xf54 353 16384 |@@ 2 ip_input+0xc8 354 swi_net+0x192 355 intr_event_execute_handlers+0x93 356 ithread_loop+0xa6 357 fork_exit+0x84 358 0xffffffff808cf9ee 359------------------------------------------------------------------------------- 360[...] 361.Ed 362.El 363.Sh SEE ALSO 364.Xr dtrace 1 , 365.Xr ksyms 4 , 366.Xr locking 9 367.Sh NOTES 368Tail-call elimination can affect call sites. 369For example, if 370.Fn foo Ns +0x50 371calls 372.Fn bar 373and the last thing 374.Fn bar 375does is call 376.Fn mtx_unlock , 377the compiler can arrange for 378.Fn bar 379to branch to 380.Fn mtx_unlock 381with a return address of 382.Fn foo Ns +0x58. 383Thus, the 384.Fn mtx_unlock 385in 386.Fn bar 387will appear as though it occurred at 388.Fn foo Ns +0x58. 389.Pp 390The PC in the stack frame in which an interrupt occurs can be bogus because, 391between function calls, the compiler is free to use the return address register 392for local storage. 393.Pp 394When using the 395.Fl I 396and 397.Fl s 398options together, the interrupted PC will usually not appear anywhere in the 399stack since the interrupt handler is entered asynchronously, not by a function 400call from that PC. 401