Ceph

This looks like a test case race.

2 processes hung while mon thrasher keeps running:
ubuntu 7800 1 0 02:09 ? 00:00:02 ceph_test_rados_delete_pools_parallel
ubuntu 7801 1 0 02:09 ? 00:00:02 ceph_test_rados_delete_pools_parallel

Thread 13 (LWP 7800):
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:86
#1 0x00000000004050b2 in CrossProcessSem::wait (this=0x243a960) at test/system/cross_process_sem.cc:63
#2 0x0000000000404a22 in StRadosDeletePool::run (this=0x7fff684d8e90) at test/system/st_rados_delete_pool.cc:46
#3 0x0000000000405397 in systest_runnable_pthread_helper (arg=0x7fff684d8e90) at test/system/systest_runnable.cc:202
#4 0x000000000040542b in SysTestRunnable::start (this=0x7fff684d8e90) at test/system/systest_runnable.cc:102
#5 0x000000000040706b in SysTestRunnable::run_until_finished (runnables=...) at test/system/systest_runnable.cc:174
#6 0x0000000000403987 in main (argc=1, argv=0x7fff684d9078) at test/system/rados_delete_pools_parallel.cc:101

int StRadosDeletePool::run() {
rados_t cl;
RETURN1_IF_NONZERO(rados_create(&cl, NULL));
rados_conf_parse_argv(cl, m_argc, m_argv);
RETURN1_IF_NONZERO(rados_conf_read_file(cl, NULL));
rados_conf_parse_env(cl, NULL);
RETURN1_IF_NONZERO(rados_connect(cl));
m_pool_setup_sem->wait(); <<<<thread from 7800 waiting here

Thread 13 (LWP 7801):
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:86
#1 0x00000000004050b2 in CrossProcessSem::wait (this=0x243a940) at test/system/cross_process_sem.cc:63
#2 0x0000000000404d06 in StRadosListObjects::run (this=0x7fff684d8db0) at test/system/st_rados_list_objects.cc:61
#3 0x0000000000405397 in systest_runnable_pthread_helper (arg=0x7fff684d8db0) at test/system/systest_runnable.cc:202
#4 0x000000000040542b in SysTestRunnable::start (this=0x7fff684d8db0) at test/system/systest_runnable.cc:102
#5 0x000000000040706b in SysTestRunnable::run_until_finished (runnables=...) at test/system/systest_runnable.cc:174
#6 0x0000000000403987 in main (argc=1, argv=0x7fff684d9078) at test/system/rados_delete_pools_parallel.cc:101

int StRadosListObjects::
run() {
rados_t cl;
RETURN1_IF_NONZERO(rados_create(&cl, NULL));
rados_conf_parse_argv(cl, m_argc, m_argv);
RETURN1_IF_NONZERO(rados_conf_read_file(cl, NULL));
rados_conf_parse_env(cl, NULL);
RETURN1_IF_NONZERO(rados_connect(cl));
m_pool_setup_sem->wait(); <<<<thread from 7801 waiting here

The pool create process died after getting a write error:


2013-08-09T02:08:27.288 INFO:teuthology.task.workunit.client.0.out:[10.214.132.36]: process_3_[7799]: rados_write error -2

Around this time PGs were still being created presumably for the newly created pool:

2013-08-09 02:08:27.844542 mon.0 10.214.132.35:6789/0 1247 : [INF] pgmap v575: 104 pgs: 16 creating, 88 active+clean; 9646 bytes data, 892 MB used, 2792 GB / 2793 GB avail
2013-08-09 02:08:29.799293 mon.0 10.214.132.35:6789/0 1248 : [INF] pgmap v576: 104 pgs: 16 creating, 88 active+clean; 9646 bytes data, 893 MB used, 2792 GB / 2793 GB avail

I tried adding a 30 second delay to my own OSD to increase the time it takes for a new pool's PGs to be created, but a write following a new pool creation hangs until PG creation finishes.

I've been reproducing this reliably with wip-9321.giant. Hung job in plana12.

Thread 13 (Thread 0x7f188a2d5700 (LWP 25047)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188cb0fdab in ceph::log::Log::entry (this=0x2452540) at log/Log.cc:345
#2  0x00007f188c477e9a in start_thread (arg=0x7f188a2d5700) at pthread_create.c:308
#3  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#4  0x0000000000000000 in ?? ()

Thread 12 (Thread 0x7f1889387700 (LWP 25052)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:215
#1  0x00007f188c8f84a6 in WaitUntil (when=..., mutex=..., this=0x246ec58) at ./common/Cond.h:71
#2  WaitInterval (interval=..., mutex=..., cct=<optimized out>, this=0x246ec58) at ./common/Cond.h:79
#3  CephContextServiceThread::entry (this=0x246ebe0) at common/ceph_context.cc:58
#4  0x00007f188c477e9a in start_thread (arg=0x7f1889387700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 11 (Thread 0x7f1888b86700 (LWP 25055)):
#0  0x00007f188bc82a43 in __GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00007f188c8bcffb in AdminSocket::entry (this=0x2452b30) at common/admin_socket.cc:239
#2  0x00007f188c477e9a in start_thread (arg=0x7f1888b86700) at pthread_create.c:308
#3  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#4  0x0000000000000000 in ?? ()

Thread 10 (Thread 0x7f1883fff700 (LWP 25061)):
#0  pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:85
#1  0x00007f188c852732 in get_read (this=0x2472780) at ./common/RWLock.h:68
#2  RLocker (lock=..., this=<synthetic pointer>) at ./common/RWLock.h:122
#3  Objecter::tick (this=0x24726c0) at osdc/Objecter.cc:1543
#4  0x00007f188c816489 in Context::complete (this=0x7f1858001290, r=<optimized out>) at ./include/Context.h:64
#5  0x00007f188c8d55ed in SafeTimer::timer_thread (this=0x2472838) at common/Timer.cc:105
#6  0x00007f188c8d81ed in SafeTimerThread::entry (this=<optimized out>) at common/Timer.cc:38
#7  0x00007f188c477e9a in start_thread (arg=0x7f1883fff700) at pthread_create.c:308
#8  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#9  0x0000000000000000 in ?? ()

Thread 9 (Thread 0x7f18837fe700 (LWP 25063)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188c9e8358 in Wait (mutex=..., this=0x2472220) at ./common/Cond.h:55
#2  DispatchQueue::entry (this=0x24721b8) at msg/simple/DispatchQueue.cc:196
#3  0x00007f188ca5fa7d in DispatchQueue::DispatchThread::entry (this=<optimized out>) at msg/simple/DispatchQueue.h:104
#4  0x00007f188c477e9a in start_thread (arg=0x7f18837fe700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 8 (Thread 0x7f1882ffd700 (LWP 25065)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188c9e9d5b in Wait (mutex=..., this=0x24723c0) at ./common/Cond.h:55
#2  DispatchQueue::run_local_delivery (this=0x24721b8) at msg/simple/DispatchQueue.cc:114
#3  0x00007f188ca5fa5d in DispatchQueue::LocalDeliveryThread::entry (this=<optimized out>) at msg/simple/DispatchQueue.h:118
#4  0x00007f188c477e9a in start_thread (arg=0x7f1882ffd700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 7 (Thread 0x7f18827fc700 (LWP 25067)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188ca59f49 in Wait (mutex=..., this=0x2472628) at ./common/Cond.h:55
#2  SimpleMessenger::reaper_entry (this=0x2472000) at msg/simple/SimpleMessenger.cc:211
#3  0x00007f188ca604dd in SimpleMessenger::ReaperThread::entry (this=<optimized out>) at msg/simple/SimpleMessenger.h:199
#4  0x00007f188c477e9a in start_thread (arg=0x7f18827fc700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 6 (Thread 0x7f1881ffb700 (LWP 25073)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:215
#1  0x00007f188c8d57fb in WaitUntil (when=..., mutex=..., this=0x2455230) at common/Cond.h:71
#2  SafeTimer::timer_thread (this=0x2455220) at common/Timer.cc:114
#3  0x00007f188c8d81ed in SafeTimerThread::entry (this=<optimized out>) at common/Timer.cc:38
#4  0x00007f188c477e9a in start_thread (arg=0x7f1881ffb700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 5 (Thread 0x7f18817fa700 (LWP 25074)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188c8d9360 in Wait (mutex=..., this=0x2455348) at ./common/Cond.h:55
#2  Finisher::finisher_thread_entry (this=0x24552e8) at common/Finisher.cc:81
#3  0x00007f188c477e9a in start_thread (arg=0x7f18817fa700) at pthread_create.c:308
#4  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#5  0x0000000000000000 in ?? ()

Thread 4 (Thread 0x7f1888385700 (LWP 30639)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188ca49852 in Wait (mutex=..., this=0x7f1878025048) at ./common/Cond.h:55
#2  Pipe::writer (this=0x7f1878020e20) at msg/simple/Pipe.cc:1795
#3  0x00007f188ca55aed in Pipe::Writer::entry (this=<optimized out>) at msg/simple/Pipe.h:62
#4  0x00007f188c477e9a in start_thread (arg=0x7f1888385700) at pthread_create.c:308
#5  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#6  0x0000000000000000 in ?? ()

Thread 3 (Thread 0x7f18806f7700 (LWP 30640)):
#0  0x00007f188bc82a43 in __GI___poll (fds=<optimized out>, nfds=<optimized out>, timeout=<optimized out>) at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x00007f188ca3d9e7 in Pipe::tcp_read_wait (this=<optimized out>) at msg/simple/Pipe.cc:2351
#2  0x00007f188ca3e068 in Pipe::tcp_read (this=0x7f1878020e20, buf=0x7f18806f6e1a "\377\214\030\177", len=1) at msg/simple/Pipe.cc:2321
#3  0x00007f188ca50a50 in Pipe::reader (this=0x7f1878020e20) at msg/simple/Pipe.cc:1480
#4  0x00007f188ca55b0d in Pipe::Reader::entry (this=<optimized out>) at msg/simple/Pipe.h:50
#5  0x00007f188c477e9a in start_thread (arg=0x7f18806f7700) at pthread_create.c:308
#6  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#7  0x0000000000000000 in ?? ()

Thread 2 (Thread 0x7f1880ff9700 (LWP 30641)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x00007f188ca39d37 in Wait (mutex=..., this=0x7f187c002480) at ./common/Cond.h:55
#2  Pipe::DelayedDelivery::entry (this=0x7f187c0023b0) at msg/simple/Pipe.cc:209
#3  0x00007f188c477e9a in start_thread (arg=0x7f1880ff9700) at pthread_create.c:308
#4  0x00007f188bc8e3fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#5  0x0000000000000000 in ?? ()

Thread 1 (Thread 0x7f188eebc780 (LWP 25044)):
#0  0x00007f188c479148 in pthread_join (threadid=139743270532864, thread_return=0x0) at pthread_join.c:89
#1  0x00007f188c9015e2 in Thread::join (this=0x2475230, prval=<optimized out>) at common/Thread.cc:140
#2  0x00007f188c8d728b in SafeTimer::shutdown (this=0x2472838) at common/Timer.cc:77
#3  0x00007f188c8568e0 in Objecter::shutdown (this=0x24726c0) at osdc/Objecter.cc:394
#4  0x00007f188c82006a in librados::RadosClient::shutdown (this=0x2455010) at librados/RadosClient.cc:303
#5  0x00007f188c809919 in rados_shutdown (cluster=0x2455010) at librados/librados.cc:1916
#6  0x000000000040473d in StRadosCreatePool::run (this=0x7fff41ba5960) at test/system/st_rados_create_pool.cc:112
#7  0x000000000040538a in systest_runnable_pthread_helper (arg=<optimized out>) at test/system/systest_runnable.cc:203
#8  0x000000000040544b in SysTestRunnable::start (this=0x7fff41ba5960) at test/system/systest_runnable.cc:102
#9  0x000000000040708b in SysTestRunnable::run_until_finished (runnables=...) at test/system/systest_runnable.cc:174
#10 0x0000000000403957 in main (argc=1, argv=0x7fff41ba5d18) at test/system/rados_delete_pools_parallel.cc:101

Yup, there is a shutdown race. Thread 1 is waiting for the timer thread while holding the Objecter::rwlock in write mode. The timer thread is in Objecter::tick() trying to get the rwlock in read mode.

Objecter::shutdown() should drop the rwlock so that the timer thread can exit. An assert(tick_event) needs to be done after we know that we aren't shutting down, since it would be NULL in this case.

I don't think this would have happened when safe_callbacks was true. It was set to false in a fix for #9582. See also #9650.

My last statement about the tick even was inaccurate.

gdb tells me that 'tick_event' is still set by the time we issue timer.shutdown() on Objecter::shutdown():

(gdb) p this->tick_event
$8 = (Objecter::C_Tick *) 0x1cba5f0

which happens to be the same Context being run by Thread 9:

Thread 9 (Thread 0x7f9676067700 (LWP 7219)):
#0  pthread_rwlock_rdlock () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_rwlock_rdlock.S:87
#1  0x00007f967b060ac0 in RWLock::get_read (this=0x1cb0780) at ./common/RWLock.h:68
#2  0x00007f967b088a58 in RLocker (lock=..., this=<synthetic pointer>) at ./common/RWLock.h:122
#3  Objecter::tick (this=0x1cb06c0) at osdc/Objecter.cc:1543
#4  0x00007f967b04bf39 in Context::complete (this=0x1cba5f0, r=<optimized out>) at ./include/Context.h:64

-- 8< --

See 'Context::complete (this=0x1cba5f0' matches Objecter::tick_event above.

And taking into consideration that in Objecter::shutdown() we see:

if (tick_event) {
  Mutex::Locker l(timer_lock);
  if (timer.cancel_event(tick_event))
    tick_event = NULL;
}

So we will only set 'tick_event' to NULL if we manage to cancel the event. SafeTimer::cancel_event() will return false if the event is not found, which is to be expected if the Context is already running. This means that by the time we reach this if-branch the tick Context has already been run, but it must have been run after we entered Objecter::shutdown().

this was fun though.

I'll stop with the noise now and test this with the patch from #9845.