[RT] lockdep munching nr_list_entries like popcorn

[RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

4.9.10-rt6-virgin on 72 core +SMT box.

Below is 1 line per minute, box idling along daintily nibbling, I fire
up a parallel kbuild loop at 40465, and box gobbles greedily.

I have entries bumped to 128k, and chain bits to 18 so box will get
booted and run for a while before lockdep says "I quit".  With stock
settings, this box will barely get booted.  Seems the bigger the box,
the sooner you're gonna run out.  A NOPREEMPT kernel seems to nibble
entries too, but nowhere remotely near as greedily as RT.

           <...>-100309 [064] d....13  2885.873312: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40129
           <...>-104320 [116] dN..211  2959.633630: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40155
 btrfs-transacti-1955  [043] d...111  3021.073949: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40183
           <...>-118865 [120] d....13  3086.146794: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40209
  systemd-logind-4763  [068] d....11  3146.953001: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40239
           <...>-123725 [032] dN..2..  3215.735774: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40285
           <...>-33968 [031] d...1..  3347.919001: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40409
           <...>-130886 [143] d....12  3412.586643: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40465
           <...>-138291 [037] d....11  3477.816405: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 42825
           <...>-67678 [137] d...112  3551.648282: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 47899
    ksoftirqd/45-421   [045] d....13  3617.926394: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 48751
         ihex2fw-24635 [035] d....11  3686.899690: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 49345
           <...>-76041 [047] d...111  3758.230009: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 49757
            stty-10772 [118] d...1..  3825.626815: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 50115
  kworker/u289:4-13376 [075] d....12  3896.432428: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 51189
           <...>-92785 [047] d....12  3905.137578: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 51287

With stacktrace on, buffer contains 1010 __lru_cache_add+0x4f...

(gdb) list *__lru_cache_add+0x4f
0xffffffff811dca9f is in __lru_cache_add (./include/linux/locallock.h:59).
54
55      static inline void __local_lock(struct local_irq_lock *lv)
56      {
57              if (lv->owner != current) {
58                      spin_lock_local(&lv->lock);
59                      LL_WARN(lv->owner);
60                      LL_WARN(lv->nestcnt);
61                      lv->owner = current;
62              }
63              lv->nestcnt++;

...which seems to be this.

0xffffffff811dca80 is in __lru_cache_add (mm/swap.c:397).
392     }
393     EXPORT_SYMBOL(mark_page_accessed);
394
395     static void __lru_cache_add(struct page *page)
396     {
397             struct pagevec *pvec = &get_locked_var(swapvec_lock, lru_add_pvec);
398
399             get_page(page);
400             if (!pagevec_add(pvec, page) || PageCompound(page))
401                     __pagevec_lru_add(pvec);

swapvec_lock?  Oodles of 'em?  Nope.

	-Mike

Re: [RT] lockdep munching nr_list_entries like popcorn

[Thomas Gleixner]

On Thu, 16 Feb 2017, Mike Galbraith wrote:

> 4.9.10-rt6-virgin on 72 core +SMT box.
> 
> Below is 1 line per minute, box idling along daintily nibbling, I fire
> up a parallel kbuild loop at 40465, and box gobbles greedily.
> 
> I have entries bumped to 128k, and chain bits to 18 so box will get
> booted and run for a while before lockdep says "I quit".  With stock
> settings, this box will barely get booted.  Seems the bigger the box,
> the sooner you're gonna run out.  A NOPREEMPT kernel seems to nibble
> entries too, but nowhere remotely near as greedily as RT.

Right. RT adds a bunch of locks through the local lock mechanism.

>            <...>-100309 [064] d....13  2885.873312: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 40129
>            <...>-92785 [047] d....12  3905.137578: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 51287

That's odd.

> With stacktrace on, buffer contains 1010 __lru_cache_add+0x4f...
> 
> (gdb) list *__lru_cache_add+0x4f
> 0xffffffff811dca9f is in __lru_cache_add (./include/linux/locallock.h:59).
> 54
> 55      static inline void __local_lock(struct local_irq_lock *lv)
> 56      {
> 57              if (lv->owner != current) {
> 58                      spin_lock_local(&lv->lock);
> 59                      LL_WARN(lv->owner);
> 60                      LL_WARN(lv->nestcnt);
> 61                      lv->owner = current;
> 62              }
> 63              lv->nestcnt++;
> 
> ...which seems to be this.
> 
> 0xffffffff811dca80 is in __lru_cache_add (mm/swap.c:397).
> 392     }
> 393     EXPORT_SYMBOL(mark_page_accessed);
> 394
> 395     static void __lru_cache_add(struct page *page)
> 396     {
> 397             struct pagevec *pvec = &get_locked_var(swapvec_lock, lru_add_pvec);
> 398
> 399             get_page(page);
> 400             if (!pagevec_add(pvec, page) || PageCompound(page))
> 401                     __pagevec_lru_add(pvec);
> 
> swapvec_lock?  Oodles of 'em?  Nope.

Well, it's a per cpu lock and the lru_cache_add() variants might be called
from a gazillion of different call chains, but yes, it does not make a lot
of sense. We'll have a look.

Thanks,

	tglx

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

On Thu, 2017-02-16 at 09:37 +0100, Thomas Gleixner wrote:
> On Thu, 16 Feb 2017, Mike Galbraith wrote:
> 
...
> > swapvec_lock?  Oodles of 'em?  Nope.
> 
> Well, it's a per cpu lock and the lru_cache_add() variants might be called
> from a gazillion of different call chains, but yes, it does not make a lot
> of sense. We'll have a look.

Adding explicit local_irq_lock_init() makes things heaps better, so
presumably we need better lockdep-foo in DEFINE_LOCAL_IRQ_LOCK().

	-Mike

Re: [RT] lockdep munching nr_list_entries like popcorn

[Thomas Gleixner]

On Thu, 16 Feb 2017, Mike Galbraith wrote:

> On Thu, 2017-02-16 at 09:37 +0100, Thomas Gleixner wrote:
> > On Thu, 16 Feb 2017, Mike Galbraith wrote:
> > 
> ...
> > > swapvec_lock?  Oodles of 'em?  Nope.
> > 
> > Well, it's a per cpu lock and the lru_cache_add() variants might be called
> > from a gazillion of different call chains, but yes, it does not make a lot
> > of sense. We'll have a look.
> 
> Adding explicit local_irq_lock_init() makes things heaps better, so
> presumably we need better lockdep-foo in DEFINE_LOCAL_IRQ_LOCK().

Bah.

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

On Thu, 2017-02-16 at 10:01 +0100, Thomas Gleixner wrote:
> On Thu, 16 Feb 2017, Mike Galbraith wrote:
> 
> > On Thu, 2017-02-16 at 09:37 +0100, Thomas Gleixner wrote:
> > > On Thu, 16 Feb 2017, Mike Galbraith wrote:
> > > 
> > ...
> > > > swapvec_lock?  Oodles of 'em?  Nope.
> > > 
> > > Well, it's a per cpu lock and the lru_cache_add() variants might be called
> > > from a gazillion of different call chains, but yes, it does not make a lot
> > > of sense. We'll have a look.
> > 
> > Adding explicit local_irq_lock_init() makes things heaps better, so
> > presumably we need better lockdep-foo in DEFINE_LOCAL_IRQ_LOCK().
> 
> Bah.

Hm, "bah" sounds kinda like it might be a synonym for -EDUMMY :)  Fair
enough, I know spit about about lockdep, so that's likely the case, but
the below has me down to ~17k (and climbing, but not as fast).

berio:/sys/kernel/debug/tracing/:[0]# grep -A 1 'stack trace' trace|grep '=>'|sort|uniq
 => ___slab_alloc+0x171/0x5c0
 => __percpu_counter_add+0x56/0xd0
 => __schedule+0xb0/0x7b0
 => __slab_free+0xd8/0x200
 => cgroup_idr_alloc.constprop.39+0x37/0x80
 => hrtimer_start_range_ns+0xe6/0x400
 => idr_preload+0x6c/0x300
 => jbd2_journal_extend+0x4c/0x310 [jbd2]
 => lock_hrtimer_base.isra.28+0x29/0x50
 => rcu_note_context_switch+0x2b8/0x5c0
 => rcu_report_unblock_qs_rnp+0x6e/0xa0
 => rt_mutex_slowunlock+0x25/0xc0
 => rt_spin_lock_slowlock+0x52/0x330
 => rt_spin_lock_slowlock+0x94/0x330
 => rt_spin_lock_slowunlock+0x3c/0xc0
 => swake_up+0x21/0x40
 => task_blocks_on_rt_mutex+0x42/0x1e0
 => try_to_wake_up+0x2d/0x920

berio:/sys/kernel/debug/tracing/:[0]# grep nr_list_entries: trace|tail -1
 irq/66-eth2-TxR-3670  [115] d....14  1542.321173: add_lock_to_list.isra.24.constprop.42+0x20/0x100: nr_list_entries: 17839

Got rid of the really pesky growth anyway.

--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -5522,6 +5522,7 @@ static int __init init_workqueues(void)
 
 	pwq_cache = KMEM_CACHE(pool_workqueue, SLAB_PANIC);
 
+	local_irq_lock_init(pendingb_lock);
 	wq_numa_init();
 
 	/* initialize CPU pools */
--- a/lib/radix-tree.c
+++ b/lib/radix-tree.c
@@ -1677,5 +1677,6 @@ void __init radix_tree_init(void)
 			SLAB_PANIC | SLAB_RECLAIM_ACCOUNT,
 			radix_tree_node_ctor);
 	radix_tree_init_maxnodes();
+	local_irq_lock_init(radix_tree_preloads_lock);
 	hotcpu_notifier(radix_tree_callback, 0);
 }
