5 lcnt - 锁性能分析器
在 Erlang 运行时系统内部，锁用于保护资源，防止它们以致命的方式从多个线程更新。锁对于确保运行时系统正常工作是必要的，但也带来了一些限制。锁争用和锁开销。
锁争用是指当一个线程锁定一个资源时，另一个线程或多个线程试图同时获取该资源。锁将拒绝其他线程访问资源，该线程将被阻止继续执行。第二个线程必须等到第一个线程完成对资源的访问并解锁它。该 lcnt 工具测量这些锁冲突。
锁在执行时间和内存空间方面存在固有成本。初始化、销毁、获取或释放锁都需要时间。为了减少锁争用，有时需要使用更细粒度的锁定策略。这通常也会增加锁开销，因此在锁争用和开销之间存在权衡。一般来说，锁争用随着并发运行的线程数量的增加而增加。该 lcnt 工具不测量锁开销。
5.1 启用锁计数
为了调查模拟器中的锁，我们使用了一个名为 lcnt （lock-count 的缩写）的内部工具。需要启用此选项才能编译 VM。要编译包含锁计数功能的 VM 以及普通 VM，请使用
cd $ERL_TOP ./configure --enable-lock-counter
以这种方式启动锁计数 VM
$ERL_TOP/bin/erl -emu_type lcnt
要验证是否启用了锁计数，请检查 VM 启动时状态文本中是否出现 [lock-counting]。
Erlang/OTP 20 [erts-9.0] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:10] [hipe] [kernel-poll:false] [lock-counting]
5.2 快速入门
一旦您拥有启用了锁计数的 VM，就可以使用模块 lcnt。该模块旨在从当前运行的节点 shell 中使用。要访问远程节点，请使用 lcnt:clear(Node) 和 lcnt:collect(Node)。
所有锁都会被持续监控，其统计信息会不断更新。使用 lcnt:clear/0 在运行任何特定测试之前先清除所有计数器。此命令还将重置内部的持续时间计时器。
要检索锁统计信息，请使用 lcnt:collect/0,1。collect 操作将在尚未启动的情况下启动一个 lcnt 服务器。所有收集到的数据将被构建成一个 Erlang 项并上传到服务器，持续时间也会被上传。此持续时间是 lcnt:clear/0,1 和 lcnt:collect/0,1 之间的时间。
数据收集到服务器后，可以通过多种方式进行过滤、排序和打印。
有关每个函数的描述，请参见 参考手册。
5.3 使用示例
从 Erlang shell
Erlang R13B03 (erts-5.7.4) [source] [smp:8:8] [rq:8] [async-threads:0] [hipe]
[kernel-poll:false] [lock-counting]
1> lcnt:rt_opt({copy_save, true}).
false
2> lcnt:clear(), big:bang(1000), lcnt:collect().
ok
3> lcnt:conflicts().
lock id #tries #collisions collisions [%] time [us] duration [%]
----- --- ------- ------------ --------------- ---------- -------------
alcu_allocator 50 4113692 158921 3.8632 215464 4.4962
pix_lock 256 4007140 4882 0.1218 12221 0.2550
run_queue 8 2287246 6949 0.3038 9825 0.2050
proc_main 1029 3115778 25755 0.8266 1199 0.0250
proc_msgq 1029 2467022 1910 0.0774 1048 0.0219
proc_status 1029 5708439 2435 0.0427 706 0.0147
message_pre_alloc_lock 8 2008569 134 0.0067 90 0.0019
timeofday 1 54065 8 0.0148 22 0.0005
gc_info 1 7071 7 0.0990 5 0.0001
ok
另一种对特定函数进行性能分析的方法是使用 lcnt:apply/3 或 lcnt:apply/1，它会在函数调用之前执行 lcnt:clear/0，并在函数调用之后执行 lcnt:collect/0。此方法只应在微基准测试中使用，因为它会将 copy_save 设置为 true，持续整个函数调用，如果在负载下尝试，这可能会导致模拟器内存不足。
Erlang R13B03 (erts-5.7.4) [source] [smp:8:8] [rq:8] [async-threads:0] [hipe]
[kernel-poll:false] [lock-counting]
1> lcnt:apply(fun() -> big:bang(1000) end).
4384.338
2> lcnt:conflicts().
lock id #tries #collisions collisions [%] time [us] duration [%]
----- --- ------- ------------ --------------- ---------- -------------
alcu_allocator 50 4117913 183091 4.4462 234232 5.1490
run_queue 8 2050398 3801 0.1854 6700 0.1473
pix_lock 256 4007080 4943 0.1234 2847 0.0626
proc_main 1028 3000178 28247 0.9415 1022 0.0225
proc_msgq 1028 2293677 1352 0.0589 545 0.0120
proc_status 1028 5258029 1744 0.0332 442 0.0097
message_pre_alloc_lock 8 2009322 147 0.0073 82 0.0018
timeofday 1 48616 9 0.0185 13 0.0003
gc_info 1 7455 12 0.1610 9 0.0002
ok
进程锁按其类别排序，就像所有其他锁一样。查看特定进程和端口作为类别很方便。我们可以通过交换类别和类别标识符来实现这一点 lcnt:swap_pid_keys/0。
3> lcnt:swap_pid_keys().
ok
4> lcnt:conflicts([{print, [name, tries, ratio, time]}]).
lock #tries collisions [%] time [us]
----- ------- --------------- ----------
alcu_allocator 4117913 4.4462 234232
run_queue 2050398 0.1854 6700
pix_lock 4007080 0.1234 2847
message_pre_alloc_lock 2009322 0.0073 82
<[email protected]> 13493 1.4452 41
<[email protected]> 13504 1.1404 36
<[email protected]> 13181 1.6235 35
<[email protected]> 13534 0.8202 22
<[email protected]> 8744 5.8326 22
<[email protected]> 13335 1.1174 19
<[email protected]> 13452 1.3678 19
<[email protected]> 13497 1.8745 18
<[email protected]> 11009 2.5343 18
<[email protected]> 13131 1.2566 16
<[email protected]> 13216 1.7327 15
<[email protected]> 13156 1.1098 15
<[email protected]> 13420 0.7303 14
<[email protected]> 13141 1.6437 14
<[email protected]> 13346 1.2064 13
<[email protected]> 13076 1.1701 13
ok
5.4 Mnesia 事务基准测试示例
从 Erlang shell
Erlang R13B03 (erts-5.7.4) [source] [smp:8:8] [rq:8] [async-threads:0] [hipe]
[kernel-poll:false] [lock-counting]
Eshell V5.7.4 (abort with ^G)
1> Conf=[{db_nodes, [node()]}, {driver_nodes, [node()]}, {replica_nodes, [node()]},
{n_drivers_per_node, 10}, {n_branches, 1000}, {n_accounts_per_branch, 10},
{replica_type, ram_copies}, {stop_after, 60000}, {reuse_history_id, true}].
[{db_nodes,[nonode@nohost]},
{driver_nodes,[nonode@nohost]},
{replica_nodes,[nonode@nohost]},
{n_drivers_per_node,10},
{n_branches,1000},
{n_accounts_per_branch,10},
{replica_type,ram_copies},
{stop_after,60000},
{reuse_history_id,true}]
2> mnesia_tpcb:init([{use_running_mnesia, false}|Conf]).
ignore
基准测试的初始配置已完成。现在该对实际基准测试和 Mnesia 进行性能分析了
3> lcnt:apply(fun() -> {ok,{time, Tps,_,_,_,_}} = mnesia_tpcb:run([{use_running_mnesia,
true}|Conf]), Tps/60 end).
12037.483333333334
ok
4> lcnt:swap_pid_keys().
ok
该 id 标题表示使用选项 {combine, true} （默认情况下启用）时类别下唯一标识符的数量。否则它将显示特定标识符。该 db_tab 列表显示 722287 个唯一锁，每个创建的 ets 表都有一个，Mnesia 为每个事务创建一个。
5> lcnt:conflicts().
lock id #tries #collisions collisions [%] time [us] duration [%]
----- --- ------- ------------ --------------- ---------- -------------
alcu_allocator 50 56355118 732662 1.3001 2934747 4.8862
db_tab 722287 94513441 63203 0.0669 1958797 3.2613
timeofday 1 2701048 175854 6.5106 1746079 2.9071
pix_lock 256 24306168 163214 0.6715 918309 1.5289
run_queue 8 11813811 152637 1.2920 357040 0.5945
message_pre_alloc_lock 8 17671449 57203 0.3237 263043 0.4380
mnesia_locker 4 17477633 1618548 9.2607 97092 0.1617
mnesia_tm 4 9891408 463788 4.6888 86353 0.1438
gc_info 1 823460 628 0.0763 24826 0.0413
meta_main_tab_slot 16 41393400 7193 0.0174 11393 0.0190
<[email protected]> 4 4331412 333 0.0077 7148 0.0119
timer_wheel 1 203185 30 0.0148 3108 0.0052
<[email protected]> 4 4291098 210 0.0049 885 0.0015
<[email protected]> 4 4294702 288 0.0067 442 0.0007
<[email protected]> 4 4346066 235 0.0054 390 0.0006
<[email protected]> 4 4348159 287 0.0066 379 0.0006
<[email protected]> 4 4279309 290 0.0068 325 0.0005
<[email protected]> 4 4292190 302 0.0070 315 0.0005
<[email protected]> 4 4208858 265 0.0063 276 0.0005
<[email protected]> 4 4377502 267 0.0061 276 0.0005
ok
列表显示 mnesia_locker，一个进程，具有高度争用的锁。
6> lcnt:inspect(mnesia_locker).
lock id #tries #collisions collisions [%] time [us] duration [%]
----- --- ------- ------------ --------------- ---------- -------------
mnesia_locker proc_msgq 5449930 59374 1.0894 69781 0.1162
mnesia_locker proc_main 4462782 1487374 33.3284 14398 0.0240
mnesia_locker proc_status 7564921 71800 0.9491 12913 0.0215
mnesia_locker proc_link 0 0 0.0000 0 0.0000
ok
不使用类别组合器的列表。
7> lcnt:conflicts([{combine, false}, {print, [name, id, tries, ratio, time]}]).
lock id #tries collisions [%] time [us]
----- --- ------- --------------- ----------
db_tab mnesia_transient_decision 722250 3.9463 1856852
timeofday undefined 2701048 6.5106 1746079
alcu_allocator ets_alloc 7490696 2.2737 692655
alcu_allocator ets_alloc 7081771 2.3294 664522
alcu_allocator ets_alloc 7047750 2.2520 658495
alcu_allocator ets_alloc 5883537 2.3177 610869
pix_lock 58 11011355 1.1924 564808
pix_lock 60 4426484 0.7120 262490
alcu_allocator ets_alloc 1897004 2.4248 219543
message_pre_alloc_lock undefined 4211267 0.3242 128299
run_queue 3 2801555 1.3003 116792
run_queue 2 2799988 1.2700 100091
run_queue 1 2966183 1.2712 78834
mnesia_locker proc_msgq 5449930 1.0894 69781
message_pre_alloc_lock undefined 3495672 0.3262 65773
message_pre_alloc_lock undefined 4189752 0.3174 58607
mnesia_tm proc_msgq 2094144 1.7184 56361
run_queue 4 2343585 1.3115 44300
db_tab branch 1446529 0.5229 38244
gc_info undefined 823460 0.0763 24826
ok
在这种情况下，保护 ets 表 mnesia_transient_decision 的锁花费了大部分时间等待。在运行了 60 秒的测试中，这花费了 1.8 秒。该时间也分布在八个不同的调度程序线程上。
8> lcnt:inspect(db_tab, [{print, [name, id, tries, colls, ratio, duration]}]).
lock id #tries #collisions collisions [%] duration [%]
----- --- ------- ------------ --------------- -------------
db_tab mnesia_transient_decision 722250 28502 3.9463 3.0916
db_tab branch 1446529 7564 0.5229 0.0637
db_tab account 1464500 8203 0.5601 0.0357
db_tab teller 1464529 8110 0.5538 0.0291
db_tab history 722250 3767 0.5216 0.0232
db_tab mnesia_stats 750332 7057 0.9405 0.0180
db_tab mnesia_trans_store 61 0 0.0000 0.0000
db_tab mnesia_trans_store 61 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
db_tab mnesia_trans_store 53 0 0.0000 0.0000
ok
5.5 解读输出
通常，较高的 time 值不好，这通常是需要查找的东西。但是，还应该注意高锁获取频率（#tries），因为锁会产生开销，并且因为即使在特定测试中没有显示出来，如果它们开始发生冲突，高频率也会变得有问题。