From eec56b21f02368b085b0b1076233448459b4c555 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bj=C3=B6rn-Egil=20Dahlberg?= Date: Mon, 1 Feb 2010 11:51:06 +0100 Subject: Add lcnt documentation Documentation for the lock profiling tool --- lib/tools/doc/src/Makefile | 2 + lib/tools/doc/src/lcnt.xml | 465 +++++++++++++++++++++++++++++++++++++ lib/tools/doc/src/lcnt_chapter.xml | 301 ++++++++++++++++++++++++ lib/tools/doc/src/part.xml | 3 + lib/tools/doc/src/ref_man.xml | 6 + 5 files changed, 777 insertions(+) create mode 100644 lib/tools/doc/src/lcnt.xml create mode 100644 lib/tools/doc/src/lcnt_chapter.xml diff --git a/lib/tools/doc/src/Makefile b/lib/tools/doc/src/Makefile index bab607c4bd..5ac8718b61 100644 --- a/lib/tools/doc/src/Makefile +++ b/lib/tools/doc/src/Makefile @@ -41,6 +41,7 @@ XML_REF3_FILES = \ eprof.xml \ fprof.xml \ cprof.xml \ + lcnt.xml \ instrument.xml \ make.xml \ tags.xml \ @@ -53,6 +54,7 @@ XML_CHAPTER_FILES = \ cover_chapter.xml \ fprof_chapter.xml \ cprof_chapter.xml \ + lcnt_chapter.xml \ erlang_mode_chapter.xml \ xref_chapter.xml \ notes.xml \ diff --git a/lib/tools/doc/src/lcnt.xml b/lib/tools/doc/src/lcnt.xml new file mode 100644 index 0000000000..3c55e4e422 --- /dev/null +++ b/lib/tools/doc/src/lcnt.xml @@ -0,0 +1,465 @@ + + + + +
+ + 2009 + 2010 + Ericsson AB, All Rights Reserved + + + The contents of this file are subject to the Erlang Public License, + Version 1.1, (the "License"); you may not use this file except in + compliance with the License. You should have received a copy of the + Erlang Public License along with this software. If not, it can be + retrieved online at http://www.erlang.org/. + + Software distributed under the License is distributed on an "AS IS" + basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See + the License for the specific language governing rights and limitations + under the License. + + The Initial Developer of the Original Code is Ericsson AB. + + + lcnt + Björn-Egil Dahlberg + nobody + + nobody + + 2009-11-26 + PA1 + lcnt.xml +
+ lcnt + A runtime system Lock Profiling tool. + +

The lcnt module is used to profile the internal ethread locks in the + Erlang Runtime System. With lcnt enabled, Internal counters in the + runtime system are updated each time a lock is taken. The counters stores + information about the number of acquisition tries and the number of collisions + that has occurred during the acquisition tries. The counters also record the + waiting time a lock has caused for a blocked thread when a collision has occurred. +

+

+ The data produced by the lock counters will give an estimate on how well + the runtime system will behave from a parallelizable view point for the + scenarios tested. This tool was mainly developed to help erlang runtime + developers iron out potential and generic bottlenecks. +

+

Locks in the emulator are named after what type of resource they protect and where + in the emulator they are initialized, those are lock 'classes'. Most of those + locks are also instantiated several times, and given unique identifiers, to increase + locking granularity. Typically an instantiated lock protects a disjunct set of + the resource, i.e ets-tables, processes or ports. In other cases it protects a + specific range of a resource, e.g. pix_lock which protects index to process + mappings, and is given a unique number within the class. A unique lock in lcnt + is referenced by a name (class) and an identifier, {Name, Id}. +

+

Some locks in the system are static and protects global resources, for example + bif_timers and the run_queue locks. Other locks are dynamic and not + necessarily long lived, for example process locks and ets-table locks. The + statistics data from short lived locks can be stored separately when the locks + are deleted. This behavior is by default turned off to save memory but can be + turned on via lcnt:rt_opt({copy_save, true}). The lcnt:apply/1,2,3 + functions enables this behavior during profiling. +

+ + + + + start() -> {ok, Pid} | {error, {already_started, Pid}} + Starts the lock profiler server. + + Pid = pid() + + +

Starts the lock profiler server. The server only act as a medium for the + user and performs filtering and printing of data collected by lcnt:collect/1. +

