Ceph » CephFS

On my Luminous 12.2.0 test cluster, after I have run for the last few days, the MDS process is not getting past up:replay before the log shows:

2017-09-10 23:08:49.109923 7ffabcee8700 -1 ** Caught signal (Aborted) *
in thread 7ffabcee8700 thread_name:md_log_replay

Then the processes is restarted by systemd.

The ceph-mds process runs at ~120% cpu for several minutes, seems to be reading in lots of data from the OSDs, as shown by network stats and client I/O stats, then the MDS process exits with the Caught signal (Aborted) message:

This was happening on all three of my MDS servers, as one would fail, and the next would try to replay, and then it would fail. To make debugging simpler, I have gone to a single MDS by disabling my other 2 MDS servers, set debug_mds = 9/20, and attached the log file.

From this log:

2017-09-11 02:01:55.730578 7f40e5611700  5 mds.ede-c2-mon03 handle_mds_map epoch 29027 from mon.1
2017-09-11 02:02:00.086795 7f40e5611700  5 mds.ede-c2-mon03 handle_mds_map epoch 29028 from mon.1
2017-09-11 02:02:04.889403 7f40dde02700  0 mds.0.journal EOpen.replay ino 0x1000411038c.156 not in metablob
2017-09-11 02:02:04.909457 7f40dde02700 -1 /build/ceph-12.2.0/src/mds/journal.cc: In function 'virtual void EOpen::replay(MDSRank*)' thread 7f40dde02700 time 2017-09-11 02:02:04.889408
/build/ceph-12.2.0/src/mds/journal.cc: 2214: FAILED assert(in)

 ceph version 12.2.0 (32ce2a3ae5239ee33d6150705cdb24d43bab910c) luminous (rc)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x102) [0x56184cb6d132]
 2: (EOpen::replay(MDSRank*)+0x776) [0x56184cb0d796]
 3: (MDLog::_replay_thread()+0xc6b) [0x56184cac016b]
 4: (MDLog::ReplayThread::entry()+0xd) [0x56184c84007d]
 5: (()+0x76ba) [0x7f40eb1016ba]
 6: (clone()+0x6d) [0x7f40ea16d82d]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

This problem is very repeatable on the system right now. Using grep on the log file with default logging shows:

grep -C1 "Caught signal" ceph-mds.ede-c2-mon03.log
--- end dump of recent events ---
2017-09-10 20:47:35.512059 7f7701f53700 -1 *** Caught signal (Aborted) **
 in thread 7f7701f53700 thread_name:md_log_replay
--
    -1> 2017-09-10 20:47:35.174509 7f770bf02700  1 -- 10.15.2.123:6800/4203097469 <== osd.0 10.15.2.132:6802/1957 940 ==== osd_op_reply(16961 200.0003150d [read 0~4194304 [fadvise_dontneed]] v0'0 uv50294 ondisk = 0) v8 ==== 156+0+4194304 (3089052591 0 939397831) 0x55e9be794380 con 0x55e9be95a000
     0> 2017-09-10 20:47:35.512059 7f7701f53700 -1 *** Caught signal (Aborted) **
 in thread 7f7701f53700 thread_name:md_log_replay
--
--- end dump of recent events ---
2017-09-10 21:16:03.722304 7f6334254700 -1 *** Caught signal (Aborted) **
 in thread 7f6334254700 thread_name:md_log_replay
--
    -1> 2017-09-10 21:16:03.345563 7f633ea04700  1 -- 10.15.2.123:6800/3477605165 <== osd.2 10.15.2.131:6802/1842 757 ==== osd_op_reply(16962 200.0003150e [read 0~4194304 [fadvise_dontneed]] v0'0 uv50000 ondisk = 0) v8 ==== 156+0+4194304 (2529611885 0 3069046118) 0x55eabccebc00 con 0x55eabcd68000
     0> 2017-09-10 21:16:03.722304 7f6334254700 -1 *** Caught signal (Aborted) **
 in thread 7f6334254700 thread_name:md_log_replay
--
--- end dump of recent events ---
2017-09-10 21:44:36.999431 7f9921cfe700 -1 *** Caught signal (Aborted) **
 in thread 7f9921cfe700 thread_name:md_log_replay
--
    -1> 2017-09-10 21:44:36.827626 7f992bcad700  5 -- 10.15.2.123:6800/2182054169 >> 10.15.2.123:6789/0 conn(0x559f1bcab000 :-1 s=STATE_OPEN_MESSAGE_READ_FOOTER_AND_DISPATCH pgs=87 cs=1 l=1). rx mon.2 seq 786 0x559ff1d0f500 mdsbeacon(344336/ede-c2-mon03 up:replay seq 429 v25639) v7
     0> 2017-09-10 21:44:36.999431 7f9921cfe700 -1 *** Caught signal (Aborted) **
 in thread 7f9921cfe700 thread_name:md_log_replay
--
--- end dump of recent events ---
2017-09-10 21:59:13.121796 7f2b6a7ee700 -1 *** Caught signal (Aborted) **
 in thread 7f2b6a7ee700 thread_name:md_log_replay
--
    -1> 2017-09-10 21:59:12.838076 7f2b71ffd700  1 -- 10.15.2.123:6800/1508149898 <== mon.2 10.15.2.123:6789/0 556 ==== mdsmap(e 25973) v1 ==== 721+0+0 (2764755316 0 0) 0x55f77ade9400 con 0x55f6a8342800
     0> 2017-09-10 21:59:13.121796 7f2b6a7ee700 -1 *** Caught signal (Aborted) **
 in thread 7f2b6a7ee700 thread_name:md_log_replay
--

OS Ubuntu 16.04 with a 4.13.0 kernel
uname -a
Linux ede-c2-mon03 4.13.0-041300-generic #201709031731 SMP Sun Sep 3 21:33:09 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

ceph -s
  cluster:
    id:     6d8aae1e-1125-11e5-a708-001b78e265be
    health: HEALTH_WARN
            1 filesystem is degraded
            insufficient standby MDS daemons available
            1 MDSs behind on trimming

  services:
    mon: 3 daemons, quorum ede-c2-mon01,ede-c2-mon02,ede-c2-mon03
    mgr: ede-c2-mon01(active), standbys: ede-c2-mon02, ede-c2-mon03
    mds: cephfs-1/1/1 up  {0=ede-c2-mon03=up:replay}
    osd: 19 osds: 19 up, 19 in

  data:
    pools:   4 pools, 1792 pgs
    objects: 95597 objects, 261 GB
    usage:   799 GB used, 496 GB / 1296 GB avail
    pgs:     1792 active+clean

  io:
    client:   74267 kB/s rd, 18 op/s rd, 0 op/s wr

ceph -v
ceph version 12.2.0 (32ce2a3ae5239ee33d6150705cdb24d43bab910c) luminous (rc)

free
              total        used        free      shared  buff/cache   available
Mem:       16427028      722084      201700      118848    15503244    15226820
Swap:        999420           0      999420