Ceph

# ceph health
HEALTH_OK

qemu.log attached, after this sequence:

# virsh dumpxml smhtest1 | grep rbd
      <source protocol='rbd' name='rbd/smhtest1:rbd_cache=1:rbd_cache_size=67108864:debug_rbd=20:debug_ms=1:log_file=/tmp/qemu.log'>
# virsh start smhtest1
# ssh smhtest1
# cd /tmp
# time fio --output /tmp/fio1.out /usr/share/doc/fio/examples/iometer-file-access-server
Jobs: 1 (f=1): [m] [9.9% done] [0K/0K /s] [0/0 iops] [eta 05m:19s]
    #### hung here

In another window:

# ssh smhtest1
# ps lw $(pidof fio)
F   UID   PID  PPID PRI  NI    VSZ   RSS WCHAN  STAT TTY        TIME COMMAND
0     0  1604  1588  20   0  28912 13048 -      D+   pts/0      0:35 fio --output /tmp/fio1.out /usr/share/doc/fio/examples/iometer-file-access-server
1     0  1605  1604  20   0  36544  5892 -      Ds   ?          0:00 fio --output /tmp/fio1.out /usr/share/doc/fio/examples/iometer-file-access-server
# date
Thu Oct 11 12:42:23 EST 2012
# uptime
 12:42:23 up 21 min,  2 users,  load average: 9.78, 8.21, 5.28

Reducing the amount of data fio is testing with produces different behaviour. The default is size=4g. Below about size=100m I haven't seen it fail. Around 100m the success/failure is inconsistent. Using:

strace -o /tmp/strace -ff -tt fio --output /tmp/fio.out <(sed -e 's/size=4g/size=100m/' /usr/share/doc/fio/examples/iometer-file-access-server)

...the attached strace.154³⁴ are from a successful run, and strace.15{48,50} from an unsuccessful run immediately afterwards. Unfortunately it looks like the interesting bit are stuck in strace's output buffer as strace.1550 is truncated.

Hmmm, I just rebooted the virtual and did the same tests. Once again, with size=100m, the first run succeeded and the second run failed.

After another reboot, I ran with size=10m 50 times without failure, then without a reboot, size=50m 30 times ok. Then, with size=90m, it got stuck with the % done oscillating from 86% up to 88% and the eta increasing. At that point the fio process was unkillable. I rebooted after several minutes of the same behaviour (the test would normally complete in a matter of seconds).

After a reboot, running with size=80m succeeded the first time and hung the second.

Hmmm, rdb_cache_size is set to 64m. Perhaps something to do with that? Another reboot, and ran this script:

for ((s=60; ; s+=1))
do
  for ((i=1; i<=10; i+=1))
  do
    echo -e "\ns=$s i=$i" 
    fio --output /tmp/fio.out <(sed -e "s/size=4g/size=${s}m/" /usr/share/doc/fio/examples/iometer-file-access-server)
  done
done

This hung at "s=75 i=4". Another reboot, and it hung at "s=79 i=5".

Aha! I reduced rdb_cache_size to 32m, and after a reboot the script hung immediately at "s=60 i=1".

Another reboot, and ran the script again except with the start size to "s=30". This hung at "s=49 i=1".

Another reboot and start at "s=30", and hung at "s=48 i=1".

So it looks like some issue with the rbd_cache?

Attached, output of:

# virsh dumpxml test1 | grep rbd
      <source protocol='rbd' name='rbd/test1:rbd_cache=1:rbd_cache_size=33554433:debug_rbd=20:debug_ms=1:debug_objectcacher=20:log_file=/tmp/qemu.log'>
# virsh start test1
# ssh test1
# cd /tmp
# fio --output /tmp/fio.out <(sed -e "s/size=4g/size=60m/" /usr/share/doc/fio/examples/iometer-file-access-
server)
Jobs: 1 (f=1): [m] [100.0% done] [0K/0K /s] [0/0 iops] [eta 00m:00s] 
     ### hung here

With rbd_cache=false it's survived a few size=200m iterations, and the full size=4g is still running... will let you know how it goes.

Unfortunately I haven't been able to reproduce this myself or track down the cause yet. Would it be possible to get a blktrace of the fio in addition to the debug logs from rbd during the same run?

Josh Durgin wrote:

Unfortunately I haven't been able to reproduce this myself or track down the cause yet. Would it be possible to get a blktrace of the fio in addition to the debug logs from rbd during the same run?

Attached are the blktrace.dat and qemu.log from:

host.0# virsh dumpxml test1 | grep rbd
      <source protocol='rbd' name='rbd/test1:rbd_cache=1:rbd_cache_size=67108864:debug_rbd=20:debug_ms=1:log_file=/tmp/qemu.log'>
host.0# virsh start test1
host.0# ssh test1 'blktrace -d /dev/vda1 -o -' > /tmp/blktrace.dat
host.1# ssh test1
host.2# ssh test1 'fio <(sed -e 's/size=4g/size=100m/' /usr/share/doc/fio/examples/iometer-file-access-server)'

...then when the fio hangs, I use the shell on test1 to kill -TERM the blktrace:

test1.1# kill -TERM $(pidof blktrace)
host.0# virsh destroy test1

I fixed a few bugs that could cause this in the wip-oc-hang branch. This is now merged into the next and master branches. Could you try with the next branch on the client side? Updating librbd should be enough. Instructions for dev testing packages are here in case you don't want to build it yourself: http://ceph.com/docs/master/install/debian/#add-development-testing-packages

Hooray!