+ + + + + stop() -> ok + Stops the lock profiler server. + +

Stops the lock profiler server.

+ + + + + collect() -> ok + Same as collect(node()). +

Same as collect(node()).

 + + + + collect(Node) -> ok + Collects lock statistics from the runtime system. + + Node = node() + + +

Collects lock statistics from the runtime system. The function starts a + server if it is not already started. It then populates the server with lock + statistics. If the server held any lock statistics data before the collect then + that data is lost. +

+ +

+ When collection occurs the runtime system transitions to a single thread, + blocking all other threads. No other tasks will be scheduled during this + operation. Depending on the size of the data this might take a long time + (several seconds) and cause timeouts in the system. +

+ + + + + + clear() -> ok + Same as clear(node()). +

Same as clear(node()).

 + + + + clear(Node) -> ok + Clears the internal lock statistics from runtime system. + + Node = node() + + +

Clears the internal lock statistics from the runtime system. This does not clear the + data on the server only on runtime system. All counters for static locks are zeroed, + all dynamic locks currently alive are zeroed and all saved locks now destroyed are removed. + It also resets the duration timer. +

+ + + + conflicts() -> ok + Same as conflicts([]). +

Same as conflicts([]).

 + + + conflicts([Option]) -> ok + Prints a list of internal lock counters. + + Option = {sort, Sort} | {reverse, bool()} | {thresholds, [Thresholds]} | {print, [Print | {Print, integer()}]} | {max_locks, MaxLocks} | {combine, bool()} + Sort = name | id | type | tries | colls | ratio | time | entry + Thresholds = {tries, integer()} | {colls, integer()} | {time, integer()} + Print = name | id | type | entry | tries | colls | ratio | time | duration + MaxLocks = integer() | none + + +

Prints a list of internal locks and its statistics.

+

For option description, see lcnt:inspect/2.

+ + + + + locations() -> ok + Same as locations([]). + +

Same as locations([]).

+ + + + locations([Option]) -> ok + Prints a list of internal lock counters by source code locations. + + Option = {sort, Sort} | {thresholds, [Thresholds]} | {print, [Print | {Print, integer()}]} | {max_locks, MaxLocks} | {combine, bool()} + Sort = name | id | type | tries | colls | ratio | time | entry + Thresholds = {tries, integer()} | {colls, integer()} | {time, integer()} + Print = name | id | type | entry | tries | colls | ratio | time | duration + MaxLocks = integer() | none + + +

Prints a list of internal lock counters by source code locations.

+

For option description, see lcnt:inspect/2.

+ + + + + inspect(Lock) -> ok + Same as inspect(Lock, []). +

Same as inspect(Lock, []).

 + + + inspect(Lock, [Option]) -> ok + Prints a list of internal lock counters for a specific lock. + + Lock = Name | {Name, Id | [Id]} + Name = atom() | pid() | port() + Id = atom() | integer() | pid() | port() + Option = {sort, Sort} | {thresholds, [Thresholds]} | {print, [Print | {Print, integer()}]} | {max_locks, MaxLocks} | {combine, bool()} | {locations, bool()} + Sort = name | id | type | tries | colls | ratio | time + Thresholds = {tries, integer()} | {colls, integer()} | {time, integer()} + Print = name | id | type | entry | tries | colls | ratio | time | duration + MaxLocks = integer() | none + + +

Prints a list of internal lock counters for a specific lock.

+

Lock Name and Id for ports and processes are interchangeable with the use of lcnt:swap_pid_keys/0 and is the reason why pid() and port() options can be used in both Name and Id space. Both pids and ports are special identifiers with stripped creation and can be recreated with lcnt:pid/2,3 and lcnt:port/1,2.

+

Option description:

