Root/Documentation/lockstat.txt

1
2LOCK STATISTICS
3
4- WHAT
5
6As the name suggests, it provides statistics on locks.
7
8- WHY
9
10Because things like lock contention can severely impact performance.
11
12- HOW
13
14Lockdep already has hooks in the lock functions and maps lock instances to
15lock classes. We build on that (see Documentation/lockdep-design.txt).
16The graph below shows the relation between the lock functions and the various
17hooks therein.
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
39lock, unlock - the regular lock functions
40__* - the hooks
41<> - states
42
43With 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
49           total - total time we spend waiting on this lock
50 acq-bounces - number of lock acquisitions that involved x-cpu data
51 acquisitions - number of times we took the lock
52 hold time min - shortest (non-0) time we ever held the lock
53           max - longest time we ever held the lock
54           total - total time this lock was held
55
56From these number various other statistics can be derived, such as:
57
58 hold time average = hold time total / acquisitions
59
60These numbers are gathered per lock class, per read/write state (when
61applicable).
62
63It also tracks 4 contention points per class. A contention point is a call site
64that had to wait on lock acquisition.
65
66 - CONFIGURATION
67
68Lock statistics are enabled via CONFIG_LOCK_STATS.
69
70 - USAGE
71
72Enable collection of statistics:
73
74# echo 1 >/proc/sys/kernel/lock_stat
75
76Disable collection of statistics:
77
78# echo 0 >/proc/sys/kernel/lock_stat
79
80Look at the current lock statistics:
81
82( line numbers not part of actual output, done for clarity in the explanation
83  below )
84
85# less /proc/lock_stat
86
8701 lock_stat version 0.3
8802 -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
8903 class name con-bounces contentions waittime-min waittime-max waittime-total acq-bounces acquisitions holdtime-min holdtime-max holdtime-total
9004 -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
9105
9206 &mm->mmap_sem-W: 233 538 18446744073708 22924.27 607243.51 1342 45806 1.71 8595.89 1180582.34
9307 &mm->mmap_sem-R: 205 587 18446744073708 28403.36 731975.00 1940 412426 0.58 187825.45 6307502.88
9408 ---------------
9509 &mm->mmap_sem 487 [<ffffffff8053491f>] do_page_fault+0x466/0x928
9610 &mm->mmap_sem 179 [<ffffffff802a6200>] sys_mprotect+0xcd/0x21d
9711 &mm->mmap_sem 279 [<ffffffff80210a57>] sys_mmap+0x75/0xce
9812 &mm->mmap_sem 76 [<ffffffff802a490b>] sys_munmap+0x32/0x59
9913 ---------------
10014 &mm->mmap_sem 270 [<ffffffff80210a57>] sys_mmap+0x75/0xce
10115 &mm->mmap_sem 431 [<ffffffff8053491f>] do_page_fault+0x466/0x928
10216 &mm->mmap_sem 138 [<ffffffff802a490b>] sys_munmap+0x32/0x59
10317 &mm->mmap_sem 145 [<ffffffff802a6200>] sys_mprotect+0xcd/0x21d
10418
10519 ...............................................................................................................................................................................................
10620
10721 dcache_lock: 621 623 0.52 118.26 1053.02 6745 91930 0.29 316.29 118423.41
10822 -----------
10923 dcache_lock 179 [<ffffffff80378274>] _atomic_dec_and_lock+0x34/0x54
11024 dcache_lock 113 [<ffffffff802cc17b>] d_alloc+0x19a/0x1eb
11125 dcache_lock 99 [<ffffffff802ca0dc>] d_rehash+0x1b/0x44
11226 dcache_lock 104 [<ffffffff802cbca0>] d_instantiate+0x36/0x8a
11327 -----------
11428 dcache_lock 192 [<ffffffff80378274>] _atomic_dec_and_lock+0x34/0x54
11529 dcache_lock 98 [<ffffffff802ca0dc>] d_rehash+0x1b/0x44
11630 dcache_lock 72 [<ffffffff802cc17b>] d_alloc+0x19a/0x1eb
11731 dcache_lock 112 [<ffffffff802cbca0>] d_instantiate+0x36/0x8a
118
119This excerpt shows the first two lock class statistics. Line 01 shows the
120output version - each time the format changes this will be updated. Line 02-04
121show the header with column descriptions. Lines 05-18 and 20-31 show the actual
122statistics. These statistics come in two parts; the actual stats separated by a
123short separator (line 08, 13) from the contention points.
124
125The first lock (05-18) is a read/write lock, and shows two lines above the
126short separator. The contention points don't match the column descriptors,
127they have two: contentions and [<IP>] symbol. The second set of contention
128points are the points we're contending with.
129
130The integer part of the time values is in us.
131
132Dealing with nested locks, subclasses may appear:
133
13432...............................................................................................................................................................................................
13533
13634 &rq->lock: 13128 13128 0.43 190.53 103881.26 97454 3453404 0.00 401.11 13224683.11
13735 ---------
13836 &rq->lock 645 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
13937 &rq->lock 297 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
14038 &rq->lock 360 [<ffffffff8103c4c5>] select_task_rq_fair+0x1f0/0x74a
14139 &rq->lock 428 [<ffffffff81045f98>] scheduler_tick+0x46/0x1fb
14240 ---------
14341 &rq->lock 77 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
14442 &rq->lock 174 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
14543 &rq->lock 4715 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
14644 &rq->lock 893 [<ffffffff81340524>] schedule+0x157/0x7b8
14745
14846...............................................................................................................................................................................................
14947
15048 &rq->lock/1: 11526 11488 0.33 388.73 136294.31 21461 38404 0.00 37.93 109388.53
15149 -----------
15250 &rq->lock/1 11526 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
15351 -----------
15452 &rq->lock/1 5645 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
15553 &rq->lock/1 1224 [<ffffffff81340524>] schedule+0x157/0x7b8
15654 &rq->lock/1 4336 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
15755 &rq->lock/1 181 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
158
159Line 48 shows statistics for the second subclass (/1) of &rq->lock class
160(subclass starts from 0), since in this case, as line 50 suggests,
161double_rq_lock actually acquires a nested lock of two spinlocks.
162
163View the top contending locks:
164
165# grep : /proc/lock_stat | head
166              &inode->i_data.tree_lock-W: 15 21657 0.18 1093295.30 11547131054.85 58 10415 0.16 87.51 6387.60
167              &inode->i_data.tree_lock-R: 0 0 0.00 0.00 0.00 23302 231198 0.25 8.45 98023.38
168                             dcache_lock: 1037 1161 0.38 45.32 774.51 6611 243371 0.15 306.48 77387.24
169                         &inode->i_mutex: 161 286 18446744073709 62882.54 1244614.55 3653 20598 18446744073709 62318.60 1693822.74
170                         &zone->lru_lock: 94 94 0.53 7.33 92.10 4366 32690 0.29 59.81 16350.06
171              &inode->i_data.i_mmap_mutex: 79 79 0.40 3.77 53.03 11779 87755 0.28 116.93 29898.44
172                        &q->__queue_lock: 48 50 0.52 31.62 86.31 774 13131 0.17 113.08 12277.52
173                        &rq->rq_lock_key: 43 47 0.74 68.50 170.63 3706 33929 0.22 107.99 17460.62
174                      &rq->rq_lock_key#2: 39 46 0.75 6.68 49.03 2979 32292 0.17 125.17 17137.63
175                         tasklist_lock-W: 15 15 1.45 10.87 32.70 1201 7390 0.58 62.55 13648.47
176
177Clear the statistics:
178
179# echo 0 > /proc/lock_stat
180

Archive Download this file



interactive