Ceph » CephFS

This change might turn out to have another unexpected benefit, although the reason for that might turn out to be a bug.

While one OSD was down, I created a number of hard links to files that hadn't been touched for a while. The MDS updated the parent xattr in them.

When the OSD came back up, it started log-based recovery. What surprised me was that strace showed each file that had had the parent updated was being newly-written in full to the recovering osd, even though the data had not been modified in any way.

I vaguely recall seeing, a while ago, code in the osd implementation that tried to avoid that, by keeping separate versions for file data and xattrs. My guess is that this may be failing because the file is regarded as missing during osd startup; the init code that goes backwards through the log accessing each touched file (besides taking a very long time to run on this osd, because the number of files to recover is so large) doesn't seem to be concerned with multiple version numbers. Isn't that a bug? (running 0.79 now, will upgrade to 0.80-rc shortly)

Hmm, there are several things going on here that you're conflating. Some questions and notes
1) Exploding a tarball can kill OSDs. That's a little disturbing although possibly just a result of trying to push too many ops through. Have you taken a peek at what requests are pending within the OSDs pipeline when that happens? What version are you running?
2) Flushing out parent backpointers is batched up. That's a weakness with our current implementation, but you're the first to report it as a problem.
3) We keep the backpointers on the objects because it (a) reduces the total number of objects in the system, and (b) makes cleanup of the backpointers a lot simpler. (They live with the object they are about, and get deleted together.)
4) CephFS does store user xattrs in the metadata pool, as part of the directory files are part of. The parent xattr is internal metadata and should not be confused with external user metadata.
5) We didn't consider that recovering a changed backpointer might require recovering the whole object, but I don't think we've ever had any OSD code that would avoid that. There's certainly never been separate versioning within the OSD.
6) Setting up hard links shouldn't have touched the original file, unless it hadn't yet had a parent xattr written.

1) I've had batches of ceph.parent ops pile up ever since ceph.parent was introduced (early 0.7x IIRC); I'm running 0.79 now. Requests pile up and are reported as delayed particularly on disks that are bigger and hold more data PGs, but I get them even on the smaller and faster disks containing metadata when creating a tree with lots of directories. The metadata disks delay requests but eventually catch up; the larger disks often fail to keep up, and give up when they hit the suicide timeout. When they come back up, others have most often made good progress and now they have to recover the objects that only had ceph.parent modified, but they can't keep up if activity continues, so they fail again and again, taking longer and longer to come back up as the log grows and more objects have to be checked for “missing” before the osd can come back up, and longer and longer to recover as they have to recover the full objects rather than just the ceph.parent attribute.

2) I wish it wasn't a problem; I suppose it might be more efficient to create the xattr along the osd file, when the dir containing it is still hot, but btrfs isn't know for stellar xattr performance. Sadly, switching to leveldb-stored attributes didn't make that any better.

3) I understand the motivations, but reducing the replication count of filesystem metadata for this sort of convenience doesn't sound right. Like, btrfs insists that all metadata be kept in replicated chunks, presumably because that makes recovery of the filesystem possible in case of localized corruption. Any piece of metadata stored in non-replicated data chunks could make a filesystem unrecoverable. Now, when ceph.parent was introduced, it was only meant to aid in mds recovery IIRC, and the worst effect was the slowdown out of hammering the slower data disks with metadata requests, but now that it's going to be used as the backpointer for hardlinks, it had better be handled with as much care as other pieces of metadata.

4) Sorry, I was confused by other xattrs that cephfs stores in data objects.

5) I guess it is the mds that keeps separate versions for data and metadata, then.

6) I suppose the hard-linked files were updated because their ceph.parent xattr was of an older version, so the code added a few releases ago to schedule a ceph.parent update at such times was triggered.

Can you get me the backtraces from the suiciding OSDs? That shouldn't be happening regardless of how many ops we dump at it.

There were plenty of other timeouts before the suicide, and this sort of situation is not specific to ceph.parent batches; in my experience, any sustained workload that exceeds the throughput of the slowest osd will eventually cause this slowest osd to suicide because it can't keep up: I/O on the underlying btrfs presumably gets slower and slower until some operation reaches the suicide timeout.

