https://tracker.ceph.com/
https://tracker.ceph.com/favicon.ico
2020-06-24T13:16:09Z
Ceph
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=168927
2020-06-24T13:16:09Z
Sebastian Wagner
<ul></ul><p><a class="external" href="http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175480/">http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175480/</a></p>
<pre>
2020-06-24T12:17:15.031 INFO:tasks.cephadm:Deploying osd.4 on smithi086 with /dev/vg_nvme/lv_4...
...
2020-06-24T12:39:57.962 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.395830+0000 osd.4 (osd.4) 2973 : cluster [WRN] slow request osd_op(client.25525.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:28:56.101558+0000 currently delayed
2020-06-24T12:39:57.962 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.395850+0000 osd.4 (osd.4) 2974 : cluster [WRN] slow request osd_op(client.26062.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:34:08.034626+0000 currently delayed
2020-06-24T12:39:57.962 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.395860+0000 osd.4 (osd.4) 2975 : cluster [WRN] slow request osd_op(client.26623.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:39:20.069032+0000 currently delayed
2020-06-24T12:39:57.962 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.395871+0000 osd.4 (osd.4) 2976 : cluster [WRN] slow request osd_op(client.24382.0:64 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e53) initiated 2020-06-24T12:18:35.915363+0000 currently delayed
2020-06-24T12:39:57.962 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.395881+0000 osd.4 (osd.4) 2977 : cluster [WRN] slow request osd_op(client.24970.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:23:43.738782+0000 currently delayed
2020-06-24T12:39:57.963 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: audit 2020-06-24T12:39:56.865059+0000 mgr.x (mgr.34109) 1017 : audit [DBG] from='client.26683 -' entity='client.admin' cmd=[{"prefix": "pg dump", "target": ["mon-mgr", ""], "format": "json"}]: dispatch
2020-06-24T12:39:57.963 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.395830+0000 osd.4 (osd.4) 2973 : cluster [WRN] slow request osd_op(client.25525.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:28:56.101558+0000 currently delayed
2020-06-24T12:39:57.963 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.395850+0000 osd.4 (osd.4) 2974 : cluster [WRN] slow request osd_op(client.26062.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:34:08.034626+0000 currently delayed
2020-06-24T12:39:57.963 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.395860+0000 osd.4 (osd.4) 2975 : cluster [WRN] slow request osd_op(client.26623.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:39:20.069032+0000 currently delayed
2020-06-24T12:39:57.963 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.395871+0000 osd.4 (osd.4) 2976 : cluster [WRN] slow request osd_op(client.24382.0:64 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e53) initiated 2020-06-24T12:18:35.915363+0000 currently delayed
2020-06-24T12:39:57.964 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:57 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.395881+0000 osd.4 (osd.4) 2977 : cluster [WRN] slow request osd_op(client.24970.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:23:43.738782+0000 currently delayed
2020-06-24T12:39:58.188 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: audit 2020-06-24T12:39:56.865059+0000 mgr.x (mgr.34109) 1017 : audit [DBG] from='client.26683 -' entity='client.admin' cmd=[{"prefix": "pg dump", "target": ["mon-mgr", ""], "format": "json"}]: dispatch
2020-06-24T12:39:58.189 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: cluster 2020-06-24T12:39:57.395830+0000 osd.4 (osd.4) 2973 : cluster [WRN] slow request osd_op(client.25525.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:28:56.101558+0000 currently delayed
2020-06-24T12:39:58.189 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: cluster 2020-06-24T12:39:57.395850+0000 osd.4 (osd.4) 2974 : cluster [WRN] slow request osd_op(client.26062.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:34:08.034626+0000 currently delayed
2020-06-24T12:39:58.189 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: cluster 2020-06-24T12:39:57.395860+0000 osd.4 (osd.4) 2975 : cluster [WRN] slow request osd_op(client.26623.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:39:20.069032+0000 currently delayed
2020-06-24T12:39:58.190 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: cluster 2020-06-24T12:39:57.395871+0000 osd.4 (osd.4) 2976 : cluster [WRN] slow request osd_op(client.24382.0:64 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e53) initiated 2020-06-24T12:18:35.915363+0000 currently delayed
2020-06-24T12:39:58.190 INFO:ceph.mon.b.smithi086.stdout:Jun 24 12:39:57 smithi086 bash[25326]: cluster 2020-06-24T12:39:57.395881+0000 osd.4 (osd.4) 2977 : cluster [WRN] slow request osd_op(client.24970.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:23:43.738782+0000 currently delayed
2020-06-24T12:39:58.688 INFO:ceph.osd.4.smithi086.stdout:Jun 24 12:39:58 smithi086 bash[28147]: debug 2020-06-24T12:39:58.351+0000 7f56a45d9700 -1 osd.4 54 get_health_metrics reporting 5 slow ops, oldest is osd_op(client.24382.0:64 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e53)
2020-06-24T12:39:58.965 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:57.710162+0000 mgr.x (mgr.34109) 1018 : cluster [DBG] pgmap v751: 97 pgs: 3 creating+peering, 94 active+clean; 1.9 KiB data, 4.0 MiB used, 707 GiB / 715 GiB avail
2020-06-24T12:39:58.966 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:58.351337+0000 osd.4 (osd.4) 2978 : cluster [WRN] slow request osd_op(client.25525.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:28:56.101558+0000 currently delayed
2020-06-24T12:39:58.966 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:58.351343+0000 osd.4 (osd.4) 2979 : cluster [WRN] slow request osd_op(client.26062.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:34:08.034626+0000 currently delayed
2020-06-24T12:39:58.966 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:58.351347+0000 osd.4 (osd.4) 2980 : cluster [WRN] slow request osd_op(client.26623.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:39:20.069032+0000 currently delayed
2020-06-24T12:39:58.966 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:58.351351+0000 osd.4 (osd.4) 2981 : cluster [WRN] slow request osd_op(client.24382.0:64 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e53) initiated 2020-06-24T12:18:35.915363+0000 currently delayed
2020-06-24T12:39:58.966 INFO:ceph.mon.c.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[29527]: cluster 2020-06-24T12:39:58.351355+0000 osd.4 (osd.4) 2982 : cluster [WRN] slow request osd_op(client.24970.0:62 4.d 4.a204812d (undecoded) ondisk+write+known_if_redirected e54) initiated 2020-06-24T12:23:43.738782+0000 currently delayed
2020-06-24T12:39:58.967 INFO:ceph.mon.a.smithi073.stdout:Jun 24 12:39:58 smithi073 bash[25319]: cluster 2020-06-24T12:39:57.710162+0000 mgr.x (mgr.34109) 1018 : cluster [DBG] pgmap v751: 97 pgs: 3 creating+peering, 94 active+clean; 1.9 KiB data, 4.0 MiB used, 707 GiB / 715 GiB avail
</pre>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=168928
2020-06-24T13:17:25Z
Sebastian Wagner
<ul><li><strong>Priority</strong> changed from <i>Normal</i> to <i>High</i></li></ul>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=168929
2020-06-24T13:19:41Z
Sebastian Wagner
<ul></ul><p><a class="external" href="http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175488/">http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175488/</a></p>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=168930
2020-06-24T13:20:16Z
Sebastian Wagner
<ul></ul><p><a class="external" href="http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175501/">http://pulpito.ceph.com/swagner-2020-06-24_11:30:44-rados:cephadm-wip-swagner3-testing-2020-06-24-1025-distro-basic-smithi/5175501/</a></p>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169066
2020-06-25T19:42:30Z
Neha Ojha
nojha@redhat.com
<ul><li><strong>Priority</strong> changed from <i>High</i> to <i>Urgent</i></li></ul>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169075
2020-06-25T22:27:23Z
Neha Ojha
nojha@redhat.com
<ul></ul><p>/a/yuvalif-2020-06-23_14:40:15-rgw-wip-yuval-test-35331-35155-distro-basic-smithi/5173465</p>
<p>Seems very likely to have the same root cause as <a class="external" href="https://tracker.ceph.com/issues/46180">https://tracker.ceph.com/issues/46180</a></p>
<pre>
2020-06-24T06:38:10.611 INFO:tasks.ceph.ceph_manager.ceph:PG 2.2 is not active+clean
2020-06-24T06:38:10.618 INFO:tasks.ceph.ceph_manager.ceph:{'pgid': '2.2', 'version': "0'0", 'reported_seq': '3', 'reported_epoch': '19', 'state': 'creating+peering', 'last_fresh': '2020-06-24T06:18:01.513416+0000', 'last_change': '2020-06-24T06:17:59.508158+0000', 'last_active': '2020-06-24T06:17:59.221347+0000', 'last_peered': '2020-06-24T06:17:59.221347+0000', 'last_clean': '2020-06-24T06:17:59.221347+0000', 'last_became_active': '0.000000', 'last_became_peered': '0.000000', 'last_unstale': '2020-06-24T06:18:01.513416+0000', 'last_undegraded': '2020-06-24T06:18:01.513416+0000', 'last_fullsized': '2020-06-24T06:18:01.513416+0000', 'mapping_epoch': 17, 'log_start': "0'0", 'ondisk_log_start': "0'0", 'created': 17, 'last_epoch_clean': 0, 'parent': '0.0', 'parent_split_bits': 0, 'last_scrub': "0'0", 'last_scrub_stamp': '2020-06-24T06:17:59.221347+0000', 'last_deep_scrub': "0'0", 'last_deep_scrub_stamp': '2020-06-24T06:17:59.221347+0000', 'last_clean_scrub_stamp': '2020-06-24T06:17:59.221347+0000', 'log_size': 0, 'ondisk_log_size': 0, '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, 'stat_sum': {'num_bytes': 0, 'num_objects': 0, 'num_object_clones': 0, 'num_object_copies': 0, 'num_objects_missing_on_primary': 0, 'num_objects_missing': 0, 'num_objects_degraded': 0, 'num_objects_misplaced': 0, 'num_objects_unfound': 0, 'num_objects_dirty': 0, 'num_whiteouts': 0, 'num_read': 0, 'num_read_kb': 0, 'num_write': 0, 'num_write_kb': 0, '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': [3, 6], 'acting': [3, 6], 'avail_no_missing': [], 'object_location_counts': [], 'blocked_by': [6], 'up_primary': 3, 'acting_primary': 3, 'purged_snaps': []}
2020-06-24T06:51:53.330 ERROR:teuthology.contextutil:Saw exception from nested tasks
Traceback (most recent call last):
File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-yuval-test-35331-35155/qa/tasks/ceph.py", line 1830, in task
healthy(ctx=ctx, config=dict(cluster=config['cluster']))
File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-yuval-test-35331-35155/qa/tasks/ceph.py", line 1419, in healthy
manager.wait_for_clean()
File "/home/teuthworker/src/git.ceph.com_ceph-c_wip-yuval-test-35331-35155/qa/tasks/ceph_manager.py", line 2518, in wait_for_clean
'wait_for_clean: failed before timeout expired'
AssertionError: wait_for_clean: failed before timeout expired
</pre>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169076
2020-06-25T22:43:11Z
Sebastian Wagner
<ul><li><strong>Related to</strong> <i><a class="issue tracker-1 status-3 priority-7 priority-highest closed" href="/issues/46180">Bug #46180</a>: qa: Scrubbing terminated -- not all pgs were active and clean.</i> added</li></ul>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169178
2020-06-26T19:27:04Z
Michael Fritch
<ul></ul><p><a class="external" href="http://pulpito.ceph.com/mgfritch-2020-06-26_02:07:27-rados-wip-mgfritch-testing-2020-06-25-1855-distro-basic-smithi/5180589/">http://pulpito.ceph.com/mgfritch-2020-06-26_02:07:27-rados-wip-mgfritch-testing-2020-06-25-1855-distro-basic-smithi/5180589/</a></p>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169250
2020-06-29T12:26:58Z
Sebastian Wagner
<ul></ul><p><a class="external" href="https://pulpito.ceph.com/swagner-2020-06-29_09:26:42-rados:cephadm-wip-swagner-testing-2020-06-26-1524-distro-basic-smithi/5189633/">https://pulpito.ceph.com/swagner-2020-06-29_09:26:42-rados:cephadm-wip-swagner-testing-2020-06-26-1524-distro-basic-smithi/5189633/</a> still running, if someone wants to debug.</p>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169569
2020-07-02T09:04:16Z
Ilya Dryomov
<ul><li><strong>Related to</strong> deleted (<i><a class="issue tracker-1 status-3 priority-7 priority-highest closed" href="/issues/46180">Bug #46180</a>: qa: Scrubbing terminated -- not all pgs were active and clean.</i>)</li></ul>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169571
2020-07-02T09:04:20Z
Ilya Dryomov
<ul><li><strong>Duplicates</strong> <i><a class="issue tracker-1 status-3 priority-7 priority-highest closed" href="/issues/46180">Bug #46180</a>: qa: Scrubbing terminated -- not all pgs were active and clean.</i> added</li></ul>
RADOS - Bug #46178: slow request osd_op(... (undecoded) ondisk+retry+read+ignore_overlay+known_if_redirected e49)
https://tracker.ceph.com/issues/46178?journal_id=169573
2020-07-02T09:04:44Z
Ilya Dryomov
<ul><li><strong>Status</strong> changed from <i>New</i> to <i>Duplicate</i></li></ul>