+ + {combine, bool()} + Combine the statistics from different instances of a lock class. +
Default: true + + + {locations, bool()} + Print the statistics by source file and line numbers. +
Default: false + + + {max_locks, MaxLocks} + Maximum number of locks printed or no limit with none. +
Default: 20 + + + {print, PrintOptions} + Printing options: + + name + Named lock or named set of locks (classes). The same name used for initializing the lock in the VM. + + id + Internal id for set of locks, not always unique. This could be table name for ets tables (db_tab), port id for ports, integer identifiers for allocators, etc. + + type + Type of lock: rw_mutex, mutex, spinlock, rw_spinlock or proclock. + + entry + In combination with {locations, true} this option prints the lock operations source file and line number entry-points along with statistics for each entry. + + tries + Number of acquisitions of this lock. + + colls + Number of collisions when a thread tried to acquire this lock. This is when a trylock is EBUSY, a write try on read held rw_lock, a try read on write held rw_lock, a thread tries to lock an already locked lock. (Internal states supervises this). + + ratio + The ratio between the number of collisions and the number of tries (acquisitions) in percentage. + + time + Accumulated waiting time for this lock. This could be greater than actual wall clock time, it is accumulated for all threads. Trylock conflicts does not accumulate time. + + duration + Percentage of accumulated waiting time of wall clock time. This percentage can be higher than 100% since accumulated time is from all threads. + +
Default: [name,id,tries,colls,ratio,time,duration] + + + {reverse, bool()} + Reverses the order of sorting. +
Default: false + + + {sort, Sort} + Column sorting orders. +
Default: time + + + {thresholds, Thresholds} + Filtering thresholds. Anything values above the threshold value are passed through. +
Default: [{tries, 0}, {colls, 0}, {time, 0}] + + + + + + + + + information() -> ok + Prints lcnt server state and generic information about collected lock statistics. + +

Prints lcnt server state and generic information about collected lock statistics.

+ + + + + swap_pid_keys() -> ok + Swaps places on Name and Id space for ports and processes. + +

Swaps places on Name and Id space for ports and processes.

+ + + + + load(Filename) -> ok + Restores previously saved data to the server. + + Filename = filename() + + +

Restores previously saved data to the server.

+ + + + + save(Filename) -> ok + Saves the collected data to file. + + Filename = filename() + + +

Saves the collected data to file.

+ + + + +
+ Convenience functions +

The following functions are used for convenience.

+
+ + + apply(Fun) -> term() + Same as apply(Fun, []). + +

Same as apply(Fun, []).

+ + + + apply(Fun, Args) -> term() + Clears counters, applies function and collects the profiling results. + + Fun = fun() + Args = [term()] + + +

Clears the lock counters and then setups the instrumentation to save all destroyed locks. + After setup the fun is called, passing the elements in Args as arguments. + When the fun returns the statistics are immediately collected to the server. After the + collection the instrumentation is returned to its previous behavior. + The result of the applied fun is returned. +

+ + + + apply(Module, Function, Args) -> term() + Clears counters, applies function and collects the profiling results. + + Module = atom() + Function = atom() + Args = [term()] + + +

Clears the lock counters and then setups the instrumentation to save all destroyed locks. + After setup the function is called, passing the elements in Args as arguments. + When the function returns the statistics are immediately collected to the server. After the + collection the instrumentation is returned to its previous behavior. + The result of the applied function is returned. +

+ + + + + pid(Id, Serial) -> pid() + Same as pid(node(), Id, Serial). +

Same as pid(node(), Id, Serial).

 + + + pid(Node, Id, Serial) -> pid() + Creates a process id with creation 0. + + Node = node() + Id = integer() + Serial = integer() + + +

Creates a process id with creation 0. Example:

+ + + + + port(Id) -> port() + Same as port(node(), Id). +

Same as port(node(), Id).

 + + + port(Node, Id) -> port() + Creates a port id with creation 0. + + Node = node() + Id = integer() + +

Creates a port id with creation 0.

 + + + + +
+ Internal runtime lock counter controllers +

The following functions control the behavior of the internal counters.

+
+ + + + rt_collect() -> [lock_counter_data()] + Same as rt_collect(node()). +

Same as rt_collect(node()).

 + + + rt_collect(Node) -> [lock_counter_data()] + Returns a list of raw lock counter data. + + Node = node() + +

Returns a list of raw lock counter data.

 + + + + rt_clear() -> ok + Same as rt_clear(node()). +

Same as rt_clear(node()).

 + + + rt_clear(Node) -> ok + Clears the internal counters. + + Node = node() + +

Clear the internal counters. Same as lcnt:clear(Node).

 + + + + rt_opt({Type, bool()}) -> bool() + Same as rt_opt(node(), {Type, Opt}). +

Same as rt_opt(node(), {Type, Opt}).

 + + + rt_opt(Node, {Type, bool()}) -> bool() + Changes the lock counter behavior and returns the previous behaviour. + + Node = node() + Type = copy_save | process_locks + + +

