lockstat - 报告内核锁定和分析统计信息
lockstat [-ACEHI] [-e event_list] [-i rate]
[-b | -t | -h | -s depth] [-n nrecords]
[-l lock [, size]] [-d duration]
[-f function [, size]] [-T] [-ckgwWRpP] [-D count]
[-o filename] [-x opt [=val]] command [args]
lockstat 实用程序用于收集和显示内核锁定和分析统计信息。通过 lockstat，您可以指定要观察哪些事件（例如，自适应互斥锁的自旋、由于等待写入器而阻塞对 rwlock 的读取访问等）、要为每个事件收集多少数据以及如何显示该数据。缺省情况下，lockstat 监视所有锁争用事件、收集有关这些事件的频率和时间数据，并按频率降序显示这些数据，以便首先显示最常见的事件。
lockstat 会一直收集数据，直到指定命令完成为止。例如，要按固定时间间隔收集统计信息，请使用 sleep(1) 命令，如下所示：
example# lockstat sleep 5
如果指定了 –I 选项，lockstat 将基于每个处理器建立高级别定期中断源以收集分析数据。中断处理程序只生成一个 lockstat 事件，该事件的调用者为中断的 PC（program counter，程序计数器）。分析事件与任何其他 lockstat 事件一样，因此所有常规 lockstat 选项都适用。
lockstat 依靠 DTrace 来修改运行内核的文本以拦截关注的事件。这会对所有系统活动产生较小但可察觉的开销，因此，缺省情况下，只有超级用户才能访问 lockstat。系统管理员可以通过为其他用户授予附加 DTrace 特权来允许这些用户使用 lockstat。有关 DTrace 安全功能的更多信息，请参阅《Oracle Solaris 11.4 DTrace（动态跟踪）指南》。
支持以下选项：
如果未指定事件选择选项，则缺省值为 –C。
观察所有锁定事件。–A 等效于 –CH。
观察争用事件。
观察错误事件。
仅观察指定事件，event list 是用逗号分隔的事件或事件范围列表（如 1,4-7,35）。运行无参数的 lockstat 可查看所有事件的简要说明。
观察保持事件。
观察分析中断事件。
–I 的中断速率（每秒）。缺省值为 97 Hz，因此不会以采用时钟中断（运行速率为 100 Hz）的 lockstep 运行分析。
启用或修改 DTrace 运行时选项或 D 编译器选项。选项列表位于 dtrace(8)。将通过指定名称来启用布尔选项。可通过使用等号 (=) 分隔选项名称和值来设置包含值的选项。
基本统计信息：锁、调用者、事件数。
直方图：计时和时间分布直方图。
栈跟踪：直方图加上栈跟踪，深度最多为 depth 个帧。
计时：基本计时加上所有事件的计时 [缺省]。
仅观察持续时间超过 duration 的事件。
仅观察 func 生成的事件，可以指定为符号名称或十六进制地址。size 缺省为 ELF 符号大小（如果可用）；否则缺省为 1。
仅观察 lock，可以指定为符号名称或十六进制地址。size 缺省为 ELF 符号大小，如果该符号大小不可用，则缺省为 1。
数据记录的最大数目。
跟踪（而不是抽样）事件 [缺省情况下禁用]。
合并锁数组（例如，pse_mutex[]）的锁数据。
仅显示每种类型最常发生的 count 个事件。
显示函数生成的所有事件。例如，如果 foo() 在一个循环中调用 bar()，则 bar() 生成的工作量以及 foo() 自身生成的任何工作量都会计为 foo() 生成的工作量。–g 选项统计出现每个函数的栈帧的总数。这意味着：(1) 如果栈跟踪深度不够，则 –g 报告的数据就可能造成误导，(2) 以递归方式调用的函数显示的活动可能会超过 100%。对于问题 (1)，使用 –g 时的缺省数据收集模式为 –s 50。
合并函数中的 PC。
将输出定向到 filename。
按 (count * time) 乘积对数据进行排序。
可解析的输出格式。
显示速率（每秒事件数），而不是计数。
任意对象：仅按调用者（而不按锁）区分事件。
任意位置：仅按锁（而不按调用者）区分事件。
以下标头会显示在各个数据列上。
此事件发生的次数，或者如果指定了 –R，则表示速率（每秒次数）。
由该单个事件表示的所有这类事件的百分比。
由该函数生成的所有事件的百分比。
累积百分比；各个事件的运行总计。
平均引用计数。对于独占锁（互斥锁、自旋锁、写入器持有的 rwlock），该值始终为 1，但是对于共享锁（读取器持有的 rwlock），则可能大于 1。
适用于事件的平均持续时间（以纳秒为单位）。对于分析事件，持续时间是指中断延迟。
锁的地址；如果可能，以符号形式显示。
CPU 和处理器中断级别 (processor interrupt level, PIL)。例如，如果 CPU 4 在 PIL 6 中断，则该事件将报告为 cpu[4]+6。
调用者的地址；如果可能，以符号形式显示。
example# lockstat sleep 5 Adaptive mutex spin: 2210 events in 5.055 seconds (437 events/sec)
Count indv cuml rcnt nsec Lock Caller
------------------------------------------------------------------------
269 12% 12% 1.00 2160 service_queue background+0xdc
249 11% 23% 1.00 86 service_queue qenable_locked+0x64
228 10% 34% 1.00 131 service_queue background+0x15c
68 3% 37% 1.00 79 0x30000024070 untimeout+0x1c
59 3% 40% 1.00 384 0x300066fa8e0 background+0xb0
43 2% 41% 1.00 30 rqcred_lock svc_getreq+0x3c
42 2% 43% 1.00 341 0x30006834eb8 background+0xb0
41 2% 45% 1.00 135 0x30000021058 untimeout+0x1c
40 2% 47% 1.00 39 rqcred_lock svc_getreq+0x260
37 2% 49% 1.00 2372 0x300068e83d0 hmestart+0x1c4
36 2% 50% 1.00 77 0x30000021058 timeout_common+0x4
36 2% 52% 1.00 354 0x300066fa120 background+0xb0
32 1% 53% 1.00 97 0x30000024070 timeout_common+0x4
31 1% 55% 1.00 2923 0x300069883d0 hmestart+0x1c4
29 1% 56% 1.00 366 0x300066fb290 background+0xb0
28 1% 57% 1.00 117 0x3000001e040 untimeout+0x1c
25 1% 59% 1.00 93 0x3000001e040 timeout_common+0x4
22 1% 60% 1.00 25 0x30005161110 sync_stream_buf+0xdc
21 1% 60% 1.00 291 0x30006834eb8 putq+0xa4
19 1% 61% 1.00 43 0x3000515dcb0 mdf_alloc+0xc
18 1% 62% 1.00 456 0x30006834eb8 qenable+0x8
18 1% 63% 1.00 61 service_queue queuerun+0x168
17 1% 64% 1.00 268 0x30005418ee8 vmem_free+0x3c
[...]
R/W reader blocked by writer: 76 events in 5.055 seconds (15 events/sec)
Count indv cuml rcnt nsec Lock Caller
------------------------------------------------------------------------
23 30% 30% 1.00 22590137 0x300098ba358 ufs_dirlook+0xd0
17 22% 53% 1.00 5820995 0x3000ad815e8 find_bp+0x10
13 17% 70% 1.00 2639918 0x300098ba360 ufs_iget+0x198
4 5% 75% 1.00 3193015 0x300098ba360 ufs_getattr+0x54
3 4% 79% 1.00 7953418 0x3000ad817c0 find_bp+0x10
3 4% 83% 1.00 935211 0x3000ad815e8 find_read_lof+0x14
2 3% 86% 1.00 16357310 0x300073a4720 find_bp+0x10
2 3% 88% 1.00 2072433 0x300073a4720 find_read_lof+0x14
2 3% 91% 1.00 1606153 0x300073a4370 find_bp+0x10
1 1% 92% 1.00 2656909 0x300107e7400 ufs_iget+0x198
[...]
示例 2 测量保留次数
example# lockstat -H -D 10 sleep 1 Adaptive mutex spin: 513 events
Count indv cuml rcnt nsec Lock Caller ------------------------------------------------------------------------- 480 5% 5% 1.00 1136 0x300007718e8 putnext+0x40 286 3% 9% 1.00 666 0x3000077b430 getf+0xd8 271 3% 12% 1.00 537 0x3000077b430 msgio32+0x2fc 270 3% 15% 1.00 3670 0x300007718e8 strgetmsg+0x3d4 270 3% 18% 1.00 1016 0x300007c38b0 getq_noenab+0x200 264 3% 20% 1.00 1649 0x300007718e8 strgetmsg+0xa70 216 2% 23% 1.00 6251 tcp_mi_lock tcp_snmp_get+0xfc 206 2% 25% 1.00 602 thread_free_lock clock+0x250 138 2% 27% 1.00 485 0x300007c3998 putnext+0xb8 138 2% 28% 1.00 3706 0x300007718e8 strrput+0x5b8 ------------------------------------------------------------------------- [...]示例 3 测量包含特定函数的栈跟踪的保留次数
example# lockstat -H -f so_recvmsg -s 50 -D 10 sleep 10 Adaptive mutex hold: 171792 events in 10.089 seconds (17028 events/sec)
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Lock Caller
48140 28% 28% 0.00 1109 0x184004c76ade8 so_recvmsg+0x8a0
nsec ------ Time Distribution ------ count Stack
1024 | 991 socket_recvmsg+0x28
2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 47120 socket_vop_read+0x20
4096 | 28 fop_read+0xe8
8192 | 0 read+0x2d0
16384 | 0 syscall_trap+0x238
32768 | 0
65536 | 0
131072 | 1
[...]
-------------------------------------------------------------------------------
Count indv cuml rcnt nsec Lock Caller
37756 22% 100% 0.00 1076 0x18400555603e0 so_recvmsg+0x2bc
nsec ------ Time Distribution ------ count Stack
1024 |@@@@@ 7519 socket_recvmsg+0x28
2048 |@@@@@@@@@@@@@@@@@@@@@@@ 30193 socket_vop_read+0x20
4096 | 41 fop_read+0xe8
8192 | 3 read+0x2d0
syscall_trap+0x238
[...]
示例 4 基本内核分析
对于基本分析，由于不关心分析中断抽样的是 foo()+0x4c 还是 foo()+0x78，只要求对 foo() 中的某个位置进行了抽样，因此使用 –k。CPU 和 PIL 与基本分析无关，因为将系统作为整体进行测量，而不是对特定的 CPU 或中断级别进行测量，因此使用 –W。
example# lockstat -kIW -D 20 ./polltest Profiling interrupt: 82 events in 0.424 seconds (194 events/sec)
Count indv cuml rcnt nsec Hottest CPU+PIL Caller
-----------------------------------------------------------------------
8 10% 10% 1.00 698 cpu[1] utl0
6 7% 17% 1.00 299 cpu[0] read
5 6% 23% 1.00 124 cpu[1] getf
4 5% 28% 1.00 327 cpu[0] fifo_read
4 5% 33% 1.00 112 cpu[1] poll
4 5% 38% 1.00 212 cpu[1] uiomove
4 5% 43% 1.00 361 cpu[1] mutex_tryenter
3 4% 46% 1.00 682 cpu[0] write
3 4% 50% 1.00 89 cpu[0] pcache_poll
3 4% 54% 1.00 118 cpu[1] set_active_fd
3 4% 57% 1.00 105 cpu[0] syscall_trap32
3 4% 61% 1.00 640 cpu[1] (usermode)
2 2% 63% 1.00 127 cpu[1] fifo_poll
2 2% 66% 1.00 300 cpu[1] fifo_write
2 2% 68% 1.00 669 cpu[0] releasef
2 2% 71% 1.00 112 cpu[1] bt_getlowbit
2 2% 73% 1.00 247 cpu[1] splx
2 2% 76% 1.00 503 cpu[0] mutex_enter
2 2% 78% 1.00 467 cpu[0]+10 disp_lock_enter
2 2% 80% 1.00 139 cpu[1] default_copyin
-----------------------------------------------------------------------
[...]
示例 5 分析所生成的负载
在上述示例中，5% 的抽样属于 poll()。这指出在 poll() 中花费了多长时间，但不能指出 poll() 生成了多少工作量；即，在 poll() 调用的函数中花费了多少时间。要了解这一点，需要使用 –g 选项。以下示例显示，尽管 polltest 在 poll() 中仅花费了 5% 的时间，但 poll() 产生的工作量占负载的 34%。
请注意，生成分析中断的函数（lockstat_intr()、cyclic_fire() 等）出现在每个栈跟踪中，因此会认为生成了 100% 的负载。这说明一点：所生成的负载百分比总和不会是 100%，因为这些负载不是独立的。如果 foo() 和 bar() 占所有栈跟踪的 72%，则 foo() 和 bar() 生成了 72% 的负载。
example# lockstat -kgIW -D 20 ./polltest Profiling interrupt: 80 events in 0.412 seconds (194 events/sec)
Count genr cuml rcnt nsec Hottest CPU+PIL Caller
-------------------------------------------------------------------------
80 100% ---- 1.00 310 cpu[1] lockstat_intr
80 100% ---- 1.00 310 cpu[1] cyclic_fire
80 100% ---- 1.00 310 cpu[1] cbe_level14
80 100% ---- 1.00 310 cpu[1] current_thread
27 34% ---- 1.00 176 cpu[1] poll
20 25% ---- 1.00 221 cpu[0] write
19 24% ---- 1.00 249 cpu[1] read
17 21% ---- 1.00 232 cpu[0] write32
17 21% ---- 1.00 207 cpu[1] pcache_poll
14 18% ---- 1.00 319 cpu[0] fifo_write
13 16% ---- 1.00 214 cpu[1] read32
10 12% ---- 1.00 208 cpu[1] fifo_read
10 12% ---- 1.00 787 cpu[1] utl0
9 11% ---- 1.00 178 cpu[0] pcacheset_resolve
9 11% ---- 1.00 262 cpu[0] uiomove
7 9% ---- 1.00 506 cpu[1] (usermode)
5 6% ---- 1.00 195 cpu[1] fifo_poll
5 6% ---- 1.00 136 cpu[1] syscall_trap32
4 5% ---- 1.00 139 cpu[0] releasef
3 4% ---- 1.00 277 cpu[1] polllock
-------------------------------------------------------------------------
[...]
示例 6 收集特定模块的锁争用和分析数据
In this example we use the –f option not to specify a single function, but rather to specify the entire text space of the procfs module.将收集锁争用和分析统计信息，以便了解争用与模块的整体负载之间的关联。
example# modinfo | grep procfs # modinfo | grep procfs 9 10b0a698 1b068 5 1 procfs (filesystem for proc)
example# lockstat -kICE -f 0x10b0a698,0x1b068 sleep 10 Adaptive mutex spin: 16 events in 10.042 seconds (2 events/sec)
Count indv cuml rcnt nsec Lock Caller
-------------------------------------------------------------------------------
15 94% 94% 0.00 2158 pr_pidlock pr_p_lock_i
1 6% 100% 0.00 3060 pr_pidlock prinactive
-------------------------------------------------------------------------------
Profiling interrupt: 4 events in 10.033 seconds (0 events/sec)
Count indv cuml rcnt nsec CPU+PIL Caller
-------------------------------------------------------------------------------
1 25% 25% 0.00 588 cpu[108]+11 prchoose
1 25% 50% 0.00 492 cpu[108] prchoose
1 25% 75% 0.00 225 cpu[50]+11 prchoose
1 25% 100% 0.00 1785 cpu[50] prchoose
-------------------------------------------------------------------------------
示例 7 确定 CPU 的平均 PIL（processor interrupt level，处理器中断级别）
example# lockstat -Iw -l cpu[3] ./testprog
Profiling interrupt: 14791 events in 152.463 seconds (97 events/sec)
Count indv cuml rcnt nsec CPU+PIL Hottest Caller
-----------------------------------------------------------------------
13641 92% 92% 1.00 253 cpu[3] (usermode)
579 4% 96% 1.00 325 cpu[3]+6 ip_ocsum+0xe8
375 3% 99% 1.00 411 cpu[3]+10 splx
154 1% 100% 1.00 527 cpu[3]+4 fas_intr_svc+0x80
41 0% 100% 1.00 293 cpu[3]+13 send_mondo+0x18
1 0% 100% 1.00 266 cpu[3]+12 zsa_rxint+0x400
-----------------------------------------------------------------------
[...]
示例 8 确定导致系统繁忙的子系统
example# lockstat -s 10 -I sleep 20
Profiling interrupt: 4863 events in 47.375 seconds (103 events/sec)
Count indv cuml rcnt nsec CPU+PIL Caller
787 8% 8% 0.00 1953 cpu[112] default_mutex_lock_delay+0x6c
nsec ------ Time Distribution ------ count Stack
512 |@ 31 default_mutex_lock_delay+0x64
1024 |@@@@@@@@@@@@@@@@@ 460 lock_set_spl_spin+0xcc
2048 |@@@@@@@@@@ 277 turnstile_lookup+0x48
4096 | 19 rw_enter_sleep+0xcc
sdev_access+0x10
sdev_lookup+0x20
fop_lookup+0x15c
lookuppnvp+0x49c
lookuppnatcred+0x110
-----------------------------------------------------------------------
[...]
有关下列属性的说明，请参见 attributes(7)：
|
lockstat(4D)、attributes(7)、dtrace(8)、plockstat(8)、mutex(9F)、rwlock(9F)
《Oracle Solaris 11.4 DTrace（动态跟踪）指南》
lockstat –I 提供的分析支持将取代旧的 /usr/bin/kgmon 和 /dev/profile（未在文档中说明）。
尾部调用消除技术会影响调用点。例如，如果 foo()+0x50 调用 bar()，而 bar() 最后执行的操作是调用 mutex_exit()，编译器可能会安排 bar() 转到 mutex_exit() 并将 foo()+0x58 作为返回地址。因此，bar() 中的 mutex_exit() 看起来就像发生在 foo()+0x58 一样。
栈帧中发生中断的 PC 可能是虚假的，因为在两次函数调用之间，编译器可以自由地对本地存储使用返回地址寄存器。
如果将 –I 和 –s 选项结合使用，则中断的 PC 通常不会显示在栈中的任何位置，因为中断处理程序是以异步方式进入的，而不是通过该 PC 发出函数调用进入的。
lockstat 技术是按原样提供的。lockstat 输出的格式和内容反映了当前的 Solaris 内核实现情况，因此在未来发行版中可能会更改。