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_STAT. 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