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