Re: linux-next: slab shrinkers: BUG at mm/list_lru.c:92

[Michal Hocko]

On Mon 01-07-13 18:10:56, Dave Chinner wrote:
> On Mon, Jul 01, 2013 at 09:50:05AM +0200, Michal Hocko wrote:
> > On Mon 01-07-13 11:25:58, Dave Chinner wrote:
> > > On Sun, Jun 30, 2013 at 08:33:49PM +0200, Michal Hocko wrote:
> > > > On Sat 29-06-13 12:55:09, Dave Chinner wrote:
> > > > > On Thu, Jun 27, 2013 at 04:54:11PM +0200, Michal Hocko wrote:
> > > > > > On Thu 27-06-13 09:24:26, Dave Chinner wrote:
> > > > > > > On Wed, Jun 26, 2013 at 10:15:09AM +0200, Michal Hocko wrote:
> > > > > > > > On Tue 25-06-13 12:27:54, Dave Chinner wrote:
> > > > > > > > > On Tue, Jun 18, 2013 at 03:50:25PM +0200, Michal Hocko wrote:
> > > > > > > > > > And again, another hang. It looks like the inode deletion never
> > > > > > > > > > finishes. The good thing is that I do not see any LRU related BUG_ONs
> > > > > > > > > > anymore. I am going to test with the other patch in the thread.
> > > > > > > > > > 
> > > > > > > > > > 2476 [<ffffffff8118325e>] __wait_on_freeing_inode+0x9e/0xc0	<<< waiting for an inode to go away
> > > > > > > > > > [<ffffffff81183321>] find_inode_fast+0xa1/0xc0
> > > > > > > > > > [<ffffffff8118525f>] iget_locked+0x4f/0x180
> > > > > > > > > > [<ffffffff811ef9e3>] ext4_iget+0x33/0x9f0
> > > > > > > > > > [<ffffffff811f6a1c>] ext4_lookup+0xbc/0x160
> > > > > > > > > > [<ffffffff81174ad0>] lookup_real+0x20/0x60
> > > > > > > > > > [<ffffffff81177e25>] lookup_open+0x175/0x1d0
> > > > > > > > > > [<ffffffff8117815e>] do_last+0x2de/0x780			<<< holds i_mutex
> > > > > > > > > > [<ffffffff8117ae9a>] path_openat+0xda/0x400
> > > > > > > > > > [<ffffffff8117b303>] do_filp_open+0x43/0xa0
> > > > > > > > > > [<ffffffff81168ee0>] do_sys_open+0x160/0x1e0
> > > > > > > > > > [<ffffffff81168f9c>] sys_open+0x1c/0x20
> > > > > > > > > > [<ffffffff81582fe9>] system_call_fastpath+0x16/0x1b
> > > > > > > > > > [<ffffffffffffffff>] 0xffffffffffffffff
> > > 
> > > .....
> > > > Do you mean sysrq+t? It is attached. 
> > > > 
> > > > Btw. I was able to reproduce this again. The stuck processes were
> > > > sitting in the same traces for more than 28 hours without any change so
> > > > I do not think this is a temporal condition.
> > > > 
> > > > Traces of all processes in the D state:
> > > > 7561 [<ffffffffa029c03e>] xfs_iget+0xbe/0x190 [xfs]
> > > > [<ffffffffa02a8e98>] xfs_lookup+0xe8/0x110 [xfs]
> > > > [<ffffffffa029fad9>] xfs_vn_lookup+0x49/0x90 [xfs]
> > > > [<ffffffff81174ad0>] lookup_real+0x20/0x60
> > > > [<ffffffff81177e25>] lookup_open+0x175/0x1d0
> > > > [<ffffffff8117815e>] do_last+0x2de/0x780
> > > > [<ffffffff8117ae9a>] path_openat+0xda/0x400
> > > > [<ffffffff8117b303>] do_filp_open+0x43/0xa0
> > > > [<ffffffff81168ee0>] do_sys_open+0x160/0x1e0
> > > > [<ffffffff81168f9c>] sys_open+0x1c/0x20
> > > > [<ffffffff815830e9>] system_call_fastpath+0x16/0x1b
> > > > [<ffffffffffffffff>] 0xffffffffffffffff
> > > 
> > > This looks like it may be equivalent to the ext4 trace above, though
> > > I'm not totally sure on that yet. Can you get me the line of code
> > > where the above code is sleeping - 'gdb> l *(xfs_iget+0xbe)' output
> > > is sufficient.
> > 
> > OK, this is a bit tricky because I have xfs built as a module so objdump
> > on xfs.ko shows nonsense
> >    19039:       e8 00 00 00 00          callq  1903e <xfs_iget+0xbe>
> >    1903e:       48 8b 75 c0             mov    -0x40(%rbp),%rsi
> > 
> > crash was more clever though and it says:
> > 0xffffffffa029c034 <xfs_iget+180>:      mov    $0x1,%edi
> > 0xffffffffa029c039 <xfs_iget+185>:      callq  0xffffffff815776d0
> > <schedule_timeout_uninterruptible>
> > /dev/shm/mhocko-build/BUILD/kernel-3.9.0mmotm+/fs/xfs/xfs_icache.c: 423
> > 0xffffffffa029c03e <xfs_iget+190>:      mov    -0x40(%rbp),%rsi
> > 
> > which maps to:
> > out_error_or_again:
> >         if (error == EAGAIN) {
> >                 delay(1);
> >                 goto again;
> >         }
> > 
> > So this looks like this path loops in goto again and out_error_or_again.
> 
> Yup, that's what I suspected.
> 
> > > If it's where I suspect it is, we are hitting a VFS inode that
> > > igrab() is failing on because I_FREEING is set and that is returning
> > > EAGAIN. Hence xfs_iget() sleeps for a short period and retries the
> > > lookup. If you've still got a system in this state, can you dump the
> > > xfs stats a few times about 5s apart i.e.
> > > 
> > > $ for i in `seq 0 1 5`; do echo ; date; cat /proc/fs/xfs/stat ; sleep 5 ; done
> > > 
> > > Depending on what stat is changing (i'm looking for skip vs recycle
> > > in the inode cache stats), that will tell us why the lookup is
> > > failing...
> > 
> > $ for i in `seq 0 1 5`; do echo ; date; cat /proc/fs/xfs/stat ; sleep 5 ; done
> > 
> > Mon Jul  1 09:29:57 CEST 2013
> > extent_alloc 1484333 2038118 1678 13182
> > abt 0 0 0 0
> > blk_map 21004635 3433178 1450438 1461372 1450017 25888309 0
> > bmbt 0 0 0 0
> > dir 1482235 1466711 7281 2529
> > trans 7676 6231535 1444850
> > ig 0 8534 299 1463749 0 1256778 262381
>             ^^^
> 
> That is the recycle stat, which indicates we've found an inode being
> reclaimed. When it's found an inode that have been evicted, but not
> yet reclaimed at the XFS level, that stat will increase. If the
> inode is still valid at the VFS level, and igrab() fails, then we'll
> get EAGAIN without that stat being increased. So, igrab() is
> failing, and that means I_FREEING|I_WILL_FREE are set.
> 
> So, it looks to be the same case as the ext4 hang, and it's likely
> that we have some dangling inode dispose list somewhere. So, here's
> the fun part. Use tracing to grab the inode number that is stuck
> (tracepoint xfs::xfs_iget_skip), 

