We're using CephFS with Luminous 12.2.5 and the fuse client (on
CentOS 7.4, kernel 3.10.0-693.5.2.el7.x86_64). Performance has been
very good generally, but we're currently running into some strange
performance issues with one of our applications. The client in this
case is on a higher latency link - it is about 2.5ms away from all
the ceph server nodes (all ceph server nodes are near each other on
10/40Ggbps local ethernet, only the client is "away").
The application is reading contiguous data at 64k chunks, the strace
(-tt -T flags) looks something like:
06:37:04.152667 read(3,
".:.:.\t./.:.:.:.:.\t./.:.:.:.:.\t./"..., 65536) = 65536
<0.024052>
06:37:04.178432 read(3,
",1523\t./.:.:.:.:.\t0/0:34,0:34:99"..., 65536) = 65536
<0.023990>
06:37:04.204087 read(3,
":20:21:0,21,738\t0/0:8,0:8:0:0,0,"..., 65536) = 65536
<0.024053>
06:37:04.229919 read(3,
"665\t0/0:35,0:35:99:0,102,1530\t./"..., 65536) = 65536
<0.024574>
06:37:04.255623 read(3,
":37:99:0,99,1485\t0/0:34,0:34:99:"..., 65536) = 65536
<0.023795>
06:37:04.280914 read(3,
":.\t./.:.:.:.:.:.:.\t./.:.:.:.:.:."..., 65536) = 65536
<0.023614>
06:37:04.306022 read(3,
"0,0,0\t./.:0,0:0:.:0,0,0\t./.:0,0:"..., 65536) = 65536
<0.024037>
so each 64k read takes about 23-24ms. The client has the file open
for read, the machine is not busy (load of 0.2), neither are the
ceph nodes. The fuse client seems pretty idle also.
Increasing the log level to 20 for 'client' and 'objectcacher' on
ceph-fuse, it looks like ceph-fuse gets ll_read requests of 4k in
size, and it looks like it does an async read from the OSDs in 4k
chunks (if I'm interpreting the logs right). Here is a trace of one
ll_read:
2018-06-06 08:14:17.609495 7fffe7a35700 3
client.16794661 ll_read 0x5556dadfc1a0 0x1000d092e5f
238173646848~4096
2018-06-06 08:14:17.609506 7fffe7a35700 10 client.16794661
get_caps 0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=0,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680) have pAsLsXsFsxcrwb need
Fr want Fc revoking -
2018-06-06 08:14:17.609517 7fffe7a35700 10 client.16794661
_read_async 0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680) 238173646848~4096
2018-06-06 08:14:17.609523 7fffe7a35700 10 client.16794661
min_bytes=4194304 max_bytes=268435456 max_periods=64
2018-06-06 08:14:17.609528 7fffe7a35700 10 objectcacher readx
extent(1000d092e5f.0000ddd1 (56785) in @6 94208~4096 ->
[0,4096])
2018-06-06 08:14:17.609532 7fffe7a35700 10
objectcacher.object(1000d092e5f.0000ddd1/head) map_read
1000d092e5f.0000ddd1 94208~4096
2018-06-06 08:14:17.609535 7fffe7a35700 20
objectcacher.object(1000d092e5f.0000ddd1/head) map_read miss
4096 left, bh[ 0x55555fecdd40 94208~4096 0x5556226235c0 (0) v 0
missing] waiters = {}
2018-06-06 08:14:17.609537 7fffe7a35700 7 objectcacher
bh_read on bh[ 0x55555fecdd40 94208~4096 0x5556226235c0 (0) v 0
missing] waiters = {} outstanding reads 0
2018-06-06 08:14:17.609576 7fffe7a35700 10 objectcacher readx
missed, waiting on bh[ 0x55555fecdd40 94208~4096 0x5556226235c0
(0) v 0 rx] waiters = {} off 94208
2018-06-06 08:14:17.609579 7fffe7a35700 20 objectcacher readx
defer 0x55570211ec00
2018-06-06 08:14:17.609580 7fffe7a35700 5 client.16794661
get_cap_ref got first FILE_CACHE ref on
0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.609587 7fffe7a35700 15 inode.get on
0x55555f138680 0x1000d092e5f.head now 4
2018-06-06 08:14:17.612318 7fffefa45700 7 objectcacher
bh_read_finish 1000d092e5f.0000ddd1/head tid 29067611 94208~4096
(bl is 4096) returned 0 outstanding reads 1
2018-06-06 08:14:17.612338 7fffefa45700 20 objectcacher
checking bh bh[ 0x55555fecdd40 94208~4096 0x5556226235c0 (0) v 0
rx] waiters = { 94208->[0x5557007383a0, ]}
2018-06-06 08:14:17.612341 7fffefa45700 10 objectcacher
bh_read_finish read bh[ 0x55555fecdd40 94208~4096 0x5556226235c0
(4096) v 0 clean firstbyte=46] waiters = {}
2018-06-06 08:14:17.612344 7fffefa45700 10
objectcacher.object(1000d092e5f.0000ddd1/head) try_merge_bh bh[
0x55555fecdd40 94208~4096 0x5556226235c0 (4096) v 0 clean
firstbyte=46] waiters = {}
2018-06-06 08:14:17.612346 7fffefa45700 20 objectcacher
finishing waiters 0x5557007383a0
2018-06-06 08:14:17.612347 7fffefa45700 10 objectcacher readx
extent(1000d092e5f.0000ddd1 (56785) in @6 94208~4096 ->
[0,4096])
2018-06-06 08:14:17.612349 7fffefa45700 10
objectcacher.object(1000d092e5f.0000ddd1/head) map_read
1000d092e5f.0000ddd1 94208~4096
2018-06-06 08:14:17.612350 7fffefa45700 20
objectcacher.object(1000d092e5f.0000ddd1/head) map_read hit bh[
0x55555fecdd40 94208~4096 0x5556226235c0 (4096) v 0 clean
firstbyte=46] waiters = {}
2018-06-06 08:14:17.612352 7fffefa45700 10 objectcacher readx
hit bh bh[ 0x55555fecdd40 94208~4096 0x5556226235c0 (4096) v 0
clean firstbyte=46] waiters = {}
2018-06-06 08:14:17.612354 7fffefa45700 10 objectcacher readx
rmap opos 94208: bh[ 0x55555fecdd40 94208~4096 0x5556226235c0
(4096) v 0 clean firstbyte=46] waiters = {} +0 frag 0~4096
+0~4096
2018-06-06 08:14:17.612357 7fffefa45700 10 objectcacher readx
has all buffers
2018-06-06 08:14:17.612357 7fffefa45700 10 objectcacher readx
adding buffer len 4096 at 0
2018-06-06 08:14:17.612358 7fffefa45700 10 objectcacher readx
result is 4096
2018-06-06 08:14:17.612359 7fffefa45700 20 objectcacher readx
done 0x55570211ec00 4096
2018-06-06 08:14:17.612360 7fffefa45700 10 objectcacher trim
start: bytes: max 2147483640 clean 2145931264, objects: max
8192 current 8192
2018-06-06 08:14:17.612361 7fffefa45700 10 objectcacher trim
finish: max 2147483640 clean 2145931264, objects: max 8192
current 8192
2018-06-06 08:14:17.612410 7fffe7a35700 5 client.16794661
put_cap_ref dropped last FILE_CACHE ref on
0x1000d092e5f.head(faked_ino=0 ref=4 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.612438 7fffe7a35700 10 client.16794661
put_inode on 0x1000d092e5f.head(faked_ino=0 ref=4 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.612446 7fffe7a35700 15 inode.put on
0x55555f138680 0x1000d092e5f.head now 3
The 2-3ms trip to the OSD seems clear between 17.609s to 17.612s.
This is also confirmed by running ' objecter_requests' through the
admin socket of the client. Then immediately the next ll_read
starts:
2018-06-06 08:14:17.612503 7fffe6a33700 3
client.16794661 ll_read 0x5556dadfc1a0 0x1000d092e5f
238173655040~4096
2018-06-06 08:14:17.612516 7fffe6a33700 10 client.16794661
get_caps 0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=0,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680) have pAsLsXsFsxcrwb need
Fr want Fc revoking -
2018-06-06 08:14:17.612526 7fffe6a33700 10 client.16794661
_read_async 0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680) 238173655040~4096
2018-06-06 08:14:17.612533 7fffe6a33700 10 client.16794661
min_bytes=4194304 max_bytes=268435456 max_periods=64
2018-06-06 08:14:17.612539 7fffe6a33700 10 objectcacher readx
extent(1000d092e5f.0000ddd1 (56785) in @6 102400~4096 ->
[0,4096])
2018-06-06 08:14:17.612542 7fffe6a33700 10
objectcacher.object(1000d092e5f.0000ddd1/head) map_read
1000d092e5f.0000ddd1 102400~4096
2018-06-06 08:14:17.612545 7fffe6a33700 20
objectcacher.object(1000d092e5f.0000ddd1/head) map_read miss
4096 left, bh[ 0x555653fd3b00 102400~4096 0x5556226235c0 (0) v 0
missing] waiters = {}
2018-06-06 08:14:17.612548 7fffe6a33700 7 objectcacher
bh_read on bh[ 0x555653fd3b00 102400~4096 0x5556226235c0 (0) v 0
missing] waiters = {} outstanding reads 0
2018-06-06 08:14:17.612587 7fffe6a33700 10 objectcacher readx
missed, waiting on bh[ 0x555653fd3b00 102400~4096 0x5556226235c0
(0) v 0 rx] waiters = {} off 102400
2018-06-06 08:14:17.612591 7fffe6a33700 20 objectcacher readx
defer 0x55568850eee0
2018-06-06 08:14:17.612591 7fffe6a33700 5 client.16794661
get_cap_ref got first FILE_CACHE ref on
0x1000d092e5f.head(faked_ino=0 ref=3 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.612598 7fffe6a33700 15 inode.get on
0x55555f138680 0x1000d092e5f.head now 4
2018-06-06 08:14:17.615300 7fffefa45700 7 objectcacher
bh_read_finish 1000d092e5f.0000ddd1/head tid 29067612
102400~4096 (bl is 4096) returned 0 outstanding reads 1
2018-06-06 08:14:17.615321 7fffefa45700 20 objectcacher
checking bh bh[ 0x555653fd3b00 102400~4096 0x5556226235c0 (0) v
0 rx] waiters = { 102400->[0x555724927d10, ]}
2018-06-06 08:14:17.615324 7fffefa45700 10 objectcacher
bh_read_finish read bh[ 0x555653fd3b00 102400~4096
0x5556226235c0 (4096) v 0 clean firstbyte=58] waiters = {}
2018-06-06 08:14:17.615327 7fffefa45700 10
objectcacher.object(1000d092e5f.0000ddd1/head) try_merge_bh bh[
0x555653fd3b00 102400~4096 0x5556226235c0 (4096) v 0 clean
firstbyte=58] waiters = {}
2018-06-06 08:14:17.615329 7fffefa45700 20 objectcacher
finishing waiters 0x555724927d10
2018-06-06 08:14:17.615330 7fffefa45700 10 objectcacher readx
extent(1000d092e5f.0000ddd1 (56785) in @6 102400~4096 ->
[0,4096])
2018-06-06 08:14:17.615332 7fffefa45700 10
objectcacher.object(1000d092e5f.0000ddd1/head) map_read
1000d092e5f.0000ddd1 102400~4096
2018-06-06 08:14:17.615349 7fffefa45700 20
objectcacher.object(1000d092e5f.0000ddd1/head) map_read hit bh[
0x555653fd3b00 102400~4096 0x5556226235c0 (4096) v 0 clean
firstbyte=58] waiters = {}
2018-06-06 08:14:17.615351 7fffefa45700 10 objectcacher readx
hit bh bh[ 0x555653fd3b00 102400~4096 0x5556226235c0 (4096) v 0
clean firstbyte=58] waiters = {}
2018-06-06 08:14:17.615353 7fffefa45700 10 objectcacher readx
rmap opos 102400: bh[ 0x555653fd3b00 102400~4096 0x5556226235c0
(4096) v 0 clean firstbyte=58] waiters = {} +0 frag 0~4096
+0~4096
2018-06-06 08:14:17.615356 7fffefa45700 10 objectcacher readx
has all buffers
2018-06-06 08:14:17.615357 7fffefa45700 10 objectcacher readx
adding buffer len 4096 at 0
2018-06-06 08:14:17.615358 7fffefa45700 10 objectcacher readx
result is 4096
2018-06-06 08:14:17.615358 7fffefa45700 20 objectcacher readx
done 0x55568850eee0 4096
2018-06-06 08:14:17.615359 7fffefa45700 10 objectcacher trim
start: bytes: max 2147483640 clean 2145935360, objects: max
8192 current 8192
2018-06-06 08:14:17.615361 7fffefa45700 10 objectcacher trim
finish: max 2147483640 clean 2145935360, objects: max 8192
current 8192
2018-06-06 08:14:17.615432 7fffe6a33700 5 client.16794661
put_cap_ref dropped last FILE_CACHE ref on
0x1000d092e5f.head(faked_ino=0 ref=4 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.615462 7fffe6a33700 10 client.16794661
put_inode on 0x1000d092e5f.head(faked_ino=0 ref=4 ll_ref=31
cap_refs={4=0,1024=0,2048=1,4096=0,8192=0} open={1=1,2=0}
mode=100664 size=244712765330/249011634176 mtime=2018-06-05
00:33:31.332901 caps=pAsLsXsFsxcrwb(0=pAsLsXsFsxcrwb)
objectset[0x1000d092e5f ts 0/0 objects 6769 dirty_or_tx 0]
parents=0x55555f187680 0x55555f138680)
2018-06-06 08:14:17.615470 7fffe6a33700 15 inode.put on
0x55555f138680 0x1000d092e5f.head now 3
We're running with increase client limits in ceph.conf:
client_cache_size = 262144
client_oc_max_dirty = 536870912
client_oc_max_objects = 8192
client_oc_size = 2147483640
client_readahead_max_periods = 64
client_readahead_min = 4194304
Some things I'm confused about:
- This node has exclusive access to the file, no other node is
reading/writing/accessing the file. This seems to be confirmed
by the caps, it has Fr/Fc and almost everything else. I also
don't see any trips to the MDS for caps, so no problems there.
Yet, for some reason, ceph-fuse goes to the OSD to read 4k
chunks without any read-ahead or larger reads of some kind. So
it suffers the 2-3ms latency for every 4k read. Why would this
be? I.e. why is read ahead not working here?
- Why does ceph-fuse get such tiny read requests from the kernel
when the client application is reading in 64k chunks? I see on
various other clients (on other nodes) the kernel issuing 128k
chunk read requests generally to fuse.
- Something else that is strange is that successive ll_read
offsets are 8k apart, even though the reads are 4k in size
(238173646848~4096 followed by 238173655040~4096 for example).
I don't understand how the 4k read becomes somehow 8k along the
way.
Perhaps some settings I have aren't quite right about caching here?
Any hints/suggestions would be welcome. I'd also be interested in
any hints/pointers on the internals to help me better understand how
things are supposed to work.
Thanks,
Andras
|
