- ceph-users - lists.ceph.io

The serious side-effect of rbd cache setting
by norman 20 Nov '20

20 Nov '20

Hi All, We're testing the rbd cache setting for openstack(Ceph 14.2.5 Bluestore 3-replica), and an odd problem found: 1. Setting librbd cache [client] rbd cache = true rbd cache size = 16777216 rbd cache max dirty = 12582912 rbd cache target dirty = 8388608 rbd cache max dirty age = 1 rbd cache writethrough until flush = true 2. Running rbd bench rbd -c /etc/ceph/ceph.conf \ -k /etc/ceph/keyring2 \ -n client.rbd-openstack-002 bench \ --io-size 4K \ --io-threads 1 \ --io-pattern seq \ --io-type read \ --io-total 100G \ openstack-volumes/image-you-can-drop-me 3. Start another test rbd -c /etc/ceph/ceph.conf \ -k /etc/ceph/keyring2 \ -n client.rbd-openstack-002 bench \ --io-size 4K \ --io-threads 1 \ --io-pattern rand \ --io-type write \ --io-total 100G \ openstack-volumes/image-you-can-drop-me2 Running for minutes, I found the read test almost hung for a while: 69 152069 2375.21 9728858.72 70 153627 2104.63 8620569.93 71 155748 1956.04 8011953.10 72 157665 1945.84 7970177.24 73 159661 1947.64 7977549.44 74 161522 1890.45 7743277.01 75 163583 1991.04 8155301.58 76 165791 2008.44 8226566.26 77 168433 2153.43 8820438.66 78 170269 2121.43 8689377.16 79 172511 2197.62 9001467.33 80 174845 2252.22 9225091.00 81 177089 2259.42 9254579.83 82 179675 2248.22 9208708.30 83 182053 2356.61 9652679.11 84 185087 2515.00 10301433.50 99 185345 550.16 2253434.96 101 185346 407.76 1670187.73 102 185348 282.44 1156878.38 103 185350 162.34 664931.53 104 185353 12.86 52681.27 105 185357 1.93 7916.89 106 185361 2.74 11235.38 107 185367 3.27 13379.95 108 185375 5.08 20794.43 109 185384 6.93 28365.91 110 185403 9.19 37650.06 111 185438 17.47 71544.17 128 185467 4.94 20243.53 129 185468 4.45 18210.82 131 185469 3.89 15928.44 132 185493 4.09 16764.16 133 185529 4.16 17037.21 134 185578 18.64 76329.67 135 185631 27.78 113768.65 Why this happened? It's a unacceptable performance for read.

2 3

CephFS error: currently failed to rdlock, waiting. clients crashing and evicted
by Thomas Hukkelberg 20 Nov '20

20 Nov '20

