Ceph » rgw

Additional information are following.

A request log (during latency degradation):

```
2023-03-15 12:49:33
debug 2023-03-15T03:49:33.402+0000 7ff75eead700 2 req 14124238834200714628 0.000000000s initializing for trans_id = tx00000c4036062e34f9d84-006411404d-663ba9a-ceph-object-store-0
2023-03-15 12:49:33
debug 2023-03-15T03:49:33.402+0000 7ff75eead700 2 req 14124238834200714628 0.000000000s getting op 0
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check verifying requester
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check normalizing buckets and tenants
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check init permissions
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check recalculating target
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check reading permissions
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check init op
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check verifying op mask
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check verifying op permissions
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check verifying op params
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check pre-executing
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check check rate limiting
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check executing
2023-03-15 12:50:38
debug 2023-03-15T03:50:38.282+0000 7ff737e5f700 2 req 14124238834200714628 64.880249023s swift:get_health_check completing
2023-03-15 12:52:20
debug 2023-03-15T03:52:20.396+0000 7ff7b8f61700 2 req 14124238834200714628 166.993789673s swift:get_health_check op status=0
2023-03-15 12:52:20
debug 2023-03-15T03:52:20.396+0000 7ff7b8f61700 2 req 14124238834200714628 166.993789673s swift:get_health_check http status=200
```

There is a delay of about 60 seconds between "getting op 0" and "swift:get_health_check verifying requester", and another delay about 100 seconds between "swift:get_health_check completing" and "swift:get_health_check op status=0".

I consider the first delay is related to this code.
https://github.com/ceph/ceph/blob/98318ae89f1a893a6ded3a640405cdbb33e08757/src/rgw/rgw_process.cc#L333-L358

During the latency degradation, not all requests were delayed. (There were some requests that were not delayed.)

Hi, I took over Yuma's work.

We succeeded to reproduce this problem. Here is the additional input.

problem¶

Accessing /swift/healthcheck took very long time after restarting an index OSD.

Rook regards each rgw daemon as unreachable if accessing /swift/healchcheck fails or takes > 1s for 3 times. In our case, all three rgw daemons were regarded as down.

Our considerations¶

We suspect that the part where RGW is trying to stat the lua script is taking a long time.
We found that RGW accesses the rgw pool during the loading lua script. In addition, we don't use our own lua scripts.
Since the trigger of this phenomenon is the restart of an index OSD, we guess that the response to the above stat request is delayed due to some other works after the OSD enters the UP state.
At this time, we do not know what task is taking time in the OSD.
Note that the CPU, memory, disk, and network have sufficient capacity.

how to reproduce¶

restart an index osd

cluster configuration¶

- ceph -s

  cluster:
    id:     b52d5f3d-ba14-442e-a089-0bca47b83758
    health: HEALTH_WARN
            797 large omap objects
            504 pgs not deep-scrubbed in time
            504 pgs not scrubbed in time

  services:
    mon: 3 daemons, quorum f,g,i (age 3d)
    mgr: a(active, since 3d), standbys: b
    osd: 24 osds: 24 up (since 3d), 24 in (since 4d); 71 remapped pgs
    rgw: 3 daemons active (3 hosts, 1 zones)

  data:
    pools:   9 pools, 712 pgs
    objects: 139.46M objects, 12 TiB
    usage:   40 TiB used, 100 TiB / 139 TiB avail
    pgs:     21257886/418382853 objects misplaced (5.081%)
             641 active+clean
             71  active+remapped+backfilling

  io:
    client:   39 MiB/s rd, 358 KiB/s wr, 5.03k op/s rd, 32 op/s wr
    recovery: 2.6 MiB/s, 32 objects/s

- ceph osd tree

