[thirdparty/linux.git] / Documentation / locking / lockstat.txt


LOCK STATISTICS

- WHAT

As the name suggests, it provides statistics on locks.

- WHY

Because things like lock contention can severely impact performance.

- HOW

Lockdep already has hooks in the lock functions and maps lock instances to
lock classes. We build on that (see Documentation/locking/lockdep-design.txt).
The graph below shows the relation between the lock functions and the various
hooks therein.

        __acquire
            |
           lock _____
            |        \
            |    __contended
            |         |
            |       <wait>
            | _______/
            |/
            |
       __acquired
            |
            .
          <hold>
            .
            |
       __release
            |
         unlock

lock, unlock	- the regular lock functions
__*		- the hooks
<> 		- states

With these hooks we provide the following statistics:

 con-bounces       - number of lock contention that involved x-cpu data
 contentions       - number of lock acquisitions that had to wait
 wait time min     - shortest (non-0) time we ever had to wait for a lock
           max     - longest time we ever had to wait for a lock
	   total   - total time we spend waiting on this lock
	   avg     - average time spent waiting on this lock
 acq-bounces       - number of lock acquisitions that involved x-cpu data
 acquisitions      - number of times we took the lock
 hold time min     - shortest (non-0) time we ever held the lock
	   max     - longest time we ever held the lock
	   total   - total time this lock was held
	   avg     - average time this lock was held

These numbers are gathered per lock class, per read/write state (when
applicable).

It also tracks 4 contention points per class. A contention point is a call site
that had to wait on lock acquisition.

 - CONFIGURATION

Lock statistics are enabled via CONFIG_LOCK_STAT.

 - USAGE

Enable collection of statistics:

# echo 1 >/proc/sys/kernel/lock_stat

Disable collection of statistics:

# echo 0 >/proc/sys/kernel/lock_stat

Look at the current lock statistics:

( line numbers not part of actual output, done for clarity in the explanation
  below )

# less /proc/lock_stat

