Project

General

Profile

Bug #4003

rbd: EBUSY errors from rbd unmap

Added by Sam Lang about 11 years ago. Updated about 11 years ago.

Status:
Resolved
Priority:
Urgent
Assignee:
Target version:
-
% Done:

0%

Source:
Development
Tags:
Backport:
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

From the teuthology kernel untar task on rbd, we get EBUSY trying to unmap. I'm investigating that this isn't somehow caused by teuthology changes...

2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/rdma_cm.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_marshall.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_sa.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_umem.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_pack.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/Kbuild'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_user_sa.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/rdma_user_cm.h'
2013-02-04T10:40:39.324 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_user_cm.h'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/iw_cm.h'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/ib_user_verbs.h'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/include/rdma/rdma_cm_ib.h'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed directory: `linux-3.2.9/include/rdma'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed directory: `linux-3.2.9/include'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9/vmlinux.o'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed directory: `linux-3.2.9'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed directory: `t'
2013-02-04T10:40:39.325 INFO:teuthology.task.workunit.client.0.out:removed `linux-3.2.9.tar.bz2'
2013-02-04T10:40:39.326 DEBUG:teuthology.orchestra.run:Running [10.214.132.32]: 'rm rf - /tmp/cephtest/mnt.0/client.0/tmp'
2013-02-04T10:40:39.336 INFO:teuthology.task.workunit:Stopping kernel_untar_build.sh on client.0...
2013-02-04T10:40:39.337 DEBUG:teuthology.orchestra.run:Running [10.214.132.32]: 'rm rf - /tmp/cephtest/workunits.list /tmp/cephtest/workunit.client.0'
2013-02-04T10:40:39.383 DEBUG:teuthology.parallel:result is None
2013-02-04T10:40:39.383 DEBUG:teuthology.run_tasks:Unwinding manager <contextlib.GeneratorContextManager object at 0x194e110>
2013-02-04T10:40:39.383 INFO:teuthology.task.rbd:Unmounting rbd images...
2013-02-04T10:40:39.384 INFO:teuthology.task.rbd:Unmapping rbd devices...
2013-02-04T10:40:39.384 DEBUG:teuthology.orchestra.run:Running [10.214.132.32]: 'sudo LD_LIBRARY_PATH=/tmp/cephtest/binary/usr/local/lib /tmp/cephtest/enable-coredump /tmp/cephtest/binary/usr/local/bin/ceph-coverage /tmp/cephtest/archive/coverage /tmp/cephtest/binary/usr/local/bin/rbd c /tmp/cephtest/ceph.conf -p rbd unmap /dev/rbd/rbd/testimage.client.0 && while test -e /dev/rbd/rbd/testimage.client.0 ; do sleep 1 ; done'
2013-02-04T10:40:39.489 INFO:teuthology.orchestra.run.err:rbd: failed to remove rbd device: (16) Device or resource busy
2013-02-04T10:40:39.489 INFO:teuthology.orchestra.run.err:rbd: remove failed: (16) Device or resource busy
2013-02-04T10:40:39.491 INFO:teuthology.task.rbd:Unloading rbd kernel module...
2013-02-04T10:40:39.491 DEBUG:teuthology.orchestra.run:Running [10.214.132.32]: 'sudo modprobe -r rbd || true'
2013-02-04T10:40:39.506 INFO:teuthology.orchestra.run.err:FATAL: Module rbd is in use.
2013-02-04T10:40:39.508 INFO:teuthology.task.rbd:Deleting rbd images...
2013-02-04T10:40:39.508 DEBUG:teuthology.orchestra.run:Running [10.214.132.32]: 'LD_LIBRARY_PATH=/tmp/cephtest/binary/usr/local/lib /tmp/cephtest/enable-coredump /tmp/cephtest/binary/usr/local/bin/ceph-coverage /tmp/cephtest/archive/coverage /tmp/cephtest/binary/usr/local/bin/rbd -c /tmp/cephtest/ceph.conf -p rbd rm testimage.client.0'
2013-02-04T10:40:39.914 INFO:teuthology.orchestra.run.err:2013-02-04 10:40:18.959420 7fcfda6f4700 0 -
10.214.132.32:0/1029143 >> 10.214.132.29:6800/8592 pipe(0x2085340 sd=12 :36056 s=2 pgs=10 cs=1 l=1).injecting socket failure
2013-02-04T10:40:39.966 INFO:teuthology.orchestra.run.err:2013-02-04 10:40:19.011264 7fcfdacfa700 0 -- 10.214.132.32:0/1029143 >> 10.214.132.31:6803/22416 pipe(0x207ddd0 sd=9 :52957 s=2 pgs=18 cs=1 l=1).injecting socket failure
2013-02-04T10:40:48.084 INFO:teuthology.orchestra.run.out:^MRemoving image: 1% complete...^MRemoving image: 2% complete...^MRemoving image: 3% complete...^MRemoving image: 4% complete...^MRemoving image: 5% complete...^MRemoving image: 6% complete...^MRemoving image: 7% complete...^MRemoving image: 8% complete...^MRemoving image: 9% complete...^MRemoving image: 10% complete...^MRemoving image: 11% complete...^MRemoving image: 12% complete...^MRemoving image: 13% complete...^MRemoving image: 14% complete...^MRemoving image: 15% complete...^MRemoving image: 16% complete...^MRemoving image: 17% complete...^MRemoving image: 18% complete...^MRemoving image: 19% complete...^MRemoving image: 20% complete...^MRemoving image: 21% complete...^MRemoving image: 22% complete...^MRemoving image: 23% complete...^MRemoving image: 24% complete...^MRemoving image: 25% complete...^MRemoving image: 26% complete...^MRemoving image: 27% complete...^MRemoving image: 28% complete...^MRemoving image: 29% complete...^MRemoving image: 30% complete...^MRemoving image: 31% complete...^MRemoving image: 32% complete...^MRemoving image: 33% complete...^MRemoving image: 34% complete...^MRemoving image: 35% complete...^MRemoving image: 36% complete...^MRemoving image: 37% complete...^MRemoving image: 38% complete...^MRemoving image: 39% complete...^MRemoving image: 40% complete...^MRemoving image: 41% complete...^MRemoving image: 42% complete...^MRemoving image: 43% complete...^MRemoving image: 44% complete...^MRemoving image: 45% complete...^MRemoving image: 46% complete...^MRemoving image: 47% complete...^MRemoving image: 48% complete...^MRemoving image: 49% complete...^MRemoving image: 50% complete...^MRemoving image: 51% complete...^MRemoving image: 52% complete...^MRemoving image: 53% complete...^MRemoving image: 54% complete...^MRemoving image: 55% complete...^MRemoving image: 56% complete...^MRemoving image: 57% complete...^MRemoving image: 58% complete...^MRemoving image: 59% complete...^MRemoving image: 60% complete...^MRemoving image: 61% complete...^MRemoving image: 62% complete...^MRemoving image: 63% complete...^MRemoving image: 64% complete...^MRemoving image: 65% complete...^MRemoving image: 66% complete...^MRemoving image: 67% complete...^MRemoving image: 68% complete...^MRemoving image: 69% complete...^MRemoving image: 70% complete...^MRemoving image: 71% complete...^MRemoving image: 72% complete...^MRemoving image: 73% complete...^MRemoving image: 74% complete...^MRemoving image: 75% complete...^MRemoving image: 76% complete...^MRemoving image: 77% complete...^MRemoving image: 78% complete...^MRemoving image: 79% complete...^MRemoving image: 80% complete...^MRemoving image: 81% complete...^MRemoving image: 82% complete...^MRemoving image: 83% complete...^MRemoving image: 84% complete...^MRemoving image: 85% complete...^MRemoving image: 86% complete...^MRemoving image: 87% complete...^MRemoving image: 88% complete...^MRemoving image: 89% complete...^MRemoving image: 90% complete...^MRemoving image: 91% complete...^MRemoving image: 92% complete...^MRemoving image: 93% complete...^MRemoving image: 94% complete...^MRemoving image: 95% complete...^MRemoving image: 96% complete...^MRemoving image: 97% complete...^MRemoving image: 98% complete...^MRemoving image: 99% complete...^MRemoving image: 99% complete...failed.
2013-02-04T10:40:48.085 INFO:teuthology.orchestra.run.err:rbd: error: image still has watchers
2013-02-04T10:40:48.085 INFO:teuthology.orchestra.run.err:This means the image is still open or the client using it crashed. Try again after closing/unmapping it or waiting 30s for the crashed client to timeout.
2013-02-04T10:40:48.085 INFO:teuthology.orchestra.run.err:2013-02-04 10:40:27.129557 7fcfef4a9780 -1 librbd: error removing header: (16) Device or resource busy

History

#1 Updated by Alex Elder about 11 years ago

  • Description updated (diff)
  • Status changed from New to In Progress
  • Assignee set to Alex Elder

This sounds familiar, but I'm going to look a little
more closely to see if I can learn why it's happening.

#2 Updated by Alex Elder about 11 years ago

  • Project changed from CephFS to rbd

#3 Updated by Alex Elder about 11 years ago

There is clearly something that is keeping the rbd image
from getting removed. I reproduced this with just running
the kernel_untar_build.sh script. I'm trying again now
and will interact a bit to see if I can see what's going on.

#4 Updated by Alex Elder about 11 years ago

I really can't tell who's got a watch on the header
object. It should be getting removed when the object
gets unmapped.

I'll have to check this again in the morning.

#5 Updated by Alex Elder about 11 years ago

I had the impression this might be a problem that
is holding up completion of the nightly test suite.

But I'm not sure if that's true. If it's not I would
not consider this an urgent problem. But if it is, it
most certainly is urgent.

Does anyone know? Sam L said yesterday there were
other issues as well, and teuthology runs were being
cancelled, so I'm not totally clear on what's going
on and whether this needs my primary attention.

Until I get an answer I'm putting this aside.

#6 Updated by Sam Lang about 11 years ago

I was able to verify that this happens with an older version of teuthology, one without the changes I've made recently.

I don't think that its holding up completion of the nightly test suite though, just causing a bunch of hung jobs in those runs that the overall run has to wait for before completing.

#7 Updated by Sage Weil about 11 years ago

  • Priority changed from Normal to Urgent

Sam Lang wrote:

I was able to verify that this happens with an older version of teuthology, one without the changes I've made recently.

I don't think that its holding up completion of the nightly test suite though, just causing a bunch of hung jobs in those runs that the overall run has to wait for before completing.

That's good news, but I still consider it urgent since it's preventing us from getting clean runs out of QA without manual cleanup. Alex, unless there is another high priority regression, can you look at this first? Thanks!

#8 Updated by Alex Elder about 11 years ago

Alex, unless there is another high priority regression, can you
look at this first?

Yes I will.

#9 Updated by Alex Elder about 11 years ago

I am able to reproduce this problem by running
the kernel_untar_build.sh workunit.

I ran the test using the ceph "next" branch and
the ceph-client "testing" branch.

I got a lockdep warning involving rbd code and I'm
going to look into that.

#10 Updated by Alex Elder about 11 years ago

I think I found a problem, possibly not the problem.

This commit:
bc7a62ee5 rbd: prevent open for image being removed
added locking around checking for a "removing" flag and
incrementing an open count on an rbd device. It reused
the lock used for the request queue.

The problem is that the spinlock taken doesn't disable
interrupts, but it needs to.

#11 Updated by Alex Elder about 11 years ago

I ran the kernel_untar_build.sh workunit using the
ceph "master" branch and the ceph-client "testing"
branch and got the same results, including some
weird connection problems.

I'll try again with the fix for the spinlock issue
shortly.

#12 Updated by Alex Elder about 11 years ago

The interrupt issue has been fixed, but the other issue
(rbd device can't be unmapped because EBUSY) remains.

I have opened http://tracker.ceph.com/issues/4010 to
keep track of fixing the interrupt disable problem.

#13 Updated by Alex Elder about 11 years ago

I've added some instrumentation and find that the rbd
client is not dropping its watch at the end of the
kernel_untar_build.sh workunit.

Doing simpler tests I did not see that problem.

I am now working backward from this, to see what is
preventing it from removing the watch.

#14 Updated by Sage Weil about 11 years ago

btw i am able to reproduce the EBUSY with just

tasks:
- ceph: null
- rbd:
    all: null
- exec:
    client.0:
      - false

(or true for that matter)

#15 Updated by Sage Weil about 11 years ago

aha:

[ 1200.531157] INFO: task umount:2054 blocked for more than 120 seconds.
[ 1200.580061] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1200.591253] libceph: mon0 10.214.131.27:6789 socket closed (con state CONNECTING)
[ 1200.762516] umount          D 0000000000000002     0  2054   2053 0x00000000
[ 1200.811813]  ffff88020b6a9c68 0000000000000046 ffff88020b6a9c38 0000000000000046
[ 1200.901183]  ffff88020bea1f90 ffff88020b6a9fd8 ffff88020b6a9fd8 ffff88020b6a9fd8
[ 1200.990782]  ffff880225d1bf20 ffff88020bea1f90 ffff88020b6a9c68 ffff880227234ed8
[ 1201.080567] Call Trace:
[ 1201.123130]  [<ffffffff811b6770>] ? __wait_on_buffer+0x30/0x30
[ 1201.169448]  [<ffffffff8165c329>] schedule+0x29/0x70
[ 1201.213872]  [<ffffffff8165c3ff>] io_schedule+0x8f/0xd0
[ 1201.257770]  [<ffffffff811b677e>] sleep_on_buffer+0xe/0x20
[ 1201.301230]  [<ffffffff81659fef>] __wait_on_bit+0x5f/0x90
[ 1201.343871]  [<ffffffff811b6770>] ? __wait_on_buffer+0x30/0x30
[ 1201.386355]  [<ffffffff8165a09c>] out_of_line_wait_on_bit+0x7c/0x90
[ 1201.428758]  [<ffffffff81280bf8>] ? journal_destroy+0x1c8/0x210
[ 1201.470160]  [<ffffffff8107ae70>] ? autoremove_wake_function+0x40/0x40
[ 1201.511741]  [<ffffffff811b676e>] __wait_on_buffer+0x2e/0x30
[ 1201.551800]  [<ffffffff811b7a50>] __sync_dirty_buffer+0xa0/0xd0
[ 1201.591425]  [<ffffffff811b7a93>] sync_dirty_buffer+0x13/0x20
[ 1201.630119]  [<ffffffff81213f7e>] ext3_commit_super.constprop.90+0x6e/0xf0
[ 1201.669903]  [<ffffffff81214741>] ext3_put_super+0x281/0x2b0
[ 1201.707509]  [<ffffffff81185f92>] generic_shutdown_super+0x62/0xf0
[ 1201.745168]  [<ffffffff81186050>] kill_block_super+0x30/0x80
[ 1201.781601]  [<ffffffff81186325>] deactivate_locked_super+0x45/0x70
[ 1201.818325]  [<ffffffff81186fde>] deactivate_super+0x4e/0x70
[ 1201.853647]  [<ffffffff811a3826>] mntput_no_expire+0x106/0x160
[ 1201.888443]  [<ffffffff811a474e>] sys_umount+0x6e/0x3b0
[ 1201.921770]  [<ffffffff81666619>] system_call_fastpath+0x16/0x1b
[ 1201.955391] INFO: lockdep is turned off.

umount is hanging. this is what is preventing the rbd unmap from succeeding, from what i can tell.. and is also preventing nuke form working.

#16 Updated by Alex Elder about 11 years ago

I found that unmount was hanging too. I think somehow the
completion of the I/O is not getting propagated up when
the initiator is waiting for it synchronously or something.
It works up until that final sync, and seems to get stuck
(from what I can tell).

I have pushed a version of the testing branch that does
not include any of the new rbd code and have done some
early testing and it looks better. At least these problems
go away... I can work on resolving this without holding
up the rest of the nightly testing.

testing-next       c7baef7 ceph: remove 'ceph.layout' virtual xattr

#17 Updated by Sage Weil about 11 years ago

new theory:

the reason umount hangs is because nuke is killing the client and osds at the same time. the umount ios cant complete, and it hangs.

the root cause is that rbd.py isn't unmounting and unmapping on failure, even though it says it is. trying to verify if that's the case...

#18 Updated by Sage Weil about 11 years ago

This was backing up qa stuff because the rbd.py qa task wasn't unmounting during cleanup. That bit is now fixed. I suspect this was a wild goose chase... doing a full run now.

#19 Updated by Alex Elder about 11 years ago

That sounds promising, I hope it works!

This was actually the last thing I was looking at last
night while waiting for a build, but my Python Fu is not
strong. It looked to me like the unmount should be
occurring (but I didn't consider the concurrency thing).

Anyway, sounds like great news.

#20 Updated by Alex Elder about 11 years ago

Seems to have done the trick! The kernel_untar_build.sh
task just finished for me without error, and it failed
reliably last night.

Still, I found two other problems with the rbd code in
the process of investigating this, 4010 mentioned earlier
and now http://tracker.ceph.com/issues/4033.

#21 Updated by Alex Elder about 11 years ago

  • Assignee changed from Alex Elder to Sage Weil

The testing I've been doing now has shown no problems
now that teuthology has been updated.

The two other issues I opened (4010 and 4033) document
two rbd bugs found and fixed while investigating this. But
ultimately this has turned out not to be an rbd problem.

I'm reassigning this to Sage, and he can close it when
he's comfortable that it's complete.

#22 Updated by Sage Weil about 11 years ago

  • Status changed from In Progress to Resolved

closing this. phew!

Also available in: Atom PDF