Ceph » bluestore

Could you please run fsck against this OSD and share the results

do you have a procedure or example to do the fsck?

Sébastien Bernard wrote:

Regarding this problem, /var filesystem is an xfs filesystem.
osd are setup by rook.
Rebooting the machine is enough to fsck the fs at mount time (fsck is done by mount, xfs_repair need special case).
We did reboot the faulty node without resolving the problem.
Please find attached the dmesg from the os.
Something seems very wrong.
ceph image is standard image from quai.io/ceph/ceph:16.2.9.
I attached the oldest and the second to last and last crash of osd.107 for which is still have crash report.

We still have crashes every day, do you have any information to share with us?

Aurélien Le Clainche wrote:

do you have a procedure or example to do the fsck?

Not sure how to do that with Rook but the command to fsck OSD looks like:
ceph-bluestore-tool --path <path-to-osd, e.g. /var/lib/ceph/osd-N> --command fsck

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

do you have a procedure or example to do the fsck?

Not sure how to do that with Rook but the command to fsck OSD looks like:
ceph-bluestore-tool --path <path-to-osd, e.g. /var/lib/ceph/osd-N> --command fsck

bash-5.1# ceph-bluestore-tool --path /var/lib/rook/rook-ceph/1b713b95-fb0d-4254-b83a-4421b28f35fa_2dc34d45-02a3-42a2-9522-cddd2adc773c --command fsck
fsck success
bash-5.1# 

I've already run fsck and that doesn't fix the problem.

Aurélien Le Clainche wrote:

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

do you have a procedure or example to do the fsck?

Not sure how to do that with Rook but the command to fsck OSD looks like:
ceph-bluestore-tool --path <path-to-osd, e.g. /var/lib/ceph/osd-N> --command fsck

[...]

I've already run fsck and that doesn't fix the problem.

You mean there is a single failing OSD which is crashing with exactly the same backtrace and assert location from time to time and running fsck after such a crash finds nothing. Is that summary correct?

Or various OSDs are suffering from that issue?

I can see pretty different crash symptoms in Sebastian's logs. I presume they are from a different cluster, is that correct?

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

do you have a procedure or example to do the fsck?

Not sure how to do that with Rook but the command to fsck OSD looks like:
ceph-bluestore-tool --path <path-to-osd, e.g. /var/lib/ceph/osd-N> --command fsck

[...]

I've already run fsck and that doesn't fix the problem.

You mean there is a single failing OSD which is crashing with exactly the same backtrace and assert location from time to time and running fsck after such a crash finds nothing. Is that summary correct?

Or various OSDs are suffering from that issue?

I can see pretty different crash symptoms in Sebastian's logs. I presume they are from a different cluster, is that correct?

it is indeed the same cluster and it happens on several osds, currently I have two osds which restart continuously. (osd-107 and osd-12)

Aurélien Le Clainche wrote:

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

Igor Fedotov wrote:

Aurélien Le Clainche wrote:

do you have a procedure or example to do the fsck?

Not sure how to do that with Rook but the command to fsck OSD looks like:
ceph-bluestore-tool --path <path-to-osd, e.g. /var/lib/ceph/osd-N> --command fsck

[...]

I've already run fsck and that doesn't fix the problem.

You mean there is a single failing OSD which is crashing with exactly the same backtrace and assert location from time to time and running fsck after such a crash finds nothing. Is that summary correct?

Or various OSDs are suffering from that issue?

I can see pretty different crash symptoms in Sebastian's logs. I presume they are from a different cluster, is that correct?

it is indeed the same cluster and it happens on several osds, currently I have two osds which restart continuously. (osd-107 and osd-12)

hi !

crash on osd.107 this morning:

