Ceph » RADOS

Yes, the kill_daemons failed because after 6 minutes several terminated OSDs still hadn't finished shutting down. I noticed in one case the last pg message showed a PG in DELETING state.

I've reproduced this running the test in my local tree. I'll work on generating a core dump to find out what is stuck.

/a/nojha-2018-09-24_16:58:52-rados-master-distro-basic-smithi/3065653/

I'll look at this more tomorrow but I suspect that the following commit from https://github.com/ceph/ceph/pull/22739 is causing a problem:

commit 6c583fe756c82ed6c196caa0ce783765d5e9ee41
Author: Jianpeng Ma <jianpeng.ma@intel.com>
Date:   Thu Sep 20 22:10:20 2018 +0800

    osd/OSD: choose a fixed thread do oncommits callback function

    Now bluestore oncommit callback exec by osd op threads.
    If there are multi threads of shard, it will cause out-of order.
    For example, threads_per_shard=2
                  Thread1                                 Thread2
        swap_oncommits(op1_oncommit)
                                                swap_oncommits(op2_oncommit)
        OpQueueItem.run(Op3)
                                                op2_oncommit.complete();
        op1_oncommit.complete()

    This make oncommits out of order.
    To avoiding this, we choose a fixed thread which has the smallest
    thread_index of shard to do oncommit callback function.

    Signed-off-by: Jianpeng Ma <jianpeng.ma@intel.com>

I think thread 54 may be looping while thread 8 is waiting for all 5 threads to finish (4 drained so far)

Thread 54 (Thread 0x7fcac9550700 (LWP 62090)):
#0  WeightedPriorityQueue<OpQueueItem, unsigned long>::empty (this=0x55f091128f80) at /src/ceph/src/common/WeightedPriorityQueue.h:303
#1  0x000055f085e90a56 in OSD::ShardedOpWQ::_process (this=0x55f0920111f8, thread_index=0, hb=0x55f0921f8050) at /src/ceph/src/osd/OSD.cc:10253
#2  0x000055f0864b7586 in ShardedThreadPool::shardedthreadpool_worker (this=0x55f0920109d8, thread_index=0) at /src/ceph/src/common/WorkQueue.cc:340
#3  0x000055f0864c2970 in ShardedThreadPool::WorkThreadSharded::entry (this=<optimized out>) at /src/ceph/src/common/WorkQueue.h:691
#4  0x00007fcaea4c26ba in start_thread (arg=0x7fcac9550700) at pthread_create.c:333
#5  0x00007fcae952a82d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

Thread 8 (Thread 0x7fcae4de9700 (LWP 62015)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x000055f0864c1816 in Cond::Wait (mutex=..., this=0x55f092010ae0) at /src/ceph/src/common/Cond.h:49
#2  ShardedThreadPool::drain (this=0x55f0920109d8) at /src/ceph/src/common/WorkQueue.cc:434
#3  0x000055f085e82249 in ShardedThreadPool::ShardedWQ<OpQueueItem>::drain (this=0x55f0920111f8) at /src/ceph/src/common/WorkQueue.h:676
#4  OSD::shutdown (this=this@entry=0x55f092010000) at /src/ceph/src/osd/OSD.cc:3553
#5  0x000055f085e832db in OSD::handle_signal (this=0x55f092010000, signum=<optimized out>) at /src/ceph/src/osd/OSD.cc:2213
#6  0x000055f08644d172 in SignalHandler::entry (this=0x55f09114a9c0) at /src/ceph/src/global/signal_handler.cc:497
#7  0x00007fcaea4c26ba in start_thread (arg=0x7fcae4de9700) at pthread_create.c:333
#8  0x00007fcae952a82d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

In all 3 OSDs I found that hung, the last thread to drain is the smallest thread_index (thus the thread that handles oncommits). However, in all 3 cases the context_queue is empty, but pqueue is not.

This issue is that prior to d7ca34e12fd9dd652fe12b5593bf2ccd4ce35b60 the relevant code in OSD::ShardedOpWQ::_process() looked like this:

   OpQueueItem item = sdata->pqueue->dequeue();
   if (osd->is_stopping()) {
     sdata->shard_lock.Unlock();
     return;    // OSD shutdown, discard.
   }

Here when stopping an item is discarded until the queue is empty. Without the dequeue() before returning, the work queue never drains and a thread will infinite loop, but it still resets the heartbeat timeout, so it is not detected internally.

https://github.com/ceph/ceph/pull/24296