Ceph » RADOS

When we enqueue an op in mClock, we check osd_op_queue_cutoff here https://github.com/ceph/ceph/blob/main/src/osd/scheduler/mClockScheduler.cc#L447.
By default this value is set to CEPH_MSG_PRIO_HIGH which is 196.
In some tests, we set osd_op_queue_cutoff to debug_random (https://github.com/ceph/ceph/blob/main/src/osd/scheduler/mClockScheduler.h#L161) which means that we might get the priority cutoff as CEPH_MSG_PRIO_LOW (64) https://github.com/ceph/ceph/blob/main/src/include/msgr.h#L223

These tests had debug_random for osd_op_queue_cutoff enabled and I saw that client ops with the same priority were being enqueued differently. The below op gets enqueued to the mClock scheduler as expected. (sched count increases to 3)

2023-03-22T21:36:45.242+0000 7f113d104700 15 osd.1 89 enqueue_op osd_op(client.24974.0:4821 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8 prio 127 type 42 cost 81920 latency 0.000087 epoch 89 osd_op(client.24974.0:4821 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8
2023-03-22T21:36:45.242+0000 7f113d104700 20 osd.1 op_wq(6) _enqueue OpSchedulerItem(3.16 PGOpItem(op=osd_op(client.24974.0:4821 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8) class_id 3 cost 81920 e89)
2023-03-22T21:36:45.242+0000 7f113d104700 20 mClockScheduler: enqueue { class_id: 3 client_id: 24974 profile_id: 0 } item_cost: 81920 scaled_cost: 1
2023-03-22T21:36:45.242+0000 7f113d104700 20 mClockScheduler: enqueue client_count: 2 queue_sizes: [  high_priority_queue: 0 sched: 3 ]

However the next op with the same priority is being enqueued to the high_priority_queue:

2023-03-22T21:36:45.242+0000 7f113d104700 15 osd.1 89 enqueue_op osd_op(client.24974.0:4822 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8 prio 127 type 42 cost 102400 latency 0.000150 epoch 89 osd_op(client.24974.0:4822 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8
2023-03-22T21:36:45.242+0000 7f113d104700 20 osd.1 op_wq(6) _enqueue OpSchedulerItem(3.16 PGOpItem(op=osd_op(client.24974.0:4822 3.16 3.2877e8d6 (undecoded) ondisk+write+known_if_redirected e89) v8) class_id 3 cost 102400 e89)
2023-03-22T21:36:45.242+0000 7f113d104700 20 mClockScheduler: enqueue client_count: 2 queue_sizes: [  high_priority_queue: 1 sched: 3 ]

This is causing the out of order op issue since the op in high_priority_queue will be dequeued first even though it was enqueued later.
I think this is because the osd_op_queue_cutoff changed to CEPH_MSG_PRIO_LOW from CEPH_MSG_PRIO_HIGH as it is set to debug_random.
I have a fix for this that I am working on testing. We shouldn’t be checking osd_op_queue_cutoff for each enqueue operation, we should only be checking it once. I will update the tracker with the test results.

I am not sure why this has shown up only in these tests (still working on this) but all the failed tests have osd_op_queue_cutoff set to debug_random.

Logs from: /a/amathuri-2023-03-22_17:03:44-fs-main-distro-default-smithi/7216331