Changes the lock counter behavior and returns the previous behaviour.

+

Option description:

+ + {copy_save, bool()} + Enable statistics saving from destroyed locks by copying. This might consume a lot of memory. +
Default: false + + + {process_locks, bool()} + Profile process locks. +
Default: true + + + + + + +
+ See Also +

LCNT User's Guide

+
+ diff --git a/lib/tools/doc/src/lcnt_chapter.xml b/lib/tools/doc/src/lcnt_chapter.xml new file mode 100644 index 0000000000..8f44b23f59 --- /dev/null +++ b/lib/tools/doc/src/lcnt_chapter.xml @@ -0,0 +1,301 @@ + + + + +
+ + 20092010 + Ericsson AB. All Rights Reserved. + + + The contents of this file are subject to the Erlang Public License, + Version 1.1, (the "License"); you may not use this file except in + compliance with the License. You should have received a copy of the + Erlang Public License along with this software. If not, it can be + retrieved online at http://www.erlang.org/. + + Software distributed under the License is distributed on an "AS IS" + basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See + the License for the specific language governing rights and limitations + under the License. + + + + lcnt - The Lock Profiler + Björn-Egil Dahlberg + nobody + + nobody + no + 2009-11-26 + PA1 + lcnt_chapter.xml +
+

+ Internally in the Erlang runtime system locks are used to protect resources from being updated from multiple threads in a fatal way. Locks are necessary + to ensure that the runtime system works properly but it also introduces a couple of limitations. Lock contention and locking overhead. +

+

+ With lock contention we mean when one thread locks a resource and another thread, or threads, tries to acquire the same resource at the same time. The lock will deny + the other thread access to the resource and the thread will be blocked from continuing its execution. The second thread has to wait until the first thread has + completed its access to the resource and unlocked it. The lcnt tool measures these lock conflicts. +

+

+ Locks has an inherent cost in execution time and memory space. It takes time initialize, destroy, aquiring or releasing locks. To decrease lock contention it + some times necessary to use finer grained locking strategies. This will usually also increase the locking overhead and hence there is a tradeoff + between lock contention and overhead. In general, lock contention increases with the number of threads running concurrently. The lcnt tool does not measure locking overhead. +

+
+ Enabling lock-counting +

For investigation of locks in the emulator we use an internal tool called lcnt (short for lock-count). The VM needs to be compiled with this option enabled. To enable this, use:

+ + 
+cd $ERL_TOP
+./configure --enable-lock-counter
+
+ +

+ Another way to enable this alongside a normal VM is to compile it at emulator directory level, much like a debug build. To compile it this way do the following, +

+ 
+cd $ERL_TOP/erts/emulator
+make lcnt FLAVOR=smp
+
+

and then starting Erlang with,

+ 
+$ERL_TOP/bin/cerl -lcnt
+
+

To verify that you lock-counting enabled check that [lock-counting] appears in the status text when the VM is started.

+ 
+Erlang R13B03 (erts-5.7.4) [source] [64-bit] [smp:8:8] [rq:8] [async-threads:0] [hipe]
+ [kernel-poll:false] [lock-counting]
+
+
+
+ Getting started +

Once you have a lock counting enabled VM the module lcnt can be used. The module is intended to be used from the current running nodes shell. To access remote nodes use lcnt:clear(Node) and lcnt:collect(Node).

+ +

All locks are continuously monitored and its statistics updated. Use lcnt:clear/0 to initially clear all counters before running any specific tests. This command will also reset the duration timer internally.

+

To retrieve lock statistics information use, lcnt:collect/0,1. The collect operation will start a lcnt server if it not already started. All collected data will be built into an erlang term and uploaded to the server and a duration time will also be uploaded. This duration is the time between lcnt:clear/0,1 and lcnt:collect/0,1.

+ +

Once the data is collected to the server it can be filtered, sorted and printed in many different ways.

+

See the reference manual for a description of each function.

+
+
+ Example of usage +

From the 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
+
+

+ Another way to to profile a specific function is to use lcnt:apply/3 or lcnt:apply/1 which does lcnt:clear/0 before the function and lcnt:collect/0 after its invocation. + It also sets copy_save to true for the duration of the function call +

+
+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
+
+

