Radosgw huge traffic to index bucket compared to incoming requests
Hi, we're using Ceph as S3-compatible storage to serve static files (mostly css/js/images + some videos) and I've noticed that there seem to be huge read amplification for index pool. Incoming traffic magniture is of around 15k req/sec (mostly sub 1MB request but index pool is getting hammered: pool pl-war1.rgw.buckets.index id 10 client io 632 MiB/s rd, 277 KiB/s wr, 129.92k op/s rd, 415 op/s wr pool pl-war1.rgw.buckets.data id 11 client io 4.5 MiB/s rd, 6.8 MiB/s wr, 640 op/s rd, 1.65k op/s wr and is getting order of magnitude more requests running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs. We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference. when enabling debug on affected OSD I only get spam of 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# = 0 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# = 0 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# = 0 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# -- Mariusz Gronczewski (XANi) <xani666@gmail.com> GnuPG: 0xEA8ACE64 http://devrandom.pl
Dear Mariusz,
we're using Ceph as S3-compatible storage to serve static files (mostly css/js/images + some videos) and I've noticed that there seem to be huge read amplification for index pool.
we have observed that too, under Nautilus (14.2.4-14.2.8).
Incoming traffic magniture is of around 15k req/sec (mostly sub 1MB request but index pool is getting hammered:
pool pl-war1.rgw.buckets.index id 10 client io 632 MiB/s rd, 277 KiB/s wr, 129.92k op/s rd, 415 op/s wr
pool pl-war1.rgw.buckets.data id 11 client io 4.5 MiB/s rd, 6.8 MiB/s wr, 640 op/s rd, 1.65k op/s wr
and is getting order of magnitude more requests
Our hypothesis is that this is due to the way that RadosGW maps bucket index queries (ListObjects/ListObjectsV2) to Rados-level operations against a *sharded* index. For certain types of S3 index queries, the response must be collected from multiple (potentially all) shards of the index. S3 index queries are always "bounded" by the response limitation (1000 keys by default). But when your index is distributed over, let's say, 2000 shards, RadosGW must collect some data from those 2000 shards, then throw away most of what it gets, and return the next 1000 keys. This could explain the kind of read amplification that you are seeing. (In practice, S3 index queries often use "prefix" and "delimiter" to emulate a hierarchical directory structure. A recently merged change, https://github.com/ceph/ceph/pull/30272 , should make such queries much more efficient in RadosGW (note that the change contains some extensions to the OSD-side Rados protocol). But if I read it correctly, that change is already in the version you are using.) Paul Emmerich has written about performance issues with large buckets on this list, see https://lists.ceph.io/hyperkitty/list/dev@ceph.io/thread/36P62BOOCJBVVJCVUX5... Let's say that there are opportunities for further improvements. You could look for the specific queries that cause the high read load in your system. Maybe there's something that can be done on the client side. This could also provide input for Ceph development as to what kinds of index operations are used by applications "in the wild". Those might be worth optimizing first :-)
running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs.
We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference.
Was your bucket index sharded in 12.x?
when enabling debug on affected OSD I only get spam of
2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# = 0 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# = 0 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# = 0 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head#
Hm, I don't understand enough about the operations that this represents, but maybe one of the RadosGW developers can explain why a single OSD would perform so many similar requests in such a short timeframe. Cheers, -- Simon.
Dnia 2020-06-18, o godz. 10:51:31 Simon Leinen <simon.leinen@switch.ch> napisał(a):
Dear Mariusz,
we're using Ceph as S3-compatible storage to serve static files (mostly css/js/images + some videos) and I've noticed that there seem to be huge read amplification for index pool.
we have observed that too, under Nautilus (14.2.4-14.2.8).
Incoming traffic magniture is of around 15k req/sec (mostly sub 1MB request but index pool is getting hammered:
pool pl-war1.rgw.buckets.index id 10 client io 632 MiB/s rd, 277 KiB/s wr, 129.92k op/s rd, 415 op/s wr
pool pl-war1.rgw.buckets.data id 11 client io 4.5 MiB/s rd, 6.8 MiB/s wr, 640 op/s rd, 1.65k op/s wr
and is getting order of magnitude more requests
Our hypothesis is that this is due to the way that RadosGW maps bucket index queries (ListObjects/ListObjectsV2) to Rados-level operations against a *sharded* index.
For certain types of S3 index queries, the response must be collected from multiple (potentially all) shards of the index.
S3 index queries are always "bounded" by the response limitation (1000 keys by default). But when your index is distributed over, let's say, 2000 shards, RadosGW must collect some data from those 2000 shards, then throw away most of what it gets, and return the next 1000 keys. This could explain the kind of read amplification that you are seeing.
(In practice, S3 index queries often use "prefix" and "delimiter" to emulate a hierarchical directory structure. A recently merged change, https://github.com/ceph/ceph/pull/30272 , should make such queries much more efficient in RadosGW (note that the change contains some extensions to the OSD-side Rados protocol). But if I read it correctly, that change is already in the version you are using.)
listing itself is bugged in version I'm running: https://tracker.ceph.com/issues/45955 But yes, our structure is generally /bucket/prefix/prefix/file so there is not many big directories (we're migrating from GFS where that was a problem)
Paul Emmerich has written about performance issues with large buckets on this list, see https://lists.ceph.io/hyperkitty/list/dev@ceph.io/thread/36P62BOOCJBVVJCVUX5...
Let's say that there are opportunities for further improvements.
You could look for the specific queries that cause the high read load in your system. Maybe there's something that can be done on the client side. This could also provide input for Ceph development as to what kinds of index operations are used by applications "in the wild". Those might be worth optimizing first :-)
Is there a way to debug which query exactly is causing that ? Currently there is a lot of incoming traffic (mostly from aws cli sync) as we're migrating data over but that's at most hundreds of requests per sec.
running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs.
We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference.
Was your bucket index sharded in 12.x?
we didn't touch default settings so I assume not ? "radosgw-admin metadata get" and "radosgw-admin bucket stat" doesn't say anything about shards on old cluster, while on new cluster there is from 11 to few hundred on the biggest buckets.
when enabling debug on affected OSD I only get spam of
2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# = 0 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# = 0 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# = 0 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head#
Hm, I don't understand enough about the operations that this represents, but maybe one of the RadosGW developers can explain why a single OSD would perform so many similar requests in such a short timeframe.
I'm getting similar logs on any osd/pg that takes part in the .index Cheers -- Mariusz Gronczewski (XANi) <xani666@gmail.com> GnuPG: 0xEA8ACE64 http://devrandom.pl
Mariusz Gronczewski writes:
listing itself is bugged in version I'm running: https://tracker.ceph.com/issues/45955
Ouch! Are your OSDs all running the same version as your RadosGW? The message looks a bit as if your RadosGW might be a newer version than the OSDs, and the new optimized bucket list operation was missing the new extensions to the client<->OSD protocol.
But yes, our structure is generally /bucket/prefix/prefix/file so there is not many big directories (we're migrating from GFS where that was a problem)
Paul Emmerich has written about performance issues with large buckets on this list, see https://lists.ceph.io/hyperkitty/list/dev@ceph.io/thread/36P62BOOCJBVVJCVUX5...
Let's say that there are opportunities for further improvements.
You could look for the specific queries that cause the high read load in your system. Maybe there's something that can be done on the client side. This could also provide input for Ceph development as to what kinds of index operations are used by applications "in the wild". Those might be worth optimizing first :-)
Is there a way to debug which query exactly is causing that ?
What I usually do is grep through the HTTP request logs of the front-end proxy/load balancer (Nginx in our case), and look for GET requests on a bucket that have a long duration. It's a bit crude, I know. (If someone knows better techniques for this, I'd also be interested! Maybe something based on something like Jaeger/OpenTracing, or clever log correlation?)
Currently there is a lot of incoming traffic (mostly from aws cli sync) as we're migrating data over but that's at most hundreds of requests per sec.
running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs.
We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference.
Was your bucket index sharded in 12.x?
we didn't touch default settings so I assume not ? "radosgw-admin metadata get" and "radosgw-admin bucket stat" doesn't say anything about shards on old cluster, while on new cluster there is from 11 to few hundred on the biggest buckets.
Yes, I think it's the sharding that causes the read amplification.
Hm, I don't understand enough about the operations that this represents, but maybe one of the RadosGW developers can explain why a single OSD would perform so many similar requests in such a short timeframe.
I'm getting similar logs on any osd/pg that takes part in the .index
Right, that's what I thought. Again, I can't tell whether these log messages are to be expected... the repetitions look a bit odd. Best regards, -- Simon.
Dnia 2020-06-18, o godz. 22:18:08 Simon Leinen <simon.leinen@switch.ch> napisał(a):
Mariusz Gronczewski writes:
listing itself is bugged in version I'm running: https://tracker.ceph.com/issues/45955
Ouch! Are your OSDs all running the same version as your RadosGW? The message looks a bit as if your RadosGW might be a newer version than the OSDs, and the new optimized bucket list operation was missing the new extensions to the client<->OSD protocol.
Versions are same on every node. Is there a command that is required to enable new extensions? It was clean install of octopus from upstream ceph repos (not upgrade) but the feature level appears to be stuck at luminous ? ceph features ... "client": [ { "features": "0x3f01cfb8ffadffff", "release": "luminous", "num": 16 } ], ... dunno if that's something expected or a problem.
But yes, our structure is generally /bucket/prefix/prefix/file so there is not many big directories (we're migrating from GFS where that was a problem)
Paul Emmerich has written about performance issues with large buckets on this list, see https://lists.ceph.io/hyperkitty/list/dev@ceph.io/thread/36P62BOOCJBVVJCVUX5...
Let's say that there are opportunities for further improvements.
You could look for the specific queries that cause the high read load in your system. Maybe there's something that can be done on the client side. This could also provide input for Ceph development as to what kinds of index operations are used by applications "in the wild". Those might be worth optimizing first :-)
Is there a way to debug which query exactly is causing that ?
What I usually do is grep through the HTTP request logs of the front-end proxy/load balancer (Nginx in our case), and look for GET requests on a bucket that have a long duration. It's a bit crude, I know. (If someone knows better techniques for this, I'd also be interested! Maybe something based on something like Jaeger/OpenTracing, or clever log correlation?)
I did some looking and it appears most of our indexing traffic were developers doing some cleaning and monitoring the progress by basically ls-ing over and over again so at least the problem should subsist once migration is over. AFAIK there isn't really any way to "mark request for tracing" in Ceph so sadly any tracing kinda ends at radosgw
Currently there is a lot of incoming traffic (mostly from aws cli sync) as we're migrating data over but that's at most hundreds of requests per sec.
running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs.
We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference.
Was your bucket index sharded in 12.x?
we didn't touch default settings so I assume not ? "radosgw-admin metadata get" and "radosgw-admin bucket stat" doesn't say anything about shards on old cluster, while on new cluster there is from 11 to few hundred on the biggest buckets.
Yes, I think it's the sharding that causes the read amplification.
Hm, I don't understand enough about the operations that this represents, but maybe one of the RadosGW developers can explain why a single OSD would perform so many similar requests in such a short timeframe.
I'm getting similar logs on any osd/pg that takes part in the .index
Right, that's what I thought. Again, I can't tell whether these log messages are to be expected... the repetitions look a bit odd.
Best regards,
Well, it is same requests over and over again so without/with too small cache that's to be expected. I guess I'll just wait for next release. Cheers -- Mariusz Gronczewski, Administrator Efigence S. A. ul. Wołoska 9a, 02-583 Warszawa T: [+48] 22 380 13 13 NOC: [+48] 22 380 10 20 E: admin@efigence.com
Hi, huge read amplification for index buckets is unfortunately normal, complexity of a read request is O(n) where n is the number of objects in that bucket. I've worked on many clusters with huge buckets and having 10 gbit/s of network traffic between the OSDs and radosgw is unfortunately not unusual when running a lot of listing requests. The problem is that it needs to read *all* shards for each list request and the number of shards is the number of objects divided by 100k by default. It's a little bit better in Octopus, but still not great for huge buckets. My experiences with building rgw setups for huge (> 200 million) buckets can be summed up as: * use *good* NVMe disks for the index bucket (very good experiences with Samsung 1725a, seen these things do > 50k iops during recovieres) * it can be beneficial to have a larger number of OSDs handling the load as huge rocksdb sizes can be a problem; that means it can be better to use the NVMe disks as DB device for HDDs and put the index pool here than to run a dedicated NVMe-only pool on very few OSDs * go for larger shards on large buckets, shard sizes of 300k - 600k are perfectly fine on fast NVMes (the trade-off here is recovery speed/locked objects vs. read amplification) I think the formula shards = bucket_size / 100k shouldn't apply for buckets with >= 100 million objects; shards should become bigger as the bucket size increases. Paul -- Paul Emmerich Looking for help with your Ceph cluster? Contact us at https://croit.io croit GmbH Freseniusstr. 31h 81247 München www.croit.io Tel: +49 89 1896585 90 On Thu, Jun 18, 2020 at 9:25 AM Mariusz Gronczewski < mariusz.gronczewski@efigence.com> wrote:
Hi,
we're using Ceph as S3-compatible storage to serve static files (mostly css/js/images + some videos) and I've noticed that there seem to be huge read amplification for index pool.
Incoming traffic magniture is of around 15k req/sec (mostly sub 1MB request but index pool is getting hammered:
pool pl-war1.rgw.buckets.index id 10 client io 632 MiB/s rd, 277 KiB/s wr, 129.92k op/s rd, 415 op/s wr
pool pl-war1.rgw.buckets.data id 11 client io 4.5 MiB/s rd, 6.8 MiB/s wr, 640 op/s rd, 1.65k op/s wr
and is getting order of magnitude more requests
running 15.2.3, nothing special in terms of tunning aside from disabling some logging as to not overflow the logs.
We've had similar test cluster on 12.x (and way slower hardware) getting similar traffic and haven't observed that magnitude of difference.
when enabling debug on affected OSD I only get spam of
2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# = 0 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.700+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b1a34d8:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.214:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# = 0 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.704+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.708+0200 7f80694c4700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b0d75b0:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.222:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) omap_get_header 10.51_head oid #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# = 0 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.716+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head# 2020-06-17T12:35:05.720+0200 7f806d4cc700 10 bluestore(/var/lib/ceph/osd/ceph-20) get_omap_iterator 10.51_head #10:8b5ed205:::.dir.88d4f221-0da5-444d-81a8-517771278350.454759.8.151:head#
-- Mariusz Gronczewski (XANi) <xani666@gmail.com> GnuPG: 0xEA8ACE64 http://devrandom.pl _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
participants (3)
-
Mariusz Gronczewski
-
Paul Emmerich
-
Simon Leinen