Fix an intermittent pr_emerg warning about lo becoming free.

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

A simple solution to this problem is to have dst_dev_event() reset the gc timer, which causes us to process this list shortly after the gc_mutex is relased when dst_dev_event() completes.

Signed-off-by Krister Johansen <[email protected]>

---
 net/core/dst.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

net/core/dst.c +7 -0

index 6192f11..13ba4a0 100644
@@ -469,6 +469,20 @@ static int dst_dev_event(struct notifier_block *this, unsigned long event,
 		spin_lock_bh(&dst_garbage.lock);
 		dst = dst_garbage.list;
 		dst_garbage.list = NULL;
+		/* The code in dst_ifdown places a hold on the loopback device.
+		 * If the gc entry processing is set to expire after a lengthy
+		 * interval, this hold can cause netdev_wait_allrefs() to hang
+		 * out and wait for a long time -- until the the loopback
+		 * interface is released.  If we're really unlucky, it'll emit
+		 * pr_emerg messages to console too.  Reset the interval here,
+		 * so dst cleanups occur in a more timely fashion.

Wei Wan is actually working on a patch series removing all this dst_garbage list stuff.

On Thu, 2017-06-08 at 13:12 -0700, Krister Johansen wrote:

...

Quoted 31 lines

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

A simple solution to this problem is to have dst_dev_event() reset the gc timer, which causes us to process this list shortly after the gc_mutex is relased when dst_dev_event() completes.

Signed-off-by Krister Johansen <[email protected]>

---
 net/core/dst.c | 14 ++++++++++++++
 1 file changed, 14 insertions(+)

net/core/dst.c +7 -0

index 6192f11..13ba4a0 100644
@@ -469,6 +469,20 @@ static int dst_dev_event(struct notifier_block *this, unsigned long event,
              spin_lock_bh(&dst_garbage.lock);
              dst = dst_garbage.list;
              dst_garbage.list = NULL;
+             /* The code in dst_ifdown places a hold on the loopback device.
+              * If the gc entry processing is set to expire after a lengthy
+              * interval, this hold can cause netdev_wait_allrefs() to hang
+              * out and wait for a long time -- until the the loopback
+              * interface is released.  If we're really unlucky, it'll emit
+              * pr_emerg messages to console too.  Reset the interval here,
+              * so dst cleanups occur in a more timely fashion.

net/core/dst.c static int dst_dev_event(struct notifier_block *this, unsigned long event, · line 488

Quoted 10 lines

net/core/dst.c +7 -0

+              */
+             if (dst_garbage.timer_inc > DST_GC_INC) {
+                     dst_garbage.timer_inc = DST_GC_INC;
+                     dst_garbage.timer_expires = DST_GC_MIN;
+                     mod_delayed_work(system_wq, &dst_gc_work,
+                                      dst_garbage.timer_expires);
+             }
              spin_unlock_bh(&dst_garbage.lock);
 
              if (last)

Looks very nice to me !

Acked-by Eric Dumazet <[email protected]>

Wei Wan is actually working on a patch series removing all this dst_garbage list stuff.

It looks like this:

Message from syslogd@flamingo at Apr 26 00:45:00 ...
kernel:unregister_netdevice: waiting for lo to become free. Usage count = 4

They seem to coincide with net namespace teardown.

The message is emitted by netdev_wait_allrefs().

Forced a kdump in netdev_run_todo, but found that the refcount on the lo device was already 0 at the time we got to the panic.

Used bcc to check the blocking in netdev_run_todo. The only places where we're off cpu there are in the rcu_barrier() and msleep() calls. That behavior is expected. The msleep time coincides with the amount of time we spend waiting for the refcount to reach zero; the rcu_barrier() wait times are not excessive.

After looking through the list of callbacks that the netdevice notifiers invoke in this path, it appears that the dst_dev_event is the most interesting. The dst_ifdown path places a hold on the loopback_dev as part of releasing the dev associated with the original dst cache entry. Most of our notifier callbacks are straight-forward, but this one a) looks complex, and b) places a hold on the network interface in question.

I constructed a new bcc script that watches various events in the liftime of a dst cache entry. Note that dst_ifdown will take a hold on the loopback device until the invalidated dst entry gets freed.

The way this works is that if there's still a reference on the dst entry at the time we try to free it, it gets placed in the gc list by __dst_free and the dst_destroy() call is invoked by the gc task once the refcount is 0. If the gc task processes a 10th or less of its entries on a single pass, it inreases the amount of time it waits between gc intervals.

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

A simple solution to this problem is to have dst_dev_event() reset the gc timer, which causes us to process this list shortly after the gc_mutex is relased when dst_dev_event() completes.

Signed-off-by Krister Johansen <[email protected]>

After looking through the list of callbacks that the netdevice notifiers invoke in this path, it appears that the dst_dev_event is the most interesting. The dst_ifdown path places a hold on the loopback_dev as part of releasing the dev associated with the original dst cache entry. Most of our notifier callbacks are straight-forward, but this one a) looks complex, and b) places a hold on the network interface in question.

I constructed a new bcc script that watches various events in the liftime of a dst cache entry. Note that dst_ifdown will take a hold on the loopback device until the invalidated dst entry gets freed.

The way this works is that if there's still a reference on the dst entry at the time we try to free it, it gets placed in the gc list by __dst_free and the dst_destroy() call is invoked by the gc task once the refcount is 0. If the gc task processes a 10th or less of its entries on a single pass, it inreases the amount of time it waits between gc intervals.

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

Quoted 7 lines · Krister Johansen

The way this works is that if there's still a reference on the dst entry at the time we try to free it, it gets placed in the gc list by __dst_free and the dst_destroy() call is invoked by the gc task once the refcount is 0. If the gc task processes a 10th or less of its entries on a single pass, it inreases the amount of time it waits between gc intervals.

Quoted 7 lines

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

I am glad to see you don't have a dst leak here.

But from my experience of a similar bug (refcnt wait on lo), this goes infinitely rather than just 14sec, so it looked more like a real leak than just a gc delay. So in your case, this annoying warning eventually disappears, right?

Quoted 17 lines · Cong Wang

Quoted 7 lines · Krister Johansen

The way this works is that if there's still a reference on the dst entry at the time we try to free it, it gets placed in the gc list by __dst_free and the dst_destroy() call is invoked by the gc task once the refcount is 0. If the gc task processes a 10th or less of its entries on a single pass, it inreases the amount of time it waits between gc intervals.

Quoted 7 lines

Looking at the gc_task intervals, they started at 663ms when we invoked __dst_free(). After that, they increased to 1663, 3136, 5567, 8191, 10751, and 14848. The release that set the refcnt to 0 on our dst entry occurred after the gc_task was enqueued for 14 second interval so we had to wait longer than the warning time in wait_allrefs in order for the dst entry to get free'd and the hold on 'lo' to be released.

Quoted 6 lines

I am glad to see you don't have a dst leak here.

But from my experience of a similar bug (refcnt wait on lo), this goes infinitely rather than just 14sec, so it looked more like a real leak than just a gc delay. So in your case, this annoying warning eventually disappears, right?

That's correct. The problem occurs intermittently, and the warnings are less frequent than the interval in netdev_wait_allrefs(). At least when I observed it, it tended to conincide with our controlplane canary issuing an API call that lead to a network namespace teardown on the dataplane.