Project

General

Profile

Actions
Copy link

Bug #16042

closed

MDS Deadlock on shutdown active rank while busy with metadata IO

Added by John Spray almost 8 years ago. Updated over 7 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Patrick Donnelly
Category:
Correctness/Safety
Target version:
-
% Done:

0%

Source:
other
Tags:
Backport:
jewel
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(FS):
MDS
Labels (FS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):

Description

Report and log here: https://bugzilla.redhat.com/show_bug.cgi?id=1340004

Log looks like one of the MDLog threads might be getting stuck.

For users this manifests as a delay in failover rather than a total failure, because even though this daemon is getting stuck, the MDSMonitor will eventually let another daemon take over.

Related issues 1 (0 open — 1 closed)

Copied to CephFS - Backport #16797: jewel: MDS Deadlock on shutdown active rank while busy with metadata IOResolvedAbhishek VarshneyActions
Actions
Copy link
 #1

Updated by John Spray almost 8 years ago

  • Assignee set to Patrick Donnelly
Actions
Copy link
 #2

Updated by John Spray almost 8 years ago

I just saw this (or similar shutdown bug) for the first time in an automated test: http://qa-proxy.ceph.com/teuthology/jspray-2016-06-13_14:56:46-fs-wip-jcsp-testing-quota-2-distro-basic-mira/257048/teuthology.log (see remote/mira122/log/ceph-mds.a-s.log.gz in the output)

Actions
Copy link
 #3

Updated by John Spray almost 8 years ago

This is rearing its head in general testing now:
http://pulpito.ceph.com/jspray-2016-06-15_05:28:02-fs-wip-jcsp-testing-20160615---basic-mira/261446/
(remote/mira088/log/ceph-mds.a-s.log.gz in that one)

Actions
Copy link
 #4

Updated by Patrick Donnelly almost 8 years ago

  • Status changed from New to In Progress
Actions
Copy link
 #5

Updated by Zhi Zhang almost 8 years ago

Hi guys,

Looks like this issue is very similar to this one here: http://tracker.ceph.com/issues/16396

Actions
Copy link
 #6

Updated by John Spray almost 8 years ago

Interesting, #16396 is with async messenger (and is probably the issue we're seeing in current master testing), but we originally got this issue on Red Hat testing of Jewel which would presumably have been using the simple messenger.

Actions
Copy link
 #7

Updated by Zhi Zhang almost 8 years ago

Could it be via following paths to call MDSDaemon::ms_handle_reset() like async msgr?

One mds thread: ... -> SimpleMessenger::shutdown -> SimpleMessenger::mark_down_all -> dispatch_queue.queue_reset

Another simple msgr's dispatch thread: DispatchQueue::entry -> dequeue reset item from dispatch_queue -> messenger::ms_deliver_handle_reset -> ...

Actions
Copy link
 #8

Updated by Patrick Donnelly almost 8 years ago

I'm able to reproduce this with vstart.sh and `cp -a /usr ...`. I'm seeing this every 10 seconds:

2016-06-30 13:43:41.632422 7f1cca736700 10 monclient: tick
2016-06-30 13:43:41.632445 7f1cca736700 10 cephx: validate_tickets want 39 have 39 need 0
2016-06-30 13:43:41.632448 7f1cca736700 20 cephx client: need_tickets: want=39 need=0 have=39
2016-06-30 13:43:41.632454 7f1cca736700 10 monclient: _check_auth_rotating have uptodate secrets (they expire after 2016-06-30 13:43:11.632451)
2016-06-30 13:43:41.632460 7f1cca736700 10 auth: dump_rotating:
2016-06-30 13:43:41.632461 7f1cca736700 10 auth:  id 1 AQAEhHVXorWfGxAAuFNIH8KnXtfFXjsFDIw8Lg== expires 2016-06-30 14:41:40.463444
2016-06-30 13:43:41.632474 7f1cca736700 10 auth:  id 2 AQAEhHVX9OafGxAAEDpBCWZxiLU3mnbD451yKg== expires 2016-06-30 15:41:40.463444
2016-06-30 13:43:41.632479 7f1cca736700 10 auth:  id 3 AQAEhHVXjROgGxAAtk1jWbJVcc1HpFgelwQFSg== expires 2016-06-30 16:41:40.463444
2016-06-30 13:43:43.631140 7f1ccdf3d700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2016-06-30 13:43:48.631231 7f1ccdf3d700  1 heartbeat_map is_healthy 'MDSRank' had timed out after 15

The thread processing the SIGTERM I sent is here:

#0  0x00007f1cd0ad4297 in pthread_join (threadid=139761580963584, thread_return=0x0) at pthread_join.c:92
#1  0x00007f1cd175fd90 in Thread::join (this=this@entry=0x7f1cdd3a99e0, prval=prval@entry=0x0) at common/Thread.cc:171
#2  0x00007f1cd16aabdd in Finisher::stop (this=0x7f1cdd3a98c0) at common/Finisher.cc:27
#3  0x00007f1cd13b2146 in MDSRankDispatcher::shutdown (this=0x7f1cdd441200) at mds/MDSRank.cc:225
#4  0x00007f1cd139b471 in MDSDaemon::suicide (this=this@entry=0x7f1cdd440000) at mds/MDSDaemon.cc:1079
#5  0x00007f1cd139b5f8 in MDSDaemon::handle_signal (this=0x7f1cdd440000, signum=<optimized out>) at mds/MDSDaemon.cc:1045
#6  0x00007f1cd1681667 in SignalHandler::entry (this=0x7f1cdd3b01a0) at global/signal_handler.cc:255
#7  0x00007f1cd0ad2f33 in start_thread (arg=0x7f1cc8631700) at pthread_create.c:309
#8  0x00007f1ccee73ead in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Other threads:

  24   Thread 0x7f1cce73e700 (LWP 15265) "log" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  23   Thread 0x7f1ccdf3d700 (LWP 15266) "service" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  22   Thread 0x7f1ccd73c700 (LWP 15267) "admin_socket" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  21   Thread 0x7f1cccf3b700 (LWP 15268) "ms_reaper" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  20   Thread 0x7f1ccc73a700 (LWP 15269) "ceph-mds" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  19   Thread 0x7f1ccbf39700 (LWP 15270) "ms_dispatch" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  18   Thread 0x7f1ccb738700 (LWP 15271) "ms_local" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  17   Thread 0x7f1ccaf37700 (LWP 15272) "ms_accepter" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  16   Thread 0x7f1cca736700 (LWP 15273) "safe_timer" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  15   Thread 0x7f1cc9f35700 (LWP 15274) "fn_anonymous" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  14   Thread 0x7f1cd1154700 (LWP 15275) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  13   Thread 0x7f1cc9734700 (LWP 15278) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  12   Thread 0x7f1cc8631700 (LWP 15314) "sginal_handler" 0x00007f1cd0ad4297 in pthread_join (threadid=139761580963584, thread_return=0x0)
    at pthread_join.c:92
  11   Thread 0x7f1cc7e30700 (LWP 15315) "mds_rank_progr" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  10   Thread 0x7f1cc762f700 (LWP 15316) "fn_anonymous" __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
  9    Thread 0x7f1cc6e2e700 (LWP 15317) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  8    Thread 0x7f1cc652c700 (LWP 15321) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  7    Thread 0x7f1cc642b700 (LWP 15322) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  6    Thread 0x7f1cc632a700 (LWP 15325) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  5    Thread 0x7f1cc6229700 (LWP 15326) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  4    Thread 0x7f1cc6128700 (LWP 15328) "ms_pipe_read" 0x00007f1ccee69a8d in poll () at ../sysdeps/unix/syscall-template.S:81
  3    Thread 0x7f1cc6027700 (LWP 15478) "ms_pipe_read" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  2    Thread 0x7f1cc5f26700 (LWP 15479) "ms_pipe_write" pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
* 1    Thread 0x7f1cd115a180 (LWP 15264) "ceph-mds" 0x00007f1cd0ad4297 in pthread_join (threadid=139761649157888, thread_return=0x0) at pthread_join.c:92

I can confirm that http://tracker.ceph.com/issues/16396 is unrelated. I applied #9884 to v10.2.1 without any change in behavior.

Actions
Copy link
 #9

Updated by Patrick Donnelly almost 8 years ago

  • Status changed from In Progress to Fix Under Review
Actions
Copy link
 #10

Updated by Greg Farnum almost 8 years ago

  • Category changed from 47 to Correctness/Safety
  • Component(FS) MDS added
Actions
Copy link
 #11

Updated by Patrick Donnelly almost 8 years ago

  • Status changed from Fix Under Review to Pending Backport
  • Backport set to jewel
Actions
Copy link
 #12

Updated by Nathan Cutler almost 8 years ago

  • Copied to Backport #16797: jewel: MDS Deadlock on shutdown active rank while busy with metadata IO added
Actions
Copy link
 #13

Updated by Loïc Dachary over 7 years ago

  • Status changed from Pending Backport to Resolved
Actions
Copy link

Also available in: Atom PDF