01 lock_stat version 0.4
02-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
03                              class name    con-bounces    contentions   waittime-min   waittime-max waittime-total   waittime-avg    acq-bounces   acquisitions   holdtime-min   holdtime-max holdtime-total   holdtime-avg
04-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
05
06                         &mm->mmap_sem-W:            46             84           0.26         939.10       16371.53         194.90          47291        2922365           0.16     2220301.69 17464026916.32        5975.99
07                         &mm->mmap_sem-R:            37            100           1.31      299502.61      325629.52        3256.30         212344       34316685           0.10        7744.91    95016910.20           2.77
08                         ---------------
09                           &mm->mmap_sem              1          [<ffffffff811502a7>] khugepaged_scan_mm_slot+0x57/0x280
10                           &mm->mmap_sem             96          [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
11                           &mm->mmap_sem             34          [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
12                           &mm->mmap_sem             17          [<ffffffff81127e71>] vm_munmap+0x41/0x80
13                         ---------------
14                           &mm->mmap_sem              1          [<ffffffff81046fda>] dup_mmap+0x2a/0x3f0
15                           &mm->mmap_sem             60          [<ffffffff81129e29>] SyS_mprotect+0xe9/0x250
16                           &mm->mmap_sem             41          [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
17                           &mm->mmap_sem             68          [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
18
19.............................................................................................................................................................................................................................
20
21                         unix_table_lock:           110            112           0.21          49.24         163.91           1.46          21094          66312           0.12         624.42       31589.81           0.48
22                         ---------------
23                         unix_table_lock             45          [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
24                         unix_table_lock             47          [<ffffffff8150b111>] unix_release_sock+0x31/0x250
25                         unix_table_lock             15          [<ffffffff8150ca37>] unix_find_other+0x117/0x230
26                         unix_table_lock              5          [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0
27                         ---------------
28                         unix_table_lock             39          [<ffffffff8150b111>] unix_release_sock+0x31/0x250
29                         unix_table_lock             49          [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
30                         unix_table_lock             20          [<ffffffff8150ca37>] unix_find_other+0x117/0x230
31                         unix_table_lock              4          [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0


This excerpt shows the first two lock class statistics. Line 01 shows the
output version - each time the format changes this will be updated. Line 02-04
show the header with column descriptions. Lines 05-18 and 20-31 show the actual
statistics. These statistics come in two parts; the actual stats separated by a
short separator (line 08, 13) from the contention points.

Lines 09-12 show the first 4 recorded contention points (the code
which tries to get the lock) and lines 14-17 show the first 4 recorded
contended points (the lock holder). It is possible that the max
con-bounces point is missing in the statistics.

The first lock (05-18) is a read/write lock, and shows two lines above the
short separator. The contention points don't match the column descriptors,
they have two: contentions and [<IP>] symbol. The second set of contention
points are the points we're contending with.

The integer part of the time values is in us.

Dealing with nested locks, subclasses may appear:

32...........................................................................................................................................................................................................................
33
34                               &rq->lock:       13128          13128           0.43         190.53      103881.26           7.91          97454        3453404           0.00         401.11    13224683.11           3.82
35                               ---------
36                               &rq->lock          645          [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
37                               &rq->lock          297          [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
38                               &rq->lock          360          [<ffffffff8103c4c5>] select_task_rq_fair+0x1f0/0x74a
39                               &rq->lock          428          [<ffffffff81045f98>] scheduler_tick+0x46/0x1fb
40                               ---------
41                               &rq->lock           77          [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
42                               &rq->lock          174          [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
43                               &rq->lock         4715          [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
44                               &rq->lock          893          [<ffffffff81340524>] schedule+0x157/0x7b8
45
46...........................................................................................................................................................................................................................
47
48                             &rq->lock/1:        1526          11488           0.33         388.73      136294.31          11.86          21461          38404           0.00          37.93      109388.53           2.84
49                             -----------
50                             &rq->lock/1        11526          [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
51                             -----------
52                             &rq->lock/1         5645          [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
53                             &rq->lock/1         1224          [<ffffffff81340524>] schedule+0x157/0x7b8
54                             &rq->lock/1         4336          [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
55                             &rq->lock/1          181          [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a

Line 48 shows statistics for the second subclass (/1) of &rq->lock class
(subclass starts from 0), since in this case, as line 50 suggests,
double_rq_lock actually acquires a nested lock of two spinlocks.

View the top contending locks:

# grep : /proc/lock_stat | head
			clockevents_lock:       2926159        2947636           0.15       46882.81  1784540466.34         605.41        3381345        3879161           0.00        2260.97    53178395.68          13.71
		     tick_broadcast_lock:        346460         346717           0.18        2257.43    39364622.71         113.54        3642919        4242696           0.00        2263.79    49173646.60          11.59
		  &mapping->i_mmap_mutex:        203896         203899           3.36      645530.05 31767507988.39      155800.21        3361776        8893984           0.17        2254.15    14110121.02           1.59
			       &rq->lock:        135014         136909           0.18         606.09      842160.68           6.15        1540728       10436146           0.00         728.72    17606683.41           1.69
	       &(&zone->lru_lock)->rlock:         93000          94934           0.16          59.18      188253.78           1.98        1199912        3809894           0.15         391.40     3559518.81           0.93
			 tasklist_lock-W:         40667          41130           0.23        1189.42      428980.51          10.43         270278         510106           0.16         653.51     3939674.91           7.72
			 tasklist_lock-R:         21298          21305           0.20        1310.05      215511.12          10.12         186204         241258           0.14        1162.33     1179779.23           4.89
			      rcu_node_1:         47656          49022           0.16         635.41      193616.41           3.95         844888        1865423           0.00         764.26     1656226.96           0.89
       &(&dentry->d_lockref.lock)->rlock:         39791          40179           0.15        1302.08       88851.96           2.21        2790851       12527025           0.10        1910.75     3379714.27           0.27
			      rcu_node_0:         29203          30064           0.16         786.55     1555573.00          51.74          88963         244254           0.00         398.87      428872.51           1.76

Clear the statistics:

# echo 0 > /proc/lock_stat
Commit	Line	Data
a560aa48 PZ	1
	2	LOCK STATISTICS
	3
	4	- WHAT
	5
	6	As the name suggests, it provides statistics on locks.
	7
	8	- WHY
	9
	10	Because things like lock contention can severely impact performance.
	11
	12	- HOW
	13
	14	Lockdep already has hooks in the lock functions and maps lock instances to
e58cdf58	15	lock classes. We build on that (see Documentation/locking/lockdep-design.txt).
f62508f6 JL	16	The graph below shows the relation between the lock functions and the various
f62508f6 JL	17	hooks therein.
a560aa48 PZ	18
	19	__acquire
	20	\|
	21	lock _____
	22	\| \
	23	\| __contended
	24	\| \|
	25	\| <wait>
	26	\| _______/
	27	\|/
	28	\|
	29	__acquired
	30	\|
	31	.
	32	<hold>
	33	.
	34	\|
	35	__release
	36	\|
	37	unlock
	38
	39	lock, unlock - the regular lock functions
	40	__* - the hooks
	41	<> - states
	42
	43	With these hooks we provide the following statistics:
	44
	45	con-bounces - number of lock contention that involved x-cpu data
	46	contentions - number of lock acquisitions that had to wait
	47	wait time min - shortest (non-0) time we ever had to wait for a lock
	48	max - longest time we ever had to wait for a lock
1232e380 DB	49	total - total time we spend waiting on this lock
1232e380 DB	50	avg - average time spent waiting on this lock
a560aa48 PZ	51	acq-bounces - number of lock acquisitions that involved x-cpu data
	52	acquisitions - number of times we took the lock
	53	hold time min - shortest (non-0) time we ever held the lock
1232e380 DB	54	max - longest time we ever held the lock
	55	total - total time this lock was held
	56	avg - average time this lock was held
a560aa48 PZ	57
	58	These numbers are gathered per lock class, per read/write state (when
	59	applicable).
	60
	61	It also tracks 4 contention points per class. A contention point is a call site
	62	that had to wait on lock acquisition.
	63
f5754bfd FR	64	- CONFIGURATION
f5754bfd FR	65
0be5c8ff	66	Lock statistics are enabled via CONFIG_LOCK_STAT.
f5754bfd	67
a560aa48 PZ	68	- USAGE
a560aa48 PZ	69
f5754bfd FR	70	Enable collection of statistics:
	71
	72	# echo 1 >/proc/sys/kernel/lock_stat
	73
	74	Disable collection of statistics:
	75
	76	# echo 0 >/proc/sys/kernel/lock_stat
	77
a560aa48 PZ	78	Look at the current lock statistics:
	79
	80	( line numbers not part of actual output, done for clarity in the explanation
	81	below )
	82
	83	# less /proc/lock_stat
	84
1232e380 DB	85	01 lock_stat version 0.4
	86	02-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
	87	03 class name con-bounces contentions waittime-min waittime-max waittime-total waittime-avg acq-bounces acquisitions holdtime-min holdtime-max holdtime-total holdtime-avg
	88	04-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
a560aa48	89	05
1232e380 DB	90	06 &mm->mmap_sem-W: 46 84 0.26 939.10 16371.53 194.90 47291 2922365 0.16 2220301.69 17464026916.32 5975.99
	91	07 &mm->mmap_sem-R: 37 100 1.31 299502.61 325629.52 3256.30 212344 34316685 0.10 7744.91 95016910.20 2.77
	92	08 ---------------
	93	09 &mm->mmap_sem 1 [<ffffffff811502a7>] khugepaged_scan_mm_slot+0x57/0x280
bccb484b	94	10 &mm->mmap_sem 96 [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
1232e380 DB	95	11 &mm->mmap_sem 34 [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
	96	12 &mm->mmap_sem 17 [<ffffffff81127e71>] vm_munmap+0x41/0x80
	97	13 ---------------
	98	14 &mm->mmap_sem 1 [<ffffffff81046fda>] dup_mmap+0x2a/0x3f0
	99	15 &mm->mmap_sem 60 [<ffffffff81129e29>] SyS_mprotect+0xe9/0x250
	100	16 &mm->mmap_sem 41 [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
	101	17 &mm->mmap_sem 68 [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
c7e78cff	102	18
1232e380	103	19.............................................................................................................................................................................................................................
c7e78cff	104	20
1232e380 DB	105	21 unix_table_lock: 110 112 0.21 49.24 163.91 1.46 21094 66312 0.12 624.42 31589.81 0.48
	106	22 ---------------
	107	23 unix_table_lock 45 [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
	108	24 unix_table_lock 47 [<ffffffff8150b111>] unix_release_sock+0x31/0x250
	109	25 unix_table_lock 15 [<ffffffff8150ca37>] unix_find_other+0x117/0x230
	110	26 unix_table_lock 5 [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0
	111	27 ---------------
	112	28 unix_table_lock 39 [<ffffffff8150b111>] unix_release_sock+0x31/0x250
	113	29 unix_table_lock 49 [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
	114	30 unix_table_lock 20 [<ffffffff8150ca37>] unix_find_other+0x117/0x230
	115	31 unix_table_lock 4 [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0
	116
a560aa48 PZ	117
	118	This excerpt shows the first two lock class statistics. Line 01 shows the
	119	output version - each time the format changes this will be updated. Line 02-04
c7e78cff	120	show the header with column descriptions. Lines 05-18 and 20-31 show the actual
a560aa48	121	statistics. These statistics come in two parts; the actual stats separated by a
c7e78cff	122	short separator (line 08, 13) from the contention points.
a560aa48	123
7b7e1b7b DW	124	Lines 09-12 show the first 4 recorded contention points (the code
	125	which tries to get the lock) and lines 14-17 show the first 4 recorded
	126	contended points (the lock holder). It is possible that the max
	127	con-bounces point is missing in the statistics.
	128
c7e78cff	129	The first lock (05-18) is a read/write lock, and shows two lines above the
a560aa48	130	short separator. The contention points don't match the column descriptors,
c7e78cff PZ	131	they have two: contentions and [<IP>] symbol. The second set of contention
c7e78cff PZ	132	points are the points we're contending with.
a560aa48	133
cdad7220	134	The integer part of the time values is in us.
a560aa48	135
f62508f6 JL	136	Dealing with nested locks, subclasses may appear:
f62508f6 JL	137
1232e380	138	32...........................................................................................................................................................................................................................
f62508f6	139	33
1232e380	140	34 &rq->lock: 13128 13128 0.43 190.53 103881.26 7.91 97454 3453404 0.00 401.11 13224683.11 3.82
f62508f6	141	35 ---------
1232e380 DB	142	36 &rq->lock 645 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
	143	37 &rq->lock 297 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
	144	38 &rq->lock 360 [<ffffffff8103c4c5>] select_task_rq_fair+0x1f0/0x74a
	145	39 &rq->lock 428 [<ffffffff81045f98>] scheduler_tick+0x46/0x1fb
f62508f6	146	40 ---------
1232e380 DB	147	41 &rq->lock 77 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
	148	42 &rq->lock 174 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
	149	43 &rq->lock 4715 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
	150	44 &rq->lock 893 [<ffffffff81340524>] schedule+0x157/0x7b8
f62508f6	151	45
1232e380	152	46...........................................................................................................................................................................................................................
f62508f6	153	47
1232e380	154	48 &rq->lock/1: 1526 11488 0.33 388.73 136294.31 11.86 21461 38404 0.00 37.93 109388.53 2.84
f62508f6	155	49 -----------
1232e380	156	50 &rq->lock/1 11526 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
f62508f6	157	51 -----------
1232e380 DB	158	52 &rq->lock/1 5645 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
	159	53 &rq->lock/1 1224 [<ffffffff81340524>] schedule+0x157/0x7b8
	160	54 &rq->lock/1 4336 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
	161	55 &rq->lock/1 181 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
f62508f6 JL	162
	163	Line 48 shows statistics for the second subclass (/1) of &rq->lock class
	164	(subclass starts from 0), since in this case, as line 50 suggests,
	165	double_rq_lock actually acquires a nested lock of two spinlocks.
	166
a560aa48 PZ	167	View the top contending locks:
	168
	169	# grep : /proc/lock_stat \| head
1232e380 DB	170	clockevents_lock: 2926159 2947636 0.15 46882.81 1784540466.34 605.41 3381345 3879161 0.00 2260.97 53178395.68 13.71
	171	tick_broadcast_lock: 346460 346717 0.18 2257.43 39364622.71 113.54 3642919 4242696 0.00 2263.79 49173646.60 11.59
	172	&mapping->i_mmap_mutex: 203896 203899 3.36 645530.05 31767507988.39 155800.21 3361776 8893984 0.17 2254.15 14110121.02 1.59
	173	&rq->lock: 135014 136909 0.18 606.09 842160.68 6.15 1540728 10436146 0.00 728.72 17606683.41 1.69
	174	&(&zone->lru_lock)->rlock: 93000 94934 0.16 59.18 188253.78 1.98 1199912 3809894 0.15 391.40 3559518.81 0.93
	175	tasklist_lock-W: 40667 41130 0.23 1189.42 428980.51 10.43 270278 510106 0.16 653.51 3939674.91 7.72
	176	tasklist_lock-R: 21298 21305 0.20 1310.05 215511.12 10.12 186204 241258 0.14 1162.33 1179779.23 4.89
	177	rcu_node_1: 47656 49022 0.16 635.41 193616.41 3.95 844888 1865423 0.00 764.26 1656226.96 0.89
	178	&(&dentry->d_lockref.lock)->rlock: 39791 40179 0.15 1302.08 88851.96 2.21 2790851 12527025 0.10 1910.75 3379714.27 0.27
	179	rcu_node_0: 29203 30064 0.16 786.55 1555573.00 51.74 88963 244254 0.00 398.87 428872.51 1.76
a560aa48 PZ	180
	181	Clear the statistics:
	182
	183	# echo 0 > /proc/lock_stat