Ceph » rbd

I have only seen it once in over 6-months of running a dozen VMs that run video surveillance workloads. These are Windows boxes with about a 95% write to 5% read ratio. The writes average ~16KB each in the guest. RBD writeback cache is enabled.

Sorry there isn't more to go on.

Mike Dawson wrote:

Just discovered that the load on the host spikes when the crash occurs. I don't have info on the first, but the past two crashes show load spiking up to a 1-minute average of around 325 on the hypervisor host. These are boxes have 2x Intel E5520s.

interesting. is there a memory or network spike or anything else obvious going on at the same time?

Memory usage on the host looks stable. Traffic on the host dips because it loses the crashed guest's traffic. Disk util is a bit elevated on the OS drive (I believe that is writing the core dump).

In addition to comment posted by Andrey:
The disk workload of the VM was very peaky: http://imgur.com/SLFdJvv
VM crashed as soon as filesystem run out of free space http://imgur.com/e7SI7B5

• glibc detected * /usr/bin/kvm: invalid fastbin entry (free): 0x00007fd520001500 * ======= Backtrace: =========
  /lib/x86_64-linux-gnu/libc.so.6(+0x7e566)[0x7fd6289e4566]
  /usr/lib/librados.so.2(_ZNSt8_Rb_treeImSt4pairIKmSt4listIS0_IjN13DispatchQueue9QueueItemEESaIS5_EEESt10_Select1stIS8_ESt4lessImESaIS8_EE12_M_erase_auxESt23_Rb_tree_const_iteratorIS8_E+0x31)[0x7fd62bf56a01]
  /usr/lib/librados.so.2(_ZN16PrioritizedQueueIN13DispatchQueue9QueueItemEmE7dequeueEv+0x913)[0x7fd62bf57333]
  /usr/lib/librados.so.2(_ZN13DispatchQueue5entryEv+0x1c7)[0x7fd62bf53f07]
  /usr/lib/librados.so.2(_ZN13DispatchQueue14DispatchThread5entryEv+0xd)[0x7fd62bfbc60d]
  /lib/x86_64-linux-gnu/libpthread.so.0(+0x7e9a)[0x7fd628d2ae9a]
  /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fd628a583dd]

They say there was a bug in malloc in libc 2.15 (we have the same major version)

https://jira.mongodb.org/browse/SERVER-5174
https://sourceware.org/git/?p=glibc.git;a=commitdiff;h=5f24d53acb2cd02ffb4ac925c0244e4f1f854499;hp=d84acf388ed8b3f162dda0512139095bfc268beb

so it might be a reason of the crash in our case too. Though i'm not familiar with neither libc nor ceph internals so this analogue may be irrelevant.

Igor Lukyanov wrote:

They say there was a bug in malloc in libc 2.15 (we have the same major version)

https://jira.mongodb.org/browse/SERVER-5174
https://sourceware.org/git/?p=glibc.git;a=commitdiff;h=5f24d53acb2cd02ffb4ac925c0244e4f1f854499;hp=d84acf388ed8b3f162dda0512139095bfc268beb

so it might be a reason of the crash in our case too. Though i'm not familiar with neither libc nor ceph internals so this assumption may be irrelevant.

Just a note, bug itself is very unlikely to reproduce in a short times (one crash per 1k VM instances per month or so).

Still getting these crashes multiple times a week across a dozen guests on separate hosts. These guests are video surveillance DVRs, so they tend to have full drives that are constantly overwriting the oldest data with new video. Writes average ~16KB each, with each guest taking a max of about 5MB/s of write throughput. We're using RBD writeback cache.