$ cat /sys/kernel/debug/tracing/trace_pipe > demon.trace.log &
$ pid=$!
$ sleep 10s ; kill $pid
$ awk '{print $1, $9}' demon.trace.log | sort -u
cc1-7561 0xf78d4f
cc1-9100 0x80b2a35

> and then run crash on the live kernel on the process that is looping,
> and find the struct xfs_inode and print it.  Use the inode number from
> the trace point to check you've got the right inode.

crash> bt -f 7561
 #4 [ffff88003744db40] xfs_iget at ffffffffa029c03e [xfs]
    ffff88003744db48: 0000000000000000 0000000000000000 
    ffff88003744db58: 0000000000013b40 ffff88003744dc30 
    ffff88003744db68: 0000000000000000 0000000000000000 
    ffff88003744db78: 0000000000f78d4f ffffffffa02dafec 
    ffff88003744db88: ffff88000c09e1c0 0000000000000008 
    ffff88003744db98: 0000000000000000 ffff88000c0a0ac0 
    ffff88003744dba8: ffff88003744dc18 0000000000000000 
    ffff88003744dbb8: ffff88003744dc08 ffffffffa02a8e98
crash> dis xfs_iget
[...]
0xffffffffa029c045 <xfs_iget+197>:      callq  0xffffffff812ca190 <radix_tree_lookup>
0xffffffffa029c04a <xfs_iget+202>:      test   %rax,%rax
0xffffffffa029c04d <xfs_iget+205>:      mov    %rax,-0x30(%rbp)

