Ceph » CephFS

I recently found a bug. It can explain the crash.

https://github.com/ceph/ceph/pull/15440

commit 0d71c6120e61f31b803c3fb6488fc7e97134e348
Author: Yan, Zheng <zyan@redhat.com>
Date:   Sat Jun 3 12:06:10 2017 +0800

    mds/flock: properly remove item from global_waiting_locks

    ceph_lock_state_t::remove_waiting() uses wrong key to search
    global_waiting_locks. It should use item in waiting_locks as
    key.

    Signed-off-by: "Yan, Zheng" <zyan@redhat.com>

For the slow recovery. are there "MDS health message (mds.0): Behind on trimming (xxx/100)" warnings in cluster log. how many caps do cephfs clients use (ceph daemon mds.x session ls) ?

Running it today on the same cluster that crashed (client usage is about the same by the time):

~# ceph daemon mds.c session ls
[ {
"id": 889364,
"num_leases": 302,
"num_caps": 170838,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.889364 10.0.2.192:0\/77167272",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail02-fe01.m9.network",
"kernel_version": "4.4.0-22-generic"
}
}, {
"id": 864144,
"num_leases": 0,
"num_caps": 18778,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.864144 10.0.2.1:0\/1943224316",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail02-ds01.m9.network",
"kernel_version": "4.4.0-22-generic"
}
}, {
"id": 1030234,
"num_leases": 325,
"num_caps": 183941,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.1030234 10.0.2.200:0\/3543349573",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail00-fe02.m9.network",
"kernel_version": "4.4.0-24-generic"
}
}, {
"id": 945213,
"num_leases": 234,
"num_caps": 138801,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.945213 10.0.2.193:0\/3058601307",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail02-fe02.m9.network",
"kernel_version": "4.4.0-22-generic"
}
}, {
"id": 1029565,
"num_leases": 0,
"num_caps": 2588906,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.1029565 10.0.2.19:0\/1447852959",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail02-ds05.m9.network",
"kernel_version": "4.4.0-62-generic"
}
}
]

There is something interesting here. The host "bhs1-mail02-ds05.m9.network" has the highest number of caps (over 2.5M) but nothing on this host is actually using cephfs. It's just mounted there.

