Actions
Bug #6370
closedosd: slow request warning exponential backoff fails at 3840 seconds
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
on cuttlefish, user reports: The OSD keeps logging this as a "slow request". The back-off logic is funny; first it does factor-2 backoff (30, 60, 120, ... seconds). But after 3840 seconds, it logs every second.
root@h0:/var/log/ceph# grep slow /var/log/ceph/ceph-osd.23.log | head -20 2013-09-23 21:23:03.186703 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 30.928934 secs 2013-09-23 21:23:03.186713 7f5aca7b0700 0 log [WRN] : slow request 30.928934 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:23:33.192198 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 60.934474 secs 2013-09-23 21:23:33.192211 7f5aca7b0700 0 log [WRN] : slow request 60.934474 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:24:33.208885 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 120.951151 secs 2013-09-23 21:24:33.208897 7f5aca7b0700 0 log [WRN] : slow request 120.951151 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:26:33.231156 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 240.973433 secs 2013-09-23 21:26:33.231170 7f5aca7b0700 0 log [WRN] : slow request 240.973433 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:30:32.277457 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 480.019722 secs 2013-09-23 21:30:32.277471 7f5aca7b0700 0 log [WRN] : slow request 480.019722 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:38:32.906922 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 960.649180 secs 2013-09-23 21:38:32.906933 7f5aca7b0700 0 log [WRN] : slow request 960.649180 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 21:54:33.153896 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 1920.896178 secs 2013-09-23 21:54:33.153917 7f5aca7b0700 0 log [WRN] : slow request 1920.896178 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 22:26:32.608132 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 3840.350403 secs 2013-09-23 22:26:32.608145 7f5aca7b0700 0 log [WRN] : slow request 3840.350403 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 22:26:33.608345 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 3841.350622 secs 2013-09-23 22:26:33.608358 7f5aca7b0700 0 log [WRN] : slow request 3841.350622 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg 2013-09-23 22:26:34.608672 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 3842.350947 secs 2013-09-23 22:26:34.608684 7f5aca7b0700 0 log [WRN] : slow request 3842.350947 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg root@h0:/var/log/ceph# grep slow /var/log/ceph/ceph-osd.23.log | tail -10 2013-09-23 23:53:13.195878 7f5aca7b0700 0 log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 9040.938146 secs 2013-09-23 23:53:13.195892 7f5aca7b0700 0 log [WRN] : slow request 9040.938146 seconds old, received at 2013-09-23 21:22:32.257689: osd_op(client.192673.0:10548 [pgls start_epoch 0] 0.cfa e69131) v4 currently reached pg ....
Actions