So the inode should be at -0x30(%rbp) which is
crash> struct xfs_inode.i_ino ffff88000c09e1c0
  i_ino = 16223567
crash> p /x 16223567
$15 = 0xf78d4f

> Th struct inode of the VFS inode is embedded into the struct
> xfs_inode, 

crash> struct -o xfs_inode.i_vnode ffff88000c09e1c0
struct xfs_inode {
  [ffff88000c09e2f8] struct inode i_vnode;
}

> and the dispose list that it is on should be the on the
> inode->i_lru_list. 

crash> struct inode.i_lru ffff88000c09e2f8
  i_lru = {
    next = 0xffff88000c09e3e8, 
    prev = 0xffff88000c09e3e8
  }
crash> struct inode.i_flags ffff88000c09e2f8
  i_flags = 4096

The full xfs_inode dump is attached.

> What that, and see how many other inodes are on that list. Once we
> know if it's a single inode,

The list seems to be empty. And the same is the case for the other inode:
crash> bt -f 9100
 #4 [ffff88001c8c5b40] xfs_iget at ffffffffa029c03e [xfs]
    ffff88001c8c5b48: 0000000000000000 0000000000000000 
    ffff88001c8c5b58: 0000000000013b40 ffff88001c8c5c30 
    ffff88001c8c5b68: 0000000000000000 0000000000000000 
    ffff88001c8c5b78: 00000000000b2a35 ffffffffa02dafec 
    ffff88001c8c5b88: ffff88000c09ec40 0000000000000008 
    ffff88001c8c5b98: 0000000000000000 ffff8800359e9b00 
    ffff88001c8c5ba8: ffff88001c8c5c18 0000000000000000 
    ffff88001c8c5bb8: ffff88001c8c5c08 ffffffffa02a8e98
crash> p /x 0xffff88001c8c5bb8-0x30
$16 = 0xffff88001c8c5b88
sh> struct xfs_inode.i_ino ffff88000c09ec40
  i_ino = 134949429
crash> p /x 134949429
$17 = 0x80b2a35
crash> struct -o xfs_inode.i_vnode ffff88000c09ec40
struct xfs_inode {
  [ffff88000c09ed78] struct inode i_vnode;
}
crash> struct inode.i_lru ffff88000c09ed78
  i_lru = {
    next = 0xffff88000c09ee68, 
    prev = 0xffff88000c09ee68
  }
crash> struct inode.i_flags ffff88000c09ed78
  i_flags = 4096

> and whether the dispose list it is on is intact, empty or corrupt, we
> might have a better idea of how these inodes are getting lost....
> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@xxxxxxxxxxxxx