{
    "backtrace": [
        "/lib64/libpthread.so.0(+0x12ce0) [0x7f7532a0ace0]",
        "gsignal()",
        "abort()",
        "/lib64/libstdc++.so.6(+0x9009b) [0x7f753202109b]",
        "/lib64/libstdc++.so.6(+0x9653c) [0x7f753202753c]",
        "/lib64/libstdc++.so.6(+0x96597) [0x7f7532027597]",
        "/lib64/libstdc++.so.6(+0x967f8) [0x7f75320277f8]",
        "(ceph::buffer::v15_2_0::list::iterator_impl<true>::copy(unsigned int, ceph::buffer::v15_2_0::list&)+0xb2) [0x5587a0ada172]",
        "(pg_log_entry_t::decode_with_checksum(ceph::buffer::v15_2_0::list::iterator_impl<true>&)+0xc6) [0x5587a04c0ce6]",
        "(void PGLog::read_log_and_missing<pg_missing_set<true> >(ObjectStore*, boost::intrusive_ptr<ObjectStore::CollectionImpl>&, ghobject_t, pg_info_t const&, PGLog::IndexedLog&, pg_missing_set<true>&, std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >&, bool, bool*, DoutPrefixProvider const*, std::set<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > >*, bool)+0x1a14) [0x5587a0353b04]",
        "(PG::read_state(ObjectStore*)+0x13e7) [0x5587a0340557]",
        "(OSD::load_pgs()+0xa47) [0x5587a028c0e7]",
        "(OSD::init()+0x26f7) [0x5587a02bc567]",
        "main()",
        "__libc_start_main()",
        "_start()" 
    ],
    "ceph_version": "16.2.9",
    "crash_id": "2022-07-19T02:10:55.597806Z_a3078f30-f137-46cf-9134-e3f6d7eb7b6a",
    "entity_name": "osd.107",
    "os_id": "centos",
    "os_name": "CentOS Stream",
    "os_version": "8",
    "os_version_id": "8",
    "process_name": "ceph-osd",
    "stack_sig": "951c75224296b8e62c3acf78d34b418e0e7a491cf48d138754101bf52bbb9df4",
    "timestamp": "2022-07-19T02:10:55.597806Z",
    "utsname_hostname": "kw210-vso-pr",
    "utsname_machine": "x86_64",
    "utsname_release": "5.15.36-talos",
    "utsname_sysname": "Linux",
    "utsname_version": "#1 SMP Wed Apr 27 17:49:57 UTC 2022" 
}

Hi!

May I have some clarifications then.
I can see multiple backtraces for .107 like the last one. All are happening in load_pgs() function which implies OSD is [re]-starting. Hence some questions:

1) Is this OSD able to start at all? If so - does it crash over time or restart is happening due to other reasons? What's the backtrace/last log output then? You might need to access OSD logs for that - originally they're located under /var/log/ceph/... but unfortunately I have no idea how this is implemented under rook.

2) Have you run fsck for OSD.107 as well? From your comment above it's not clear what OSD have you run fsck successfully for..

3) Can't you see weird/high RAM usage during OSD.107 startup and/or regular running?

4) You mentioned osd.12 is also crashing - please share log output. Is it at the same node as osd.107 or not? What's about other crashes if any - are they at different nodes?

5) Originally OSD.254 was crashing (with a completely different backtrace) - is it still happening? If so - please share the last OSD log snippets prior to that.

Well, this doesn't look like a bluestore issue anymore. Neither I can't see any clues it's the same as the original one.

Given the last OSD logs it's apparently a corrupted entry in a PG log which prevent OSD to start up.

So I can see two subtasks with that:

1) Make broken OSD to start.
If you have enough experience (and/or courage) you might want to treat affected OSDs with ceph-objectstore-tool and fix broken PG via PG export/import from either local (unlikely) or remote (likelyt) replica (using export/export-remove/remove commands) or just remove a PG and make Ceph to recover that automatically.

From the log you sHow to determine the broken PG id? In the log you shared one can see the following pattern:

-1> 2022-07-19T12:26:04.029+0000 7f0bdf9e8200 5 osd.12 pg_epoch: 22831 pg[16.68(unlocked)] enter Initial
0> 2022-07-19T12:26:04.121+0000 7f0bdf9e8200 -1 ** Caught signal (Aborted) * in thread 7f0bdf9e8200 thread_name:ceph-osd

Highly likely the PG mentioned in the first line is the culprit, i.e. PG id is 16.68 in this case.

Please note that there might be more that one broken PG so you'll need to treat all of them by reiterating PG export/import multiple times.

2) Investigate the root cause for such entry(-ies) appearance. At least we need to understand what had been happening to OSD before the first startup failure appearance - hence we need relevant log(S) for that period. Not to mention this might be far from enough and potentially this investigation looks like a tricky task. I'd be glad to take a look at the mentioned "first appearance" log if any but I'm not sure I'll be available for a thorough investigation

Hope this helps.

We spent full last day to recover 4 osds that wouldn't come back up.
We saw on the machines a lot of errors like this in the dmesg.
Could this be related ?

