Ceph » CephFS

http://qa-proxy.ceph.com/teuthology/teuthology-2014-06-02_23:02:20-knfs-master-testing-basic-plana/289526/

Not sure if this is our fault or not.

2014-06-05T03:29:43.594994-07:00 plana72 kernel: imklog 5.8.6, log source = /proc/kmsg started.
2014-06-05T03:30:07.038906-07:00 plana72 kernel: [ 5155.320945] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,user_xattr,user_xattr
2014-06-05T03:33:09.230433-07:00 plana72 kernel: [ 5337.624700] NFS: Registering the id_resolver key type
2014-06-05T03:33:09.230453-07:00 plana72 kernel: [ 5337.629808] Key type id_resolver registered
2014-06-05T03:33:09.234641-07:00 plana72 kernel: [ 5337.634020] Key type id_legacy registered
2014-06-05T03:41:42.925446-07:00 plana72 kernel: [ 5851.226149] 
2014-06-05T03:41:42.925468-07:00 plana72 kernel: [ 5851.227661] ======================================================
2014-06-05T03:41:42.925479-07:00 plana72 kernel: [ 5851.233860] [ INFO: possible circular locking dependency detected ]
2014-06-05T03:41:42.925482-07:00 plana72 kernel: [ 5851.240145] 3.15.0-rc6-ceph-00012-gd278040 #1 Tainted: G          I E
2014-06-05T03:41:42.925484-07:00 plana72 kernel: [ 5851.246604] -------------------------------------------------------
2014-06-05T03:41:42.925486-07:00 plana72 kernel: [ 5851.252889] 10.214.133.32-m/22953 is trying to acquire lock:
2014-06-05T03:41:42.925490-07:00 plana72 kernel: [ 5851.258567]  (&(&sp->so_lock)->rlock){+.+...}, at: [<ffffffffa07259ab>] nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925491-07:00 plana72 kernel: [ 5851.268404] 
2014-06-05T03:41:42.925493-07:00 plana72 kernel: [ 5851.268404] but task is already holding lock:
2014-06-05T03:41:42.925499-07:00 plana72 kernel: [ 5851.274270]  (&sp->so_reclaim_seqcount){+.+...}, at: [<ffffffffa0726203>] nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925501-07:00 plana72 kernel: [ 5851.284883] 
2014-06-05T03:41:42.925503-07:00 plana72 kernel: [ 5851.284883] which lock already depends on the new lock.
2014-06-05T03:41:42.925504-07:00 plana72 kernel: [ 5851.284883] 
2014-06-05T03:41:42.925505-07:00 plana72 kernel: [ 5851.293110] 
2014-06-05T03:41:42.925507-07:00 plana72 kernel: [ 5851.293110] the existing dependency chain (in reverse order) is:
2014-06-05T03:41:42.925508-07:00 plana72 kernel: [ 5851.300627] 
2014-06-05T03:41:42.925511-07:00 plana72 kernel: [ 5851.300627] -> #1 (&sp->so_reclaim_seqcount){+.+...}:
2014-06-05T03:41:42.925515-07:00 plana72 kernel: [ 5851.305927]        [<ffffffff810a80b7>] lock_acquire+0x87/0x110
2014-06-05T03:41:42.925518-07:00 plana72 kernel: [ 5851.311879]        [<ffffffffa0725705>] nfs4_do_reclaim+0x155/0x680 [nfsv4]
2014-06-05T03:41:42.925521-07:00 plana72 kernel: [ 5851.318882]        [<ffffffffa0726203>] nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925523-07:00 plana72 kernel: [ 5851.326507]        [<ffffffff81077964>] kthread+0xe4/0x100
2014-06-05T03:41:42.925525-07:00 plana72 kernel: [ 5851.332026]        [<ffffffff816f4cec>] ret_from_fork+0x7c/0xb0
2014-06-05T03:41:42.925526-07:00 plana72 kernel: [ 5851.337977] 
2014-06-05T03:41:42.925528-07:00 plana72 kernel: [ 5851.337977] -> #0 (&(&sp->so_lock)->rlock){+.+...}:
2014-06-05T03:41:42.925533-07:00 plana72 kernel: [ 5851.343104]        [<ffffffff810a741e>] __lock_acquire+0x163e/0x1ce0
2014-06-05T03:41:42.925535-07:00 plana72 kernel: [ 5851.349488]        [<ffffffff810a80b7>] lock_acquire+0x87/0x110
2014-06-05T03:41:42.925537-07:00 plana72 kernel: [ 5851.355437]        [<ffffffff816eb3f1>] _raw_spin_lock+0x31/0x40
2014-06-05T03:41:42.925540-07:00 plana72 kernel: [ 5851.361474]        [<ffffffffa07259ab>] nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925542-07:00 plana72 kernel: [ 5851.368477]        [<ffffffffa0726203>] nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925547-07:00 plana72 kernel: [ 5851.376102]        [<ffffffff81077964>] kthread+0xe4/0x100
2014-06-05T03:41:42.925571-07:00 plana72 kernel: [ 5851.381618]        [<ffffffff816f4cec>] ret_from_fork+0x7c/0xb0
2014-06-05T03:41:42.925573-07:00 plana72 kernel: [ 5851.387568] 
2014-06-05T03:41:42.925578-07:00 plana72 kernel: [ 5851.387568] other info that might help us debug this:
2014-06-05T03:41:42.925579-07:00 plana72 kernel: [ 5851.387568] 
2014-06-05T03:41:42.925581-07:00 plana72 kernel: [ 5851.395620]  Possible unsafe locking scenario:
2014-06-05T03:41:42.925582-07:00 plana72 kernel: [ 5851.395620] 
2014-06-05T03:41:42.925584-07:00 plana72 kernel: [ 5851.401571]        CPU0                    CPU1
2014-06-05T03:41:42.925585-07:00 plana72 kernel: [ 5851.406118]        ----                    ----
2014-06-05T03:41:42.925587-07:00 plana72 kernel: [ 5851.410665]   lock(&sp->so_reclaim_seqcount);
2014-06-05T03:41:42.925592-07:00 plana72 kernel: [ 5851.415060]                                lock(&(&sp->so_lock)->rlock);
2014-06-05T03:41:42.925594-07:00 plana72 kernel: [ 5851.421803]                                lock(&sp->so_reclaim_seqcount);
2014-06-05T03:41:42.925596-07:00 plana72 kernel: [ 5851.428717]   lock(&(&sp->so_lock)->rlock);
2014-06-05T03:41:42.925597-07:00 plana72 kernel: [ 5851.432940] 
2014-06-05T03:41:42.925598-07:00 plana72 kernel: [ 5851.432940]  *** DEADLOCK ***
2014-06-05T03:41:42.925600-07:00 plana72 kernel: [ 5851.432940] 
2014-06-05T03:41:42.925601-07:00 plana72 kernel: [ 5851.438907] 1 lock held by 10.214.133.32-m/22953:
2014-06-05T03:41:42.925605-07:00 plana72 kernel: [ 5851.443628]  #0:  (&sp->so_reclaim_seqcount){+.+...}, at: [<ffffffffa0726203>] nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925609-07:00 plana72 kernel: [ 5851.454684] 
2014-06-05T03:41:42.925610-07:00 plana72 kernel: [ 5851.454684] stack backtrace:
2014-06-05T03:41:42.925613-07:00 plana72 kernel: [ 5851.459076] CPU: 7 PID: 22953 Comm: 10.214.133.32-m Tainted: G          I E 3.15.0-rc6-ceph-00012-gd278040 #1
2014-06-05T03:41:42.925615-07:00 plana72 kernel: [ 5851.469027] Hardware name: Dell Inc. PowerEdge R410/01V648, BIOS 1.6.3 02/07/2011
2014-06-05T03:41:42.925617-07:00 plana72 kernel: [ 5851.476544]  ffffffff82171e70 ffff8800364e3b18 ffffffff816e32d9 0000000000000007
2014-06-05T03:41:42.925619-07:00 plana72 kernel: [ 5851.484016]  ffffffff82171cc0 ffff8800364e3b68 ffffffff816de6c0 ffff88021f054a00
2014-06-05T03:41:42.925621-07:00 plana72 kernel: [ 5851.491489]  ffff8800364e3bf0 ffff880220b3aa38 ffff880220b3aa10 ffff880220b3aa38
2014-06-05T03:41:42.925625-07:00 plana72 kernel: [ 5851.498961] Call Trace:
2014-06-05T03:41:42.925627-07:00 plana72 kernel: [ 5851.501426]  [<ffffffff816e32d9>] dump_stack+0x46/0x58
2014-06-05T03:41:42.925630-07:00 plana72 kernel: [ 5851.506582]  [<ffffffff816de6c0>] print_circular_bug+0x1fb/0x20c
2014-06-05T03:41:42.925632-07:00 plana72 kernel: [ 5851.512609]  [<ffffffff810a741e>] __lock_acquire+0x163e/0x1ce0
2014-06-05T03:41:42.925634-07:00 plana72 kernel: [ 5851.518463]  [<ffffffff8138e321>] ? lockref_put_or_lock+0x11/0x40
2014-06-05T03:41:42.925636-07:00 plana72 kernel: [ 5851.524576]  [<ffffffff8138e321>] ? lockref_put_or_lock+0x11/0x40
2014-06-05T03:41:42.925638-07:00 plana72 kernel: [ 5851.530688]  [<ffffffff810a896a>] ? mark_held_locks+0x6a/0x90
2014-06-05T03:41:42.925643-07:00 plana72 kernel: [ 5851.536453]  [<ffffffff810a8a95>] ? trace_hardirqs_on_caller+0x105/0x1d0
2014-06-05T03:41:42.925646-07:00 plana72 kernel: [ 5851.543183]  [<ffffffffa07259ab>] ? nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925648-07:00 plana72 kernel: [ 5851.549817]  [<ffffffff810a80b7>] lock_acquire+0x87/0x110
2014-06-05T03:41:42.925650-07:00 plana72 kernel: [ 5851.555244]  [<ffffffffa07259ab>] ? nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925652-07:00 plana72 kernel: [ 5851.561879]  [<ffffffff816eb3f1>] _raw_spin_lock+0x31/0x40
2014-06-05T03:41:42.925671-07:00 plana72 kernel: [ 5851.567392]  [<ffffffffa07259ab>] ? nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925674-07:00 plana72 kernel: [ 5851.574034]  [<ffffffffa07259ab>] nfs4_do_reclaim+0x3fb/0x680 [nfsv4]
2014-06-05T03:41:42.925676-07:00 plana72 kernel: [ 5851.580502]  [<ffffffffa0726203>] ? nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925681-07:00 plana72 kernel: [ 5851.587769]  [<ffffffffa07299b5>] ? nfs_delegation_mark_reclaim+0x5/0xd0 [nfsv4]
2014-06-05T03:41:42.925684-07:00 plana72 kernel: [ 5851.596350]  [<ffffffffa0726203>] nfs4_run_state_manager+0x5d3/0x950 [nfsv4]
2014-06-05T03:41:42.925687-07:00 plana72 kernel: [ 5851.603427]  [<ffffffffa0725c30>] ? nfs4_do_reclaim+0x680/0x680 [nfsv4]
2014-06-05T03:41:42.925689-07:00 plana72 kernel: [ 5851.610060]  [<ffffffff81077964>] kthread+0xe4/0x100
2014-06-05T03:41:42.925691-07:00 plana72 kernel: [ 5851.615045]  [<ffffffff81077880>] ? flush_kthread_worker+0x130/0x130
2014-06-05T03:41:42.925693-07:00 plana72 kernel: [ 5851.621417]  [<ffffffff816f4cec>] ret_from_fork+0x7c/0xb0
2014-06-05T03:41:42.925695-07:00 plana72 kernel: [ 5851.626836]  [<ffffffff81077880>] ? flush_kthread_worker+0x130/0x130
2014-06-05T03:42:15.619450-07:00 plana72 kernel: [ 5884.340560] INFO: task ffsb:22919 blocked for more than 120 seconds.
2014-06-05T03:42:15.619473-07:00 plana72 kernel: [ 5884.346954]       Tainted: G          I E 3.15.0-rc6-ceph-00012-gd278040 #1
2014-06-05T03:42:15.626436-07:00 plana72 kernel: [ 5884.353942] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
2014-06-05T03:42:15.641405-07:00 plana72 kernel: [ 5884.361814] ffsb            D 0000000000000002     0 22919  21187 0x00000000
2014-06-05T03:42:15.651635-07:00 plana72 kernel: [ 5884.368921]  ffff8802206dbc98 0000000000000046 ffff8802206dbc48 ffffffff810a8a95
2014-06-05T03:42:15.659109-07:00 plana72 kernel: [ 5884.376400]  ffff880036e643c0 0000000000013d40 ffff8802206dbfd8 0000000000013d40
2014-06-05T03:42:15.666257-07:00 plana72 kernel: [ 5884.383882]  ffff880223d821e0 ffff880036e643c0 ffffffff81108752 ffff8802272346b8