{
"id": 1029565,
"num_leases": 0,
"num_caps": 2588906,
"state": "open",
"replay_requests": 0,
"completed_requests": 0,
"reconnecting": false,
"inst": "client.1029565 10.0.2.19:0\/1447852959",
"client_metadata": {
"entity_id": "",
"hostname": "bhs1-mail02-ds05.m9.network",
"kernel_version": "4.4.0-62-generic"
}

2588906 is quite large. If I am right, the recovery mds stuck in rejoin state for a long time.

please check how many inodes and open files on each machine.
sudo cat /proc/sys/fs/file-nr
sudo cat /proc/sys/fs/inode-nr

If the actual number of open files are not that large, we can do some quick optimization. Otherwise, we need add new mechanism to track open files for quick recovery

root@bhs1-mail02-ds05:~# cat /proc/sys/fs/file-nr
3360 0 3273932
root@bhs1-mail02-ds05:~# cat /proc/sys/fs/inode-nr
4961157 916551

bhs1-mail02-ds05.m9.network use to run an instance of dovecot too, so cephfs is mounted there, but it's not running anymore since last week.

Webert Lima wrote:

root@bhs1-mail02-ds05:~# cat /proc/sys/fs/file-nr
3360 0 3273932
root@bhs1-mail02-ds05:~# cat /proc/sys/fs/inode-nr
4961157 916551

how about other machines

bhs1-mail02-ds05.m9.network use to run an instance of dovecot too, so cephfs is mounted there, but it's not running anymore since last week.

It's better to umount it, or run 'echo 3 > /proc/sys/vm/drop_caches"

Zheng Yan wrote:

how about other machines

Sorry I didn't check at the time. I'll post everything as it looks today.

It's better to umount it, or run 'echo 3 > /proc/sys/vm/drop_caches"

I went to umount it and I saw that the CAPs dropped to 3 on that host. I've umounted it anyway.

These are all hosts on this cluster today:

root@bhs1-mail00-fe02:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 355409  2659
 88544   0       3274282

root@bhs1-mail02-fe01:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 423591  9083
 101152  0       3274269

root@bhs1-mail02-fe02:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 401796  3688
 102208  0       3274268

root@bhs1-mail02-ds01:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 1767614 1389515
 4224    0       3274268

root@bhs1-mail02-ds02:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 2545540 1547328
 4032    0       3274268

root@bhs1-mail02-ds03:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 379577  162589
 4576    0       3274268

root@bhs1-mail02-ds04:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 497047  203917
 6912    0       3274268

root@bhs1-mail02-ds05:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 456680  423484
 3520    0       3273932

Hosts with cephfs mounted:

bhs1-mail00-fe02 (used by dovecot)
 bhs1-mail02-fe01 (used by dovecot)
 bhs1-mail02-fe02 (used by dovecot)
 bhs1-mail02-ds01 (used by custom script)

and these are from another cluster that is nearly identical:

root@bhs1-mail00-fe01:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
96268 221
7648 0 3274282

root@bhs1-mail01-fe01:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 597439  200002
 53824   0       3274268

root@bhs1-mail01-fe02:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 346847  15250
 81600   0       3274268

root@bhs1-mail01-ds01:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 344420  252542
 4064    0       3274267

root@bhs1-mail01-ds02:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 100984  47608
 3936    0       3274268

root@bhs1-mail01-ds03:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 281508  80696
 7008    0       3274268

root@bhs1-mail01-ds04:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 274520  77608
 4032    0       3274268

root@bhs1-mail01-ds05:~# cat /proc/sys/fs/inode-nr /proc/sys/fs/file-nr
 184926  25445
 108544  0       3273933

Hosts with cephfs mounted:

bhs1-mail00-fe01 (mounted but not used)
 bhs1-mail01-fe01 (mounted but not used)
 bhs1-mail01-fe02 (used by dovecot)
 bhs1-mail01-ds01 (used by custom script) 
 bhs1-mail01-ds05 (used by dovecot)

and this is current session ls from each Active MDS on each of both clusters:

root@bhs1-mail01-ds02:~# ceph daemon mds.b session ls | grep "num_caps\|hostname" 
        "num_caps": 1429,
            "hostname": "bhs1-mail01-fe01.m9.network",
        "num_caps": 100868,
            "hostname": "bhs1-mail01-ds05",
        "num_caps": 1776,
            "hostname": "bhs1-mail01-ds01",
        "num_caps": 3,
            "hostname": "bhs1-mail00-fe01",
        "num_caps": 154609,
            "hostname": "bhs1-mail01-fe02",

root@bhs1-mail02-ds03:~# ceph daemon mds.c session ls | grep "num_caps\|hostname" 
        "num_caps": 204144,
            "hostname": "bhs1-mail02-fe01",
        "num_caps": 2788,
            "hostname": "bhs1-mail02-ds01",
        "num_caps": 198677,
            "hostname": "bhs1-mail00-fe02",
        "num_caps": 173802,
            "hostname": "bhs1-mail02-fe02",

Patrick Donnelly wrote:

Okay, it appears the deadlock is fixed.

I'm sorry. Do you refer to that commit? If so, is there a schedule for it to be on a LTS version?

Please open a new ticket if you're still seeing issues with rejoin taking unreasonable amounts of time.

I'm pretty sure the crash will happen again, this was like the 7th time in the last 2 months.
Any suggestion from preventing the mds crash from happening?

it should be backported to jewel/kraken if feasible

Consider backport to jewel only, since kraken goes EOL the moment Luminous is declared stable.

In other words, there will be a 11.2.1 but I doubt there will be in a 11.2.2.

Patrick Donnelly wrote:

Zheng, PR#15440 indicates it's a multimds fix but Webert's setup is single MDS. Any issues you see backporting the fix?

You're right. It's a Single Active-MDS setup. Used to run Active/Standby and now I run Active/Standby-Replay pairs.

You can either backport the fix yourself, wait for the backport (which could happen after Luminous) or Luminous, or update to the latest Luminous RC if you feel comfortable doing that.

I'm not really comfortable in doing a upgrade like that, as the service and data availability is very critical here. I feel more comfortable in upgrading to the latest Jewel version and backporting the fix if that doesn't break anything else. Could you point me directions on doing the backport myself?

Obs: our current version is a backport done by you guys last year because of this: http://tracker.ceph.com/issues/15920

I'm not really comfortable in doing a upgrade like that, as the service and data availability is very critical here. I feel more comfortable in upgrading to the latest Jewel version and backporting the fix if that doesn't break anything else. Could you point me directions on doing the backport myself?

I went ahead and did it since our CI will build the repos for you: https://shaman.ceph.com/builds/ceph/i20535-backport/2223e478c4b770e75cb7db196f5cd9d985929ac9/default/55553/

PR: https://github.com/ceph/ceph/pull/16248

Patrick Donnelly wrote:

I went ahead and did it since our CI will build the repos for you: https://shaman.ceph.com/builds/ceph/i20535-backport/2223e478c4b770e75cb7db196f5cd9d985929ac9/default/55553/

Oh I really appreciate that! I see DIST=xenial, will that run on trusty too?

I meant to link: https://shaman.ceph.com/builds/ceph/i20535-backport/2223e478c4b770e75cb7db196f5cd9d985929ac9/

Looks like something went wrong in the build. I'll take a look.

Awesome! Thanks!

New run: https://shaman.ceph.com/builds/ceph/i20535-backport/387e184970bc2949e16139db0cbda6acfa3f7b3a/

Patrick Donnelly wrote:

New run: https://shaman.ceph.com/builds/ceph/i20535-backport/387e184970bc2949e16139db0cbda6acfa3f7b3a/

Thanks! It looks like it's build.
Couple questions:
- any recommendations choosing over notcmalloc or default flavors?
- what I have to do is download the packages at ubuntu/trusty/flavors/default/pool/main/c/ceph/ and install them? (respecting some update guide)

Webert Lima wrote:

Couple questions:
- any recommendations choosing over notcmalloc or default flavors?

Generally you want default (i.e. with tcmalloc).

- what I have to do is download the packages at ubuntu/trusty/flavors/default/pool/main/c/ceph/ and install them? (respecting some update guide)

I think you should be able to add the keys according to this guide:

http://docs.ceph.com/docs/master/install/get-packages/

Then manually install the downloaded package (which I don't know how to do).

Ok. I'll do it in two small clusters tomorrow and I'll update this troublesome clusters next week.
Thanks a lot for that backport.

Does this built package include the fix for the MDS regression that was found in 10.2.8? I read about it in the mailing list.

Webert Lima wrote:

Does this built package include the fix for the MDS regression that was found in 10.2.8? I read about it in the mailing list.

It does not include the fix. Do not use that branch. I'll make a note to update it...

Patrick Donnelly wrote:

It does not include the fix. Do not use that branch. I'll make a note to update it...

Thanks. I'll be waiting.

https://shaman.ceph.com/builds/ceph/i20535-backport-v10.2.9/

Patrick Donnelly wrote:

https://shaman.ceph.com/builds/ceph/i20535-backport-v10.2.9/

Thanks, I'll be upgrading all clusters by the ned of next week.
Will that repo be permanently available or does it expire?

It will expire in a week or two.

ok i'll download them just in case.

Any update?

Patrick Donnelly wrote:

Any update?

Hey Patrick, I have upgrade one test cluster first, but it keeps as HEALTH_WARN:

health HEALTH_WARN
 all OSDs are running jewel or later but the 'require_jewel_osds' osdmap flag is not set

Webert Lima wrote:

Patrick Donnelly wrote:

Any update?

Hey Patrick, I have upgrade one test cluster first, but it keeps as HEALTH_WARN:

health HEALTH_WARN
all OSDs are running jewel or later but the 'require_jewel_osds' osdmap flag is not set

See this announcement: http://ceph.com/geen-categorie/v10-2-4-jewel-released/

Patrick Donnelly wrote:

See this announcement: http://ceph.com/geen-categorie/v10-2-4-jewel-released/

Thank you Patrick. So that was because I was running 10.2.2 and that flag didn't exist on that version.
The update on the test cluster went well. I've being cautious about it because I never did a ceph update before.

I have the 3 production clusters' update scheduled for Saturday 29th.
I was supposed to do it by tomorrow but it won't be possible due to other issues.

I'll keep you informed.

One of our production clusters upgraded.
Next one scheduled for next Wednesday, August 2nd.

Just upgraded the other 2 production clusters where the problem tends to happen frequently.
Will watch from now on.

Webert Lima wrote:

Just upgraded the other 2 production clusters where the problem tends to happen frequently.
Will watch from now on.

Thanks for keeping us in the loop!

Reporting in, I've had the first incident after the version upgrade.

My active MDS had committed suicide due to "dne in mds map" (this is happening a lot but I don't think it's related to the upgrade)
When the recovery was already done, a new crash happened (never seen this one before):

2017-08-19 06:37:54.542005 7f9721654700  1 mds.0.1370 rejoin_joint_start
 2017-08-19 06:37:54.542206 7f971ec4d700  1 heartbeat_map reset_timeout 'MDSRank' had timed out after 15
 2017-08-19 07:27:07.427682 7f971cc49700  1 mds.0.1370 rejoin_done
 2017-08-19 07:27:08.658514 7f9721654700  1 mds.0.1370 handle_mds_map i am now mds.0.1370
 2017-08-19 07:27:08.658522 7f9721654700  1 mds.0.1370 handle_mds_map state change up:rejoin --> up:active
 2017-08-19 07:27:08.658539 7f9721654700  1 mds.0.1370 recovery_done -- successful recovery!
 2017-08-19 07:27:08.658709 7f9721654700  1 mds.0.1370 active_start
 2017-08-19 07:27:11.154702 7f9721654700 1 mds/Locker.cc: In function 'void Locker::file_recover(ScatterLock*)' thread 7f9721654700 time 2017-08-19 07:27:11.152839
 mds/Locker.cc: 4924: FAILED assert(lock>get_state() == LOCK_PRE_SCAN)
  ceph version 10.2.9-4-gbeaec39 (beaec397f00491079cd74f7b9e3e10660859e26b)
  1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x565179789adb]
  2: (Locker::file_recover(ScatterLock*)+0x1c9) [0x565179523a19]
  3: (MDCache::start_files_to_recover()+0xd3) [0x565179455813]
  4: (MDSRank::active_start()+0x8e) [0x5651793bf56e]
  5: (MDSRankDispatcher::handle_mds_map(MMDSMap*, MDSMap*)+0x10eb) [0x5651793d0f6b]
  6: (MDSDaemon::handle_mds_map(MMDSMap*)+0xe07) [0x5651793aa557]
  7: (MDSDaemon::handle_core_message(Message*)+0x78b) [0x5651793ab9fb]
  8: (MDSDaemon::ms_dispatch(Message*)+0xab) [0x5651793abc5b]
  9: (DispatchQueue::entry()+0x78b) [0x56517988668b]
  10: (DispatchQueue::DispatchThread::entry()+0xd) [0x56517976f38d]
  11: (()+0x8184) [0x7f972701c184]
  12: (clone()+0x6d) [0x7f9725570bed]
  NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

Webert Lima wrote:

My active MDS had committed suicide due to "dne in mds map" (this is happening a lot but I don't think it's related to the upgrade)

Probably related to: http://tracker.ceph.com/issues/19706

When the recovery was already done, a new crash happened (never seen this one before):

2017-08-19 06:37:54.542005 7f9721654700 1 mds.0.1370 rejoin_joint_start
2017-08-19 06:37:54.542206 7f971ec4d700 1 heartbeat_map reset_timeout 'MDSRank' had timed out after 15
2017-08-19 07:27:07.427682 7f971cc49700 1 mds.0.1370 rejoin_done
2017-08-19 07:27:08.658514 7f9721654700 1 mds.0.1370 handle_mds_map i am now mds.0.1370
2017-08-19 07:27:08.658522 7f9721654700 1 mds.0.1370 handle_mds_map state change up:rejoin --> up:active
2017-08-19 07:27:08.658539 7f9721654700 1 mds.0.1370 recovery_done -- successful recovery!
2017-08-19 07:27:08.658709 7f9721654700 1 mds.0.1370 active_start
2017-08-19 07:27:11.154702 7f9721654700 1 mds/Locker.cc: In function 'void Locker::file_recover(ScatterLock*)' thread 7f9721654700 time 2017-08-19 07:27:11.152839
mds/Locker.cc: 4924: FAILED assert(lock>get_state() == LOCK_PRE_SCAN)
ceph version 10.2.9-4-gbeaec39 (beaec397f00491079cd74f7b9e3e10660859e26b)
1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x8b) [0x565179789adb]
2: (Locker::file_recover(ScatterLock*)+0x1c9) [0x565179523a19]
3: (MDCache::start_files_to_recover()+0xd3) [0x565179455813]
4: (MDSRank::active_start()+0x8e) [0x5651793bf56e]
5: (MDSRankDispatcher::handle_mds_map(MMDSMap*, MDSMap*)+0x10eb) [0x5651793d0f6b]
6: (MDSDaemon::handle_mds_map(MMDSMap*)+0xe07) [0x5651793aa557]
7: (MDSDaemon::handle_core_message(Message*)+0x78b) [0x5651793ab9fb]
8: (MDSDaemon::ms_dispatch(Message*)+0xab) [0x5651793abc5b]
9: (DispatchQueue::entry()+0x78b) [0x56517988668b]
10: (DispatchQueue::DispatchThread::entry()+0xd) [0x56517976f38d]
11: (()+0x8184) [0x7f972701c184]
12: (clone()+0x6d) [0x7f9725570bed]
NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

Please fork another issue for this one.

Probably related to: http://tracker.ceph.com/issues/19706

I'll keep an eye on it. I'm suspecting out of sync clocks may be causing it.

Please fork another issue for this one.

I'll do it if it happens again. Still hasn't.

Thanks a lot Patrick and @everyone involved.