```
[Wed Jul 20 07:38:43 2022] bstore_kv_final<sup>53756</sup>: segfault at 0 ip 00007fd0f81a3573 sp 00007fd0e7bc5ef0 error 4 in libtcmalloc.so.4.5.3[7fd0f8178000+4d000]
[Wed Jul 20 07:38:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] bstore_kv_final<sup>242382</sup>: segfault at 0 ip 00007fece5b99573 sp 00007fecd55bbef0 error 4 in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Wed Jul 20 18:54:44 2022] traps: tp_osd_tp<sup>242427</sup> general protection fault ip:7fece5ba9d6a sp:7fecc2f5bdc8 error:0
[Wed Jul 20 18:54:44 2022] tp_osd_tp<sup>242434</sup>: segfault at 0 ip 00007fece5b99573 sp 00007fecbf74c420 error 4 in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Wed Jul 20 18:54:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Fri Jul 22 09:35:30 2022] traps: msgr-worker-2<sup>64574</sup> general protection fault ip:7fc2ca340d6a sp:7fc2c47f3ab8 error:0 in libtcmalloc.so.4.5.3[7fc2ca305000+4d000]
[Fri Jul 22 09:35:30 2022] traps: bstore_kv_final<sup>65681</sup> general protection fault ip:7fc2c846b99d sp:7fc2b9d4c110 error:0 in libc-2.28.so[7fc2c841a000+1bc000]
```

Sébastien Bernard wrote:

We spent full last day to recover 4 osds that wouldn't come back up.
We saw on the machines a lot of errors like this in the dmesg.
Could this be related ?

Can't say for sure but definitely this looks suspicious. Curious what's present in relevant OSD log(s) at those points in time?

```
[Wed Jul 20 07:38:43 2022] bstore_kv_final<sup>53756</sup>: segfault at 0 ip 00007fd0f81a3573 sp 00007fd0e7bc5ef0 error 4 in libtcmalloc.so.4.5.3[7fd0f8178000+4d000]
[Wed Jul 20 07:38:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] bstore_kv_final<sup>242382</sup>: segfault at 0 ip 00007fece5b99573 sp 00007fecd55bbef0 error 4 in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Wed Jul 20 18:54:44 2022] traps: tp_osd_tp<sup>242427</sup> general protection fault ip:7fece5ba9d6a sp:7fecc2f5bdc8 error:0
[Wed Jul 20 18:54:44 2022] tp_osd_tp<sup>242434</sup>: segfault at 0 ip 00007fece5b99573 sp 00007fecbf74c420 error 4 in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Wed Jul 20 18:54:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] Code: d9 4c 89 e7 41 29 df e8 4b c0 fe ff 44 39 fb 7c a6 48 8b 75 00 48 89 f2 41 83 ff 01 7e 14 b8 01 00 00 00 0f 1f 40 00 83 c0 01 <48> 8b 12 41 39 c7 75 f5 48 8b 02 48 89 45 00 48 c7 02 00 00 00 00
[Wed Jul 20 18:54:44 2022] in libtcmalloc.so.4.5.3[7fece5b6e000+4d000]
[Fri Jul 22 09:35:30 2022] traps: msgr-worker-2<sup>64574</sup> general protection fault ip:7fc2ca340d6a sp:7fc2c47f3ab8 error:0 in libtcmalloc.so.4.5.3[7fc2ca305000+4d000]
[Fri Jul 22 09:35:30 2022] traps: bstore_kv_final<sup>65681</sup> general protection fault ip:7fc2c846b99d sp:7fc2b9d4c110 error:0 in libc-2.28.so[7fc2c841a000+1bc000]
```

Hello, a quick follow up to say the problem has been resolved.
We removed the 15Gib memory limit per OSD and crashes were gone.

We don't know why there is error in tcmalloc while not triggering and OOMKill when memory limit is reached.

Hi Sebastien,

does the above mean that OSDs are using more that 15GB RAM at some point?

How large is the peak then? At what stage (startup/shutdown/regular functioning) does it happen?

Igor,
We can't know how large is the peak since we removed rook osd limits.
Without limit, the biggest OSD is taking 55Gib of memory and the smallest around 1.5 Gib.
I think rook is setting the osd_memory_target according to the memory limit it puts on the pod.

We're also using erasure coding and topology which may or not put some pressure on host ressource.

The crash occured randomly while running. Moreover, the crashes seems to corrupt the osd data randomly also.
First symptom is this line in the dmesg related to tcmalloc.