Bug #43888
closedosd/osd-bench.sh 'tell osd.N bench' hang
Added by Sage Weil over 4 years ago. Updated over 3 years ago.
0%
Description
2020-01-29T04:20:23.704 INFO:tasks.workunit.client.0.smithi138.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/osd/osd-bench.sh:79: TEST_bench: ceph tell osd.0 bench 2020-01-29T07:20:16.231 INFO:tasks.workunit.client.0.smithi138.stderr:Terminated
/a/sage-2020-01-28_23:42:06-rados-wip-sage-testing-2020-01-28-1413-distro-basic-smithi/4715542
looks like #21480 but that was fixed and we have no bluestore logs.
Updated by Sage Weil over 4 years ago
Updated by Neha Ojha about 4 years ago
- Priority changed from High to Urgent
/a/nojha-2020-03-16_17:35:35-rados:standalone-master-distro-basic-smithi/4860664/
Updated by Neha Ojha about 4 years ago
- Backport set to octopus
Still fails occasionally
/a/nojha-2020-04-10_22:42:57-rados:standalone-master-distro-basic-smithi/4943804/
Updated by Brad Hubbard almost 4 years ago
/a/yuriw-2020-05-22_19:55:53-rados-wip-yuri-master_5.22.20-distro-basic-smithi/5083462
Updated by Brad Hubbard almost 4 years ago
/a/yuriw-2020-05-23_15:15:01-rados-wip-yuri-master_5.22.20-distro-basic-smithi/5085549
Updated by David Zafman almost 4 years ago
Saw this in at least 17 jobs:
http://pulpito.ceph.com/dzafman-2020-06-08_11:45:40-rados-wip-zafman-testing-distro-basic-smithi/
Updated by Neha Ojha almost 4 years ago
- Status changed from New to In Progress
/a/dzafman-2020-06-08_11:45:40-rados-wip-zafman-testing-distro-basic-smithi/5130086
This is the command we care about because it appears to hang in teuthology.log.
2020-06-08T20:20:19.160 INFO:tasks.workunit.client.0.smithi165.stderr:/home/ubuntu/cephtest/clone.client.0/qa/standalone/osd/osd-bench.sh:80: TEST_bench: ceph tell osd.0 bench
This is what I see in osd.0's log. Highlighting the log lines when we see the command come in and a reply is sent for it.
020-06-08T20:20:18.952+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4119 127.0.0.1:0/3824347730 2 ==== command(tid 2: {"prefix": "bench", "count": 1024, "size": 67108865}) v1 ==== 76+0+0 (crc 0 0 0) 0x55b3370bfb80 con 0x55b33a382800
2020-06-08T20:20:18.952+0000 7f667428b700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] --> 127.0.0.1:0/3824347730 -- command_reply(tid 2: -22 block 'size' values are capped at 64 MiB. If you wish to use a higher value, please adjust 'osd_bench_max_block_size') v1 -- 0x55b3370bfe40 con 0x55b33a382800
2020-06-08T20:20:19.053+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4121 127.0.0.1:0/686417273 2 ==== command(tid 2: {"prefix": "bench", "count": 3072001, "size": 1024}) v1 ==== 75+0+0 (crc 0 0 0) 0x55b3370bfb80 con 0x55b33a382c00
2020-06-08T20:20:19.053+0000 7f667428b700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] --> 127.0.0.1:0/686417273 -- command_reply(tid 2: -22 'count' values greater than 3072000 for a block size of 1 KiB, assuming 100 IOPS, for 30 seconds, can cause ill effects on osd. Please adjust 'osd_bench_small_size_max_iops' with a higher value if you wish to use a higher 'count'.) v1 -- 0x55b3370bfe40 con 0x55b33a382c00
2020-06-08T20:20:19.153+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4123 127.0.0.1:0/2447131935 2 ==== command(tid 2: {"prefix": "bench", "count": 3145728001, "size": 1048577}) v1 ==== 81+0+0 (crc 0 0 0) 0x55b3370bfb80 con 0x55b33a383000
2020-06-08T20:20:19.154+0000 7f667428b700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] --> 127.0.0.1:0/2447131935 -- command_reply(tid 2: -22 'count' values greater than 3145728000 for a block size of 1.0 MiB, assuming 100 MiB/s, for 30 seconds, can cause ill effects on osd. Please adjust 'osd_bench_large_size_max_throughput' with a higher value if you wish to use a higher 'count'.) v1 -- 0x55b3370bfe40 con 0x55b33a383000
2020-06-08T20:20:19.285+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4125 127.0.0.1:0/306671637 2 ==== command(tid 2: {"prefix": "bench"}) v1 ==== 43+0+0 (crc 0 0 0) 0x55b3370bfb80 con 0x55b33a382c00
2020-06-08T20:20:44.416+0000 7f667428b700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] --> 127.0.0.1:0/306671637 -- command_reply(tid 2: 0 ) v1 -- 0x55b34d676420 con 0x55b33a382c00
2020-06-08T20:20:44.447+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4125 127.0.0.1:0/306671637 8 ==== command(tid 3: {"prefix": "bench"}) v1 ==== 43+0+0 (crc 0 0 0) 0x55b34d676420 con 0x55b33a382c00
2020-06-08T20:50:19.277+0000 7f6663be5700 1 -- [v2:127.0.0.1:6802/635276,v1:127.0.0.1:6803/635276] <== client.4125 127.0.0.1:0/306671637 1 ==== command(tid 3: {"prefix": "bench"}) v1 ==== 43+0+0 (crc 0 0 0) 0x55b34d6766e0 con 0x55b33a382000
From the above, it looks like a reply was sent for the command we care about "2020-06-08T20:20:19.285+0000" and osd bench seems to be doing its job fine, but for some reason we see a couple more retries of the same later on. Need to figure out why the reply wasn't received and why the retries were sent.
Updated by Neha Ojha almost 4 years ago
Couple of updates on this:
1. Reproduced the issue with some extra debug logging.
https://pulpito.ceph.com/nojha-2020-07-09_01:30:23-rados:standalone-wip-43888-distro-basic-smithi/
Here, the osd bench command hangs at the first time itself, not on a retry from the client.
/a/nojha-2020-07-09_01:30:23-rados:standalone-wip-43888-distro-basic-smithi/5209821
2020-07-09T03:23:51.227+0000 7fba848c5700 1 -- [v2:127.0.0.1:6802/602022,v1:127.0.0.1:6803/602022] <== client.4125 127.0.0.1:0/3446735419 2 ==== command(tid 2: {"prefix": "bench"}) v1 ==== 43+0+0 (crc 0 0 0) 0x56524b0ad760 con 0x56524c350c00
2020-07-09T03:23:51.227+0000 7fba956fe700 1 osd.0 5 bench count 1073741824 bsize 4 MiB
2020-07-09T03:23:51.228+0000 7fba956fe700 1 osd.0 5 asok_command starting waiter.wait() // This is the first waiter.wait() https://github.com/ceph/ceph/blob/master/src/osd/OSD.cc#L2840 and the last thing we see this thread do
The problem I see here is that (!service.meta_ch->flush_commit(&waiter)) returns true for some reason, which is probably making waiter.wait() hang.
2. Did another test with https://github.com/ceph/ceph-ci/commit/2faf64d223f04bb07457a8db732eb7c6004e6c63#diff-fa6c2eba8356ae1442d1bf749beacfdfL2838, to make sure we do not flush_commit unless the benchmark does some work.
https://pulpito.ceph.com/nojha-2020-07-09_23:36:25-rados:standalone-wip-43888-2-distro-basic-smithi/
/a/nojha-2020-07-09_23:36:25-rados:standalone-wip-43888-2-distro-basic-smithi/5211928
The benchmark starts off fine
2020-07-10T01:32:52.763+0000 7f6e5007e700 1 -- [v2:127.0.0.1:6802/607416,v1:127.0.0.1:6803/607416] <== client.4125 127.0.0.1:0/1233782752 2 ==== command(tid 2: {"prefix": "bench"}) v1 ==== 43+0+0 (crc 0 0 0) 0x558b124cd600 con 0x558b134bec00
2020-07-10T01:32:52.763+0000 7f6e5007e700 20 osd.0 5 OSD::ms_dispatch: command(tid 2: {"prefix": "bench"}) v1
2020-07-10T01:32:52.763+0000 7f6e5007e700 10 osd.0 5 do_waiters -- start
2020-07-10T01:32:52.763+0000 7f6e5007e700 10 osd.0 5 do_waiters -- finish
2020-07-10T01:32:52.763+0000 7f6e5007e700 20 osd.0 5 _dispatch 0x558b124cd600 command(tid 2: {"prefix": "bench"}) v1
2020-07-10T01:32:52.763+0000 7f6e5007e700 10 -- [v2:127.0.0.1:6802/607416,v1:127.0.0.1:6803/607416] dispatch_throttle_release 43 to dispatch throttler 43/104857600
2020-07-10T01:32:52.763+0000 7f6e60f41700 1 osd.0 5 bench count 1073741824 bsize 4 MiB
2020-07-10T01:32:52.764+0000 7f6e60f41700 1 osd.0 5 asok_command 2 start queue_transaction
2020-07-10T01:32:52.764+0000 7f6e60f41700 10 bluestore(td/osd-bench/0) queue_transactions ch 0x558b133b8780 meta
2020-07-10T01:32:52.764+0000 7f6e60f41700 20 bluestore(td/osd-bench/0) _txc_create osr 0x558b1250b040 = 0x558b13434f00 seq 8
2020-07-10T01:32:52.764+0000 7f6e60f41700 20 bluestore(td/osd-bench/0).collection(meta 0x558b133b8780) get_onode oid #-1:892e9aca:::disk_bw_test_0:0# key 0x7F7FFFFFFFFFFFFFFF892E9ACA'!disk_bw_test_0!='0x0000000000000000FFFFFFFFFFFFFFFF6F
2020-07-10T01:32:52.765+0000 7f6e60f41700 20 bluestore(td/osd-bench/0).collection(meta 0x558b133b8780) r -2 v.len 0
2020-07-10T01:32:52.765+0000 7f6e60f41700 15 bluestore(td/osd-bench/0) _write meta #-1:892e9aca:::disk_bw_test_0:0# 0x0~400000
and we finally hang here
2020-07-10T01:33:19.855+0000 7f6e60f41700 20 freelist _xor first_key 0x3fc00000 last_key 0x40000000 2020-07-10T01:33:19.855+0000 7f6e60f41700 10 bluestore(td/osd-bench/0) _txc_state_proc txc 0x558b2aa58f00 prepare 2020-07-10T01:33:19.855+0000 7f6e60f41700 20 bluestore(td/osd-bench/0) _txc_finish_io 0x558b2aa58f00 2020-07-10T01:33:19.855+0000 7f6e60f41700 10 bluestore(td/osd-bench/0) _txc_state_proc txc 0x558b2aa58f00 io_done 2020-07-10T01:33:19.856+0000 7f6e60f41700 1 osd.0 5 asok_command 2 starting waiter.wait() // This is the second waiter.wait() https://github.com/ceph/ceph/blob/master/src/osd/OSD.cc#L2866
Adam will take a look to check for any abnormal bluestore behavior in all of this.
Updated by Neha Ojha almost 4 years ago
/a/yuriw-2020-07-13_19:30:53-rados-wip-yuri6-testing-2020-07-13-1520-octopus-distro-basic-smithi/5223525
Updated by Neha Ojha almost 4 years ago
- Status changed from In Progress to Fix Under Review
- Pull request ID set to 36251
More details in https://gist.github.com/aclamk/fac791df3510840c640e18a0e6a4c724
Updated by Neha Ojha almost 4 years ago
- Status changed from Fix Under Review to Pending Backport
Updated by Nathan Cutler almost 4 years ago
- Copied to Backport #46722: octopus: osd/osd-bench.sh 'tell osd.N bench' hang added
Updated by Nathan Cutler over 3 years ago
- Status changed from Pending Backport to Resolved
While running with --resolve-parent, the script "backport-create-issue" noticed that all backports of this issue are in status "Resolved" or "Rejected".