Here is the latest sample, in which the osd was recovering from earlier failures while other uses of the cephfs were underway:

398> 2014-04-28 12:18:47.798145 7f617de64700  5 - op tracker -- , seq: 96045, time: 2014-04-28 12:18:47.798144, event: waiting for subops from (1,255),(10,255), request: osd_op(client.610213.0:731234 1000082579d.00000019 [write 3505880~458752] 0.9515a9ad snapc 1=[] ondisk+write e71456) v4
  397> 2014-04-28 12:18:47.798203 7f617de64700  1 - 172.31.160.7:6802/16998 --> osd.1 172.31.160.6:6813/2659 -- osd_sub_op(client.610213.0:731234 0.2d 9515a9ad/1000082579d.00000019/head//0 [] v 71456'222312 snapset=0=[]:[] snapc=0=[]) v9 -- ?+459363 0x16195000
  396> 2014-04-28 12:18:47.798279 7f617de64700  1 - 172.31.160.7:6802/16998 --> osd.10 172.31.160.7:6811/13035 -- osd_sub_op(client.610213.0:731234 0.2d 9515a9ad/1000082579d.00000019/head//0 [] v 71456'222312 snapset=0=[]:[] snapc=0=[]) v9 -- ?+459363 0x16191400
  395> 2014-04-28 12:18:47.798467 7f617de64700  5 - op tracker -- , seq: 96045, time: 2014-04-28 12:18:47.798467, event: commit_queued_for_journal_write, request: osd_op(client.610213.0:731234 1000082579d.00000019 [write 3505880~458752] 0.9515a9ad snapc 1=[] ondisk+write e71456) v4
  -394> 2014-04-28 12:18:47.798536 7f617de64700  1 heartbeat_map reset_timeout 'OSD::op_tp thread 0x7f617de64700' had timed out after 30
  -393> 2014-04-28 12:18:47.798554 7f617de64700  1 heartbeat_map reset_timeout 'OSD::op_tp thread 0x7f617de64700' had suicide timed out after 300
[...]
     0> 2014-04-28 12:18:50.190783 7f617de64700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f617de64700 time 2014-04-28 12:18:47.798628
common/HeartbeatMap.cc: 79: FAILED assert(0  "hit suicide timeout")

ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2d9) [0x9b52c9]
 2: (ceph::HeartbeatMap::reset_timeout(ceph::heartbeat_handle_d*, long, long)+0x89) [0x9b55e9]
 3: (ThreadPool::worker(ThreadPool::WorkThread*)+0x5ed) [0xa636fd]
 4: (ThreadPool::WorkThread::entry()+0x10) [0xa64b10]
 5: /lib64/libpthread.so.0() [0x3801607f33]
 6: (clone()+0x6d) [0x3800ef4ded]
 NOTE: a copy of the executable, or `objdump rdS <executable>` is needed to interpret this.
[...]
-- end dump of recent events ---
2014-04-28 12:18:50.190784 7f61ffb30700 -1 common/HeartbeatMap.cc: In function 'bool ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, const char*, time_t)' thread 7f61ffb30700 time 2014-04-28 12:18:47.805406
common/HeartbeatMap.cc: 79: FAILED assert(0  "hit suicide timeout")

ceph version 0.79 (4c2d73a5095f527c3a2168deb5fa54b3c8991a6e)
 1: (ceph::HeartbeatMap::_check(ceph::heartbeat_handle_d*, char const*, long)+0x2d9) [0x9b52c9]
 2: (ceph::HeartbeatMap::is_healthy()+0xc6) [0x9b5ba6]
 3: (ceph::HeartbeatMap::check_touch_file()+0x2c) [0x9b61ec]
 4: (CephContextServiceThread::entry()+0x15b) [0xa86e6b]
 5: /lib64/libpthread.so.0() [0x3801607f33]
 6: (clone()+0x6d) [0x3800ef4ded]
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.