Our Luminous ceph cluster have been worked without problems for a while, but in the last days we have been suffering from continuous slow requests.
We have indeed done some changes in the infrastructure recently:
- Moved OSD nodes to a new switch
- Increased pg nums for a pool, to have about ~ 100 PGs/OSD (also because we have to install new OSDs in the cluster). The output of 'ceph osd df' is attached.
The problem could also be due to some ''bad' client, but in the log I don't see a clear "correlation" with specific clients or images for such blocked requests.
I also tried to update to latest luminous release and latest CentOS7, but this didn't help.
Attached you can find the detail of one of such slow operations which took about 266 secs (output from 'ceph daemon osd.11 dump_historic_ops').
So as far as I can understand from these events:
{
"time": "2019-02-08 10:26:25.651728",
"event": "op_commit"
},
{
"time": "2019-02-08 10:26:25.651965",
"event": "op_applied"
},
{
"time": "2019-02-08 10:26:25.653236",
"event": "sub_op_commit_rec from 33"
},
{
"time": "2019-02-08 10:30:51.890404",
"event": "sub_op_commit_rec from 23"
},
the problem seems with the "sub_op_commit_rec from 23" event which took too much.
So the problem is that the answer from OSD 23 took to much ?
In the logs of the 2 OSD (11 and 23)in that time frame (attached) I can't find anything useful.
When the problem happened the load and the usage of memory was not high in the relevant nodes.
Any help to debug the issue is really appreciated ! :-)
Thanks, Massimo
{ { "description": "osd_op(client.171725953.0:368920029 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2744320~200704] snapc 0=[] ondisk+write+known_if_redirected e1203982)", "initiated_at": "2019-02-08 10:26:25.614728", "age": 331.598616, "duration": 266.275721, "type_data": { "flag_point": "commit sent; apply or cleanup", "client_info": { "client": "client.171725953", "client_addr": "192.168.61.66:0/4056439540", "tid": 368920029 }, "events": [ { "time": "2019-02-08 10:26:25.614728", "event": "initiated" }, { "time": "2019-02-08 10:26:25.650783", "event": "queued_for_pg" }, { "time": "2019-02-08 10:26:25.650819", "event": "reached_pg" }, { "time": "2019-02-08 10:26:25.650860", "event": "started" }, { "time": "2019-02-08 10:26:25.650919", "event": "waiting for subops from 23,33" }, { "time": "2019-02-08 10:26:25.651111", "event": "commit_queued_for_journal_write" }, { "time": "2019-02-08 10:26:25.651111", "event": "commit_queued_for_journal_write" }, { "time": "2019-02-08 10:26:25.651141", "event": "write_thread_in_journal_buffer" }, { "time": "2019-02-08 10:26:25.651694", "event": "journaled_completion_queued" }, { "time": "2019-02-08 10:26:25.651728", "event": "op_commit" }, { "time": "2019-02-08 10:26:25.651965", "event": "op_applied" }, { "time": "2019-02-08 10:26:25.653236", "event": "sub_op_commit_rec from 33" }, { "time": "2019-02-08 10:30:51.890404", "event": "sub_op_commit_rec from 23" }, { "time": "2019-02-08 10:30:51.890434", "event": "commit_sent" }, { "time": "2019-02-08 10:30:51.890450", "event": "done" } ] } },
2019-02-08 10:26:56.123551 7fb74826d700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 30.547377 secs 2019-02-08 10:26:56.123562 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.547377 seconds old, received at 2019-02-08 10:26:25.576108: osd_op(client.171725953.0:368920028 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1863680~196608] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 33 2019-02-08 10:26:56.123567 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.508756 seconds old, received at 2019-02-08 10:26:25.614728: osd_op(client.171725953.0:368920029 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2744320~200704] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 33 2019-02-08 10:26:58.113263 7fb74826d700 0 log_channel(cluster) log [WRN] : 4 slow requests, 2 included below; oldest blocked for > 32.537095 secs 2019-02-08 10:26:58.113275 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.744069 seconds old, received at 2019-02-08 10:26:27.369134: osd_op(client.180322578.0:99562427 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3756032~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:26:58.113281 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.744016 seconds old, received at 2019-02-08 10:26:27.369187: osd_op(client.180322578.0:99562428 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3874816~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:01.097832 7fb74826d700 0 log_channel(cluster) log [WRN] : 6 slow requests, 2 included below; oldest blocked for > 35.521663 secs 2019-02-08 10:27:01.097844 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.574524 seconds old, received at 2019-02-08 10:26:30.523246: osd_op(client.180372047.0:1026768 17.5 17:a2dd5ec7:::rb.0.21221e5.238e1f29.000000001055:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1032192~8192] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:01.097851 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.534039 seconds old, received at 2019-02-08 10:26:30.563732: osd_op(client.180372047.0:1026769 17.5 17:a2dd5ec7:::rb.0.21221e5.238e1f29.000000001055:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2482176~8192] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:03.087583 7fb74826d700 0 log_channel(cluster) log [WRN] : 14 slow requests, 5 included below; oldest blocked for > 37.511385 secs 2019-02-08 10:27:03.087596 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.524456 seconds old, received at 2019-02-08 10:26:32.563037: osd_op(client.180322578.0:99562517 17.5 17:a306ab40:::rb.0.21293df.238e1f29.0000000025ac:head [set-alloc-hint object_size 4194304 write_size 4194304,write 929792~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:03.087602 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.524290 seconds old, received at 2019-02-08 10:26:32.563202: osd_op(client.180322578.0:99562518 17.5 17:a306ab40:::rb.0.21293df.238e1f29.0000000025ac:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1110016~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:03.087607 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.530046 seconds old, received at 2019-02-08 10:26:32.557447: osd_op(client.180322578.0:99562460 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1835008~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently op_applied 2019-02-08 10:27:03.087612 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.529949 seconds old, received at 2019-02-08 10:26:32.557544: osd_op(client.180322578.0:99562461 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1863680~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently op_applied 2019-02-08 10:27:03.087616 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.529863 seconds old, received at 2019-02-08 10:26:32.557629: osd_op(client.180322578.0:99562462 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2007040~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:04.082503 7fb74826d700 0 log_channel(cluster) log [WRN] : 14 slow requests, 3 included below; oldest blocked for > 38.506326 secs 2019-02-08 10:27:04.082514 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 31.524473 seconds old, received at 2019-02-08 10:26:32.557960: osd_op(client.180322578.0:99562463 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3096576~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:04.082519 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 31.524379 seconds old, received at 2019-02-08 10:26:32.558054: osd_op(client.180322578.0:99562464 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3117056~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:04.082523 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 31.524285 seconds old, received at 2019-02-08 10:26:32.558148: osd_op(client.180322578.0:99562465 17.5 17:a19e1d9d:::rb.0.21293df.238e1f29.000000000581:head [set-alloc-hint object_size 4194304 write_size 4194304,write 3145728~4096] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:05.077344 7fb74826d700 0 log_channel(cluster) log [WRN] : 15 slow requests, 1 included below; oldest blocked for > 39.501195 secs 2019-02-08 10:27:05.077354 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.869063 seconds old, received at 2019-02-08 10:26:34.208240: osd_op(client.180372047.0:1026799 17.5 17:a2cd55a1:::rb.0.21221e5.238e1f29.0000000026de:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1036288~20480] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 44 2019-02-08 10:27:25.968947 7fb74826d700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 60.354190 secs 2019-02-08 10:27:25.968959 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 60.354190 seconds old, received at 2019-02-08 10:26:25.614728: osd_op(client.171725953.0:368920029 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2744320~200704] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 33 2019-02-08 10:28:25.659114 7fb74826d700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 120.044336 secs 2019-02-08 10:28:25.659128 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 120.044336 seconds old, received at 2019-02-08 10:26:25.614728: osd_op(client.171725953.0:368920029 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2744320~200704] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 33 2019-02-08 10:30:22.054636 7fb74826d700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 236.439844 secs 2019-02-08 10:30:22.054649 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 30.820549 seconds old, received at 2019-02-08 10:29:51.234023: osd_op(client.171725953.0:368926335 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [read 3194880~4096] snapc 0=[] ondisk+read+known_if_redirected e1203982) currently waiting for rw locks 2019-02-08 10:30:26.034012 7fb74826d700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 240.419251 secs 2019-02-08 10:30:26.034025 7fb74826d700 0 log_channel(cluster) log [WRN] : slow request 240.419251 seconds old, received at 2019-02-08 10:26:25.614728: osd_op(client.171725953.0:368920029 8.208 8:10448e0e:::rbd_data.c47f3c390c8495.0000000000018b81:head [set-alloc-hint object_size 4194304 write_size 4194304,write 2744320~200704] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 33 2019-02-08 10:30:59.859156 7fb72d415700 0 log_channel(cluster) log [DBG] : 17.5 deep-scrub starts 2019-02-08 10:31:57.067739 7fb746a6a700 1 leveldb: Level-0 table #1142634: started 2019-02-08 10:31:57.200073 7fb746a6a700 1 leveldb: Level-0 table #1142634: 1296751 bytes OK 2019-02-08 10:31:57.232903 7fb746a6a700 1 leveldb: Delete type=0 #1142631
2019-02-08 10:27:20.785155 7f48a0176700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 33.386816 secs 2019-02-08 10:27:20.785166 7f48a0176700 0 log_channel(cluster) log [WRN] : slow request 33.386816 seconds old, received at 2019-02-08 10:26:47.398289: osd_op(client.171725953.0:368920480 8.10c 8:30936f77:::rbd_data.c47f3c390c8495.0000000000018b12:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1429504~196608] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 43 2019-02-08 10:27:47.460038 7f48a0176700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 60.061712 secs 2019-02-08 10:27:47.460052 7f48a0176700 0 log_channel(cluster) log [WRN] : slow request 60.061712 seconds old, received at 2019-02-08 10:26:47.398289: osd_op(client.171725953.0:368920480 8.10c 8:30936f77:::rbd_data.c47f3c390c8495.0000000000018b12:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1429504~196608] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 43 2019-02-08 10:28:47.478844 7f48a0176700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 120.080509 secs 2019-02-08 10:28:47.478857 7f48a0176700 0 log_channel(cluster) log [WRN] : slow request 120.080509 seconds old, received at 2019-02-08 10:26:47.398289: osd_op(client.171725953.0:368920480 8.10c 8:30936f77:::rbd_data.c47f3c390c8495.0000000000018b12:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1429504~196608] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 43 2019-02-08 10:30:47.515630 7f48a0176700 0 log_channel(cluster) log [WRN] : 1 slow requests, 1 included below; oldest blocked for > 240.117304 secs 2019-02-08 10:30:47.515642 7f48a0176700 0 log_channel(cluster) log [WRN] : slow request 240.117304 seconds old, received at 2019-02-08 10:26:47.398289: osd_op(client.171725953.0:368920480 8.10c 8:30936f77:::rbd_data.c47f3c390c8495.0000000000018b12:head [set-alloc-hint object_size 4194304 write_size 4194304,write 1429504~196608] snapc 0=[] ondisk+write+known_if_redirected e1203982) currently sub_op_commit_rec from 43 2019-02-08 10:35:16.335740 7f487e7e2700 1 leveldb: Level-0 table #695400: started 2019-02-08 10:35:16.403264 7f487e7e2700 1 leveldb: Level-0 table #695400: 1286799 bytes OK 2019-02-08 10:35:16.419211 7f487e7e2700 1 leveldb: Delete type=0 #695387 2019-02-08 10:38:20.034506 7f4882feb700 0 log_channel(cluster) log [DBG] : 8.169 scrub starts 2019-02-08 10:38:43.871902 7f4882feb700 0 log_channel(cluster) log [DBG] : 8.169 scrub ok 2019-02-08 10:45:27.061046 7f487e7e2700 1 leveldb: Level-0 table #695402: started 2019-02-08 10:45:27.777479 7f487e7e2700 1 leveldb: Level-0 table #695402: 1295600 bytes OK 2019-02-08 10:45:27.794082 7f487e7e2700 1 leveldb: Delete type=0 #695399
ID CLASS WEIGHT REWEIGHT SIZE USE AVAIL %USE VAR PGS 30 hdd 5.45609 1.00000 5.46TiB 2.65TiB 2.81TiB 48.48 0.88 102 31 hdd 5.45609 1.00000 5.46TiB 2.71TiB 2.75TiB 49.59 0.90 105 32 hdd 5.45609 1.00000 5.46TiB 3.19TiB 2.26TiB 58.55 1.06 101 33 hdd 5.45609 1.00000 5.46TiB 2.60TiB 2.86TiB 47.63 0.86 105 34 hdd 5.45609 1.00000 5.46TiB 3.15TiB 2.31TiB 57.72 1.04 109 35 hdd 5.45609 1.00000 5.46TiB 2.62TiB 2.84TiB 47.98 0.87 101 36 hdd 5.45609 1.00000 5.46TiB 2.80TiB 2.65TiB 51.36 0.93 109 37 hdd 5.45609 1.00000 5.46TiB 3.25TiB 2.21TiB 59.56 1.08 111 38 hdd 5.45609 1.00000 5.46TiB 3.08TiB 2.38TiB 56.40 1.02 110 39 hdd 5.45609 1.00000 5.46TiB 3.49TiB 1.97TiB 63.94 1.15 109 40 hdd 5.45609 1.00000 5.46TiB 3.19TiB 2.26TiB 58.51 1.06 113 41 hdd 5.45609 1.00000 5.46TiB 3.17TiB 2.28TiB 58.18 1.05 109 42 hdd 5.45609 1.00000 5.46TiB 3.17TiB 2.28TiB 58.13 1.05 103 43 hdd 5.45609 1.00000 5.46TiB 2.53TiB 2.93TiB 46.33 0.84 97 44 hdd 5.45609 1.00000 5.46TiB 2.65TiB 2.80TiB 48.59 0.88 104 45 hdd 5.45609 1.00000 5.46TiB 2.63TiB 2.82TiB 48.29 0.87 105 46 hdd 5.45609 1.00000 5.46TiB 2.38TiB 3.08TiB 43.55 0.79 104 47 hdd 5.45609 1.00000 5.46TiB 3.41TiB 2.05TiB 62.49 1.13 104 48 hdd 5.45609 1.00000 5.46TiB 3.51TiB 1.94TiB 64.41 1.16 105 49 hdd 5.45609 1.00000 5.46TiB 2.87TiB 2.58TiB 52.69 0.95 105 10 hdd 5.45609 1.00000 5.46TiB 3.14TiB 2.32TiB 57.50 1.04 103 11 hdd 5.45609 1.00000 5.46TiB 2.76TiB 2.69TiB 50.67 0.92 99 12 hdd 5.45609 1.00000 5.46TiB 3.15TiB 2.31TiB 57.75 1.04 100 13 hdd 5.45609 1.00000 5.46TiB 2.96TiB 2.49TiB 54.32 0.98 106 14 hdd 5.45609 1.00000 5.46TiB 2.78TiB 2.68TiB 50.94 0.92 112 15 hdd 5.45609 1.00000 5.46TiB 3.39TiB 2.07TiB 62.09 1.12 111 16 hdd 5.45609 1.00000 5.46TiB 3.17TiB 2.29TiB 58.07 1.05 105 17 hdd 5.45609 1.00000 5.46TiB 3.55TiB 1.91TiB 65.06 1.17 109 18 hdd 5.45609 1.00000 5.46TiB 3.18TiB 2.28TiB 58.22 1.05 112 19 hdd 5.45609 1.00000 5.46TiB 3.35TiB 2.11TiB 61.39 1.11 103 20 hdd 5.45609 1.00000 5.46TiB 2.61TiB 2.84TiB 47.91 0.87 108 21 hdd 5.45609 1.00000 5.46TiB 2.78TiB 2.68TiB 50.95 0.92 103 22 hdd 5.45609 1.00000 5.46TiB 3.47TiB 1.99TiB 63.54 1.15 108 23 hdd 5.45609 1.00000 5.46TiB 3.10TiB 2.35TiB 56.85 1.03 103 24 hdd 5.45609 1.00000 5.46TiB 3.18TiB 2.28TiB 58.23 1.05 104 25 hdd 5.45609 1.00000 5.46TiB 3.81TiB 1.65TiB 69.76 1.26 111 26 hdd 5.45609 1.00000 5.46TiB 3.31TiB 2.15TiB 60.68 1.10 99 27 hdd 5.45609 1.00000 5.46TiB 2.54TiB 2.91TiB 46.63 0.84 100 28 hdd 5.45609 1.00000 5.46TiB 2.94TiB 2.52TiB 53.80 0.97 103 29 hdd 5.45609 1.00000 5.46TiB 2.32TiB 3.13TiB 42.56 0.77 109 0 hdd 5.45609 1.00000 5.46TiB 3.40TiB 2.06TiB 62.31 1.13 108 1 hdd 5.45609 1.00000 5.46TiB 2.14TiB 3.32TiB 39.18 0.71 98 2 hdd 5.45609 1.00000 5.46TiB 2.90TiB 2.56TiB 53.12 0.96 110 3 hdd 5.45609 1.00000 5.46TiB 3.34TiB 2.12TiB 61.16 1.10 107 4 hdd 5.45609 1.00000 5.46TiB 3.41TiB 2.05TiB 62.46 1.13 110 5 hdd 5.45609 1.00000 5.46TiB 3.84TiB 1.61TiB 70.42 1.27 113 6 hdd 5.45609 1.00000 5.46TiB 3.33TiB 2.12TiB 61.09 1.10 109 7 hdd 5.45609 1.00000 5.46TiB 2.57TiB 2.88TiB 47.19 0.85 102 8 hdd 5.45609 1.00000 5.46TiB 2.76TiB 2.70TiB 50.53 0.91 100 9 hdd 5.45609 1.00000 5.46TiB 2.81TiB 2.64TiB 51.57 0.93 104 TOTAL 273TiB 151TiB 122TiB 55.37 MIN/MAX VAR: 0.71/1.27 STDDEV: 6.98
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com