Hi all! Hopefully some of you can shed some light on this. We have big problems with samba crashing when macOS smb clients access certain/random folders/files over vfs_ceph. When browsing cephfs folder in question directly on a cephnode where cephfs is mouted we experience some issues like slow dir listing. We suspect that maybe macOS fetching of xattr metadata creates a lot of traffic, but it should not lockup the cluster like this. In logs we see both rdlock and wrlock, but mostly rdlocks. End clients experience spurious disconnects when issue occurs, roughly up to a handfull times a day. Is this a config issue? Have we hit a bug? It's certainly not a feature :/ Any pointers on how to troubleshoot or rectify this problem is most welcome. ceph version 14.2.11 samba version 4.12.10-SerNet-Ubuntu-10.focal Supermicro X11, Intel Silver 4110, 9 ceph nodes, 2x40gbe network, 150OSD spinners, NVMe db/journal -- 2020-11-17 22:09:07.525706 [WRN] evicting unresponsive client bo-samba-03 (3887652779), after 301.746 seconds 2020-11-17 22:09:07.525580 [INF] Evicting (and blacklisting) client session 3877970532 (10.40.30.133:0/3971626932) 2020-11-17 22:09:07.525536 [WRN] evicting unresponsive client bo-samba-03 (3877970532), after 302.034 seconds 2020-11-17 22:07:23.915412 [INF] Cluster is now healthy 2020-11-17 22:07:23.915381 [INF] Health check cleared: MDS_SLOW_REQUEST (was: 1 MDSs report slow requests) 2020-11-17 22:07:23.915330 [INF] Health check cleared: MDS_CLIENT_LATE_RELEASE (was: 1 clients failing to respond to capability release) 2020-11-17 22:07:23.064492 [INF] MDS health message cleared (mds.?): 1 slow requests are blocked > 30 secs 2020-11-17 22:07:23.064457 [INF] MDS health message cleared (mds.?): Client bo-samba-03 failing to respond to capability release 2020-11-17 22:07:17.524023 [WRN] client.3887663354 isn't responding to mclientcaps(revoke), ino 0x10001202b55 pending pAsLsXsFs issued pAsLsXsFsx, sent 63.325997 seconds ago 2020-11-17 22:07:17.523987 [INF] Evicting (and blacklisting) client session 3887663354 (10.40.30.133:0/3230547239) 2020-11-17 22:07:17.523967 [WRN] evicting unresponsive client bo-samba-03 (3887663354), after 64.5412 seconds 2020-11-17 22:07:17.523610 [WRN] slow request 63.325528 seconds old, received at 2020-11-17 22:06:14.197986: client_request(client.3878823430:4 lookup #0x100011f9a68/mappe uten navn 2020-11-17 22:06:14.197908 caller_uid=111139, caller_gid=110513{}) currently failed to rdlock, waiting 2020-11-17 22:07:17.523596 [WRN] 1 slow requests, 1 included below; oldest blocked for > 63.325529 secs 2020-11-17 22:07:19.255177 [WRN] Health check failed: 1 clients failing to respond to capability release (MDS_CLIENT_LATE_RELEASE) 2020-11-17 22:07:12.523453 [WRN] 1 slow requests, 0 included below; oldest blocked for > 58.325433 secs 2020-11-17 22:07:07.523382 [WRN] 1 slow requests, 0 included below; oldest blocked for > 53.325362 secs 2020-11-17 22:07:02.523360 [WRN] 1 slow requests, 0 included below; oldest blocked for > 48.325307 secs 2020-11-17 22:06:57.523218 [WRN] 1 slow requests, 0 included below; oldest blocked for > 43.325199 secs 2020-11-17 22:06:52.523203 [WRN] 1 slow requests, 0 included below; oldest blocked for > 38.325158 secs 2020-11-17 22:06:47.523105 [WRN] slow request 33.325065 seconds old, received at 2020-11-17 22:06:14.197986: client_request(client.3878823430:4 lookup #0x100011f9a68/mappe uten navn 2020-11-17 22:06:14.197908 caller_uid=111139, caller_gid=110513{}) currently failed to rdlock, waiting 2020-11-17 22:06:47.523100 [WRN] 1 slow requests, 1 included below; oldest blocked for > 33.325065 secs 2020-11-17 22:06:51.431745 [WRN] Health check failed: 1 MDSs report slow requests (MDS_SLOW_REQUEST) 2020-11-17 22:06:20.045030 [INF] Cluster is now healthy 2020-11-17 22:06:20.045008 [INF] Health check cleared: MDS_SLOW_REQUEST (was: 1 MDSs report slow requests) 2020-11-17 22:06:20.044960 [INF] Health check cleared: MDS_CLIENT_LATE_RELEASE (was: 1 clients failing to respond to capability release) 2020-11-17 22:06:19.062307 [INF] MDS health message cleared (mds.?): 1 slow requests are blocked > 30 secs 2020-11-17 22:06:19.062253 [INF] MDS health message cleared (mds.?): Client bo-samba-03 failing to respond to capability release 2020-11-17 22:06:15.936150 [WRN] Health check failed: 1 clients failing to respond to capability release (MDS_CLIENT_LATE_RELEASE) 2020-11-17 22:06:12.522624 [WRN] client.3869410498 isn't responding to mclientcaps(revoke), ino 0x10001202b55 pending pAsLsXsFs issued pAsLsXsFsx, sent 64.045677 seconds ago --thomas -- Thomas Hukkelberg thomas(a)hovedkvarteret.no +47 971 81 192 -- support(a)hovedkvarteret.no +47 966 44 999

2 1

one osd down / rgw damoen wont start
by Bernhard Krieger 20 Nov '20

20 Nov '20

Hello, today i came across a strange behaviour. After stoppping an osd, im not able to restart or /stop/start a radosgw daemon. The boot proccess will stuck until i have started the osd again. Specs: 3 ceph nodes 2 radosgw nautilus 14.2.13 CentOS7 Steps: * stopping radosgw daemon on rgw * stopping one osd on a ceph-node * starting radosgw daemon on rgw * rgw daemon stucks in boot proccess 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework: civetweb 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework conf key: port, val: 10.220.196.31:80 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework conf key: num_threads, val: 100 2020-11-20 09:58:35.412 7f8a0b7c4900 0 deferred set uid:gid to 167:167 (ceph:ceph) 2020-11-20 09:58:35.412 7f8a0b7c4900 0 ceph version 14.2.13 (1778d63e55dbff6cedb071ab7d367f8f52a8699f) nautilus (stable), process radosgw, pid 8145 -- > STUCKS/no log entries * As soon as i starting the osd, the boot sequence continues and everything works. 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework: civetweb 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework conf key: port, val: 10.220.196.31:80 2020-11-20 09:58:35.412 7f8a0b7c4900 0 framework conf key: num_threads, val: 100 2020-11-20 09:58:35.412 7f8a0b7c4900 0 deferred set uid:gid to 167:167 (ceph:ceph) 2020-11-20 09:58:35.412 7f8a0b7c4900 0 ceph version 14.2.13 (1778d63e55dbff6cedb071ab7d367f8f52a8699f) nautilus (stable), process radosgw, pid 8145 2020-11-20 10:00:23.895 7f8a0b7c4900 0 starting handler: civetweb 2020-11-20 10:00:23.913 7f8a0b7c4900 1 mgrc service_daemon_register rgw.rgw1 metadata {arch=x86_64,ceph_release=nautilus,ceph_version=ceph version 14.2.13 (1778d63e55dbff6cedb071ab7d367f8f52a8699f) nautilus (stable),ceph_version_short=14.2.13,cpu=Intel Xeon E3-12xx v2 (Ivy Bridge, IBRS),distro=centos,distro_description=CentOS Linux 7 (Core),distro_version=7,frontend_config#0=civetweb port=10.220.196.31:80 num_threads=100,frontend_type#0=civetweb,hostname=rgw1,kernel_description=#1 SMP Tue Oct 20 16:53:08 UTC 2020,kernel_version=3.10.0-1160.2.2.el7.x86_64,mem_swap_kb=1048572,mem_total_kb=1881836,num_handles=1,os=Linux,pid=8145,zone_id=ecf200a8-2c4a-4c96-96d8-4fcff5b2c8c3,zone_name=default,zonegroup_id=01d11ed1-6157-4c26-addf-ecba49820e20,zonegroup_name=default} 2020-11-20 10:00:25.551 7f89d3aac700 1 civetweb: 0x557f6a6f2000: 10.220.199.4 - - [20/Nov/2020:10:00:25 +0100] "GET / HTTP/1.0" 200 416 - - 2020-11-20 10:00:25.582 7f89d3aac700 1 civetweb: 0x557f6a6f2000: 10.220.199.3 - - [20/Nov/2020:10:00:25 +0100] "GET / HTTP/1.0" 200 416 - - 2020-11-20 10:00:27.555 7f89d3aac700 1 civetweb: 0x557f6a6f2000: 10.220.199.4 - - [20/Nov/2020:10:00:27 +0100] "GET / HTTP/1.0" 200 416 - - 2020-11-20 10:00:27.586 7f89d3aac700 1 civetweb: 0x557f6a6f2000: 10.220.199.3 - - [20/Nov/2020:10:00:27 +0100] "GET / HTTP/1.0" 200 416 - - regards Bernhard

2 1

EC cluster cascade failures and performance problems
by Paul Kramme 19 Nov '20

19 Nov '20

Hello, currently, we are experiencing problems with a cluster used for storing RBD backups. Config: * 8 nodes, each with 6 HDDs OSDs and 1 SSD used for blockdb and WAL * k=4 m=2 EC * dual 25GbE NIC * v14.2.8 ceph health detail shows the following messages: HEALTH_WARN BlueFS spillover detected on 1 OSD(s); 45 pgs not deep-scrubbed in time; snap trim queue for 2 pg(s) >= 32768 (mon_osd_snap_trim_queue_warn_on); 1 slow ops, oldest one blocked for 18629 sec, mon.cloud10-1517 has slow ops BLUEFS_SPILLOVER BlueFS spillover detected on 1 OSD(s) osd.0 spilled over 68 MiB metadata from 'db' device (35 GiB used of 185 GiB) to slow device PG_NOT_DEEP_SCRUBBED 45 pgs not deep-scrubbed in time pg 18.3f5 not deep-scrubbed since 2020-09-03 21:58:28.316958 pg 18.3ed not deep-scrubbed since 2020-09-01 15:11:54.335935 [--- cut ---] PG_SLOW_SNAP_TRIMMING snap trim queue for 2 pg(s) >= 32768 (mon_osd_snap_trim_queue_warn_on) snap trim queue for pg 18.2c5 at 41630 snap trim queue for pg 18.d6 at 44079 longest queue on pg 18.d6 at 44079 try decreasing "osd snap trim sleep" and/or increasing "osd pg max concurrent snap trims". SLOW_OPS 1 slow ops, oldest one blocked for 18629 sec, mon.cloud10-1517 has slow ops We've made some observations on that cluster: * The BlueFS spillover goes away with "ceph tell osd.0 compact" but comes back eventually * The blockdb/WAL SSD is highly utilized, while the HDDs are not * When one OSD fails, there is a cascade failure taking down many other OSDs across all nodes. Most of the time, the cluster comes back when setting the nodown flag and restarting all failed OSDs one by one * Sometimes, especially during maintenance, "Long heartbeat ping times on front/back interface seen, longest is 1390.076 msec" messages pop up * The cluster performance deteriorates sharply when upgrading from 14.2.8 to 14.2.11 or later, so we've rolled back to 14.2.8 Of these problems, the OSD cascade failure is the most important, and is responsible for lenghty downtimes in the past few weeks. Do you have any ideas on how to combat these problems? Thank you, Paul -- Mit freundlichen Grüßen Paul Kramme Ihr Profihost Team ------------------------------- Profihost AG Expo Plaza 1 30539 Hannover Deutschland Tel.: +49 (511) 5151 8181 | Fax.: +49 (511) 5151 8282 URL: http://www.profihost.com | E-Mail: info(a)profihost.com Sitz der Gesellschaft: Hannover, USt-IdNr. DE813460827 Registergericht: Amtsgericht Hannover, Register-Nr.: HRB 202350 Vorstand: Cristoph Bluhm, Stefan Priebe, Marc Zocher, Dr. Claus Boyens, Daniel Hagemeier Aufsichtsrat: Gabriele Pulvermüller (Vorsitzende)

2 2

Mon's falling out of quorum, require rebuilding. Rebuilt with only V2 address.
by Wesley Dillingham 19 Nov '20

19 Nov '20

We have had multiple clusters experiencing the following situation over the past few months on both 14.2.6 and 14.2.11. On a few instances it seemed random , in a second situation we had temporary networking disruption, in a third situation we accidentally made some osd changes which caused certain OSDs to reach the hard limit of too many pgs-per-osd and said PGs were stuck inactive. Regardless of the scenario one monitor always falls out of quorum and seemingly can't rejoin and its logs contain the following: 2020-11-18 05:34:54.113 7f14286d9700 1 mon.a2plcephmon01@2(probing) e30 handle_auth_request failed to assign global_id 2020-11-18 05:34:54.295 7f14286d9700 -1 mon.a2plcephmon01@2(probing) e30 handle_auth_bad_method hmm, they didn't like 2 result (13) Permission denied 2020-11-18 05:34:55.397 7f14286d9700 1 mon.a2plcephmon01@2(probing) e30 handle_auth_request failed to assign global_id Ultimately, we take the quick route of rebuilding the mon by wiping its DB and re-doing a mkfs and rejoining the quorum using: sudo -u ceph ceph-mon -i a2plcephmon01 --public-addr 10.1.1.1:3300 Luckily we have never dropped below 50% in quorum so far but we are very interested in preventing this from happening going forward. Inspecting "ceph mon dump" on the given clusters I see that all of the rebuilt mons use only msgrv2 on 3300 but all of the mons that never required rebuilding are using v1 and v2 addressing. So my question are: - Does this monitor failure sound familiar? - Is it problematic the manner in which we are rebuilding mons and it only lands them on using msgr v2 or should we be using v2 only on an all-nautilus cluster? Thanks for any insight. Respectfully, *Wes Dillingham* wes(a)wesdillingham.com LinkedIn <http://www.linkedin.com/in/wesleydillingham>

1 0

newbie Cephfs auth permissions issues
by Jonathan D. Proulx 19 Nov '20

19 Nov '20

Hi All, I've been using ceph block and object storage for years but just wandering into cephfs now (Nautilus all servers on 14.2.9 ). I created small data and metadata pools, a new filesystem and used: ceph fs authorize <fsname> client.<name> / rw creating two new users to mount it, both can one using fuse (14.2.9) and one using kernel client (Ubuntu 20.04 kernel 5.4.0-53). so far so good, but then it gets "weird" I can perform metadata operations like "mkdir" and "touch" but not actually write any data: testy-mctestface% touch /mnt/cephfs/boo testy-mctestface% echo foo > /mnt/cephfs/boo echo: write error: operation not permitted auth caps look good to me, but seem most likely to be worng: root@ceph-mon0:/ # ceph auth get client.client0 exported keyring for client.client0 [client.client0] key = <SEKRET> caps mds = "allow rw" caps mon = "allow r" caps osd = "allow rw tag cephfs data=<fsname>" is "data" hear supposed to be <fsname> or <data_pool_name>? Presumably it's fsname since that what the "fa authorize" put there and it should know... can anyone see what I'm doing wrong here? Thanks, -Jon

2 1

BLUEFS_SPILLOVER BlueFS spillover detected
by Zhenshi Zhou 19 Nov '20

19 Nov '20

Hi, I have a cluster of 14.2.8. I created OSDs with dedicated PCIE for wal/db when deployed the cluster. I set 72G for db and 3G for wal on each OSD. And now my cluster is in a WARN stats until a long health time. # ceph health detail HEALTH_WARN BlueFS spillover detected on 1 OSD(s) BLUEFS_SPILLOVER BlueFS spillover detected on 1 OSD(s) osd.63 spilled over 33 MiB metadata from 'db' device (1.5 GiB used of 72 GiB) to slow device I lookup on google and find https://tracker.ceph.com/issues/38745 I'm not sure if it's the same issue. How can I deal with this? THANKS

3 4

Can't upgrade from 15.2.5 to 15.2.6... (Cannot calculate service_id: daemon_id='cephfs....')
by Gencer Genç 19 Nov '20

19 Nov '20

Hi, I ran those commands as usual: $ ceph orch host ls Result is as expected by hosts names and addresses. $ ceph orch ls Again, Expected result as before. Then I started to upgrade via this command: $ ceph orch upgrade start --ceph-version 15.2.6 It failed with attached logs. Please see logs.txt for detailed output. It says; orchestrator._interface.OrchestratorError: DaemonDescription: Cannot calculate service_id: daemon_id='cephfs.host-1.shsruc' hostname='host' This cluster have 2 nodes. Then I just ran same command again: $ ceph orch ls Result is NOT as expected. I got; >> Error EINVAL: DaemonDescription: Cannot calculate service_id: daemon_id='cephfs.host-1.shsruc' hostname='host' (See attached logs.) If I restart "host-1" then i can execute "ceph orch ls" command. After I start upgrade it errors again. Interestingly I only have cephfs mounted in node "host". Not "host-1". How can I fix this issue? Thanks, Gencer.

1 1

Slow OSDs
by Kristof Coucke 19 Nov '20

19 Nov '20

Hi, We are having slow osd's... A hot topic to search on it... I've tried to dive as deep as I can, but I need to know which debug setting will help me to dive even deeper... Okay: situation: - After expansion lot's of backfill operations are running spread over the osd's. - max_backfills is set to 1 (meaning only 1 read and 1 write operation might take place at the same time for the backfill operation) - Disks are monitored and manual compaction is performed as soon as load goes over 80% - Requests thru RGW goes okay for some objects, and less okay for others. When it goes fine requests are returned within a few ms, other requests vary from a few ms to >10s. - Ceph version 14.2.11 - Erasure coding configured, 6-3 - Backfill is running at an incredible terrible pace. I assume it's all related Okay, what have I done to navigate down: 1. Removed 1 RGW from the load balancer to increase logging and dive into it 2. Using s3cmd to request the object teaches me that the delay is between the request from the RGW to the OSD and the response. 3. Investigating the osd using iostat doesn't reveal an issue. Load is very low. 3. Next I increased logging on the osd (debug_osd 20/20) and launched a request (debug setting has been immediately reversed)... 4. First you see that it is starting with the block for getting all available shards... so far so good 5. Next we will see multiple blocks like: 2020-11-19 11:53:21.938 7fe90f79c700 15 osd.156 45341 *enqueue_op* 0x559f94d43ce0 prio 127 cost 0 latency 0.000032 epoch 45341 *MOSDECSubOpRead*(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 45341 *dequeue_op* 0x559f94d43ce0 prio 127 cost 0 latency 0.000135 *MOSDECSubOpRead*(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 pg pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 share_map osd.156 v2: 192.168.34.57:6892/1464289 45341 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 should_share_map osd.156 v2:192.168.34.57:6892/1464289 45341 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] _handle_message: MOSDECSubOpRead(1.1e2s0 45341/45313 ECSubRead(tid=191, to_read={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=0,28672,0}, subchunks={1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head=[0,1]}, attrs_to_read=)) v3 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] handle_sub_read read request=28672 r=28672 len=28672 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: Getting attr on 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: not in cache 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] get_hash_info: found on disk, size 28672 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 pg_epoch: 45341 pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] handle_sub_read: Checking hash of 1:47c1b09f:::44a57332-bad8-47b4-85d6-6d34be960d5f.51962.196_CT%2f20201001%2f82078cfd-a111-4b58-8b79-88a860915c56.PNG:head 2020-11-19 11:53:21.938 7fe90678a700 20 osd.156 45341 share_map_peer 0x559f71ee3400 don't know epoch, doing nothing 2020-11-19 11:53:21.938 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f94d43ce0 finish .... This goes on... The latency is caused between such blocks. E.g.: Last line of a block of logging: ... 2020-11-19 11:53:*22.150* 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f96a5f600 finish 2020-11-19 11:53:*22.150* 7fe90678a700 20 osd.156 op_wq(2) _process empty q, waiting ... Next block of logging: 2020-11-19 11:53:*27.089* 7fe925251700 15 osd.156 45341 enqueue_op 0x559f8f9618c0 prio 127 cost 0 latency 0.000019 epoch 45341 *MOSDECSubOpReadReply*(1.1e2s0 45341/45313 *ECSubReadReply*(tid=191, attrs_read=0)) v2 2020-11-19 11:53:27.089 7fe925251700 20 osd.156 op_wq(2) _enqueue OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process 1.1e2s0 to_process <> waiting <> waiting_peering {} 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) queued 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process 1.1e2s0 to_process <OpQueueItem(1.1e2s0 PGOpItem(op=MOSDECSubOpReadReply(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341)> waiting <> waiting_peering {} 2020-11-19 11:53:27.089 7fe90678a700 20 osd.156 op_wq(2) _process OpQueueItem(1.1e2s0 PGOpItem(op=*MOSDECSubOpReadReply*(1.1e2s0 45341/45313 *ECSubReadReply*(tid=191, attrs_read=0)) v2) prio 127 cost 0 e45341) pg 0x559f8b5e5000 2020-11-19 11:53:27.089 7fe90678a700 10 osd.156 45341 dequeue_op 0x559f8f9618c0 prio 127 cost 0 latency 0.000092 MOSDECSubOpReadReply(1.1e2s0 45341/45313 ECSubReadReply(tid=191, attrs_read=0)) v2 pg pg[1.1e2s0( v 45295'4373744 (34740'4370700,45295'4373744] local-lis/les=45313/45317 n=1842926 ec=5869/714 lis/c 45313/45313 les/c/f 45317/45322/0 45313/45313/45313) [156,64,146,256,98,67,46,31,100]p156(0) r=0 lpr=45313 crt=45295'4373744 lcod 0'0 mlcod 0'0 active+clean] Now my question is: What is triggering the enqueue_op? And what is triggering this operation ('cause it takes 5 seconds)? Which debug setting can help me find that out? Many thanks for the feedback, Kristof

1 0

EC overwrite
by Szabo, Istvan (Agoda) 19 Nov '20

19 Nov '20

Hi, Is it s problem if ec_overwrite enabled in the data pool? https://docs.ceph.com/en/latest/rados/operations/erasure-code/#erasure-codi… Thanks ________________________________ This message is confidential and is for the sole use of the intended recipient(s). It may also be privileged or otherwise protected by copyright or other legal rules. If you have received it by mistake please let us know by reply email and delete it from your system. It is prohibited to copy this message or disclose its content to anyone. Any confidentiality or privilege is not waived or lost by any mistaken delivery or unauthorized disclosure of the message. All messages sent to and from Agoda may be monitored to ensure compliance with company policies, to protect the company's interests and to remove potential malware. Electronic messages may be intercepted, amended, lost or deleted, or contain viruses.

2 1