1. head -100 qemu/instance-00000027.log
   • Error in `qemu-system-x86_64': invalid fastbin entry (free): 0x00007ff12887ff20 *** ======= Backtrace: =========
     /lib/x86_64-linux-gnu/libc.so.6(+0x80a46)[0x7ff3dea1fa46]
     /usr/lib/librados.so.2(+0x29eb03)[0x7ff3e3d43b03]
     /usr/lib/librados.so.2(_ZNK9CryptoKey7encryptEP11CephContextRKN4ceph6buffer4listERS4_RSs+0x71)[0x7ff3e3d42661]
     /usr/lib/librados.so.2(_Z21encode_encrypt_enc_blIN4ceph6buffer4listEEvP11CephContextRKT_RK9CryptoKeyRS2_RSs+0xfe)[0x7ff3e3d417de]
     /usr/lib/librados.so.2(_Z14encode_encryptIN4ceph6buffer4listEEiP11CephContextRKT_RK9CryptoKeyRS2_RSs+0xa2)[0x7ff3e3d41912]
     /usr/lib/librados.so.2(_ZN19CephxSessionHandler12sign_messageEP7Message+0x242)[0x7ff3e3d40de2]
     /usr/lib/librados.so.2(_ZN4Pipe6writerEv+0x92b)[0x7ff3e3e61b2b]
     /usr/lib/librados.so.2(_ZN4Pipe6Writer5entryEv+0xd)[0x7ff3e3e6c7fd]
     /lib/x86_64-linux-gnu/libpthread.so.0(+0x7f8e)[0x7ff3ded6ff8e]
     /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7ff3dea99a0d] ======= Memory map: ========
     ...

One more:

*** Error in `qemu-system-x86_64': invalid fastbin entry (free): 0x00007f42a4002de0 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x80a46)[0x7f452f1f3a46]
/usr/lib/x86_64-linux-gnu/libnss3.so(PK11_FreeSymKey+0xa8)[0x7f452e72ff98]
/usr/lib/librados.so.2(+0x2a18cd)[0x7f453451a8cd]
/usr/lib/librados.so.2(_ZNK9CryptoKey7encryptEP11CephContextRKN4ceph6buffer4listERS4_RSs+0x71)[0x7f4534519421]
/usr/lib/librados.so.2(_Z21encode_encrypt_enc_blIN4ceph6buffer4listEEvP11CephContextRKT_RK9CryptoKeyRS2_RSs+0xfe)[0x7f453451859e]
/usr/lib/librados.so.2(_Z14encode_encryptIN4ceph6buffer4listEEiP11CephContextRKT_RK9CryptoKeyRS2_RSs+0xa2)[0x7f45345186d2]
/usr/lib/librados.so.2(_ZN19CephxSessionHandler23check_message_signatureEP7Message+0x246)[0x7f4534516866]
/usr/lib/librados.so.2(_ZN4Pipe12read_messageEPP7Message+0xdcc)[0x7f453462ecbc]
/usr/lib/librados.so.2(_ZN4Pipe6readerEv+0xa5c)[0x7f453464059c]
/usr/lib/librados.so.2(_ZN4Pipe6Reader5entryEv+0xd)[0x7f4534643ecd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x7f8e)[0x7f452f543f8e]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f452f26da0d]
======= Memory map: ========
...

Josh, What can I do here to get you more information?

I found another source of race conditions, and hopefully fixed them in the wip-6480-0.67.7 branch. I'm running tests to make sure it doesn't break anything (the most likely regression is a hang). Mike, could you try upgrading librbd and librados to that branch and running some test vms on them? I think this addresses all the races in this bug, but there may be more.

This may help somehow - recently I`ve started to collect perf samples via endless loop on selected hosts and some hosts threw out gfp allocation error due to low memory condition on the lowest NUMA node. Those hosts also tended to produce same errors as in this bug(qemu processes w/o strict NUMA pinning), so it is almost clearly a race. Just FYI.

Josh, I am now running wip-6480-0.67.7 across our whole infrastructure. No issues yet. Because the race is rare, I think a week or two will be needed to have more certainty that the issue is resolved.

Andrey, could you test this branch, too?

I've run wip-6480-0.67.7 across our infrastructure for 10 days now without any qemu crashes. Thanks Josh!

Hi Andrey, that does look like this bug on cuttlefish. We haven't been backporting anything to cuttlefish for a long time now (including the fix for this bug). I'd suggest upgrading to dumpling or firefly.

Yes, I had no assumption to make a fix for a cuttlefish on purpose. I asked Mike (as he running newer release) to compare his occasional after-6480 crashes with backtrace above. As I have received none of cephx-related crashes after backporting this fix to cuttlefish, there is a chance that we may face the same issue.

This resurfaced in a similar form on a hammer cluster. After some analysis of the core file, it appeared that some of the libnss functions we use in this path are not threadsafe (in particular PK11_GetBestSlot()).

Post-hammer, these functions had already been refactored to be called once from a single thread as an optimization, so I backported that to hammer. #14620 tracks this backport.

IMHO, it was an issue in glibc: https://bugzilla.redhat.com/show_bug.cgi?id=1305406