ID    CLASS  WEIGHT     TYPE NAME                 STATUS  REWEIGHT  PRI-AFF
  -1         139.32303  root default                                       
  -8          44.16434      zone rack0                                     
 -19           0.25000          host 10-69-0-19                            
  10    ssd    0.25000              osd.10            up   1.00000  1.00000
 -73           7.27739          host 10-69-0-24                            
  23    hdd    7.27739              osd.23            up   1.00000  1.00000
 -34           7.27739          host 10-69-0-26                            
   7    hdd    7.27739              osd.7             up   1.00000  1.00000
 -22           7.27739          host 10-69-0-27                            
   3    hdd    7.27739              osd.3             up   1.00000  1.00000
 -58           7.27739          host 10-69-0-28                            
  12    hdd    7.27739              osd.12            up   1.00000  1.00000
 -61           7.27739          host 10-69-0-29                            
  15    hdd    7.27739              osd.15            up   1.00000  1.00000
 -49           7.27739          host 10-69-0-30                            
  13    hdd    7.27739              osd.13            up   1.00000  1.00000
  -7           0.25000          host 10-69-0-8                             
   1    ssd    0.25000              osd.1             up   1.00000  1.00000
  -4          44.16434      zone rack1                                     
  -3           0.25000          host 10-69-0-200                           
   0    ssd    0.25000              osd.0             up   1.00000  1.00000
 -11           0.25000          host 10-69-0-202                           
   2    ssd    0.25000              osd.2             up   1.00000  1.00000
 -46           7.27739          host 10-69-0-214                           
   9    hdd    7.27739              osd.9             up   1.00000  1.00000
 -67           7.27739          host 10-69-0-215                           
  19    hdd    7.27739              osd.19            up   1.00000  1.00000
 -40           7.27739          host 10-69-0-216                           
   4    hdd    7.27739              osd.4             up   1.00000  1.00000
 -55           7.27739          host 10-69-0-218                           
   8    hdd    7.27739              osd.8             up   1.00000  1.00000
 -79           7.27739          host 10-69-0-221                           
  22    hdd    7.27739              osd.22            up   1.00000  1.00000
 -37           7.27739          host 10-69-0-223                           
   6    hdd    7.27739              osd.6             up   1.00000  1.00000
 -26          29.60956      zone rack2                                     
 -25           0.25000          host 10-69-1-133                           
  17    ssd    0.25000              osd.17            up   1.00000  1.00000
 -85           0.25000          host 10-69-1-134                           
  18    ssd    0.25000              osd.18            up   1.00000  1.00000
 -31                 0          host 10-69-1-147                           
 -76                 0          host 10-69-1-151                           
 -82                 0          host 10-69-1-152                           
 -64           7.27739          host 10-69-1-154                           
  14    hdd    7.27739              osd.14            up   1.00000  1.00000
 -88           7.27739          host 10-69-1-155                           
  16    hdd    7.27739              osd.16            up   1.00000  1.00000
 -52           7.27739          host 10-69-1-156                           
  11    hdd    7.27739              osd.11            up   1.00000  1.00000
 -70                 0          host 10-69-1-157                           
 -43           7.27739          host 10-69-1-158                           
   5    hdd    7.27739              osd.5             up   1.00000  1.00000
 -98          10.69240      zone rack3                                     
 -97          10.69240          host 10-69-2-94                            
  21    hdd   10.69240              osd.21            up   1.00000  1.00000
 -92          10.69240      zone rack4                                     
 -91                 0          host 10-69-3-23                            
-103          10.69240          host 10-69-3-31                            
  20    hdd   10.69240              osd.20            up   1.00000  1.00000

osd 0, 1, 2, 10, 17, 18 (ssd) are index OSDs. The log pool also uses these OSDs. Other osds (hdd) are data osds.

There is a large omap warning because we haven't resharded bucket indexes to avoid the following bug.

https://tracker.ceph.com/issues/57770

software environment¶

- ceph: 17.2.5
- rook: 1.10.7

reproduce operation¶

1. Restart OSD.0 around 2023 May 11, 04:06 ~ 04:09
2. Restart OSD.1 around 2023 May 11, 04:18 ~ 04:20
3. Restart OSD.1 around 2023 May 11, 04:20 ~ 04:21
(We restarted OSD.1 twice by mistake.)

This problem didn't happen after restarting OSD.0.
This problem happended after restarting OSD.1.

log samples¶

- index osd's logs

