cddl/contrib/opensolaris/cmd/lockstat/lockstat.1

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