Hmm, OK, thanks. I'm not certain what the cause would be; hopefully
others chime in as well. How long after creating that OSD as Pacific
did this issue start?
Josh
On Fri, Apr 8, 2022 at 7:33 AM Clippinger, Sam
<Sam.Clippinger@xxxxxxxxxx> wrote:
>
> Yes, I see those messages in the logs. ("debug_rocksdb" is 4/5, is that the correct option?) All of the reasons seem to be "LevelMaxLevelSize" and "LevelL0FilesNum". FWIW, I see *more* of those messages from the non-problematic OSD daemons with the same two reasons -- about twice as many messages per day compared to this OSD daemon. Here are some of the messages from the buggy OSD this morning:
>
> 2022-04-08T05:20:43.844-0500 7fed35c89700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649413243846014, "job": 3246, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29208, 29194, 29186, 29173, 29161, 29154, 29144, 29115], "files_L1": [29090, 29091, 29092, 29094, 29095, 29096, 29098, 29099], "score": 1, "input_data_size": 572375191}
> 2022-04-08T05:24:29.341-0500 7fed39c91700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649413469342968, "job": 3249, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29220, 29198, 29184, 29175, 29163, 29152, 29139, 29113], "files_L1": [29073, 29074, 29075, 29077, 29078, 29079, 29080, 29081], "score": 1, "input_data_size": 635871766}
> 2022-04-08T05:25:39.728-0500 7fed39c91700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649413539730161, "job": 3250, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29229], "files_L2": [27935, 27936, 27770, 27771, 25736], "score": 1.10752, "input_data_size": 263047746}
> 2022-04-08T05:30:10.599-0500 7fed3a492700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649413810599479, "job": 3253, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29235, 29196, 29179, 29156, 29128, 29069, 29052, 29037], "files_L1": [29019], "score": 1, "input_data_size": 44429645}
> 2022-04-08T05:37:04.062-0500 7fed3748c700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649414224063609, "job": 3258, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29242, 29218, 29200, 29189, 29177, 29165, 29150, 29141], "files_L1": [29118, 29119, 29120, 29121, 29122, 29124, 29125, 29126], "score": 1, "input_data_size": 615274835}
> 2022-04-08T05:38:04.277-0500 7fed3748c700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649414284278865, "job": 3259, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29246], "files_L2": [28704, 27821, 28283], "score": 1.07011, "input_data_size": 281401567}
> 2022-04-08T07:13:03.212-0500 7fed3648a700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649419983213804, "job": 3306, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29324, 29269, 29171, 29067, 29008, 28896, 28821, 28742], "files_L1": [28671, 28672, 28673, 28674, 28675, 28676], "score": 1, "input_data_size": 599890763}
> 2022-04-08T07:33:33.858-0500 7fed33c85700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421213859232, "job": 3326, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29358, 29344, 29320, 29307, 29294, 29283, 29271, 29257], "files_L1": [29221, 29222, 29223, 29224, 29225, 29226, 29227, 29228], "score": 1, "input_data_size": 654997766}
> 2022-04-08T07:34:11.973-0500 7fed33c85700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421251975019, "job": 3327, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29364], "files_L2": [28093, 28094, 28095], "score": 1.13718, "input_data_size": 281785167}
> 2022-04-08T07:35:17.965-0500 7fed35488700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421317965462, "job": 3329, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29373, 29342, 29317, 29305, 29292, 29279, 29263, 29240], "files_L1": [29209, 29210, 29211, 29212, 29213, 29214, 29215, 29216], "score": 1, "input_data_size": 655723965}
> 2022-04-08T07:35:56.142-0500 7fed35488700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421356143693, "job": 3332, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29378, 29348, 29330, 29313, 29301, 29290, 29277, 29265], "files_L1": [29243, 29244, 29245, 29247, 29248, 29249, 29250, 29251], "score": 1, "input_data_size": 612400664}
> 2022-04-08T07:36:31.271-0500 7fed35488700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421391272777, "job": 3333, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29374], "files_L2": [20985, 20986, 20987, 28361], "score": 1.1601, "input_data_size": 352034231}
> 2022-04-08T07:36:50.897-0500 7fed35488700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421410898231, "job": 3334, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29392], "files_L2": [28561, 28562, 28565, 27984], "score": 1.07674, "input_data_size": 282846401}
> 2022-04-08T07:37:05.556-0500 7fed35488700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649421425557370, "job": 3335, "event": "compaction_started", "compaction_reason": "LevelMaxLevelSize", "files_L1": [29380], "files_L2": [28505, 28506, 28507, 28508], "score": 1.01021, "input_data_size": 351670762}
> 2022-04-08T07:50:41.021-0500 7fed424a2700 4 rocksdb: EVENT_LOG_v1 {"time_micros": 1649422241022946, "job": 3341, "event": "compaction_started", "compaction_reason": "LevelL0FilesNum", "files_L0": [29413, 29356, 29346, 29337, 29315, 29303, 29287, 29267], "files_L1": [29236], "score": 1, "input_data_size": 40356475}
>
> -- Sam Clippinger
>
>
> -----Original Message-----
> From: Josh Baergen <jbaergen@xxxxxxxxxxxxxxxx>
> Sent: Friday, April 8, 2022 8:07 AM
> To: Clippinger, Sam <Sam.Clippinger@xxxxxxxxxx>
> Cc: ceph-users@xxxxxxx
> Subject: Re: Re: OSD daemon writes constantly to device without Ceph traffic - bug?
>
> CAUTION - EXTERNAL EMAIL: Do not click any links or open any attachments unless you trust the sender and know the content is safe.
>
>
> Hi Sam,
>
> Do the OSD logs indicate rocksdb compaction happening? (These logs occur at debug level 4, so depending on your logging settings you may or may not see them.) If so, what is the "compaction_reason"?
>
> Josh
>
> On Fri, Apr 8, 2022 at 6:42 AM Clippinger, Sam <Sam.Clippinger@xxxxxxxxxx> wrote:
> >
> > Quick follow-up:
> >
> > Running "iotop -tobk" shows the culprits seem to be the "bstore_kv_sync" and "rocksdb:low27" threads. Here's the output from one iteration for the daemon process:
> > b'07:36:22 513912 be/4 651 0.00 K/s 218342.12 K/s 0.00 % 0.18 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [bstore_kv_sync]'
> > b'07:36:22 513467 be/4 651 0.00 K/s 134410.60 K/s 0.00 % 0.15 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [rocksdb:low27]'
> > b'07:36:22 513941 be/4 651 0.00 K/s 63.61 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513942 be/4 651 0.00 K/s 141.36 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513943 be/4 651 0.00 K/s 10.60 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513944 be/4 651 0.00 K/s 3.53 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513945 be/4 651 0.00 K/s 14.14 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513946 be/4 651 0.00 K/s 151.96 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513947 be/4 651 0.00 K/s 7.07 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513948 be/4 651 28.27 K/s 925.90 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513949 be/4 651 0.00 K/s 148.43 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513950 be/4 651 0.00 K/s 7.07 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513951 be/4 651 0.00 K/s 14.14 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513952 be/4 651 0.00 K/s 7.07 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513953 be/4 651 0.00 K/s 14.14 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513954 be/4 651 0.00 K/s 24.74 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513955 be/4 651 0.00 K/s 141.36 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> > b'07:36:22 513956 be/4 651 28.27 K/s 38.87 K/s 0.00 % 0.00 % ceph-osd -d --cluster ceph --id 9000 --setuser ceph --setgroup ceph [tp_osd_tp]'
> >
> > Is there any way to figure out what these threads are doing?
> >
> > -- Sam Clippinger
> >
> >
> > -----Original Message-----
> > From: Clippinger, Sam <Sam.Clippinger@xxxxxxxxxx>
> > Sent: Friday, April 8, 2022 7:26 AM
> > To: ceph-users@xxxxxxx
> > Subject: OSD daemon writes constantly to device without Ceph traffic - bug?
> >
> > Hello everyone!
> >
> > I've noticed something strange since updating our cluster from Nautilus to Pacific 16.2.7. Out of 40 OSDs, one was created with Pacific 16.2.7 and all others in the cluster were created with Nautilus or Mimic (the daemons are all running Pacific). Every few days, the OSD created with Pacific will suddenly start writing to its device constantly. As I type this, it is writing 250-350 MiB/s to the drive (according to iotop). All other OSDs are writing about 15-30 MiB/s to their devices. Read activity is normal - all OSDs are reading 50-100 MiB/s.
> >
> > There isn't nearly enough client activity to justify this activity, the cluster is healthy, nothing is rebalancing or scrubbing. Using "ceph osd status" shows the OSD has about the same number of reads and writes as all the others. I tried using "ceph tell osd.X config set" to increase every debug_* option to its maximum setting, but nothing seemed to stand out. There was some additional output (not much) and it was mostly "bluestore.MempoolThread(x) _resize_shards", "prioritycache tune_memory", "heartbeat osd_stat" and "ms_handle_reset con".
> >
> > What else can I do to troubleshoot this? Is this a bug? Restarting the OSD daemon "fixes" it for a few days, then it always seems to start happening again. I'm planning to recreate all of the OSDs in this cluster this weekend (to split each NVMe drive into multiple OSDs), so I'm concerned about every OSD showing this behavior next week. Should I postpone this weekend's work? I haven't restarted the OSD daemon yet this morning, so I can still try some additional debugging while the writing is going on.
> >
> > -- Sam Clippinger
> >
> > ________________________________
> >
> > CONFIDENTIALITY NOTICE: This email and any attachments are for the sole use of the intended recipient(s) and contain information that may be Garmin confidential and/or Garmin legally privileged. If you have received this email in error, please notify the sender by reply email and delete the message. Any disclosure, copying, distribution or use of this communication (including attachments) by someone other than the intended recipient is prohibited. Thank you.
> > _______________________________________________
> > ceph-users mailing list -- ceph-users@xxxxxxx To unsubscribe send an
> > email to ceph-users-leave@xxxxxxx
> _______________________________________________
> ceph-users mailing list -- ceph-users@xxxxxxx
> To unsubscribe send an email to ceph-users-leave@xxxxxxx
_______________________________________________
ceph-users mailing list -- ceph-users@xxxxxxx
To unsubscribe send an email to ceph-users-leave@xxxxxxx