debug 2023-05-11T04:22:02.936+0000 7f6543198700 10 osd.0 94781 dequeue_op 0x55cf90711080 finish
debug 2023-05-11T04:22:02.889+0000 7f6543198700  7 osd.0 pg_epoch: 94781 pg[5.63( v 94778'10303508 (94715'10300462,94778'10303508] local-lis/les=94780/94781 n=15 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,17] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'10303508 lcod 94778'10303507 mlcod 0'0 active mbc={}] build_push_op 5:c6fb0402:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.728:head v 94778'10303490 size 0 recovery_info: ObjectRecoveryInfo(5:c6fb0402:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.728:head@94778'10303490, size: 0, copy_subset: [], clone_subset: {}, snapset: 0=[]:{}, object_exist: 1)
debug 2023-05-11T04:22:02.889+0000 7f6543198700 10 osd.0 pg_epoch: 94781 pg[5.63( v 94778'10303508 (94715'10300462,94778'10303508] local-lis/les=94780/94781 n=15 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,17] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'10303508 lcod 94778'10303507 mlcod 0'0 active mbc={}] _handle_message: 0x55cf90711080
debug 2023-05-11T04:22:02.889+0000 7f6543198700 10 osd.0 94781 dequeue_op 0x55cf90711080 prio 196 cost 8389608 latency 0.000049 MOSDPGPull(5.63 e94781/94780 cost 8389608) v3 pg pg[5.63( v 94778'10303508 (94715'10300462,94778'10303508] local-lis/les=94780/94781 n=15 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,17] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'10303508 lcod 94778'10303507 mlcod 0'0 active mbc={}]
debug 2023-05-11T04:22:02.889+0000 7f656445a700 15 osd.0 94781 enqueue_op 0x55cf90711080 prio 196 type 106 cost 8389608 latency 0.000015 epoch 94781 MOSDPGPull(5.63 e94781/94780 cost 8389608) v3
debug 2023-05-11T04:22:02.888+0000 7f6541995700 10 log is not dirty
debug 2023-05-11T04:22:02.888+0000 7f6541995700 10 osd.0 pg_epoch: 94781 pg[3.6( v 94766'4152 (49145'1437,94766'4152] local-lis/les=94780/94781 n=27 ec=62/62 lis/c=94780/94780 les/c/f=94781/94781/0 sis=94780) [1,17,0] r=2 lpr=94780 luod=0'0 crt=94766'4152 lcod 0'0 mlcod 0'0 active mbc={}] proc_lease pg_lease(ru 84.334770203s ub 93.439544678s int 16.000000000s)
debug 2023-05-11T04:22:02.888+0000 7f6541995700 10 osd.0 pg_epoch: 94781 pg[3.6( v 94766'4152 (49145'1437,94766'4152] local-lis/les=94780/94781 n=27 ec=62/62 lis/c=94780/94780 les/c/f=94781/94781/0 sis=94780) [1,17,0] r=2 lpr=94780 luod=0'0 crt=94766'4152 lcod 0'0 mlcod 0'0 active mbc={}] do_peering_event: epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.1 pg_lease(ru 84.334770203s ub 93.439544678s int 16.000000000s)
debug 2023-05-11T04:22:02.888+0000 7f656445a700 15 osd.0 94781 enqueue_peering_evt 3.6 epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.1 pg_lease(ru 84.334770203s ub 93.439544678s int 16.000000000s)
debug 2023-05-11T04:22:02.886+0000 7f65479a1700  7 osd.0 pg_epoch: 94781 pg[5.6a( v 94778'20615431 (94718'20612409,94778'20615431] local-lis/les=94780/94781 n=12 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,18] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'20615431 lcod 94778'20615430 mlcod 0'0 active mbc={}] build_push_op 5:56d41e18:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.169:head v 94773'20615413 size 0 recovery_info: ObjectRecoveryInfo(5:56d41e18:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.169:head@94773'20615413, size: 0, copy_subset: [], clone_subset: {}, snapset: 0=[]:{}, object_exist: 1)
debug 2023-05-11T04:22:02.886+0000 7f6543999700  7 osd.0 pg_epoch: 94781 pg[5.2( v 94778'19603630 (94668'19600598,94778'19603630] local-lis/les=94780/94781 n=6 ec=74/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [0,18,1] r=0 lpr=94780 pi=[94770,94780)/1 crt=94778'19603630 lcod 94778'19603629 mlcod 0'0 active+recovering+degraded rops=2 mbc={255={(2+0)=3}}] build_push_op 5:40b5d906:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.495:head v 94773'19603618 size 0 recovery_info: ObjectRecoveryInfo(5:40b5d906:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.495:head@94773'19603618, size: 0, copy_subset: [], clone_subset: {}, snapset: 0=[]:{}, object_exist: 1)
debug 2023-05-11T04:22:02.886+0000 7f6543999700 10 osd.0 pg_epoch: 94781 pg[5.2( v 94778'19603630 (94668'19600598,94778'19603630] local-lis/les=94780/94781 n=6 ec=74/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [0,18,1] r=0 lpr=94780 pi=[94770,94780)/1 crt=94778'19603630 lcod 94778'19603629 mlcod 0'0 active+recovering+degraded rops=2 mbc={255={(2+0)=3}}]  pushing more from, 0 of []
debug 2023-05-11T04:22:02.886+0000 7f65479a1700 10 osd.0 pg_epoch: 94781 pg[5.6a( v 94778'20615431 (94718'20612409,94778'20615431] local-lis/les=94780/94781 n=12 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,18] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'20615431 lcod 94778'20615430 mlcod 0'0 active mbc={}] _handle_message: 0x55cf90ddfa20
debug 2023-05-11T04:22:02.886+0000 7f6543999700 10 osd.0 pg_epoch: 94781 pg[5.2( v 94778'19603630 (94668'19600598,94778'19603630] local-lis/les=94780/94781 n=6 ec=74/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [0,18,1] r=0 lpr=94780 pi=[94770,94780)/1 crt=94778'19603630 lcod 94778'19603629 mlcod 0'0 active+recovering+degraded rops=2 mbc={255={(2+0)=3}}] _handle_message: 0x55cf892ce000
debug 2023-05-11T04:22:02.886+0000 7f65479a1700 10 osd.0 94781 dequeue_op 0x55cf90ddfa20 prio 3 cost 8389608 latency 0.000028 MOSDPGPull(5.6a e94781/94780 cost 8389608) v3 pg pg[5.6a( v 94778'20615431 (94718'20612409,94778'20615431] local-lis/les=94780/94781 n=12 ec=24663/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [1,0,18] r=1 lpr=94780 pi=[94770,94780)/1 luod=0'0 crt=94778'20615431 lcod 94778'20615430 mlcod 0'0 active mbc={}]
debug 2023-05-11T04:22:02.886+0000 7f6543999700 10 osd.0 94781 dequeue_op 0x55cf892ce000 prio 196 cost 8389608 latency 0.000078 MOSDPGPushReply(5.2 94781/94780 [PushReplyOp(5:40b5d906:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.495:head)]) v3 pg pg[5.2( v 94778'19603630 (94668'19600598,94778'19603630] local-lis/les=94780/94781 n=6 ec=74/74 lis/c=94780/94770 les/c/f=94781/94771/0 sis=94780) [0,18,1] r=0 lpr=94780 pi=[94770,94780)/1 crt=94778'19603630 lcod 94778'19603629 mlcod 0'0 active+recovering+degraded rops=2 mbc={255={(2+0)=3}}]
debug 2023-05-11T04:22:02.886+0000 7f656445a700 15 osd.0 94781 enqueue_op 0x55cf90ddfa20 prio 3 type 106 cost 8389608 latency 0.000014 epoch 94781 MOSDPGPull(5.6a e94781/94780 cost 8389608) v3
debug 2023-05-11T04:22:02.886+0000 7f656445a700 15 osd.0 94781 enqueue_op 0x55cf892ce000 prio 196 type 107 cost 8389608 latency 0.000024 epoch 94781 MOSDPGPushReply(5.2 94781/94780 [PushReplyOp(5:40b5d906:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.495:head)]) v3
debug 2023-05-11T04:22:02.846+0000 7f655c1d9700  0 log_channel(cluster) log [WRN] : 1 slow requests (by type [ 'delayed' : 1 ] most affected pool [ 'ceph-object-store-0.rgw.buckets.index' : 1 ])
debug 2023-05-11T04:22:02.846+0000 7f655c1d9700 -1 osd.0 94781 get_health_metrics reporting 1 slow ops, oldest is osd_op(client.116406765.0:115378 5.15 5:a91b7908:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.194:head [call rgw.guard_bucket_resharding in=36b,call rgw.bucket_prepare_op in=349b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e94781)
debug 2023-05-11T04:22:02.846+0000 7f655c1d9700 10 osd.0 94781 promote_throttle_recalibrate  actual 0, actual/prob ratio 1, adjusted new_prob 1000, prob 1000 -> 1000
debug 2023-05-11T04:22:02.846+0000 7f655c1d9700 10 osd.0 94781 promote_throttle_recalibrate 0 attempts, promoted 0 objects and 0 B; target 25 obj/sec or 5 MiB/sec
debug 2023-05-11T04:22:02.846+0000 7f655c1d9700 10 osd.0 94781 tick_without_osd_lock
debug 2023-05-11T04:22:02.726+0000 7f65579d0700  4 rocksdb: EVENT_LOG_v1 {"time_micros": 1683778922726846, "cf_name": "p-0", "job": 419, "event": "table_file_creation", "file_number": 167071, "file_size": 69614045, "file_checksum": "", "file_checksum_func_name": "Unknown", "table_properties": {"data_size": 67112593, "index_size": 1016223, "index_partitions": 0, "top_level_index_size": 0, "index_key_is_user_key": 1, "index_value_is_delta_encoded": 1, "filter_size": 1484229, "raw_key_size": 58857540, "raw_average_key_size": 99, "raw_value_size": 31256491, "raw_average_value_size": 52, "num_data_blocks": 17041, "num_entries": 593654, "num_deletions": 469256, "num_merge_operands": 0, "num_range_deletions": 0, "format_version": 0, "fixed_key_len": 0, "filter_policy": "rocksdb.BuiltinBloomFilter", "column_family_name": "p-0", "column_family_id": 4, "comparator": "leveldb.BytewiseComparator", "merge_operator": "nullptr", "prefix_extractor_name": "nullptr", "property_collectors": "[]", "compression": "NoCompression", "compression_options": "window_bits=-14; level=32767; strategy=0; max_dict_bytes=0; zstd_max_train_bytes=0; enabled=0; ", "creation_time": 1681352923, "oldest_key_time": 0, "file_creation_time": 1683778919, "db_id": "feb9ef26-123a-44a9-bef7-17fc4d0f6538", "db_session_id": "I4V7FERQ3A7SUFU4JCOW"}}
debug 2023-05-11T04:22:02.726+0000 7f65579d0700  4 rocksdb: [db/compaction/compaction_job.cc:1516] [p-0] [JOB 419] Generated table #167071: 593654 keys, 69614045 bytes
debug 2023-05-11T04:22:02.685+0000 7f65609e2700 10 osd.0 94781 do_waiters -- finish
debug 2023-05-11T04:22:02.685+0000 7f65609e2700 10 osd.0 94781 do_waiters -- start
debug 2023-05-11T04:22:02.685+0000 7f65609e2700 10 osd.0 94781 tick
debug 2023-05-11T04:22:02.159+0000 7f6542196700 10 log is not dirty
debug 2023-05-11T04:22:02.159+0000 7f6542196700 10 osd.0 pg_epoch: 94781 pg[5.55( v 94778'11153516 (94710'11150497,94778'11153516] local-lis/les=94770/94771 n=18 ec=24663/74 lis/c=94770/94770 les/c/f=94771/94771/0 sis=94770) [18,0,10] r=1 lpr=94770 luod=0'0 crt=94778'11153514 mlcod 94778'11153503 active mbc={}] proc_lease pg_lease(ru 1296569.875000000s ub 1296577.875000000s int 16.000000000s)
debug 2023-05-11T04:22:02.159+0000 7f6542196700 10 osd.0 pg_epoch: 94781 pg[5.55( v 94778'11153516 (94710'11150497,94778'11153516] local-lis/les=94770/94771 n=18 ec=24663/74 lis/c=94770/94770 les/c/f=94771/94771/0 sis=94770) [18,0,10] r=1 lpr=94770 luod=0'0 crt=94778'11153514 mlcod 94778'11153503 active mbc={}] do_peering_event: epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.18 pg_lease(ru 1296569.875000000s ub 1296577.875000000s int 16.000000000s)
debug 2023-05-11T04:22:02.159+0000 7f656445a700 15 osd.0 94781 enqueue_peering_evt 5.55 epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.18 pg_lease(ru 1296569.875000000s ub 1296577.875000000s int 16.000000000s)
debug 2023-05-11T04:22:02.116+0000 7f654619e700 10 log is not dirty
debug 2023-05-11T04:22:02.116+0000 7f654619e700 10 osd.0 pg_epoch: 94781 pg[5.4d( v 94778'12874484 (94746'12871482,94778'12874484] local-lis/les=94770/94771 n=16 ec=24663/74 lis/c=94770/94770 les/c/f=94771/94771/0 sis=94770) [17,10,0] r=2 lpr=94770 luod=0'0 lua=94778'12874480 crt=94778'12874484 lcod 94778'12874483 mlcod 94778'12874482 active mbc={}] proc_lease pg_lease(ru 1297597.875000000s ub 1297606.000000000s int 16.000000000s)
debug 2023-05-11T04:22:02.116+0000 7f654619e700 10 osd.0 pg_epoch: 94781 pg[5.4d( v 94778'12874484 (94746'12871482,94778'12874484] local-lis/les=94770/94771 n=16 ec=24663/74 lis/c=94770/94770 les/c/f=94771/94771/0 sis=94770) [17,10,0] r=2 lpr=94770 luod=0'0 lua=94778'12874480 crt=94778'12874484 lcod 94778'12874483 mlcod 94778'12874482 active mbc={}] do_peering_event: epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.17 pg_lease(ru 1297597.875000000s ub 1297606.000000000s int 16.000000000s)
debug 2023-05-11T04:22:02.116+0000 7f6564c5b700 15 osd.0 94781 enqueue_peering_evt 5.4d epoch_sent: 94781 epoch_requested: 94781 MLease epoch 94781 from osd.17 pg_lease(ru 1297597.875000000s ub 1297606.000000000s int 16.000000000s)
debug 2023-05-11T04:22:02.111+0000 7f654619e700 10 log is not dirty

- rgw's log

debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700  2 req 17177950262429030953 0.000000000s initializing for trans_id = tx00000ee6456c041691a29-00645c6d7c-6efb411-ceph-object-store-0
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 10 req 17177950262429030953 0.000000000s rgw api priority: s3=8 s3website=7
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 10 req 17177950262429030953 0.000000000s host=10.64.19.41
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 20 req 17177950262429030953 0.000000000s subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 20 req 17177950262429030953 0.000000000s final domain/bucket subdomain= domain= in_hosted_domain=0 in_hosted_domain_s3website=0 s->info.domain= s->info.request_uri=/swift/healthcheck
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 10 req 17177950262429030953 0.000000000s handler=28RGWHandler_SWIFT_HealthCheck
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700  2 req 17177950262429030953 0.000000000s getting op 0
debug 2023-05-11T04:22:20.831+0000 7f4b76ec1700 20 req 17177950262429030953 0.000000000s get_system_obj_state: rctx=0x7f4cf04f0770 obj=ceph-object-store-0.rgw.log:script.prerequest. state=0x7f48d4002670 s->prefetch_data=0
#### Took long time here ####
debug 2023-05-11T04:25:18.303+0000 7f4b035da700 10 req 17177950262429030953 177.471832275s swift:get_health_check scheduling with throttler client=3 cost=1
debug 2023-05-11T04:25:18.303+0000 7f4b035da700 10 req 17177950262429030953 177.471832275s swift:get_health_check op=32RGWGetHealthCheck_ObjStore_SWIFT
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check verifying requester
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check normalizing buckets and tenants
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check init permissions
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check recalculating target
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check reading permissions
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check init op
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check verifying op mask
debug 2023-05-11T04:25:18.303+0000 7f4b035da700 20 req 17177950262429030953 177.471832275s swift:get_health_check required_mask= 1 user.op_mask=7
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check verifying op permissions
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check verifying op params
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check pre-executing
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check check rate limiting
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check executing
debug 2023-05-11T04:25:18.303+0000 7f4b035da700  2 req 17177950262429030953 177.471832275s swift:get_health_check completing
debug 2023-05-11T04:25:18.303+0000 7f4b035da700 20 req 17177950262429030953 177.471832275s get_system_obj_state: rctx=0x7f4cf04f0770 obj=ceph-object-store-0.rgw.log:script.postrequest. state=0x7f48d4002670 s->prefetch_data=0
#### Took long time here ####
debug 2023-05-11T04:25:44.271+0000 7f4b59686700  2 req 17177950262429030953 203.440002441s swift:get_health_check op status=0
debug 2023-05-11T04:25:44.271+0000 7f4b59686700  2 req 17177950262429030953 203.440002441s swift:get_health_check http status=200

- ops logs: we took `ceph daemon osd.X 'dump_historic_ops dump_ops_in_flight ops'` once per 30 secs during slow healchcheck.

        {
            "description": "osd_op(client.116406765.0:93517 5.16 5:69274e6f:::.dir.67ade7e7-b37b-486e-a969-5d39c507d06d.64431775.1.186:head [call rgw.guard_bucket_resharding in=36b,call rgw.bucket_prepare_op in=349b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e94776)",
            "initiated_at": "2023-05-11T04:19:23.626475+0000",
            "age": 200.544154045,
            "duration": 16.333650203000001,
            "type_data": {
                "flag_point": "commit sent; apply or cleanup",
                "client_info": {
                    "client": "client.116406765",
                    "client_addr": "10.64.14.90:0/1590675739",
                    "tid": 93517
                },
                "events": [
                    {
                        "event": "initiated",
                        "time": "2023-05-11T04:19:23.626475+0000",
                        "duration": 0
                    },
                    {
                        "event": "throttled",
                        "time": "2023-05-11T04:19:23.626475+0000",
                        "duration": 0
                    },
                    {
                        "event": "header_read",
                        "time": "2023-05-11T04:19:23.626475+0000",
                        "duration": 4294967295.9999995
                    },
                    {
                        "event": "all_read",
                        "time": "2023-05-11T04:19:23.626479+0000",
                        "duration": 3.5779999999999999e-06
                    },
                    {
                        "event": "dispatched",
                        "time": "2023-05-11T04:19:23.626482+0000",
                        "duration": 3.4319999999999999e-06
                    },
                    {
                        "event": "queued_for_pg",
                        "time": "2023-05-11T04:19:23.626487+0000",
                        "duration": 5.361e-06
                    },
                    {
                        "event": "reached_pg",
                        "time": "2023-05-11T04:19:23.626547+0000",
                        "duration": 5.9861000000000002e-05
                    },
                    {
                        "event": "waiting for degraded object",
                        "time": "2023-05-11T04:19:23.626603+0000",
                        "duration": 5.5455999999999999e-05
                    },
                    {
                        "event": "reached_pg",
                        "time": "2023-05-11T04:19:38.942878+0000",
                        "duration": 15.316275408999999
                    },
                    {
                        "event": "waiting for peered",
                        "time": "2023-05-11T04:19:38.942885+0000",
                        "duration": 6.404e-06
                    },
                    {
                        "event": "reached_pg",
                        "time": "2023-05-11T04:19:39.949108+0000",
                        "duration": 1.00622308
                    },
                    {
                        "event": "started",
                        "time": "2023-05-11T04:19:39.949196+0000",
                        "duration": 8.8764000000000006e-05
                    },
                    {
                        "event": "waiting for subops from 18",
                        "time": "2023-05-11T04:19:39.951455+0000",
                        "duration": 0.0022586799999999999
                    },
                    {
                        "event": "op_commit",
                        "time": "2023-05-11T04:19:39.952883+0000",
                        "duration": 0.0014283939999999999
                    },
                    {
                        "event": "sub_op_commit_rec",
                        "time": "2023-05-11T04:19:39.960050+0000",
                        "duration": 0.0071662039999999998
                    },
                    {
                        "event": "commit_sent",
                        "time": "2023-05-11T04:19:39.960093+0000",
                        "duration": 4.3247000000000001e-05
                    },
                    {
                        "event": "done",
                        "time": "2023-05-11T04:19:39.960126+0000",
                        "duration": 3.2756999999999998e-05
                    }
                ]
            }
        },

In the above log, log levels are 15 for index osd daemons and 20 for rgw daemons. We couldn't set osd daemons' log levels to 20 since these daemons crashes after restarting an index osds due to the limitation of our system.

We have captured many other logs as follows.

- All index OSD's full log.
- All RGW's full log.
- Complete result of `ceph daemon osd.X 'dump_historic_ops dump_ops_in_flight ops'.

However, we don't attach them in this message since they are big. Please let me know if necessary.

I succeeded to create a reproducer. I found that increasing the number of index OSD reduces the latency. So I'll increase the number of index OSDs in the environment where I hit the original problem.

In addition, I got perf record during reproducing this problem. However, I couldn't find the root cause of this problem.

Could you tell me if you know the root cause from my logs and perf records(see below). In addition, I'm glad if there is a recommendation about the number of index OSDs.

Here is the detail.

Additional information¶

• bucket index resharding (before adding index OSDs) didn't resolve this problem.
  • the number of shards is increased from 307 to 509
• Increasing the number of OSDs from 6 to 12 reduces the latency of all requests.
  • The number of PGs are also increased from 128 to 512 by pg-autoscaler. So whether the latency improvement came from the number of OSDs, number of PGs or both.
• Increasing the number of OSDs from 12 to 18, 18 to 24 didn't take effects.
• I captured the log of the restarted index OSD1 and the perf record2 during reproducing this problem(attached in this message). However, I didn't find the root cause.

reproducer¶

1. Create a Ceph cluster for RGW. The number of index OSD (SSD) is 6 and the number of data OSD (HDD) is 33
2. Create a test bucket
3. PUT about 47M objects in the test bucket as follows.

create-objects.sh:

warp get --host=${BUCKET_HOST}:${BUCKET_PORT} --bucket=${BUCKET_NAME} \
                --benchdata /tmp/warp-benchdata --analyze.v \
                --access-key=${AWS_ACCESS_KEY_ID} --secret-key=${AWS_SECRET_ACCESS_KEY} \
                --concurrent=50 --objects=46708840 --obj.size=76800 --noprefix \
                --noclear --duration 10s

4. Increase the number of shards of test bucket to 509
5. Run the following three scripts background.

list.sh:

ENDPOINT=<rgw's endpoint>
BUCKET=<bucket name>
while :
  do
    date
    aws s3 ls --endpoint-url ${ENDPOINT} s3://${BUCKET}/111111 > /dev/null
    sleep 15
  done

get.sh:

ENDPOINT=<rgw's endpoint>
BUCKET=<bucket name>
OBJS=$(aws s3 ls --endpoint-url ${ENDPOINT} s3://${BUCKET}/111111 | awk '{ print $4 }')

mkdir -p ./work
download() {
aws s3 cp --endpoint-url ${ENDPOINT} s3://${BUCKET}/$1 ./work/$1
rm ./work/$1
}
while :
 do
  for OBJ in ${OBJS}; do
    download ${OBJ} &amp;
    sleep 0.05
  done
 done

put.sh:

ENDPOINT=<rgw's endpoint>
BUCKET=<bucket name>
mkdir -p ./work
OBJ=test

upload() {
    aws s3 cp --endpoint-url ${ENDPOINT} ./work/$1 s3://${BUCKET}/$1-$((RANDOM % 10000000 + 10000000))
}

dd if=/dev/urandom of=work/${OBJ} count=1 bs=256k

while :
do
  upload ${OBJ} &amp;
  sleep 0.33
done

6. Restart an index OSD pod.

The reproduction probability seems to be different for each OSD. In our environment, it's almost 100% by restarting an index OSD. However, it's not in other OSDs.

I found that increasing the number of index OSD reduces the latency. So I'll increase the number of index OSDs in the environment where I hit the original problem.

I succeeded to reduce the latency by increasing the number of OSDs in my production environment.

Please close this ticket.