Actions
Bug #52503
opencli_generic.sh: slow ops when trying rand write on cache pools
% Done:
0%
Source:
Tags:
Backport:
quincy,pacific, octopus
Regression:
No
Severity:
3 - minor
Reviewed:
Affected Versions:
ceph-qa-suite:
Component(RADOS):
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
failing: leads to slow ops: http://qa-proxy.ceph.com/teuthology/yuriw-2021-09-01_19:04:25-rbd-wip-yuri-testing-2021-09-01-0844-pacific-distro-basic-smithi/6371432/teuthology.log
2021-09-02T01:46:35.007 INFO:tasks.workunit.client.0.smithi107.stderr:+ rbd bench --io-type write --io-pattern rand --io-total 32M --io-size 4K rbd/image2 2021-09-02T01:46:35.075 INFO:tasks.workunit.client.0.smithi107.stdout:bench type write io_size 4096 io_threads 16 bytes 33554432 pattern random 2021-09-02T01:46:35.505 INFO:tasks.workunit.client.0.smithi107.stdout: SEC OPS OPS/SEC BYTES/SEC 2021-09-02T01:46:35.506 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:35.504+0000 7ff778b0f700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6800/32737,v1:172.21.15.107:6801/32737] conn(0x7ff754008780 msgr2=0x7ff75400abd0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:35.579 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:35.578+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x5609d2ea8040 msgr2=0x5609d2f90d50 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1)._try_send injecting socket failure 2021-09-02T01:46:35.586 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:35.585+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x7ff754008780 msgr2=0x7ff75c073cc0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1)._try_send injecting socket failure 2021-09-02T01:46:36.512 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:36.510+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x7ff754008780 msgr2=0x7ff75c073ca0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:36.804 INFO:tasks.workunit.client.0.smithi107.stdout: 1 3216 1870.4 7.3 MiB/s 2021-09-02T01:46:36.990 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:36.988+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x7ff75c035a40 msgr2=0x7ff75c037e70 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:36.995 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:36.993+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x5609d2ea8040 msgr2=0x7ff75c0741d0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1)._try_send injecting socket failure 2021-09-02T01:46:37.225 INFO:tasks.workunit.client.0.smithi107.stdout: 2 3248 1518.87 5.9 MiB/s 2021-09-02T01:46:38.048 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:38.044+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x5609d2ea8040 msgr2=0x7ff75c037e30 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:38.160 INFO:tasks.workunit.client.0.smithi107.stdout: 3 4944 1608.33 6.3 MiB/s 2021-09-02T01:46:38.505 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:38.504+0000 7ff778b0f700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6800/32737,v1:172.21.15.107:6801/32737] conn(0x5609d2ea8040 msgr2=0x7ff75c037e30 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1)._try_send injecting socket failure 2021-09-02T01:46:39.257 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:39.256+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x7ff75c035a40 msgr2=0x7ff75c074190 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:39.403 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:39.395+0000 7ff779310700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6808/32738,v1:172.21.15.107:6810/32738] conn(0x5609d2ea8040 msgr2=0x7ff75c037e30 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1).read_until injecting socket failure 2021-09-02T01:46:39.624 INFO:tasks.workunit.client.0.smithi107.stderr:2021-09-02T01:46:39.622+0000 7ff778b0f700 0 -- 172.21.15.107:0/3363340619 >> [v2:172.21.15.107:6800/32737,v1:172.21.15.107:6801/32737] conn(0x7ff754008780 msgr2=0x7ff75c073ca0 crc :-1 s=STATE_CONNECTION_ESTABLISHED l=1)._try_send injecting socket failure 2021-09-02T01:46:40.103 INFO:tasks.workunit.client.0.smithi107.stdout: 5 6816 1358.81 5.3 MiB/s 2021-09-02T01:47:10.451 INFO:tasks.ceph.osd.1.smithi107.stderr:2021-09-02T01:47:10.450+0000 7fee233dc700 -1 osd.1 153 get_health_metrics reporting 16 slow ops, oldest is osd_op(client.10600.0:5250 3.2 3:6612ec91:::rbd_data.2965a7ef300.0000000000000051:head [write 2244608~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=6 ondisk+retry+write+known_if_redirected e152)
2021-08-30T09:20:23.438 INFO:tasks.workunit.client.0.smithi164.stdout:bench type write io_size 4096 io_threads 16 bytes 33554432 pattern random 2021-08-30T09:20:24.631 INFO:tasks.workunit.client.0.smithi164.stdout: SEC OPS OPS/SEC BYTES/SEC 2021-08-30T09:20:24.631 INFO:tasks.workunit.client.0.smithi164.stdout: 1 3632 3063.03 12 MiB/s 2021-08-30T09:20:24.804 INFO:tasks.workunit.client.0.smithi164.stderr:2021-08-30T09:20:24.802+0000 7f880d2bc700 0 -- 172.21.15.164:0/1034694029 >> [v2:172.21.15.164:6805/31302,v1:172.21.15.164:6808/31302] conn(0x55be70eb70e0 msgr2=0x7f87f00d1c90 crc :-1
msgr-failures/few objectstore/bluestore-stupid pool/small-cache-pool supported-random-distro$/{rhel_8}
workloads/rbd_cli_generic}
object grep: /home/ideepika/rbd_cli.log teuthology server
Updated by Ilya Dryomov over 2 years ago
On osd0 and osd1:
2021-09-02T01:47:10.657+0000 7fe68cea5700 20 slow request osd_op(client.10600.0:6900 3.3 3:cd69d880:::rbd_data.2965a7ef300.00000000000000a7:head [write 1867776~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.982700+0000 currently reached pg 2021-09-02T01:47:10.658+0000 7fe68cea5700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:6900 3.3 3:cd69d880:::rbd_data.2965a7ef300.00000000000000a7:head [write 1867776~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.982700+0000 currently reached pg 2021-09-02T01:47:10.658+0000 7fe68cea5700 20 slow request osd_op(client.10600.0:6944 3.3 3:cba9a6dd:::rbd_data.2965a7ef300.000000000000002e:head [write 241664~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:40.009694+0000 currently reached pg 2021-09-02T01:47:10.658+0000 7fe68cea5700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:6944 3.3 3:cba9a6dd:::rbd_data.2965a7ef300.000000000000002e:head [write 241664~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:40.009694+0000 currently reached pg 2021-09-02T01:47:10.658+0000 7fe68cea5700 20 slow request osd_op(client.10600.0:7023 3.3 3:cd722bda:::rbd_data.2965a7ef300.000000000000009b:head [write 3067904~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:40.083513+0000 currently reached pg 2021-09-02T01:47:10.658+0000 7fe68cea5700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:7023 3.3 3:cd722bda:::rbd_data.2965a7ef300.000000000000009b:head [write 3067904~4096 [fadvise_random] in=4096b] snapc 0=[] ondisk+write+known_if_redirected e152) initiated 2021-09-02T01:46:40.083513+0000 currently reached pg
2021-09-02T01:47:10.450+0000 7fee233dc700 20 slow request osd_op(client.10600.0:5250 3.2 3:6612ec91:::rbd_data.2965a7ef300.0000000000000051:head [write 2244608~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=6 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.499062+0000 currently reached pg 2021-09-02T01:47:10.450+0000 7fee233dc700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:5250 3.2 3:6612ec91:::rbd_data.2965a7ef300.0000000000000051:head [write 2244608~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=6 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.499062+0000 currently reached pg 2021-09-02T01:47:10.450+0000 7fee233dc700 20 slow request osd_op(client.10600.0:5595 3.2 3:76e5ac0f:::rbd_data.2965a7ef300.00000000000000bf:head [write 716800~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=4 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.644644+0000 currently reached pg 2021-09-02T01:47:10.450+0000 7fee233dc700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:5595 3.2 3:76e5ac0f:::rbd_data.2965a7ef300.00000000000000bf:head [write 716800~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=4 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.644644+0000 currently reached pg 2021-09-02T01:47:10.450+0000 7fee233dc700 20 slow request osd_op(client.10600.0:5631 3.2 3:7f41f6b9:::rbd_data.2965a7ef300.0000000000000085:head [write 2641920~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=4 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.693385+0000 currently reached pg 2021-09-02T01:47:10.450+0000 7fee233dc700 0 log_channel(cluster) log [WRN] : slow request osd_op(client.10600.0:5631 3.2 3:7f41f6b9:::rbd_data.2965a7ef300.0000000000000085:head [write 2641920~4096 [fadvise_random] in=4096b] snapc 0=[] RETRY=4 ondisk+retry+write+known_if_redirected e152) initiated 2021-09-02T01:46:39.693385+0000 currently reached pg
But not on osd2. The first slow request messages there are
2021-09-02T01:47:12.115+0000 7fe387740700 20 slow request osd_op(osd.1.8:17044 2.0 2:04ecb063:::rbd_data.2965a7ef300.0000000000000039:head [copy-from ver 6042 in=75b] snapc 0=[] ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e152) initiated 2021-09-02T01:46:41.792865+0000 currently started 2021-09-02T01:47:12.115+0000 7fe387740700 0 log_channel(cluster) log [WRN] : slow request osd_op(osd.1.8:17044 2.0 2:04ecb063:::rbd_data.2965a7ef300.0000000000000039:head [copy-from ver 6042 in=75b] snapc 0=[] ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e152) initiated 2021-09-02T01:46:41.792865+0000 currently started 2021-09-02T01:47:12.115+0000 7fe387740700 20 slow request osd_op(osd.1.8:17046 2.0 2:0cb47c91:::rbd_data.2965a7ef300.00000000000000b6:head [copy-from ver 6030 in=75b] snapc 0=[] ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e152) initiated 2021-09-02T01:46:41.800931+0000 currently started 2021-09-02T01:47:12.115+0000 7fe387740700 0 log_channel(cluster) log [WRN] : slow request osd_op(osd.1.8:17046 2.0 2:0cb47c91:::rbd_data.2965a7ef300.00000000000000b6:head [copy-from ver 6030 in=75b] snapc 0=[] ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e152) initiated 2021-09-02T01:46:41.800931+0000 currently started 2021-09-02T01:47:12.115+0000 7fe387740700 -1 osd.2 153 get_health_metrics reporting 2 slow ops, oldest is osd_op(osd.1.8:17044 2.0 2:04ecb063:::rbd_data.2965a7ef300.0000000000000039:head [copy-from ver 6042 in=75b] snapc 0=[] ondisk+write+ignore_overlay+enforce_snapc+known_if_redirected e152)
This job configures cache tiering, maybe there is a lingering bug there? Or perhaps the socket error injection got loose?
Anyway I don't see anything rbd related here. Deepika, did you have a specific fix/work item in mind when you transfered from RADOS to rbd and marked for backporting?
Updated by Deepika Upadhyay over 2 years ago
- Project changed from rbd to RADOS
Hey Ilya, nope, since the issue was seen in pacific I thought it might be something we backported to recent versions.
moved to RBD since the failure was seen in RBD suite, moved back to RADOS, thanks for looking!
Updated by Neha Ojha over 2 years ago
Most likely caused by failure injections, might be worth looking at what was going in the osd logs when we started seeing the first instance of slow request.
Updated by Deepika Upadhyay over 2 years ago
- Priority changed from Normal to High
/ceph/teuthology-archive/ideepika-2021-11-02_12:33:30-rbd-wip-ssd-cache-testing-distro-basic-smithi/6477582/teuthology.log
Updated by Neha Ojha over 2 years ago
Deepika Upadhyay wrote:
/ceph/teuthology-archive/ideepika-2021-11-02_12:33:30-rbd-wip-ssd-cache-testing-distro-basic-smithi/6477582/teuthology.log
this also has failure injection - we can ignore the slow ops warnings for these test, if we can verify they are solely caused due to failure injection
Updated by Ilya Dryomov about 2 years ago
- Assignee set to Neha Ojha
This has been bugging the rbd suite for a while. I don't think messenger failure injection is the problem because the same rbd/cli_generic.sh workunit always passes when small-cache-pool.yaml facet isn't involved. With small-cache-pool.yaml, it pretty reliably times out. The time difference is substantial: 20-30 minutes for a passing job and a 3-hour timeout for a failing job.
I'd appreciate some RADOS guidance here. Do we care about/support writeback cache pools? If so, is a "few" (not "many") messenger failure injection really expected to break them?
Updated by Neha Ojha about 2 years ago
- Subject changed from cli_generic.sh: slow ops when trying rand write to cli_generic.sh: slow ops when trying rand write on cache pools
- Backport changed from pacific, octopus to quincy,pacific, octopus
Ilya Dryomov wrote:
This has been bugging the rbd suite for a while. I don't think messenger failure injection is the problem because the same rbd/cli_generic.sh workunit always passes when small-cache-pool.yaml facet isn't involved. With small-cache-pool.yaml, it pretty reliably times out. The time difference is substantial: 20-30 minutes for a passing job and a 3-hour timeout for a failing job.
I'd appreciate some RADOS guidance here. Do we care about/support writeback cache pools? If so, is a "few" (not "many") messenger failure injection really expected to break them?
Cache tiering is not actively maintained, there is no deprecation yet, but we have https://docs.ceph.com/en/latest/rados/operations/cache-tiering/#a-word-of-caution in our docs.
Coming to the issue, based on https://sentry.ceph.com/organizations/ceph/issues/13324/events/a1d16f6ccb394188a22d28d560be5bda/events/?cursor=0%3A200%3A0&project=2, looks like we started seeing it in master in the end of Oct 2021 and then in Pacific and Octopus. Is that correct? Can you share a recent passed run for this test? logs for the passed run: http://qa-proxy.ceph.com/teuthology/teuthology-2021-08-30_06:07:02-rbd-pacific-distro-basic-smithi/6366493/teuthology.log are no longer available.
Updated by Ilya Dryomov about 2 years ago
Here is a representative run (wip-dis-testing is essentially master):
https://pulpito.ceph.com/dis-2022-01-25_16:18:06-rbd-wip-dis-testing-distro-default-smithi/
I pinned the objectstore facet, the two things that vary are rbd image features and the "type" of pool. All non-cache-pool jobs passed. All cache-pool jobs regardless of rbd image feature set are full of slow op reports and most likely going to time out (the run is still in progress):
rbd/cli/{base/install clusters/{fixed-1 openstack} features/layering msgr-failures/few objectstore/bluestore-comp-snappy pool/ec-data-pool supported-random-distro$/{ubuntu_latest} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/layering msgr-failures/few objectstore/bluestore-comp-snappy pool/none supported-random-distro$/{rhel_8} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/layering msgr-failures/few objectstore/bluestore-comp-snappy pool/replicated-data-pool supported-random-distro$/{centos_8} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/layering msgr-failures/few objectstore/bluestore-comp-snappy pool/small-cache-pool supported-random-distro$/{ubuntu_latest} workloads/rbd_cli_generic} <------
rbd/cli/{base/install clusters/{fixed-1 openstack} features/journaling msgr-failures/few objectstore/bluestore-comp-snappy pool/ec-data-pool supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/journaling msgr-failures/few objectstore/bluestore-comp-snappy pool/none supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/journaling msgr-failures/few objectstore/bluestore-comp-snappy pool/replicated-data-pool supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/journaling msgr-failures/few objectstore/bluestore-comp-snappy pool/small-cache-pool supported-random-distro$/{centos_8} workloads/rbd_cli_generic} <------
rbd/cli/{base/install clusters/{fixed-1 openstack} features/defaults msgr-failures/few objectstore/bluestore-comp-snappy pool/ec-data-pool supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/defaults msgr-failures/few objectstore/bluestore-comp-snappy pool/none supported-random-distro$/{centos_8} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/defaults msgr-failures/few objectstore/bluestore-comp-snappy pool/replicated-data-pool supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli/{base/install clusters/{fixed-1 openstack} features/defaults msgr-failures/few objectstore/bluestore-comp-snappy pool/small-cache-pool supported-random-distro$/{centos_8} workloads/rbd_cli_generic} <------
rbd/cli_v1/{base/install clusters/{fixed-1 openstack} features/format-1 msgr-failures/few objectstore/bluestore-comp-snappy pool/none supported-random-distro$/{centos_8.stream} workloads/rbd_cli_generic}
rbd/cli_v1/{base/install clusters/{fixed-1 openstack} features/format-1 msgr-failures/few objectstore/bluestore-comp-snappy pool/small-cache-pool supported-random-distro$/{ubuntu_latest} workloads/rbd_cli_generic} <------
Actions