The process locks are sorted after its class like all other locks. It is convenient to look at specific processes and ports as classes. We can do this by swapping class and class identifiers with 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
+  <nonode@nohost.660.0>   13493          1.4452         41
+  <nonode@nohost.724.0>   13504          1.1404         36
+  <nonode@nohost.803.0>   13181          1.6235         35
+  <nonode@nohost.791.0>   13534          0.8202         22
+   <nonode@nohost.37.0>    8744          5.8326         22
+  <nonode@nohost.876.0>   13335          1.1174         19
+  <nonode@nohost.637.0>   13452          1.3678         19
+  <nonode@nohost.799.0>   13497          1.8745         18
+  <nonode@nohost.469.0>   11009          2.5343         18
+  <nonode@nohost.862.0>   13131          1.2566         16
+  <nonode@nohost.642.0>   13216          1.7327         15
+  <nonode@nohost.582.0>   13156          1.1098         15
+  <nonode@nohost.622.0>   13420          0.7303         14
+  <nonode@nohost.596.0>   13141          1.6437         14
+  <nonode@nohost.592.0>   13346          1.2064         13
+  <nonode@nohost.526.0>   13076          1.1701         13
+ok
+
+
+
+ Example with Mnesia Transaction Benchmark +

From the 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
+
+

Initial configuring of the benchmark is done. It is time to profile the actual benchmark and 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
+
+

The id header represents the number of unique identifiers under a class when the option {combine, true} is used (which is on by default). It will otherwise show the specific identifier. +The db_tab listing shows 722287 unique locks, it is one for each ets-table created and Mnesia creates one for each transaction. +

+
+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
+ <nonode@nohost.1108.0>      4  4331412          333          0.0077       7148        0.0119
+            timer_wheel      1   203185           30          0.0148       3108        0.0052
+ <nonode@nohost.1110.0>      4  4291098          210          0.0049        885        0.0015
+ <nonode@nohost.1114.0>      4  4294702          288          0.0067        442        0.0007
+ <nonode@nohost.1113.0>      4  4346066          235          0.0054        390        0.0006
+ <nonode@nohost.1106.0>      4  4348159          287          0.0066        379        0.0006
+ <nonode@nohost.1111.0>      4  4279309          290          0.0068        325        0.0005
+ <nonode@nohost.1107.0>      4  4292190          302          0.0070        315        0.0005
+ <nonode@nohost.1112.0>      4  4208858          265          0.0063        276        0.0005
+ <nonode@nohost.1109.0>      4  4377502          267          0.0061        276        0.0005
+ok
+
+

The listing shows mnesia_locker, a process, has highly contended locks.

+
+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
+
+

Listing without class combiner.

+ +
+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
+
+

+In this scenario the lock that protects ets-table mnesia_transient_decision has spent most of its waiting for. That is 1.8 seconds in a test that run for 60 seconds. The time is also spread on eight different scheduler threads. +

+
+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
+
+ +
+
+ Deciphering the output +

Typically high time values are bad and this is often the thing to look for. However, one should also look for high lock acquisition frequencies (#tries) since locks generate overhead and because high frequency could become problematic if they begin to have conflicts even if it is not shown in a particular test.

+
+ +
+ See Also +

LCNT Reference Manual

+
+ diff --git a/lib/tools/doc/src/part.xml b/lib/tools/doc/src/part.xml index 3e02086b80..19f0763410 100644 --- a/lib/tools/doc/src/part.xml +++ b/lib/tools/doc/src/part.xml @@ -55,6 +55,8 @@ instrument Utility functions for obtaining and analysing resource usage in an instrumented Erlang runtime system. + lcnt + A lock profiling tool for the Erlang runtime system. make A make utility for Erlang similar to UNIX make. tags @@ -69,6 +71,7 @@ + diff --git a/lib/tools/doc/src/ref_man.xml b/lib/tools/doc/src/ref_man.xml index aea74e3746..6cd4975075 100644 --- a/lib/tools/doc/src/ref_man.xml +++ b/lib/tools/doc/src/ref_man.xml @@ -51,9 +51,14 @@ Erlang programs. Uses trace to file to minimize runtime performance impact, and displays time for calling and called functions. + instrument Utility functions for obtaining and analysing resource usage in an instrumented Erlang runtime system. + + lcnt + A lock profiling tool for the Erlang runtime system. + make A make utility for Erlang similar to UNIX make. tags @@ -70,6 +75,7 @@ + -- cgit v1.2.3