So far what I see is that the client op didn't get scheduled at all on osd.1 due a continuous stream of higher priority peering ops on the same OSD shard . As a result the slow request warning is reported. But this warning is ignored since it is a part of the ignore list. I didn't see any rados api test failures though. The test fails because a few PGs didn't get backfilled in time. Each of those PGs has a single missing object which for some reason is not getting backfilled shown below:
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:PG 13.1 is not active+clean
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:{'pgid': '13.1', 'version': "1222'7", 'reported_seq': 5407, 'reported_epoch': 4192, 'state': 'active+remapped+backfilling', 'last_fresh': '2024-02-13T19:18:32.968671+0000', 'last_change': '2024-02-13T18:33:52.663811+0000', 'last_active': '2024-02-13T19:18:32.968671+0000', 'last_peered': '2024-02-13T19:18:32.968671+0000', 'last_clean': '2024-02-13T18:19:16.469528+0000', 'last_became_active': '2024-02-13T18:27:20.655505+0000', 'last_became_peered': '2024-02-13T18:27:20.655505+0000', 'last_unstale': '2024-02-13T19:18:32.968671+0000', 'last_undegraded': '2024-02-13T19:18:32.968671+0000', 'last_fullsized': '2024-02-13T19:18:32.968671+0000', 'mapping_epoch': 2381, 'log_start': "1222'5", 'ondisk_log_start': "1222'5", 'created': 70, 'last_epoch_clean': 2149, 'parent': '0.0', 'parent_split_bits': 0, 'last_scrub': "0'0", 'last_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'last_deep_scrub': "0'0", 'last_deep_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'last_clean_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'objects_scrubbed': 0, 'log_size': 2, 'log_dups_size': 5, 'ondisk_log_size': 2, 'stats_invalid': False, 'dirty_stats_invalid': False, 'omap_stats_invalid': False, 'hitset_stats_invalid': False, 'hitset_bytes_stats_invalid': False, 'pin_stats_invalid': False, 'manifest_stats_invalid': False, 'snaptrimq_len': 0, 'last_scrub_duration': 0, 'scrub_schedule': 'no scrub is scheduled', 'scrub_duration': 0, 'objects_trimmed': 0, 'snaptrim_duration': 0, 'stat_sum': {'num_bytes': 5, 'num_objects': 1, 'num_object_clones': 0, 'num_object_copies': 3, 'num_objects_missing_on_primary': 0, 'num_objects_missing': 0, 'num_objects_degraded': 0, 'num_objects_misplaced': 1, 'num_objects_unfound': 0, 'num_objects_dirty': 1, 'num_whiteouts': 0, 'num_read': 6, 'num_read_kb': 6, 'num_write': 7, 'num_write_kb': 7, 'num_scrub_errors': 0, 'num_shallow_scrub_errors': 0, 'num_deep_scrub_errors': 0, 'num_objects_recovered': 2, 'num_bytes_recovered': 10, 'num_keys_recovered': 0, 'num_objects_omap': 0, 'num_objects_hit_set_archive': 0, 'num_bytes_hit_set_archive': 0, 'num_flush': 0, 'num_flush_kb': 0, 'num_evict': 0, 'num_evict_kb': 0, 'num_promote': 0, 'num_flush_mode_high': 0, 'num_flush_mode_low': 0, 'num_evict_mode_some': 0, 'num_evict_mode_full': 0, 'num_objects_pinned': 0, 'num_legacy_snapsets': 0, 'num_large_omap_objects': 0, 'num_objects_manifest': 0, 'num_omap_bytes': 0, 'num_omap_keys': 0, 'num_objects_repaired': 0}, 'up': [1, 4, 3], 'acting': [1, 4, 0], 'avail_no_missing': ['1', '0', '4'], 'object_location_counts': [{'shards': '0,1,4', 'objects': 1}], 'blocked_by': [], 'up_primary': 1, 'acting_primary': 1, 'purged_snaps': []}
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:PG 5.11 is not active+clean
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:{'pgid': '5.11', 'version': "2578'7", 'reported_seq': 5062, 'reported_epoch': 4191, 'state': 'active+remapped+backfilling', 'last_fresh': '2024-02-13T19:18:30.998467+0000', 'last_change': '2024-02-13T18:34:10.970040+0000', 'last_active': '2024-02-13T19:18:30.998467+0000', 'last_peered': '2024-02-13T19:18:30.998467+0000', 'last_clean': '2024-02-13T18:26:49.076456+0000', 'last_became_active': '2024-02-13T18:27:08.059580+0000', 'last_became_peered': '2024-02-13T18:27:08.059580+0000', 'last_unstale': '2024-02-13T19:18:30.998467+0000', 'last_undegraded': '2024-02-13T19:18:30.998467+0000', 'last_fullsized': '2024-02-13T19:18:30.998467+0000', 'mapping_epoch': 2423, 'log_start': "2243'4", 'ondisk_log_start': "2243'4", 'created': 70, 'last_epoch_clean': 2411, 'parent': '0.0', 'parent_split_bits': 0, 'last_scrub': "0'0", 'last_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'last_deep_scrub': "0'0", 'last_deep_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'last_clean_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'objects_scrubbed': 0, 'log_size': 3, 'log_dups_size': 4, 'ondisk_log_size': 3, 'stats_invalid': False, 'dirty_stats_invalid': False, 'omap_stats_invalid': False, 'hitset_stats_invalid': False, 'hitset_bytes_stats_invalid': False, 'pin_stats_invalid': False, 'manifest_stats_invalid': False, 'snaptrimq_len': 0, 'last_scrub_duration': 0, 'scrub_schedule': 'no scrub is scheduled', 'scrub_duration': 0, 'objects_trimmed': 0, 'snaptrim_duration': 0, 'stat_sum': {'num_bytes': 128, 'num_objects': 1, 'num_object_clones': 0, 'num_object_copies': 3, 'num_objects_missing_on_primary': 0, 'num_objects_missing': 0, 'num_objects_degraded': 0, 'num_objects_misplaced': 1, 'num_objects_unfound': 0, 'num_objects_dirty': 1, 'num_whiteouts': 0, 'num_read': 0, 'num_read_kb': 0, 'num_write': 7, 'num_write_kb': 4, 'num_scrub_errors': 0, 'num_shallow_scrub_errors': 0, 'num_deep_scrub_errors': 0, 'num_objects_recovered': 1, 'num_bytes_recovered': 128, 'num_keys_recovered': 0, 'num_objects_omap': 0, 'num_objects_hit_set_archive': 0, 'num_bytes_hit_set_archive': 0, 'num_flush': 0, 'num_flush_kb': 0, 'num_evict': 0, 'num_evict_kb': 0, 'num_promote': 0, 'num_flush_mode_high': 0, 'num_flush_mode_low': 0, 'num_evict_mode_some': 0, 'num_evict_mode_full': 0, 'num_objects_pinned': 0, 'num_legacy_snapsets': 0, 'num_large_omap_objects': 0, 'num_objects_manifest': 0, 'num_omap_bytes': 0, 'num_omap_keys': 0, 'num_objects_repaired': 0}, 'up': [3, 2, 4], 'acting': [3, 2, 5], 'avail_no_missing': ['3', '2', '5'], 'object_location_counts': [{'shards': '2,3,5', 'objects': 1}], 'blocked_by': [], 'up_primary': 3, 'acting_primary': 3, 'purged_snaps': []}
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:PG 5.1d is not active+clean
2024-02-13T19:18:34.399 INFO:tasks.ceph.ceph_manager.ceph:{'pgid': '5.1d', 'version': "2578'7", 'reported_seq': 7113, 'reported_epoch': 4192, 'state': 'active+remapped+backfilling', 'last_fresh': '2024-02-13T19:18:32.969131+0000', 'last_change': '2024-02-13T18:33:46.389640+0000', 'last_active': '2024-02-13T19:18:32.969131+0000', 'last_peered': '2024-02-13T19:18:32.969131+0000', 'last_clean': '2024-02-13T18:27:05.509667+0000', 'last_became_active': '2024-02-13T18:27:08.564327+0000', 'last_became_peered': '2024-02-13T18:27:08.564327+0000', 'last_unstale': '2024-02-13T19:18:32.969131+0000', 'last_undegraded': '2024-02-13T19:18:32.969131+0000', 'last_fullsized': '2024-02-13T19:18:32.969131+0000', 'mapping_epoch': 2423, 'log_start': "2243'4", 'ondisk_log_start': "2243'4", 'created': 70, 'last_epoch_clean': 2409, 'parent': '0.0', 'parent_split_bits': 0, 'last_scrub': "0'0", 'last_scrub_stamp': '2024-02-13T17:36:30.244815+0000', 'last_deep_scrub': "0'0", 'last_deep_scrub_stamp': '2024-02-13T17:25:01.973344+0000', 'last_clean_scrub_stamp': '2024-02-13T17:36:30.244815+0000', 'objects_scrubbed': 0, 'log_size': 3, 'log_dups_size': 4, 'ondisk_log_size': 3, 'stats_invalid': False, 'dirty_stats_invalid': False, 'omap_stats_invalid': False, 'hitset_stats_invalid': False, 'hitset_bytes_stats_invalid': False, 'pin_stats_invalid': False, 'manifest_stats_invalid': False, 'snaptrimq_len': 0, 'last_scrub_duration': 1, 'scrub_schedule': 'no scrub is scheduled', 'scrub_duration': 902, 'objects_trimmed': 0, 'snaptrim_duration': 0, 'stat_sum': {'num_bytes': 128, 'num_objects': 1, 'num_object_clones': 0, 'num_object_copies': 3, 'num_objects_missing_on_primary': 0, 'num_objects_missing': 0, 'num_objects_degraded': 0, 'num_objects_misplaced': 1, 'num_objects_unfound': 0, 'num_objects_dirty': 1, 'num_whiteouts': 0, 'num_read': 0, 'num_read_kb': 0, 'num_write': 7, 'num_write_kb': 4, 'num_scrub_errors': 0, 'num_shallow_scrub_errors': 0, 'num_deep_scrub_errors': 0, 'num_objects_recovered': 0, 'num_bytes_recovered': 0, 'num_keys_recovered': 0, 'num_objects_omap': 0, 'num_objects_hit_set_archive': 0, 'num_bytes_hit_set_archive': 0, 'num_flush': 0, 'num_flush_kb': 0, 'num_evict': 0, 'num_evict_kb': 0, 'num_promote': 0, 'num_flush_mode_high': 0, 'num_flush_mode_low': 0, 'num_evict_mode_some': 0, 'num_evict_mode_full': 0, 'num_objects_pinned': 0, 'num_legacy_snapsets': 0, 'num_large_omap_objects': 0, 'num_objects_manifest': 0, 'num_omap_bytes': 0, 'num_omap_keys': 0, 'num_objects_repaired': 0}, 'up': [1, 4, 6], 'acting': [1, 6, 2], 'avail_no_missing': ['1', '2', '6'], 'object_location_counts': [{'shards': '1,2,6', 'objects': 1}], 'blocked_by': [], 'up_primary': 1, 'acting_primary': 1, 'purged_snaps': []}
2024-02-13T19:18:34.401 INFO:tasks.thrashosds.thrasher:Traceback (most recent call last):
File "/home/teuthworker/src/git.ceph.com_ceph-c_3d2b0d7b9d303971fd78b4efe33cf2a06e3a7a4d/qa/tasks/ceph_manager.py", line 190, in wrapper
return func(self)
File "/home/teuthworker/src/git.ceph.com_ceph-c_3d2b0d7b9d303971fd78b4efe33cf2a06e3a7a4d/qa/tasks/ceph_manager.py", line 1425, in _do_thrash
self.ceph_manager.wait_for_recovery(
File "/home/teuthworker/src/git.ceph.com_ceph-c_3d2b0d7b9d303971fd78b4efe33cf2a06e3a7a4d/qa/tasks/ceph_manager.py", line 2873, in wait_for_recovery
assert now - start < timeout, \
AssertionError: wait_for_recovery: failed before timeout expired
I will update with additional details if I find anything else.