--- a/mm/memcontrol.c
+++ b/mm/memcontrol.c
@@ -5786,6 +5786,7 @@ static int __init mem_cgroup_init(void)
 	int cpu, node;
 
 	hotcpu_notifier(memcg_cpu_hotplug_callback, 0);
+	local_irq_lock_init(event_lock);
 
 	for_each_possible_cpu(cpu)
 		INIT_WORK(&per_cpu_ptr(&memcg_stock, cpu)->work,
--- a/mm/swap.c
+++ b/mm/swap.c
@@ -681,6 +681,14 @@ static inline void remote_lru_add_drain(
 	local_unlock_on(swapvec_lock, cpu);
 }
 
+static int __init lru_init(void)
+{
+	local_irq_lock_init(swapvec_lock);
+	local_irq_lock_init(rotate_lock);
+	return 0;
+}
+early_initcall(lru_init);
+
 #else
 
 /*
--- a/net/netfilter/core.c
+++ b/net/netfilter/core.c
@@ -525,6 +525,7 @@ int __init netfilter_init(void)
 {
 	int ret;
 
+	local_irq_lock_init(xt_write_lock);
 	ret = register_pernet_subsys(&netfilter_net_ops);
 	if (ret < 0)
 		goto err;

Re: [RT] lockdep munching nr_list_entries like popcorn

[Peter Zijlstra]

On Thu, Feb 16, 2017 at 10:01:18AM +0100, Thomas Gleixner wrote:
> On Thu, 16 Feb 2017, Mike Galbraith wrote:
> 
> > On Thu, 2017-02-16 at 09:37 +0100, Thomas Gleixner wrote:
> > > On Thu, 16 Feb 2017, Mike Galbraith wrote:
> > > 
> > ...
> > > > swapvec_lock?  Oodles of 'em?  Nope.
> > > 
> > > Well, it's a per cpu lock and the lru_cache_add() variants might be called
> > > from a gazillion of different call chains, but yes, it does not make a lot
> > > of sense. We'll have a look.
> > 
> > Adding explicit local_irq_lock_init() makes things heaps better, so
> > presumably we need better lockdep-foo in DEFINE_LOCAL_IRQ_LOCK().
> 
> Bah.


#ifdef CONFIG_DEBUG_LOCK_ALLOC
#define PER_CPU_DEP_MAP_INIT(lockname)                          \
        .dep_map = {                                            \
                .key = ({ static struct lock_class_key __key; &__key }), \
                .name = #lockname,                              \
        }
#else
#define PER_CPU_DEP_MAP_INIT(lockname)
#endif

#define DEFINE_LOCAL_IRQ_LOCK(lvar)                             \
        DEFINE_PER_CPU(struct local_irq_lock, lvar) = {         \
                .lock = { .rlock = {                            \
                        .raw_lock = __ARCH_SPIN_LOCK_UNLOCKED,  \
                        SPIN_DEBUG_INIT(lvar)                   \
                        PER_CPU_DEP_MAP_INIT(lvar)              \
                } }                                             \
        }

That's fairly horrible for poking inside all the internals, but it might
just work ;-)

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

On Thu, 2017-02-16 at 12:06 +0100, Peter Zijlstra wrote:
> On Thu, Feb 16, 2017 at 10:01:18AM +0100, Thomas Gleixner wrote:
> > On Thu, 16 Feb 2017, Mike Galbraith wrote:
> > 
> > > On Thu, 2017-02-16 at 09:37 +0100, Thomas Gleixner wrote:
> > > > On Thu, 16 Feb 2017, Mike Galbraith wrote:
> > > > 
> > > ...
> > > > > swapvec_lock?  Oodles of 'em?  Nope.
> > > > 
> > > > Well, it's a per cpu lock and the lru_cache_add() variants might be called
> > > > from a gazillion of different call chains, but yes, it does not make a lot
> > > > of sense. We'll have a look.
> > > 
> > > Adding explicit local_irq_lock_init() makes things heaps better, so
> > > presumably we need better lockdep-foo in DEFINE_LOCAL_IRQ_LOCK().
> > 
> > Bah.
> 
> 
> #ifdef CONFIG_DEBUG_LOCK_ALLOC
> #define PER_CPU_DEP_MAP_INIT(lockname)                          \
>         .dep_map = {                                            \
>                 .key = ({ static struct lock_class_key __key; &__key }), \
>                 .name = #lockname,                              \
>         }
> #else
> #define PER_CPU_DEP_MAP_INIT(lockname)
> #endif
> 
> #define DEFINE_LOCAL_IRQ_LOCK(lvar)                             \
>         DEFINE_PER_CPU(struct local_irq_lock, lvar) = {         \
>                 .lock = { .rlock = {                            \
>                         .raw_lock = __ARCH_SPIN_LOCK_UNLOCKED,  \
>                         SPIN_DEBUG_INIT(lvar)                   \
>                         PER_CPU_DEP_MAP_INIT(lvar)              \
>                 } }                                             \
>         }
> 
> That's fairly horrible for poking inside all the internals, but it might
> just work ;-

Weeell, I'm trying to cobble something kinda like that together using
__RT_SPIN_INITIALIZER() instead, but seems mean ole Mr. Compiler NAKs
the PER_CPU_DEP_MAP_INIT() thingy.

  CC      mm/swap.o
mm/swap.c:54:689: error: braced-group within expression allowed only
inside a function

	-Mike

Re: [RT] lockdep munching nr_list_entries like popcorn

[Sebastian Andrzej Siewior]

On 2017-02-16 15:42:59 [+0100], Mike Galbraith wrote:
> 
> Weeell, I'm trying to cobble something kinda like that together using
> __RT_SPIN_INITIALIZER() instead, but seems mean ole Mr. Compiler NAKs
> the PER_CPU_DEP_MAP_INIT() thingy.
> 
>   CC      mm/swap.o
> mm/swap.c:54:689: error: braced-group within expression allowed only
> inside a function

so this is what I have now. I need to get the `static' symbol working
again and PER_CPU_DEP_MAP_INIT but aside from that it seems to do its
job.

diff --git a/include/linux/locallock.h b/include/linux/locallock.h
index 845c77f1a5ca..36201b37012d 100644
--- a/include/linux/locallock.h
+++ b/include/linux/locallock.h
@@ -22,9 +22,27 @@ struct local_irq_lock {
 	unsigned long		flags;
 };
 
+#ifdef CONFIG_DEBUG_LOCK_ALLOC
+#define PER_CPU_DEP_MAP_INIT(lockname)					\
+	.dep_map = {							\
+		.key = ({ static struct lock_class_key __key; &__key }),\
+		.name = #lockname,					\
+	}
+#else
+#define PER_CPU_DEP_MAP_INIT(lockname)
+#endif
+
 #define DEFINE_LOCAL_IRQ_LOCK(lvar)					\
+	struct lock_class_key lvar##__key;			\
 	DEFINE_PER_CPU(struct local_irq_lock, lvar) = {			\
-		.lock = __SPIN_LOCK_UNLOCKED((lvar).lock) }
+		.lock = {	\
+			.lock = __RT_SPIN_INITIALIZER(lvar.lock),	\
+			.dep_map = {				\
+				.key = &lvar##__key,		\
+				.name = #lvar,			\
+			}					\
+		}							\
+	}
 
 #define DECLARE_LOCAL_IRQ_LOCK(lvar)					\
 	DECLARE_PER_CPU(struct local_irq_lock, lvar)

> 	-Mike

Sebastian

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

On Thu, 2017-02-16 at 15:53 +0100, Sebastian Andrzej Siewior wrote:
> On 2017-02-16 15:42:59 [+0100], Mike Galbraith wrote:
> > 
> > Weeell, I'm trying to cobble something kinda like that together using
> > __RT_SPIN_INITIALIZER() instead, but seems mean ole Mr. Compiler NAKs
> > the PER_CPU_DEP_MAP_INIT() thingy.
> > 
> >   CC      mm/swap.o
> > mm/swap.c:54:689: error: braced-group within expression allowed only
> > inside a function
> 
> so this is what I have now. I need to get the `static' symbol working
> again and PER_CPU_DEP_MAP_INIT but aside from that it seems to do its
> job.

...

Yeah, works, I should be able to do an ltp run with stock lockdep
settings without it taking it's toys and going home in a snit. 

berio:/sys/kernel/debug/tracing/:[0]# !while
while sleep 60; do tail -1 trace; done
           <...>-10315 [064] d...1..   226.953935: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14223
               w-13148 [120] d...111   287.414978: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14465
               w-16492 [089] d...111   347.128742: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14653
(starts kbuild loop)
 btrfs-transacti-1964  [016] d...1..   411.101549: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 17011
           <...>-100268 [127] d...112   472.271769: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18153
               w-18864 [011] d...1..   534.386443: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18543
           <...>-50390 [035] dN..2..   597.794164: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18765
           <...>-80098 [127] d...111   659.912145: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18977
       checkproc-11123 [017] d...1..   721.483463: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19247
          <idle>-0     [055] d..h5..   782.685953: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19383
           <...>-93632 [055] d...111   835.527817: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19441

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

BTW, this ain't gone.  I'll take a peek.  It doesn't happen in my tree,
seems likely to be because whether running sirqs fully threaded or not,
I don't let one any thread handle what another exists to handle.

[  638.107293] NOHZ: local_softirq_pending 80
[  939.729684] NOHZ: local_softirq_pending 80
[  945.600869] NOHZ: local_softirq_pending 80
[ 1387.101178] NOHZ: local_softirq_pending 80
[ 1387.101343] NOHZ: local_softirq_pending 80
[ 1387.101549] NOHZ: local_softirq_pending 80
[ 1413.313212] NOHZ: local_softirq_pending 80
[ 1413.313305] NOHZ: local_softirq_pending 80
[ 1413.313347] NOHZ: local_softirq_pending 80
> 

Re: [RT] lockdep munching nr_list_entries like popcorn

[Mike Galbraith]

On Thu, 2017-02-16 at 19:06 +0100, Mike Galbraith wrote:
> On Thu, 2017-02-16 at 15:53 +0100, Sebastian Andrzej Siewior wrote:
> > On 2017-02-16 15:42:59 [+0100], Mike Galbraith wrote:
> > > 
> > > Weeell, I'm trying to cobble something kinda like that together using
> > > __RT_SPIN_INITIALIZER() instead, but seems mean ole Mr. Compiler NAKs
> > > the PER_CPU_DEP_MAP_INIT() thingy.
> > > 
> > >   CC      mm/swap.o
> > > mm/swap.c:54:689: error: braced-group within expression allowed only
> > > inside a function
> > 
> > so this is what I have now. I need to get the `static' symbol working
> > again and PER_CPU_DEP_MAP_INIT but aside from that it seems to do its
> > job.
> 
> ...
> 
> Yeah, works, I should be able to do an ltp run with stock lockdep
> settings without it taking it's toys and going home in a snit. 
> 
> berio:/sys/kernel/debug/tracing/:[0]# !while
> while sleep 60; do tail -1 trace; done
>            <...>-10315 [064] d...1..   226.953935: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14223
>                w-13148 [120] d...111   287.414978: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14465
>                w-16492 [089] d...111   347.128742: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14653
> (starts kbuild loop)
>  btrfs-transacti-1964  [016] d...1..   411.101549: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 17011
>            <...>-100268 [127] d...112   472.271769: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18153
>                w-18864 [011] d...1..   534.386443: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18543
>            <...>-50390 [035] dN..2..   597.794164: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18765
>            <...>-80098 [127] d...111   659.912145: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 18977
>        checkproc-11123 [017] d...1..   721.483463: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19247
>           -0     [055] d..h5..   782.685953: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19383
>            <...>-93632 [055] d...111   835.527817: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 19441

And now Thomas's patch.  Spiffiness.  Now to start ltp.

berio:/sys/kernel/debug/tracing/:[0]# !while 
while sleep 60; do tail -1 trace; done
           <...>-12462 [105] d...1..   211.489528: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 12847
 btrfs-transacti-3136  [002] d...211   272.672777: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 12947
 irq/155-eth2-Tx-4495  [096] dN..213   332.035236: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 13001
(starts kbuild loop)
           <...>-44245 [087] d...114   396.892748: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 13917
           <...>-105411 [067] dN..211   457.708259: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14367
               w-21800 [113] dN..2..   519.231735: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14449
         modpost-31558 [020] d....11   576.065855: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14601
   kworker/dying-11860 [133] d...112   637.170497: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14679
           <...>-118853 [055] d....11   703.884755: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14759
           <...>-52143 [090] d...1..   767.624735: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14813
           <...>-71788 [126] d...1..   829.160330: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14857
  kworker/u289:5-2991  [002] d...1..   892.402939: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14883
              sh-15106 [008] d...211   953.172196: add_lock_to_list.isra.24.constprop.42: nr_list_entries: 14937
>