Kernel-4.18.0-80.el8_lockstat

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 [] khugepaged_scan_mm_slot+0x57/0x280
19 &mm->mmap_sem 96 [] __do_page_fault+0x1d4/0x510
11 &mm->mmap_sem 34 [] vm_mmap_pgoff+0x87/0xd0
12 &mm->mmap_sem 17 [] vm_munmap+0x41/0x80
13 —————
14 &mm->mmap_sem 1 [] dup_mmap+0x2a/0x3f0
15 &mm->mmap_sem 60 [] SyS_mprotect+0xe9/0x250
16 &mm->mmap_sem 41 [] __do_page_fault+0x1d4/0x510
17 &mm->mmap_sem 68 [] 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 [] unix_create1+0x16e/0x1b0
24 unix_table_lock 47 [] unix_release_sock+0x31/0x250
25 unix_table_lock 15 [] unix_find_other+0x117/0x230
26 unix_table_lock 5 [] unix_autobind+0x11f/0x1b0
27 —————
28 unix_table_lock 39 [] unix_release_sock+0x31/0x250
29 unix_table_lock 49 [] unix_create1+0x16e/0x1b0
30 unix_table_lock 20 [] unix_find_other+0x117/0x230
31 unix_table_lock 4 [] 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 [] 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 [] task_rq_lock+0x43/0x75
37 &rq->lock 297 [] try_to_wake_up+0x127/0x25a
38 &rq->lock 360 [] select_task_rq_fair+0x1f0/0x74a
39 &rq->lock 428 [] scheduler_tick+0x46/0x1fb
40 ———
41 &rq->lock 77 [] task_rq_lock+0x43/0x75
42 &rq->lock 174 [] try_to_wake_up+0x127/0x25a
43 &rq->lock 4715 [] double_rq_lock+0x42/0x54
44 &rq->lock 893 [] 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 [] double_rq_lock+0x4f/0x54
51 ———–
52 &rq->lock/1 5645 [] double_rq_lock+0x42/0x54
53 &rq->lock/1 1224 [] schedule+0x157/0x7b8
54 &rq->lock/1 4336 [] double_rq_lock+0x4f/0x54
55 &rq->lock/1 181 [] 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