Ceph » rgw

Is there anything I can do to debug this?

Hi,
Can you provide rgw logs with debug_rgw=20 and debug_ms=1?
Can you provide more info about your setup and config?

maybe an issue with the is_truncated check when reading the usage?

the usage log isn't read by RGWs themselves (as per my understanding so far, I could be wrong) are there tools using radosgw-admin usage show (or the non standard S3 API get usage?), commonly collectd/prometheus/ceilometer plugins poll by reading these stats, are there any such tools which are operating on the cluster?

For invoicing purposes, I use the following calls:

• /$rgw_admin_entry/user
• /$rgw_admin_entry/metadata/user
• /$rgw_admin_entry/usage {'uid':self.uid, 'show-summary': True, 'start': now['fromdate'], 'end': now['todate'], 'show-entries': False}
• /$rgw_admin_entry/bucket {uid=self.uid, stats=True}

2017-11-20 17:04:09.146690 7fd5d8968700 20 QUERY_STRING=format=json&show-summary=True&start=2017-11-01&show-entries=False&end=2017-12-01&uid=XYZ%24ABC
2017-11-20 17:04:09.146699 7fd5d8968700 20 REQUEST_METHOD=GET
2017-11-20 17:04:09.146700 7fd5d8968700 20 REQUEST_URI=/$rgw_admin_entry/usage
2017-11-20 17:04:09.146700 7fd5d8968700 20 SCRIPT_URI=/$rgw_admin_entry/usage

This seems to be the cause. After this call, it ends up looping with call rgw.user_usage_log_read..

The bucket at hand is the one causing the issues in http://tracker.ceph.com/issues/22046.

I am not sure if my problem is related but my "radosgw-admin usage show" calls do not return. They just hang on the following loop:

2017-11-20 22:25:31.524999 7fdd6d14f700 10 client.723664.objecter ms_dispatch 0x5643435cf9f0 osd_op_reply(291 usage.29 [call] v0'0 uv489002 ondisk = 0) v8
2017-11-20 22:25:31.525008 7fdd6d14f700 10 client.723664.objecter in handle_osd_op_reply
2017-11-20 22:25:31.525010 7fdd6d14f700  7 client.723664.objecter handle_osd_op_reply 291 ondisk uv 489002 in 74.0 attempt 0
2017-11-20 22:25:31.525012 7fdd6d14f700 10 client.723664.objecter  op 0 rval 0 len 15
2017-11-20 22:25:31.525013 7fdd6d14f700 15 client.723664.objecter handle_osd_op_reply completed tid 291
2017-11-20 22:25:31.525014 7fdd6d14f700 15 client.723664.objecter finish_op 291
2017-11-20 22:25:31.525016 7fdd6d14f700 20 client.723664.objecter put_session s=0x564343756fb0 osd=3 4
2017-11-20 22:25:31.525017 7fdd6d14f700 15 client.723664.objecter _session_op_remove 3 291
2017-11-20 22:25:31.525019 7fdd6d14f700  5 client.723664.objecter 0 in flight
2017-11-20 22:25:31.525023 7fdd6d14f700 20 client.723664.objecter put_session s=0x564343756fb0 osd=3 3
2017-11-20 22:25:31.525072 7fdd7e9beb80 10 client.723664.objecter _op_submit op 0x564343731710
2017-11-20 22:25:31.525076 7fdd7e9beb80 20 client.723664.objecter _calc_target epoch 17682 base usage.29 @74 precalc_pgid 0 pgid 0.0 is_read
2017-11-20 22:25:31.525079 7fdd7e9beb80 20 client.723664.objecter _calc_target target usage.29 @74 -> pgid 74.f6822e40
2017-11-20 22:25:31.525089 7fdd7e9beb80 10 client.723664.objecter _calc_target  raw pgid 74.f6822e40 -> actual 74.0 acting [3,16,9] primary 3
2017-11-20 22:25:31.525108 7fdd7e9beb80 20 client.723664.objecter _get_session s=0x564343756fb0 osd=3 3
2017-11-20 22:25:31.525112 7fdd7e9beb80 10 client.723664.objecter _op_submit oid usage.29 '@74' '@74' [call rgw.user_usage_log_read] tid 292 osd.3
2017-11-20 22:25:31.525115 7fdd7e9beb80 20 client.723664.objecter get_session s=0x564343756fb0 osd=3 3
2017-11-20 22:25:31.525116 7fdd7e9beb80 15 client.723664.objecter _session_op_assign 3 292
2017-11-20 22:25:31.525118 7fdd7e9beb80 15 client.723664.objecter _send_op 292 to 74.0 on osd.3
2017-11-20 22:25:31.525126 7fdd7e9beb80 20 client.723664.objecter put_session s=0x564343756fb0 osd=3 4
2017-11-20 22:25:31.525128 7fdd7e9beb80  5 client.723664.objecter 1 in flight

The "tid" keeps on increasing but the call never returns. I don't see any errors or issues when I bump up the log levels on OSD either. This was not an issue before the upgrade to Luminous 12.2.0, that occurred this week.

If my problem is not related, I will make a new ticket.

Can you also give us the output of radosgw-admin usage show --debug-rgw=20 --debug-ms=1 (this is verbose)

Certainly. Please see the output of that command here: https://hastebin.com/raw/omoqetimun. Let me know if there's anything else I can provide.

BTW just wanted to note here, that as a workaround we can bump the value of "osd_max_omap_entries_per_request" (a new Luminous-based config option) on all OSDs that store objects of usage pool to a sufficiently high value (and not too high of course) in order to avoid truncating output of OMAP values. That should help prevent this infinite loop as a temporary workaround until the fix goes out into the next patch release.

Can you clarify this? I now restart my rgw daemons every hour, which is ... ehm ... Suboptimal. :)

I assume there are a lot of entries in usage pool which might explain the slowdown, can you try doing something in the lines of
$ rados -p default.rgw.usage ls > objs.out list of objects
$ for i in `cat objs.out`; do rados -p default.rgw.usage listomapkeys $i | wc -l; done and see how many omap values we have

if we have millions of keys, purging older logs may be the way to go, given that they are already backed up in some sort of database like your collectd;

root@osdnode01:~# rados -p default.rgw.usage ls > objs.out
root@osdnode01:~# for i in `cat objs.out`; do rados -p default.rgw.usage listomapkeys $i | wc -l; done
4666
3162
6
718
920
1550
1636
3572
190
8
2240
1154
1164
1082
6
6
2930
992
3414
2460
80
360
38078

12.2.2 solves it permanently, especially this change: https://github.com/ceph/ceph/pull/17939.

Truncation logic was broken when query would hit >1000 omap entries for usage shards. This was sending reads into infinite loop because the flag would never become false after that point. The 1000 number comes from hard-coded constants here: https://github.com/ceph/ceph/blob/v12.2.1/src/rgw/rgw_op.cc#L1902 and here: https://github.com/ceph/ceph/blob/v12.2.1/src/rgw/rgw_usage.cc#L38. Since the value for omap entry pagination is applied only at 131K, it'd never be hit since the hard-coded constants kick in a lot before it does.

Thanks for confirmation, good to hear that

Yes, after upgrading to 12.2.2, I haven't seen this behaviour anymore.