aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorDavidlohr Bueso <davidlohr@hp.com>2013-10-08 23:37:16 -0400
committerIngo Molnar <mingo@kernel.org>2013-10-09 02:19:08 -0400
commit1232e3807f597748d437ab8680873af21fa81da9 (patch)
tree71761745e731220a8e2e971e1a093ab227732f06
parent2a929242ee50db84c1a561c81897bb0551f2c32f (diff)
lockstat: Report avg wait and hold times
While both the nr and total times are showed, having the avg lock hold and wait times show in the report is quite useful when working on performance related issues. Furthermore, I find myself constantly doing the calculations manually. In addition, some of the documentation examples were changed to easily update them to show the two new columns. No textual change otherwise, as descriptions match the lockstat output. Signed-off-by: Davidlohr Bueso <davidlohr@hp.com> Cc: aswin@hp.com Cc: Peter Zijlstra <peterz@infradead.org> Link: http://lkml.kernel.org/r/1380746928.2313.14.camel@buesod1.americas.hpqcorp.net [ Fixlets: changed a seq_printf() to seq_puts(), converted spaces to tabs. ] Signed-off-by: Ingo Molnar <mingo@kernel.org>
Diffstat
-rw-r--r--Documentation/lockstat.txt123
-rw-r--r--kernel/lockdep_proc.c15
2 files changed, 70 insertions, 68 deletions
diff --git a/Documentation/lockstat.txt b/Documentation/lockstat.txt
index dd2f7b26ca30..72d010689751 100644
--- a/Documentation/lockstat.txt
+++ b/Documentation/lockstat.txt
@@ -46,16 +46,14 @@ With these hooks we provide the following statistics:
46 contentions - number of lock acquisitions that had to wait 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 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 48 max - longest time we ever had to wait for a lock
49 total - total time we spend waiting on this lock 49 total - total time we spend waiting on this lock
50 avg - average time spent waiting on this lock
50 acq-bounces - number of lock acquisitions that involved x-cpu data 51 acq-bounces - number of lock acquisitions that involved x-cpu data
51 acquisitions - number of times we took the lock 52 acquisitions - number of times we took the lock
52 hold time min - shortest (non-0) time we ever held the lock 53 hold time min - shortest (non-0) time we ever held the lock
53 max - longest time we ever held the lock 54 max - longest time we ever held the lock
54 total - total time this lock was held 55 total - total time this lock was held
55 56 avg - average time this lock was held
56From these number various other statistics can be derived, such as:
57
58 hold time average = hold time total / acquisitions
59 57
60These numbers are gathered per lock class, per read/write state (when 58These numbers are gathered per lock class, per read/write state (when
61applicable). 59applicable).
@@ -84,37 +82,38 @@ Look at the current lock statistics:
84 82
85# less /proc/lock_stat 83# less /proc/lock_stat
86 84
8701 lock_stat version 0.3 8501 lock_stat version 0.4
8802 ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 8602-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
8903 class name con-bounces contentions waittime-min waittime-max waittime-total acq-bounces acquisitions holdtime-min holdtime-max holdtime-total 8703 class name con-bounces contentions waittime-min waittime-max waittime-total waittime-avg acq-bounces acquisitions holdtime-min holdtime-max holdtime-total holdtime-avg
9004 ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 8804-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
9105 8905
9206 &mm->mmap_sem-W: 233 538 18446744073708 22924.27 607243.51 1342 45806 1.71 8595.89 1180582.34 9006 &mm->mmap_sem-W: 46 84 0.26 939.10 16371.53 194.90 47291 2922365 0.16 2220301.69 17464026916.32 5975.99
9307 &mm->mmap_sem-R: 205 587 18446744073708 28403.36 731975.00 1940 412426 0.58 187825.45 6307502.88 9107 &mm->mmap_sem-R: 37 100 1.31 299502.61 325629.52 3256.30 212344 34316685 0.10 7744.91 95016910.20 2.77
9408 --------------- 9208 ---------------
9509 &mm->mmap_sem 487 [<ffffffff8053491f>] do_page_fault+0x466/0x928 9309 &mm->mmap_sem 1 [<ffffffff811502a7>] khugepaged_scan_mm_slot+0x57/0x280
9610 &mm->mmap_sem 179 [<ffffffff802a6200>] sys_mprotect+0xcd/0x21d 9419 &mm->mmap_sem 96 [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
9711 &mm->mmap_sem 279 [<ffffffff80210a57>] sys_mmap+0x75/0xce 9511 &mm->mmap_sem 34 [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
9812 &mm->mmap_sem 76 [<ffffffff802a490b>] sys_munmap+0x32/0x59 9612 &mm->mmap_sem 17 [<ffffffff81127e71>] vm_munmap+0x41/0x80
9913 --------------- 9713 ---------------
10014 &mm->mmap_sem 270 [<ffffffff80210a57>] sys_mmap+0x75/0xce 9814 &mm->mmap_sem 1 [<ffffffff81046fda>] dup_mmap+0x2a/0x3f0
10115 &mm->mmap_sem 431 [<ffffffff8053491f>] do_page_fault+0x466/0x928 9915 &mm->mmap_sem 60 [<ffffffff81129e29>] SyS_mprotect+0xe9/0x250
10216 &mm->mmap_sem 138 [<ffffffff802a490b>] sys_munmap+0x32/0x59 10016 &mm->mmap_sem 41 [<ffffffff815351c4>] __do_page_fault+0x1d4/0x510
10317 &mm->mmap_sem 145 [<ffffffff802a6200>] sys_mprotect+0xcd/0x21d 10117 &mm->mmap_sem 68 [<ffffffff81113d77>] vm_mmap_pgoff+0x87/0xd0
10418 10218
10519 ............................................................................................................................................................................................... 10319.............................................................................................................................................................................................................................
10620 10420
10721 dcache_lock: 621 623 0.52 118.26 1053.02 6745 91930 0.29 316.29 118423.41 10521 unix_table_lock: 110 112 0.21 49.24 163.91 1.46 21094 66312 0.12 624.42 31589.81 0.48
10822 ----------- 10622 ---------------
10923 dcache_lock 179 [<ffffffff80378274>] _atomic_dec_and_lock+0x34/0x54 10723 unix_table_lock 45 [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
11024 dcache_lock 113 [<ffffffff802cc17b>] d_alloc+0x19a/0x1eb 10824 unix_table_lock 47 [<ffffffff8150b111>] unix_release_sock+0x31/0x250
11125 dcache_lock 99 [<ffffffff802ca0dc>] d_rehash+0x1b/0x44 10925 unix_table_lock 15 [<ffffffff8150ca37>] unix_find_other+0x117/0x230
11226 dcache_lock 104 [<ffffffff802cbca0>] d_instantiate+0x36/0x8a 11026 unix_table_lock 5 [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0
11327 ----------- 11127 ---------------
11428 dcache_lock 192 [<ffffffff80378274>] _atomic_dec_and_lock+0x34/0x54 11228 unix_table_lock 39 [<ffffffff8150b111>] unix_release_sock+0x31/0x250
11529 dcache_lock 98 [<ffffffff802ca0dc>] d_rehash+0x1b/0x44 11329 unix_table_lock 49 [<ffffffff8150ad8e>] unix_create1+0x16e/0x1b0
11630 dcache_lock 72 [<ffffffff802cc17b>] d_alloc+0x19a/0x1eb 11430 unix_table_lock 20 [<ffffffff8150ca37>] unix_find_other+0x117/0x230
11731 dcache_lock 112 [<ffffffff802cbca0>] d_instantiate+0x36/0x8a 11531 unix_table_lock 4 [<ffffffff8150a09f>] unix_autobind+0x11f/0x1b0
116
118 117
119This excerpt shows the first two lock class statistics. Line 01 shows the 118This 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 119output version - each time the format changes this will be updated. Line 02-04
@@ -131,30 +130,30 @@ The integer part of the time values is in us.
131 130
132Dealing with nested locks, subclasses may appear: 131Dealing with nested locks, subclasses may appear:
133 132
13432............................................................................................................................................................................................... 13332...........................................................................................................................................................................................................................
13533 13433
13634 &rq->lock: 13128 13128 0.43 190.53 103881.26 97454 3453404 0.00 401.11 13224683.11 13534 &rq->lock: 13128 13128 0.43 190.53 103881.26 7.91 97454 3453404 0.00 401.11 13224683.11 3.82
13735 --------- 13635 ---------
13836 &rq->lock 645 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75 13736 &rq->lock 645 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
13937 &rq->lock 297 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a 13837 &rq->lock 297 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
14038 &rq->lock 360 [<ffffffff8103c4c5>] select_task_rq_fair+0x1f0/0x74a 13938 &rq->lock 360 [<ffffffff8103c4c5>] select_task_rq_fair+0x1f0/0x74a
14139 &rq->lock 428 [<ffffffff81045f98>] scheduler_tick+0x46/0x1fb 14039 &rq->lock 428 [<ffffffff81045f98>] scheduler_tick+0x46/0x1fb
14240 --------- 14140 ---------
14341 &rq->lock 77 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75 14241 &rq->lock 77 [<ffffffff8103bfc4>] task_rq_lock+0x43/0x75
14442 &rq->lock 174 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a 14342 &rq->lock 174 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
14543 &rq->lock 4715 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54 14443 &rq->lock 4715 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
14644 &rq->lock 893 [<ffffffff81340524>] schedule+0x157/0x7b8 14544 &rq->lock 893 [<ffffffff81340524>] schedule+0x157/0x7b8
14745 14645
14846............................................................................................................................................................................................... 14746...........................................................................................................................................................................................................................
14947 14847
15048 &rq->lock/1: 11526 11488 0.33 388.73 136294.31 21461 38404 0.00 37.93 109388.53 14948 &rq->lock/1: 1526 11488 0.33 388.73 136294.31 11.86 21461 38404 0.00 37.93 109388.53 2.84
15149 ----------- 15049 -----------
15250 &rq->lock/1 11526 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54 15150 &rq->lock/1 11526 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
15351 ----------- 15251 -----------
15452 &rq->lock/1 5645 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54 15352 &rq->lock/1 5645 [<ffffffff8103ed4b>] double_rq_lock+0x42/0x54
15553 &rq->lock/1 1224 [<ffffffff81340524>] schedule+0x157/0x7b8 15453 &rq->lock/1 1224 [<ffffffff81340524>] schedule+0x157/0x7b8
15654 &rq->lock/1 4336 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54 15554 &rq->lock/1 4336 [<ffffffff8103ed58>] double_rq_lock+0x4f/0x54
15755 &rq->lock/1 181 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a 15655 &rq->lock/1 181 [<ffffffff8104ba65>] try_to_wake_up+0x127/0x25a
158 157
159Line 48 shows statistics for the second subclass (/1) of &rq->lock class 158Line 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, 159(subclass starts from 0), since in this case, as line 50 suggests,
@@ -163,16 +162,16 @@ double_rq_lock actually acquires a nested lock of two spinlocks.
163View the top contending locks: 162View the top contending locks:
164 163
165# grep : /proc/lock_stat | head 164# 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 165 clockevents_lock: 2926159 2947636 0.15 46882.81 1784540466.34 605.41 3381345 3879161 0.00 2260.97 53178395.68 13.71
167 &inode->i_data.tree_lock-R: 0 0 0.00 0.00 0.00 23302 231198 0.25 8.45 98023.38 166 tick_broadcast_lock: 346460 346717 0.18 2257.43 39364622.71 113.54 3642919 4242696 0.00 2263.79 49173646.60 11.59
168 dcache_lock: 1037 1161 0.38 45.32 774.51 6611 243371 0.15 306.48 77387.24 167 &mapping->i_mmap_mutex: 203896 203899 3.36 645530.05 31767507988.39 155800.21 3361776 8893984 0.17 2254.15 14110121.02 1.59
169 &inode->i_mutex: 161 286 18446744073709 62882.54 1244614.55 3653 20598 18446744073709 62318.60 1693822.74 168 &rq->lock: 135014 136909 0.18 606.09 842160.68 6.15 1540728 10436146 0.00 728.72 17606683.41 1.69
170 &zone->lru_lock: 94 94 0.53 7.33 92.10 4366 32690 0.29 59.81 16350.06 169 &(&zone->lru_lock)->rlock: 93000 94934 0.16 59.18 188253.78 1.98 1199912 3809894 0.15 391.40 3559518.81 0.93
171 &inode->i_data.i_mmap_mutex: 79 79 0.40 3.77 53.03 11779 87755 0.28 116.93 29898.44 170 tasklist_lock-W: 40667 41130 0.23 1189.42 428980.51 10.43 270278 510106 0.16 653.51 3939674.91 7.72
172 &q->__queue_lock: 48 50 0.52 31.62 86.31 774 13131 0.17 113.08 12277.52 171 tasklist_lock-R: 21298 21305 0.20 1310.05 215511.12 10.12 186204 241258 0.14 1162.33 1179779.23 4.89
173 &rq->rq_lock_key: 43 47 0.74 68.50 170.63 3706 33929 0.22 107.99 17460.62 172 rcu_node_1: 47656 49022 0.16 635.41 193616.41 3.95 844888 1865423 0.00 764.26 1656226.96 0.89
174 &rq->rq_lock_key#2: 39 46 0.75 6.68 49.03 2979 32292 0.17 125.17 17137.63 173 &(&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
175 tasklist_lock-W: 15 15 1.45 10.87 32.70 1201 7390 0.58 62.55 13648.47 174 rcu_node_0: 29203 30064 0.16 786.55 1555573.00 51.74 88963 244254 0.00 398.87 428872.51 1.76
176 175
177Clear the statistics: 176Clear the statistics:
178 177
diff --git a/kernel/lockdep_proc.c b/kernel/lockdep_proc.c
index b2c71c5873e4..09220656d888 100644
--- a/kernel/lockdep_proc.c
+++ b/kernel/lockdep_proc.c
@@ -421,6 +421,7 @@ static void seq_lock_time(struct seq_file *m, struct lock_time *lt)
421 seq_time(m, lt->min); 421 seq_time(m, lt->min);
422 seq_time(m, lt->max); 422 seq_time(m, lt->max);
423 seq_time(m, lt->total); 423 seq_time(m, lt->total);
424 seq_time(m, lt->nr ? do_div(lt->total, lt->nr) : 0);
424} 425}
425 426
426static void seq_stats(struct seq_file *m, struct lock_stat_data *data) 427static void seq_stats(struct seq_file *m, struct lock_stat_data *data)
@@ -518,20 +519,20 @@ static void seq_stats(struct seq_file *m, struct lock_stat_data *data)
518 } 519 }
519 if (i) { 520 if (i) {
520 seq_puts(m, "\n"); 521 seq_puts(m, "\n");
521 seq_line(m, '.', 0, 40 + 1 + 10 * (14 + 1)); 522 seq_line(m, '.', 0, 40 + 1 + 12 * (14 + 1));
522 seq_puts(m, "\n"); 523 seq_puts(m, "\n");
523 } 524 }
524} 525}
525 526
526static void seq_header(struct seq_file *m) 527static void seq_header(struct seq_file *m)
527{ 528{
528 seq_printf(m, "lock_stat version 0.3\n"); 529 seq_puts(m, "lock_stat version 0.4\n");
529 530
530 if (unlikely(!debug_locks)) 531 if (unlikely(!debug_locks))
531 seq_printf(m, "*WARNING* lock debugging disabled!! - possibly due to a lockdep warning\n"); 532 seq_printf(m, "*WARNING* lock debugging disabled!! - possibly due to a lockdep warning\n");
532 533
533 seq_line(m, '-', 0, 40 + 1 + 10 * (14 + 1)); 534 seq_line(m, '-', 0, 40 + 1 + 12 * (14 + 1));
534 seq_printf(m, "%40s %14s %14s %14s %14s %14s %14s %14s %14s " 535 seq_printf(m, "%40s %14s %14s %14s %14s %14s %14s %14s %14s %14s %14s "
535 "%14s %14s\n", 536 "%14s %14s\n",
536 "class name", 537 "class name",
537 "con-bounces", 538 "con-bounces",
@@ -539,12 +540,14 @@ static void seq_header(struct seq_file *m)
539 "waittime-min", 540 "waittime-min",
540 "waittime-max", 541 "waittime-max",
541 "waittime-total", 542 "waittime-total",
543 "waittime-avg",
542 "acq-bounces", 544 "acq-bounces",
543 "acquisitions", 545 "acquisitions",
544 "holdtime-min", 546 "holdtime-min",
545 "holdtime-max", 547 "holdtime-max",
546 "holdtime-total"); 548 "holdtime-total",
547 seq_line(m, '-', 0, 40 + 1 + 10 * (14 + 1)); 549 "holdtime-avg");
550 seq_line(m, '-', 0, 40 + 1 + 12 * (14 + 1));
548 seq_printf(m, "\n"); 551 seq_printf(m, "\n");
549} 552}
550 553
generated by cgit v1.2.2 (git 2.25.0) at 2025-08-22 06:13:00 -0400