-- 
Michal Hocko
SUSE Labs
crash> struct xfs_inode ffff88000c09e1c0
struct xfs_inode {
  i_mount = 0xffff88001ca4d000, 
  i_udquot = 0x0, 
  i_gdquot = 0x0, 
  i_ino = 16223567, 
  i_imap = {
    im_blkno = 8111776, 
    im_len = 16, 
    im_boffset = 3840
  }, 
  i_afp = 0x0, 
  i_df = {
    if_bytes = 16, 
    if_real_bytes = 0, 
    if_broot = 0x0, 
    if_broot_bytes = 0, 
    if_flags = 2 '\002', 
    if_u1 = {
      if_extents = 0xffff88000c09e218, 
      if_ext_irec = 0xffff88000c09e218, 
      if_data = 0xffff88000c09e218 ""
    }, 
    if_u2 = {
      if_inline_ext = {{
          l0 = 0, 
          l1 = 2135699750913
        }, {
          l0 = 0, 
          l1 = 0
        }}, 
      if_inline_data = "\000\000\000\000\000\000\000\000\001\000\240A\361\001\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000", 
      if_rdev = 0, 
      if_uuid = {
        __u_bits = "\000\000\000\000\000\000\000\000\001\000\240A\361\001\000"
      }
    }
  }, 
  i_itemp = 0x0, 
  i_lock = {
    mr_lock = {
      count = 0, 
      wait_lock = {
        raw_lock = {
          {
            head_tail = 0, 
            tickets = {
              head = 0, 
              tail = 0
            }
          }
        }
      }, 
      wait_list = {
        next = 0xffff88000c09e250, 
        prev = 0xffff88000c09e250
      }
    }
  }, 
  i_iolock = {
    mr_lock = {
      count = 0, 
      wait_lock = {
        raw_lock = {
          {
            head_tail = 0, 
            tickets = {
              head = 0, 
              tail = 0
            }
          }
        }
      }, 
      wait_list = {
        next = 0xffff88000c09e270, 
        prev = 0xffff88000c09e270
      }
    }
  }, 
  i_pincount = {
    counter = 0
  }, 
  i_flags_lock = {
    {
      rlock = {
        raw_lock = {
          {
            head_tail = 878654559, 
            tickets = {
              head = 13407, 
              tail = 13407
            }
          }
        }
      }
    }
  }, 
  i_flags = 0, 
  i_delayed_blks = 0, 
  i_d = {
    di_magic = 18766, 
    di_mode = 33204, 
    di_version = 2 '\002', 
    di_format = 2 '\002', 
    di_onlink = 0, 
    di_uid = 0, 
    di_gid = 0, 
    di_nlink = 1, 
    di_projid_lo = 0, 
    di_projid_hi = 0, 
    di_pad = "\000\000\000\000\000", 
    di_flushiter = 2, 
    di_atime = {
      t_sec = 1372433043, 
      t_nsec = 599568074
    }, 
    di_mtime = {
      t_sec = 1352637873, 
      t_nsec = 0
    }, 
    di_ctime = {
      t_sec = 1372432997, 
      t_nsec = 935341638
    }, 
    di_size = 3280, 
    di_nblocks = 1, 
    di_extsize = 0, 
    di_nextents = 1, 
    di_anextents = 0, 
    di_forkoff = 0 '\000', 
    di_aformat = 2 '\002', 
    di_dmevmask = 0, 
    di_dmstate = 0, 
    di_flags = 0, 
    di_gen = 15307555
  }, 
  i_vnode = {
    i_mode = 33204, 
    i_opflags = 5, 
    i_uid = 0, 
    i_gid = 0, 
    i_flags = 4096, 
    i_acl = 0x0, 
    i_default_acl = 0x0, 
    i_op = 0xffffffffa0301800, 
    i_sb = 0xffff88001e70c800, 
    i_mapping = 0xffff88000c09e440, 
    i_security = 0x0, 
    i_ino = 16223567, 
    {
      i_nlink = 1, 
      __i_nlink = 1
    }, 
    i_rdev = 0, 
    i_size = 3280, 
    i_atime = {
      tv_sec = 1372433043, 
      tv_nsec = 599568074
    }, 
    i_mtime = {
      tv_sec = 1352637873, 
      tv_nsec = 0
    }, 
    i_ctime = {
      tv_sec = 1372432997, 
      tv_nsec = 935341638
    }, 
    i_lock = {
      {
        rlock = {
          raw_lock = {
            {
              head_tail = 852898518, 
              tickets = {
                head = 13014, 
                tail = 13014
              }
            }
          }
        }
      }
    }, 
    i_bytes = 0, 
    i_blkbits = 12, 
    i_blocks = 0, 
    i_state = 32, 
    i_mutex = {
      count = {
        counter = 1
      }, 
      wait_lock = {
        {
          rlock = {
            raw_lock = {
              {
                head_tail = 0, 
                tickets = {
                  head = 0, 
                  tail = 0
                }
              }
            }
          }
        }
      }, 
      wait_list = {
        next = 0xffff88000c09e3a8, 
        prev = 0xffff88000c09e3a8
      }, 
      owner = 0x0
    }, 
    dirtied_when = 0, 
    i_hash = {
      next = 0x0, 
      pprev = 0xffff88000c09e3c8
    }, 
    i_wb_list = {
      next = 0xffff88000c09e3d8, 
      prev = 0xffff88000c09e3d8
    }, 
    i_lru = {
      next = 0xffff88000c09e3e8, 
      prev = 0xffff88000c09e3e8
    }, 
    i_sb_list = {
      next = 0xffff88000c0a0cf8, 
      prev = 0xffff880012423d38
    }, 
    {
      i_dentry = {
        first = 0x0
      }, 
      i_rcu = {
        next = 0x0, 
        func = 0xffffffffa029acb0 <xfs_inode_free_callback>
      }
    }, 
    i_version = 0, 
    i_count = {
      counter = 0
    }, 
    i_dio_count = {
      counter = 0
    }, 
    i_writecount = {
      counter = 0
    }, 
    i_fop = 0xffffffffa03015c0, 
    i_flock = 0x0, 
    i_data = {
      host = 0xffff88000c09e2f8, 
      page_tree = {
        height = 0, 
        gfp_mask = 32, 
        rnode = 0x0
      }, 
      tree_lock = {
        {
          rlock = {
            raw_lock = {
              {
                head_tail = 4849738, 
                tickets = {
                  head = 74, 
                  tail = 74
                }
              }
            }
          }
        }
      }, 
      i_mmap_writable = 0, 
      i_mmap = {
        rb_node = 0x0
      }, 
      i_mmap_nonlinear = {
        next = 0xffff88000c09e468, 
        prev = 0xffff88000c09e468
      }, 
      i_mmap_mutex = {
        count = {
          counter = 1
        }, 
        wait_lock = {
          {
            rlock = {
              raw_lock = {
                {
                  head_tail = 0, 
                  tickets = {
                    head = 0, 
                    tail = 0
                  }
                }
              }
            }
          }
        }, 
        wait_list = {
          next = 0xffff88000c09e480, 
          prev = 0xffff88000c09e480
        }, 
        owner = 0x0
      }, 
      nrpages = 0, 
      writeback_index = 0, 
      a_ops = 0xffffffffa0301460, 
      flags = 131290, 
      backing_dev_info = 0xffff88001c7b9950, 
      private_lock = {
        {
          rlock = {
            raw_lock = {
              {
                head_tail = 1835036, 
                tickets = {
                  head = 28, 
                  tail = 28
                }
              }
            }
          }
        }
      }, 
      private_list = {
        next = 0xffff88000c09e4c8, 
        prev = 0xffff88000c09e4c8
      }, 
      private_data = 0x0
    }, 
    i_dquot = {0x0, 0x0}, 
    i_devices = {
      next = 0xffff88000c09e4f0, 
      prev = 0xffff88000c09e4f0
    }, 
    {
      i_pipe = 0x0, 
      i_bdev = 0x0, 
      i_cdev = 0x0
    }, 
    i_generation = 15307555, 
    i_fsnotify_mask = 0, 
    i_fsnotify_marks = {
      first = 0x0
    }, 
    i_private = 0x0
  }
}