Bug #10116
closedCeph vm guest disk lockup when using fio
0%
Description
When running a disk benchmark within a guest, I'm getting a disk lockup that doesn't ever appear to resolve itself. This issue ONLY happens when running the VM that resides on RBD, when using a local disk instead, the guest does not lock up.
Here is the command I run in the guest:
fio --rw=randrw --refill_buffers --norandommap --randrepeat=0 --ioengine=libaio --bs=4k --rwmixread=100 --iodepth=16 --numjobs=16 --runtime=60 --group_reporting --name=4ktest --size=128m
The lockup also occurs when using other ioengines like sync.
However, using a lower "numjobs" such as 4 works fine with a result like:
read : io=524288KB, bw=49818KB/s, iops=12454, runt= 10524msec
I'm using qemu 2.1.2 (and have also tried qemu 1.7 with the same results). Both ceph firefly and ceph giant have the issue.
Now, the odd part is I can only reproduce this issue on the new production gear we are QAing. Our test lab cannot reproduce this issue. However, the test lab equipment is much slower and only uses 1Gb networking gear, the new production uses 10Gb SFP+ direct attach for low latency and high performance.
The environment is proxmox 3.3 (Debian Wheezy 64bit), and it is passing this as the command line option for qemu:
-drive file=rbd:ssd/vm-101-disk-1:mon_host=ceph1 ceph2 ceph3:id=admin:auth_supported=cephx:keyring=/etc/pve/priv/ceph/ssd.keyring,if=none,id=drive-virtio0,aio=native,cache=none,detect-zeroes=on
I'm not even sure where to begin. Everything else looks great, and performance is great. I haven't yet reproduced a lockup outside of the fio benchmark, but I'm sure its possible.
Files
Updated by Brad House over 9 years ago
I wonder if this isn't the issue from #9854.
fio gets through writing the test files, and the lock occurs during the 4k read operations as the test is set to 100% read.
Updated by Brad House over 9 years ago
What is more interesting to me is if I break into it with GDB when it is hung, then tell it to continue, I get notifications of 2 SIGPIPEs so I continue twice more, and the VM comes back to life and the guest outputs something like:
Message from syslogd@centostest at Nov 17 08:25:03 ... kernel:BUG: soft lockup - CPU#0 stuck for 23s! [fio:2152]
Not sure if it helps, but this is what GDB shows:
(gdb) info threads Id Target Id Frame 22 Thread 0x7fd35331f700 (LWP 4047) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6 21 Thread 0x7fd350e16700 (LWP 4046) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 20 Thread 0x7fd356d97700 (LWP 323) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 19 Thread 0x7fd355e31700 (LWP 324) "kvm" 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 18 Thread 0x7fd355424700 (LWP 325) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 17 Thread 0x7fd354c23700 (LWP 326) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 16 Thread 0x7fd354422700 (LWP 327) "kvm" 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 15 Thread 0x7fd353c21700 (LWP 328) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 12 Thread 0x7fd35321e700 (LWP 331) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 11 Thread 0x7fd352a1d700 (LWP 332) "kvm" 0x00007fd35fd5e20b in ?? () from /lib/x86_64-linux-gnu/libc.so.6 10 Thread 0x7fd35221c700 (LWP 333) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 9 Thread 0x7fd35211b700 (LWP 334) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6 8 Thread 0x7fd35201a700 (LWP 335) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 7 Thread 0x7fd351f19700 (LWP 338) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6 6 Thread 0x7fd351e18700 (LWP 339) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 5 Thread 0x7fd351617700 (LWP 340) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 4 Thread 0x7fd2cbbff700 (LWP 342) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 3 Thread 0x7fd3501ff700 (LWP 344) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 2 Thread 0x7fd2cbfff700 (LWP 345) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6 * 1 Thread 0x7fd366551900 (LWP 32765) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) thread 18 [Switching to thread 18 (Thread 0x7fd355424700 (LWP 325))] #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd364b953ab in Mutex::Lock(bool) () from /usr/lib/librados.so.2 #4 0x00007fd365962ed6 in Finisher::queue (this=0x7fd367d4a328, c=0x7fd34c010690, r=0) at ./common/Finisher.h:51 #5 0x00007fd364b20834 in librados::IoCtxImpl::C_aio_Ack::finish(int) () from /usr/lib/librados.so.2 #6 0x00007fd3658f83e9 in Context::complete (this=0x7fd34c00a340, r=<optimized out>) at ./include/Context.h:64 #7 0x00007fd365933270 in Objecter::handle_osd_op_reply (this=<optimized out>, m=0x7fd294001860) at osdc/Objecter.cc:1863 #8 0x00007fd364b176a4 in librados::RadosClient::_dispatch(Message*) () from /usr/lib/librados.so.2 #9 0x00007fd364b177db in librados::RadosClient::ms_dispatch(Message*) () from /usr/lib/librados.so.2 #10 0x00007fd364cb4b3b in DispatchQueue::entry() () from /usr/lib/librados.so.2 #11 0x00007fd364d2037d in DispatchQueue::DispatchThread::entry() () from /usr/lib/librados.so.2 #12 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #13 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6 #14 0x0000000000000000 in ?? () (gdb) thread 12 [Switching to thread 12 (Thread 0x7fd35321e700 (LWP 331))] #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd360011c4e in _L_cond_lock_1001 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd360011a7b in __pthread_mutex_cond_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd36000c76f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0 #4 0x00007fd364bb51b8 in SafeTimer::timer_thread() () from /usr/lib/librados.so.2 #5 0x00007fd364bb60ed in SafeTimerThread::entry() () from /usr/lib/librados.so.2 #6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000000000000000 in ?? () (gdb) thread 6 [Switching to thread 6 (Thread 0x7fd351e18700 (LWP 339))] #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd366a1e9b9 in ?? () #4 0x00007fd36676752d in ?? () #5 0x00007fd36675380c in ?? () #6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000000000000000 in ?? () (gdb) thread 5 [Switching to thread 5 (Thread 0x7fd351617700 (LWP 340))] #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd366a1e9b9 in ?? () #4 0x00007fd36676752d in ?? () #5 0x00007fd36675380c in ?? () #6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000000000000000 in ?? () (gdb) thread 1 [Switching to thread 1 (Thread 0x7fd366551900 (LWP 32765))] #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd364b953ab in Mutex::Lock(bool) () from /usr/lib/librados.so.2 #4 0x00007fd364b218c9 in librados::IoCtxImpl::aio_operate_read(object_t const&, ObjectOperation*, librados::AioCompletionImpl*, int, ceph::buffer::list*) () from /usr/lib/librados.so.2 #5 0x00007fd364af6c98 in librados::IoCtx::aio_operate(std::string const&, librados::AioCompletion*, librados::ObjectReadOperation*, int, ceph::buffer::list*) () from /usr/lib/librados.so.2 #6 0x00007fd3658f8e65 in librbd::AioRead::send (this=0x7fd367e0ef00) at librbd/AioRequest.cc:102 #7 0x00007fd36590b23a in librbd::aio_read (ictx=ictx@entry=0x7fd34c006c90, image_extents=..., buf=buf@entry=0x7fd367e64c00 "\330\324\377_\323\177", pbl=pbl@entry=0x0, c=c@entry=0x7fd367dfb800) at librbd/internal.cc:3153 #8 0x00007fd36590b794 in librbd::aio_read (ictx=0x7fd34c006c90, off=19317301248, len=4096, buf=0x7fd367e64c00 "\330\324\377_\323\177", bl=0x0, c=0x7fd367dfb800) at librbd/internal.cc:3091 #9 0x00007fd366a0e5bb in ?? () #10 0x00007fd366a0e850 in ?? () #11 0x00007fd3669bcf8e in ?? () #12 0x00007fd3669c2243 in ?? () #13 0x00007fd3669c2757 in ?? () #14 0x00007fd3669c215b in ?? () #15 0x00007fd3669c2757 in ?? () #16 0x00007fd3669c36e7 in ?? () #17 0x00007fd3669d524a in ?? () #18 0x00007fd35fcb7d10 in ?? () from /lib/x86_64-linux-gnu/libc.so.6 #19 0x00007fff37b7e590 in ?? () #20 0x0000000000000000 in ?? () (gdb) c Continuing. [Thread 0x7fd35331f700 (LWP 4047) exited] [Thread 0x7fd350e16700 (LWP 4046) exited] [New Thread 0x7fd353420700 (LWP 7960)] [New Thread 0x7fd35331f700 (LWP 7961)] Program received signal SIGPIPE, Broken pipe. 0x00007fd36000f19d in write () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) c Continuing. Program received signal SIGPIPE, Broken pipe. 0x00007fd36000f19d in write () from /lib/x86_64-linux-gnu/libpthread.so.0 (gdb) c Continuing.
And this is consistent. I can always get it to unlock by breaking into it with GDB, wait 20-30s, then continue.
Updated by Brad House over 9 years ago
Realized I was missing the librados debug symbols, here it is again, and also backtraced all threads:
(gdb) info threads
Id Target Id Frame
18 Thread 0x7fd356d97700 (LWP 323) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
17 Thread 0x7fd355e31700 (LWP 324) "kvm" 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
16 Thread 0x7fd355424700 (LWP 325) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
15 Thread 0x7fd354c23700 (LWP 326) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
14 Thread 0x7fd354422700 (LWP 327) "kvm" 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
13 Thread 0x7fd353c21700 (LWP 328) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
12 Thread 0x7fd35321e700 (LWP 331) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
11 Thread 0x7fd352a1d700 (LWP 332) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
10 Thread 0x7fd35221c700 (LWP 333) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
9 Thread 0x7fd35211b700 (LWP 334) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
8 Thread 0x7fd351e18700 (LWP 339) "kvm" 0x00007fd35fd4a807 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
7 Thread 0x7fd351617700 (LWP 340) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
6 Thread 0x7fd2cbbff700 (LWP 342) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
5 Thread 0x7fd3501ff700 (LWP 344) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
4 Thread 0x7fd2cbfff700 (LWP 345) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
3 Thread 0x7fd351f19700 (LWP 19942) "kvm" 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
2 Thread 0x7fd35331f700 (LWP 19945) "kvm" 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
* 1 Thread 0x7fd366551900 (LWP 32765) "kvm" 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) thread 18
[Switching to thread 18 (Thread 0x7fd356d97700 (LWP 323))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364dca25b in ceph::log::Log::entry (this=0x7fd367d470f0) at log/Log.cc:323
#2 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#4 0x0000000000000000 in ?? ()
(gdb) thread 17
[Switching to thread 17 (Thread 0x7fd355e31700 (LWP 324))]
#0 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364bcff72 in WaitUntil (when=..., mutex=..., this=0x7fd367d61a38) at ./common/Cond.h:71
#2 WaitInterval (interval=..., mutex=..., cct=<optimized out>, this=0x7fd367d61a38) at ./common/Cond.h:79
#3 CephContextServiceThread::entry (this=0x7fd367d619c0) at common/ceph_context.cc:58
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 16
[Switching to thread 16 (Thread 0x7fd355424700 (LWP 325))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd364b953ab in Mutex::Lock (this=0x7fd367d4a150, no_lockdep=<optimized out>) at common/Mutex.cc:89
#4 0x00007fd364b1776e in Locker (m=..., this=0x7fd355423880) at ./common/Mutex.h:120
#5 librados::RadosClient::ms_dispatch (this=0x7fd367d49930, m=0x7fd34c111ea0) at librados/RadosClient.cc:352
#6 0x00007fd364cb4b3b in ms_deliver_dispatch (m=0x7fd34c111ea0, this=0x7fd367d63610) at msg/Messenger.h:587
#7 DispatchQueue::entry (this=0x7fd367d63708) at msg/DispatchQueue.cc:124
#8 0x00007fd364d2037d in DispatchQueue::DispatchThread::entry (this=<optimized out>) at msg/DispatchQueue.h:104
#9 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#10 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#11 0x0000000000000000 in ?? ()
(gdb) thread 15
[Switching to thread 15 (Thread 0x7fd354c23700 (LWP 326))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364d1bba8 in Wait (mutex=..., this=0x7fd367d63b58) at ./common/Cond.h:55
#2 SimpleMessenger::reaper_entry (this=0x7fd367d63610) at msg/SimpleMessenger.cc:210
#3 0x00007fd364d20a9d in SimpleMessenger::ReaperThread::entry (this=<optimized out>) at msg/SimpleMessenger.h:225
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 14
[Switching to thread 14 (Thread 0x7fd354422700 (LWP 327))]
#0 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c6bb in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364bb51b8 in WaitUntil (when=..., mutex=..., this=0x7fd367d49d50) at common/Cond.h:71
#2 SafeTimer::timer_thread (this=0x7fd367d49d40) at common/Timer.cc:114
#3 0x00007fd364bb60ed in SafeTimerThread::entry (this=<optimized out>) at common/Timer.cc:38
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 13
[Switching to thread 13 (Thread 0x7fd353c21700 (LWP 328))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364bb6b42 in Wait (mutex=..., this=0x7fd367d49e68) at ./common/Cond.h:55
#2 Finisher::finisher_thread_entry (this=0x7fd367d49e08) at common/Finisher.cc:78
#3 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#4 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#5 0x0000000000000000 in ?? ()
(gdb) thread 12
[Switching to thread 12 (Thread 0x7fd35321e700 (LWP 331))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd360011c4e in _L_cond_lock_1001 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd360011a7b in __pthread_mutex_cond_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd36000c76f in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#4 0x00007fd364bb51b8 in WaitUntil (when=..., mutex=..., this=0x7fd367d4a248) at common/Cond.h:71
#5 SafeTimer::timer_thread (this=0x7fd367d4a238) at common/Timer.cc:114
#6 0x00007fd364bb60ed in SafeTimerThread::entry (this=<optimized out>) at common/Timer.cc:38
#7 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#8 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#9 0x0000000000000000 in ?? ()
(gdb) thread 11
[Switching to thread 11 (Thread 0x7fd352a1d700 (LWP 332))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364bb6b42 in Wait (mutex=..., this=0x7fd367d4a388) at ./common/Cond.h:55
#2 Finisher::finisher_thread_entry (this=0x7fd367d4a328) at common/Finisher.cc:78
#3 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#4 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#5 0x0000000000000000 in ?? ()
(gdb) thread 10
[Switching to thread 10 (Thread 0x7fd35221c700 (LWP 333))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364d0b81a in Wait (mutex=..., this=0x7fd34c008100) at ./common/Cond.h:55
#2 Pipe::writer (this=0x7fd34c007ef0) at msg/Pipe.cc:1730
#3 0x00007fd364d17c5d in Pipe::Writer::entry (this=<optimized out>) at msg/Pipe.h:61
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 9
[Switching to thread 9 (Thread 0x7fd35211b700 (LWP 334))]
#0 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fd364d0087c in Pipe::tcp_read_wait (this=this@entry=0x7fd34c007ef0) at msg/Pipe.cc:2282
#2 0x00007fd364d00b10 in Pipe::tcp_read (this=this@entry=0x7fd34c007ef0, buf=<optimized out>, buf@entry=0x7fd35211ab4f "\377", len=len@entry=1) at msg/Pipe.cc:2255
#3 0x00007fd364d12a9f in Pipe::reader (this=0x7fd34c007ef0) at msg/Pipe.cc:1421
#4 0x00007fd364d17d7d in Pipe::Reader::entry (this=<optimized out>) at msg/Pipe.h:49
#5 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#6 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#7 0x0000000000000000 in ?? ()
(gdb) thread 8
[Switching to thread 8 (Thread 0x7fd351e18700 (LWP 339))]
#0 0x00007fd35fd4a807 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007fd35fd4a807 in ioctl () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fd3667673e9 in ?? ()
#2 0x00007fd366767525 in ?? ()
#3 0x00007fd36675380c in ?? ()
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 7
[Switching to thread 7 (Thread 0x7fd351617700 (LWP 340))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd366a1e9b9 in ?? ()
#4 0x00007fd36676752d in ?? ()
#5 0x00007fd36675380c in ?? ()
#6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x0000000000000000 in ?? ()
(gdb) thread 6
[Switching to thread 6 (Thread 0x7fd2cbbff700 (LWP 342))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd366a1ebd9 in ?? ()
#2 0x00007fd3669b7e8b in ?? ()
#3 0x00007fd3669b8260 in ?? ()
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 5
[Switching to thread 5 (Thread 0x7fd3501ff700 (LWP 344))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd36000a3df in _L_lock_1145 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd36000a32a in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd35d882909 in PR_Lock () from /usr/lib/x86_64-linux-gnu/libnspr4.so
#4 0x00007fd356374b5b in ?? () from /usr/lib/x86_64-linux-gnu/nss/libsoftokn3.so
#5 0x00007fd3563676b8 in ?? () from /usr/lib/x86_64-linux-gnu/nss/libsoftokn3.so
#6 0x00007fd35e58f1ca in ?? () from /usr/lib/x86_64-linux-gnu/libnss3.so
#7 0x00007fd35e596db7 in ?? () from /usr/lib/x86_64-linux-gnu/libnss3.so
#8 0x00007fd35e597afb in PK11_ImportSymKey () from /usr/lib/x86_64-linux-gnu/libnss3.so
#9 0x00007fd364d44959 in nss_aes_operation (op=260, secret=..., in=..., out=..., error=...) at auth/Crypto.cc:127
#10 0x00007fd364d43881 in CryptoKey::encrypt (this=0x7fd367dc0838, cct=0x7fd367d449b0, in=..., out=..., error=...) at auth/Crypto.cc:358
#11 0x00007fd364d4303e in encode_encrypt_enc_bl<ceph::buffer::list> (cct=cct@entry=0x7fd367d449b0, t=..., key=..., out=..., error=...) at auth/cephx/CephxProtocol.h:465
#12 0x00007fd364d43172 in encode_encrypt<ceph::buffer::list> (cct=0x7fd367d449b0, t=..., key=..., out=..., error=...) at auth/cephx/CephxProtocol.h:490
#13 0x00007fd364d42659 in CephxSessionHandler::sign_message (this=0x7fd367dc0820, m=0x7fd367da5820) at auth/cephx/CephxSessionHandler.cc:48
#14 0x00007fd364d0bffb in Pipe::writer (this=0x7fd367dbf4f0) at msg/Pipe.cc:1693
#15 0x00007fd364d17c5d in Pipe::Writer::entry (this=<optimized out>) at msg/Pipe.h:61
#16 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#17 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#18 0x0000000000000000 in ?? ()
(gdb) thread 4
[Switching to thread 4 (Thread 0x7fd2cbfff700 (LWP 345))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd364b953ab in Mutex::Lock (this=0x7fd367dbf628, no_lockdep=<optimized out>) at common/Mutex.cc:89
#4 0x00007fd364d136ae in Pipe::reader (this=0x7fd367dbf4f0) at msg/Pipe.cc:1485
#5 0x00007fd364d17d7d in Pipe::Reader::entry (this=<optimized out>) at msg/Pipe.h:49
#6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#8 0x0000000000000000 in ?? ()
(gdb) thread 3
[Switching to thread 3 (Thread 0x7fd351f19700 (LWP 19942))]
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000c344 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd364d0b81a in Wait (mutex=..., this=0x7fd29410fd00) at ./common/Cond.h:55
#2 Pipe::writer (this=0x7fd29410faf0) at msg/Pipe.cc:1730
#3 0x00007fd364d17c5d in Pipe::Writer::entry (this=<optimized out>) at msg/Pipe.h:61
#4 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#5 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#6 0x0000000000000000 in ?? ()
(gdb) thread 2
[Switching to thread 2 (Thread 0x7fd35331f700 (LWP 19945))]
#0 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
(gdb) bt
#0 0x00007fd35fd46b73 in poll () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007fd364d0087c in Pipe::tcp_read_wait (this=this@entry=0x7fd29410faf0) at msg/Pipe.cc:2282
#2 0x00007fd364d00b10 in Pipe::tcp_read (this=this@entry=0x7fd29410faf0, buf=<optimized out>, buf@entry=0x7fd35331eb4f "\377\250\b\327g\323\177", len=len@entry=1) at msg/Pipe.cc:2255
#3 0x00007fd364d12a9f in Pipe::reader (this=0x7fd29410faf0) at msg/Pipe.cc:1421
#4 0x00007fd364d17d7d in Pipe::Reader::entry (this=<optimized out>) at msg/Pipe.h:49
#5 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0
#6 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6
#7 0x0000000000000000 in ?? ()
(gdb) thread 1
[Switching to thread 1 (Thread 0x7fd366551900 (LWP 32765))]
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) bt
#0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0
#1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0
#2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0
#3 0x00007fd364b953ab in Mutex::Lock (this=0x7fd367dbf628, no_lockdep=<optimized out>) at common/Mutex.cc:89
#4 0x00007fd364d1cc3a in SimpleMessenger::submit_message (this=this@entry=0x7fd367d63610, m=m@entry=0x7fd294a53cd0, con=con@entry=0x7fd367d7fc80, dest_addr=..., dest_type=4, lazy=lazy@entry=false) at msg/SimpleMessenger.cc:429
#5 0x00007fd364d1d6a9 in SimpleMessenger::_send_message (this=0x7fd367d63610, m=0x7fd294a53cd0, con=0x7fd367d7fc80, lazy=false) at msg/SimpleMessenger.cc:138
#6 0x00007fd3659311b5 in send_message (con=..., m=0x7fd294a53cd0, this=<optimized out>) at ./msg/Messenger.h:411
#7 Objecter::send_op (this=this@entry=0x7fd367d64060, op=op@entry=0x7fd29433c4c0) at osdc/Objecter.cc:1678
#8 0x00007fd365931981 in Objecter::_op_submit (this=0x7fd367d64060, op=0x7fd29433c4c0) at osdc/Objecter.cc:1340
#9 0x00007fd364b218d8 in librados::IoCtxImpl::aio_operate_read (this=0x7fd34c007200, oid=..., o=0x7fd294128e70, c=<optimized out>, flags=0, pbl=0x0) at librados/IoCtxImpl.cc:594
#10 0x00007fd364af6c98 in librados::IoCtx::aio_operate (this=0x7fd34c006dd8, oid=..., c=0x7fd294a563e0, o=0x7fd2a8759fc0, flags=0, pbl=<optimized out>) at librados/librados.cc:1106
#11 0x00007fd3658f8e65 in librbd::AioRead::send (this=0x7fd367dbae00) at librbd/AioRequest.cc:102
#12 0x00007fd36590b23a in librbd::aio_read (ictx=ictx@entry=0x7fd34c006c90, image_extents=...,
buf=buf@entry=0x7fd367da9200 "\240\344\323r\036\237\313&\224|\n\334y:\252\r\222O7\375IY\204\027\362\351?\215\214\311\006>\275\002\276\242e\260\v\247W!\371\262\255\326\003\364\252P\263%Yr\021^\025\360`|qG\025\253\002o\201\267\275\374\037U`\330n\377\326\020\t\n\214\260\275sc\265\006\201\021\261\061\226\315\342\b0\242u=\332@\230\bF\264\226v`\351\365\003\210?\264\340\201\070", pbl=pbl@entry=0x0, c=c@entry=0x7fd367df4eb0) at librbd/internal.cc:3153
#13 0x00007fd36590b794 in librbd::aio_read (ictx=0x7fd34c006c90, off=18723979264, len=4096,
buf=0x7fd367da9200 "\240\344\323r\036\237\313&\224|\n\334y:\252\r\222O7\375IY\204\027\362\351?\215\214\311\006>\275\002\276\242e\260\v\247W!\371\262\255\326\003\364\252P\263%Yr\021^\025\360`|qG\025\253\002o\201\267\275\374\037U`\330n\377\326\020\t\n\214\260\275sc\265\006\201\021\261\061\226\315\342\b0\242u=\332@\230\bF\264\226v`\351\365\003\210?\264\340\201\070", bl=0x0, c=0x7fd367df4eb0) at librbd/internal.cc:3091
#14 0x00007fd366a0e5bb in ?? ()
#15 0x00007fd366a0e850 in ?? ()
#16 0x00007fd3669bcf8e in ?? ()
#17 0x00007fd3669c2243 in ?? ()
#18 0x00007fd3669c2757 in ?? ()
#19 0x00007fd3669c215b in ?? ()
#20 0x00007fd3669c2757 in ?? ()
#21 0x00007fd3669c36e7 in ?? ()
#22 0x00007fd3669d524a in ?? ()
#23 0x00007fd35fcb7d10 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#24 0x00007fff37b7e550 in ?? ()
#25 0x04145ee5e0babd31 in ?? ()
#26 0x0000000000200020 in ?? ()
#27 0x0000000000206851 in ?? ()
#28 0x00007fd2a89611a0 in ?? ()
#29 0x00007fd2a835a7f0 in ?? ()
#30 0x00007fd2a89611a0 in ?? ()
#31 0x00007fd2a835a7f0 in ?? ()
#32 0x7461645f64627220 in ?? ()
#33 0x3437356137312e61 in ?? ()
#34 0x302e313563643062 in ?? ()
#35 0x3030303030303030 in ?? ()
#36 0x2033643131303030 in ?? ()
#37 0x2d6573726170735b in ?? ()
#38 0x3735312064616572 in ?? ()
#39 0x3930347e30363936 in ?? ()
#40 0x2030273076205d36 in ?? ()
#41 0x6f20303636327675 in ?? ()
#42 0x203d206b7369646e in ?? ()
#43 0x3d3d203676202930 in ?? ()
#44 0x302b353032203d3d in ?? ()
#45 0x312820303231342b in ?? ()
#46 0x3733383137393338 in ?? ()
#47 0x3933303420302037 in ?? ()
#48 0x2029373832333937 in ?? ()
#49 0x6334336466377830 in ?? ()
#50 0x6320303034333032 in ?? ()
#51 0x6466377830206e6f in ?? ()
#52 0x3863663764373633 in ?? ()
#53 0x0000000000000030 in ?? ()
#54 0x0000000000000000 in ?? ()
(gdb) c
Continuing.
[Thread 0x7fd351f19700 (LWP 19942) exited]
[New Thread 0x7fd353420700 (LWP 23330)]
[Thread 0x7fd35331f700 (LWP 19945) exited]
[New Thread 0x7fd35331f700 (LWP 23331)]
Program received signal SIGPIPE, Broken pipe.
0x00007fd36000f19d in write () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) c
Continuing.
Program received signal SIGPIPE, Broken pipe.
0x00007fd36000f19d in write () from /lib/x86_64-linux-gnu/libpthread.so.0
(gdb) c
Continuing.
Updated by Brad House over 9 years ago
I should also mention I am brad_mssw in the #ceph IRC channel on oftc if there are any suggestions or things to try.
Updated by Brad House over 9 years ago
During lockup:
ceph --admin-daemon /var/run/ceph/ceph-osd.0.asok dump_ops_in_flight
{ "num_ops": 0,
"ops": []}
ceph --admin-daemon /var/run/ceph/ceph-osd.1.asok dump_ops_in_flight
{ "num_ops": 0,
"ops": []}
ceph --admin-daemon /var/run/ceph/ceph-osd.2.asok dump_ops_in_flight
{ "num_ops": 0,
"ops": []}
Updated by alexandre derumier over 9 years ago
Hi,
kernel:BUG: soft lockup - CPU#0 stuck for 23s!
by default share 1thread for many things (clock,io access,...).
And ceph librbd is quite cpu intensive.
So It's possible that you have 1thread at 100% usage.
If you use proxmox pvetest repository, I have added a
iothread: 1
option, to enable new iothread feature from last qemu.
It could improve performance.
I'm also looking to implement krbd support in proxmox soon, which use a lot less cpu (4x) than librbd currently
Updated by alexandre derumier over 9 years ago
alexandre derumier wrote:
Hi,
kernel:BUG: soft lockup - CPU#0 stuck for 23s!
by default share 1thread for many things (clock,io access,...).
And ceph librbd is quite cpu intensive.
So It's possible that you have 1thread at 100% usage.If you use proxmox pvetest repository, I have added a
iothread: 1
option, to enable new iothread feature from last qemu.
It could improve performance.
I'm also looking to implement krbd support in proxmox soon, which use a lot less cpu (4x) than librbd currently
patch for krbd support in proxmox pve-storage rbd plugin (need pve-kernel 3.10)
http://pve.proxmox.com/pipermail/pve-devel/2014-November/013175.html
(you need to a "krbd" in your /etc/pve/storage.cfg rbd config)
Updated by Brad House over 9 years ago
CPU usage is 0 when the lock occurs, so I don't think it is due to excess cpu usage.
I can definitely try those options, is the krbd support in the pvetest repo?
Thanks.
-Brad
Updated by Jason Dillaman over 9 years ago
Brad, it would be helpful to see a few back-to-back GDB backtraces. In the full backtrace above, all blocked threads are (indirectly) waiting on thread 5 to complete the encryption process. If you can run this a couple times and attach the resulting output, that would be great.
gdb -ex "set pagination 0" -ex "thread apply all bt" --batch -p *QEMU PID*
Updated by Brad House over 9 years ago
logs from 3 runs back-to-back, forcibly killing the vm and restarting it between each attempt
Updated by Jason Dillaman over 9 years ago
None of the Ceph threads in the provided backtraces appeared to be deadlocked. It's possible a IO completion is being dropped, hanging the guest OS. Can you update your QEMU RBD command-line to the following:
drive file=rbd:ssd/vm-101-disk-1:rbd_cache=0:debug_rbd=20:debug_ms=1:log_file=/tmp/qemu.log:mon_host=ceph1 ceph2 ceph3:id=admin:auth_supported=cephx:keyring=/etc/pve/priv/ceph/ssd.keyring,if=none,id=drive-virtio0,aio=native,cache=none,detect-zeroes=on
Also, please provide a blktrace output from the guest:
# ssh GUEST_HOST 'blktrace -d /dev/vda1 -o -' > /tmp/blktrace.dat
Before starting your fio test, open another terminal to the guest so that you can send a 'pkill -TERM blktrace' once you've hit the hang (if possible), followed by a hard-poweroff of the guest. Then attach /tmp/blktrace.dat and /tmp/qemu.log to the ticket.
Thanks!
Updated by Brad House over 9 years ago
- File blktrace_qemu.tar.xz blktrace_qemu.tar.xz added
blktrace and qemu log attached as requested. I could not gracefully kill blktrace as the vm hardlocked so hopefully it isn't corrupt.
Updated by Brad House over 9 years ago
Using krbd instead of librbd with qemu doesn't hang, however, in the guest with dd, the total sequential performance is about half. With fio 4k reads, the iops are about 10% of what librbd can do.
Updated by Jason Dillaman over 9 years ago
I can see four outstanding read requests in the last set of logs that you provided. Any chance you can re-run the same data gathering with additional logging enabled?
-drive file=rbd:ssd/vm-101-disk-1:rbd_cache=0:debug_rbd=20:debug_rados=20:debug_objecter=20:debug_ms=20:log_file=/tmp/qemu.log:mon_host=ceph1 ceph2 ceph3:id=admin:auth_supported=cephx:keyring=/etc/pve/priv/ceph/ssd.keyring,if=none,id=drive-virtio0,aio=native,cache=none,detect-zeroes=on
Updated by Brad House over 9 years ago
Sure, I'll do that this morning first. Then I found the repo that proxmox is using to build qemu-kvm, so I'll rebuild that package with debugging symbols and see if I can get a more meaningful backtrace. I've got a meeting at 10:30am EST so that second portion will probably be after the meeting.
Updated by Brad House over 9 years ago
- File blktrace-11182014.dat.xz blktrace-11182014.dat.xz added
Attacked is the blktrace of the latest lockup.
Then the qemu output exceeded your max file size (by a couple of KB), so I've uploaded it here: http://brad-house.com/other/qemu-11182014.log.xz
Updated by Jason Dillaman over 9 years ago
Thanks, I'll start reviewing these this morning.
Updated by Jason Dillaman over 9 years ago
Logs show that the pipe reader to osd.0 is hung waiting for the pipe lock. The last message from that thread is:
2014-11-18 08:09:41.330394 7ff362452700 20 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).reader got 205 + 0 + 4120 byte message
However, numerous other threads also acquire and release the osd.0 pipe lock after the apparent deadlock in the osd.0 reader pipe.
2014-11-18 08:10:41.977178 7ff362553700 10 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer: state = open policy.server=0 2014-11-18 08:10:41.977198 7ff362553700 20 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer encoding 42133 features 17592186044415 0x7ff377b823a0 ping v1 2014-11-18 08:10:41.977252 7ff362553700 20 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer signed seq # 42133): sig = 2835095771445990709 2014-11-18 08:10:41.977261 7ff362553700 20 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer sending 42133 0x7ff377b823a0 2014-11-18 08:10:41.977295 7ff362553700 10 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer: state = open policy.server=0 2014-11-18 08:10:41.977303 7ff362553700 20 -- 10.55.30.41:0/1023222 >> 10.55.30.41:6800/18079 pipe(0x7ff377af1090 sd=18 :55051 s=2 pgs=170 cs=1 l=1 c=0x7ff377af1320).writer sleeping
In addition to possibly installing the debug symbols for qemu, can you also install libc6-dbg so that I can see exactly where __lll_lock_wait is waiting?
Updated by Greg Farnum over 9 years ago
Jason, exactly what information is making you think the Pipe is hung waiting on a lock? And what version is in use right now? The RBD client shouldn't be able to deadlock the messenger, although we've seen a number of issues with the OSD fast dispatch and deep lock cycles...
Updated by Jason Dillaman over 9 years ago
Greg, incidentally several of the attached backtraces show the Pipe reader thread waiting on the pipe lock:
(gdb) bt #0 0x00007fd36000ed5c in __lll_lock_wait () from /lib/x86_64-linux-gnu/libpthread.so.0 #1 0x00007fd36000a3a9 in _L_lock_926 () from /lib/x86_64-linux-gnu/libpthread.so.0 #2 0x00007fd36000a1cb in pthread_mutex_lock () from /lib/x86_64-linux-gnu/libpthread.so.0 #3 0x00007fd364b953ab in Mutex::Lock (this=0x7fd367dbf628, no_lockdep=<optimized out>) at common/Mutex.cc:89 #4 0x00007fd364d136ae in Pipe::reader (this=0x7fd367dbf4f0) at msg/Pipe.cc:1485 #5 0x00007fd364d17d7d in Pipe::Reader::entry (this=<optimized out>) at msg/Pipe.h:49 #6 0x00007fd360007b50 in start_thread () from /lib/x86_64-linux-gnu/libpthread.so.0 #7 0x00007fd35fd517bd in clone () from /lib/x86_64-linux-gnu/libc.so.6 #8 0x0000000000000000 in ?? ()
In those stack traces I figured it was a transient effect since I could see another thread holding the lock (via their backtraces).
For the last qemu.log provided, I can see log output from the reader and writer threads on the same pipe. At some point, you can determine from the logs that the read thread parsed a message on the pipe and must have gotten stuck waiting for the lock because the log messages following the lock are never output -- nor are any other log messages from that thread. However, I can see logs from other threads that would need to acquire the same lock proceeding (SimpleMessenger::submit_message and Pipe::writer both log after the apparent hung thread and both need to acquire / release the same lock).
Per Brad, he is using v0.80.7 -- also witnessed in v0.87
Updated by Brad House over 9 years ago
- File gdb_qemu_debug.txt gdb_qemu_debug.txt added
Attached gdb output with libc and qemu debug symbols.
Updated by Brad House over 9 years ago
- File gdb_next_lockup.txt gdb_next_lockup.txt added
another attempt and trace
Updated by Brad House over 9 years ago
- File gdb_lockup_3.txt gdb_lockup_3.txt added
and a 3rd for good measure
Updated by Brad House over 9 years ago
second batch dump from same locked process as requested
Updated by Brad House over 9 years ago
As per jdillaman's suggestion on IRC, I have backed off to the PVE 2.6.32-34-pve kernel from 3.10.0-5-pve and can no longer reproduce the issue. However, I am seeing about a 30% decline in performance, but I'll take stability over performance.
I'm not sure if this is a bug in ceph, the 3.10.0-5 kernel (which is just the RHEL7 kernel packaged for Debian), or some interaction between the RHEL7 kernel and the debian libc. However, it is very interesting that I cannot reproduce this in my test lab which has the same package versions, just different physical hardware (and 1GbE instead of 10GbE).
In the future, you may want to look out for this issue re-occurring, especially on RHEL7 systems ... if it doesn't then we'll just chock this up to some incompatibility with the kernel and debian libc.
Thanks for all your assistance! Your responsiveness to this was greatly appreciated Jason!
Updated by Warren Wang over 9 years ago
I've been seeing similar issues using Ubuntu 14.04 as a guest VM. RT throttling occurs, so I tried disabling all the RT kernel options which are included in kernel 3.10+ by running:
echo "-1" > /proc/sys/kernel/sched_rt_runtime_us
echo 0 > /proc/sys/kernel/perf_cpu_time_max_percent
This just results in the guest eventually locking up under heavy fio testing. On the hypervisor:
1.5.0+dfsg-3ubuntu5.3~cloud0
Ceph cluster is .80.7. Guest is Ubuntu 14.04 3.13.0-39-generic. This problem is pretty easy to reproduce with higher thread counts in fio.
Updated by Jason Dillaman over 9 years ago
- Status changed from New to Need More Info
Warren, can you provide an stack backtraces from when you encountered the issue and a list of any OSD ops-in-flight?
Updated by Josh Durgin about 9 years ago
- Status changed from Need More Info to Closed
Please re-open if you're still seeing this.
Updated by Brad House almost 9 years ago
I haven't tested it yet, but its possible this kernel bug is what was biting me:
https://groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64/discussion
Softlockup message in dmesg, check.
deadlock in __lll_lock_wait(). check.
Haswell processor. check.
breaking into gdb and continuing re-wakes process. check
Just putting this here as a placeholder/reminder. I'll need to verify if the bad patch was backported to the kernel I was running (based off RHEL7).