Bug #36105
closedOSD hangs during shutdown
0%
Description
2018-09-20T21:31:59.512 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/osd/osd-backfill-stats.sh:304: TEST_backfill_dowdelete_pool test 2018-09-20T21:31:59.513 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:533: delete_pool: local poolname=test 2018-09-20T21:31:59.513 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:534: delete_pool: ceph osd pool delete test test --yes-i-really-really-mean-it 2018-09-20T21:32:00.192 INFO:tasks.workunit.client.0.smithi188.stderr:pool 'test' does not exist 2018-09-20T21:32:00.204 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/osd/osd-backfill-stats.sh:305: TEST_backfill_dowkill_daemons td/osd-backfill-stats 2018-09-20T21:32:00.204 INFO:tasks.workunit.client.0.smithi188.stderr://home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:345: kill_daemons: shopt -q -o xtrace 2018-09-20T21:32:00.205 INFO:tasks.workunit.client.0.smithi188.stderr://home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:345: kill_daemons: echo true 2018-09-20T21:32:00.205 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:345: kill_daemons: local trace=true 2018-09-20T21:32:00.205 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:346: kill_daemons: true 2018-09-20T21:32:00.205 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:346: kill_daemons: shopt -u -o xtrace 2018-09-20T21:38:03.537 INFO:tasks.workunit.client.0.smithi188.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/ceph-helpers.sh:362: kill_daemons: return 1 ...
/a/sage-2018-09-20_18:56:20-rados-wip-sage-testing-2018-09-20-0933-distro-basic-smithi/3047210
If I'm reading this right, kill_daemons failed so we hit the ||return 1 and the whole thing failed.
Updated by Sage Weil over 5 years ago
- Description updated (diff)
- Status changed from New to 12
- Priority changed from Normal to High
Updated by David Zafman over 5 years ago
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.
Updated by David Zafman over 5 years ago
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.
Updated by Neha Ojha over 5 years ago
/a/nojha-2018-09-24_16:58:52-rados-master-distro-basic-smithi/3065653/
Updated by David Zafman over 5 years ago
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
Updated by David Zafman over 5 years ago
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.
Updated by David Zafman over 5 years ago
- Subject changed from qa/standalone/osd/osd-backfill-stats.sh failed during shutdown? to OSD hangs during shutdown
Updated by David Zafman over 5 years ago
Updated by David Zafman over 5 years ago
- Status changed from In Progress to Resolved