Ceph » CephFS

I changed back to max_mds 1. same result:

dumped mdsmap epoch 49925
epoch   49925
flags   0
created 2013-02-27 17:00:00.919407
modified        2013-04-02 21:35:43.060313
tableserver     0
root    0
session_timeout 60
session_autoclose       300
last_failure    49925
last_failure_osd_epoch  4410
compat  compat={},rocompat={},incompat={1=base v0.20,2=client writeable ranges,3=default file layouts on dirs,4=dir inode in separate object}
max_mds 1
in      0,1
up      {0=20876,1=20735}
failed
stopped
data_pools      [0,5,12]
metadata_pool   1
20876:  x.x.34.82:6800/15681 'ceph-mds1' mds.0.287 up:resolve seq 2
20735:  x.x.34.83:6800/16842 'ceph-mds2' mds.1.252 up:replay seq 1

Strange, it looks like you have an MDS log of about 1236MB, which is...large. What config options are you setting?

Can you re-run this after adding "debug ms = 1" to your config? It looks to me like your replay just stops, which usually indicates that it's trying to get an object from an OSD that is failing to come back.

Greg Farnum wrote:

Strange, it looks like you have an MDS log of about 1236MB, which is...large. What config options are you setting?

Can you re-run this after adding "debug ms = 1" to your config? It looks to me like your replay just stops, which usually indicates that it's trying to get an object from an OSD that is failing to come back.

the logs are big: first is ~3G, second is ~200M. the config was "debug mds = 20". There was ~200-300k files on cephfs.

I created new logs with "debug ms = 1" and "debug mds = 20", watch the 2_* files on link.

Sorry, I mean the mds journal, not the debug logs, when referring to the size.

Greg Farnum wrote:

Sorry, I mean the mds journal, not the debug logs, when referring to the size.

So the mds journal doesnt "commited" to a final state?

What can i do? need you more asserts/debug lines somewhere?

The MDS maintains a journal that it writes metadata into before committing the aggregated updates into the actual inodes. This journal is what it's "replaying" after a reboot.
The part I'm curious about is that according to your log the MDS which isn't finishing replay has a log of over a gigabyte, which is larger than it should normally be allowed to get (your other MDS has a log of 167 MB, which is a bit long but in the range of possibility). Can you upload or pastebin:
1) The output of ceph -s.
2) The output of your MDS config dump from one of your daemons (see http://ceph.com/docs/master/rados/configuration/ceph-conf/#viewing-a-configuration-at-runtime).

Here is the status: http://pastebin.com/x1XEvuWc
Here is the config dump: http://pastebin.com/YTFbY5jW

Thanks. (For future onlookers, the summary of those links is that everything is perfectly normal and as it should be, except an MDS is stuck in replay.)

Just a quick check of the messages indicates that the OSDs are giving responses to everything the mds requests, too, so it's not a failure to retrieve disk objects.

if you tell me (here or irc) where to add new debug/assert lines, we can hunt down this bug.

Don't forget #3351.. if the osd returns a short read on an object before the end of the journal, the Journaler replay code gets confused and gets stuck. Every object should be exactly 4MB except the very last one, or else!

Yeah, that all looks good too. My off-hand guess is that something isn't getting cleaned up properly with the slave requests, which leads to preventing a journal trim and somehow causes whatever the hang is (which follows a slave update replay).

here is a logcut with "debug journaler = 20": http://pastebin.com/nrzJg87E

see commit 7e04504d3ed119bb43a4eb99ca524b39dc3696bc. But the bug should just make replay slow.

Sorry, but I'm a bit lost about why that might apply here. Are you just speculating or did something in the logs look like this issue?
(In particular it sure looks to me like replay has just stopped, but I can check for odd mds messages as well.)

I think of it every time i hear "stuck in replay", that's all. I havne't looked at the logs or anything.

you said "My off-hand guess is that something isn't getting cleaned up properly with the slave requests, which leads to preventing a journal trim". that bug can prevent journal from trimming. But can't explain why does journal replay stop.

just a guess: with journaler debug, there is a line:

mds.1.journaler(ro) wait_for_readable at 67811200485 onreadable 0x20fa5e0

I added a debug line to https://github.com/ceph/ceph/blob/master/src/mds/MDLog.cc#L490 , i got this:

mds.1.log _replay_thread read_pos 67811200485, write_pos 68625972210

does this mean anything?

Are those logs posted somewhere? That indicates it's waiting to be allowed to read the stuff past where it stopped, but it's not immediately clear what it would be waiting on.

Greg Farnum wrote:

Are those logs posted somewhere? That indicates it's waiting to be allowed to read the stuff past where it stopped, but it's not immediately clear what it would be waiting on.

Yes. Watch the link, where the others are.

Okay, there's not a lot there so apparently it doesn't have as much data as it thinks it needs in order to read the next entry. But it's not kicking off any attempts to read more either, which is odd. I'm checking through the prefetch logging more carefully now, but I don't think there should be any issues here since all the actual read requests it issues were answered. Can you apply the patch below and run again (with journaler debugging enabled).

diff --git a/src/osdc/Journaler.cc b/src/osdc/Journaler.cc
index 544ac8c..734c576 100644
--- a/src/osdc/Journaler.cc
+++ b/src/osdc/Journaler.cc
@@ -882,6 +882,10 @@ bool Journaler::_is_readable()
   if (read_buf.length() >= sizeof(s) &&
       read_buf.length() >= sizeof(s) + s) 
     return true;  // yep, next entry is ready.
+  else {
+    dout (0) << "_is_readable read_bug.length() == " << read_buf.length()
+            << ", but need " << s + sizeof(s) << " for next entry" << dendl;
+  }

   // darn it!

@@ -908,6 +912,8 @@ bool Journaler::_is_readable()
             << " for len " << s << " entry" << dendl;
     temp_fetch_len = need;
   }
+
+  dout(0) << "_is_readable: not readable, returning false" << dendl;
   return false;
 }

Okay, so the next entry is >40MB and we have 38MB in our read buffer. I'm not certain, but I think our use of "temp_fetch_len" is just broken. Let's try increasing the "journaler prefetch periods" config member to 20; if that does fix it my supposition is correct and I'll go in more carefully.

Can i continue testing cephfs, or you make the fix quickly for this bug, and i can verify it on my system?

Confirmed, i tested with my system, and the journal-check can load the journal.

But, there is a line in commit:

ldout(cct, 0) << "_prefetch" << dendl;

Need this line with 0 debug level?

Heh, no; that was supposed to be a 10. Re-pushed; thanks!