[Samba] tremendous lseek amplification by smbd

[Roland]

Hello,

i'm currently investigating some weird perfomance issue i found while
trying to convert/defragment a 150GB KVM qcow2 file with qemu-img.

that virtual disk belonged to a jenkins slave VM and had been used for a
while.

The file is located on a samba share (ZFS filesystem underneath),
mounted via cifs mount on the kvm host (kernel 6.8.4-3-pve).

the whole conversion of that file lasts endless.  there seem to be
millions of extra calls to lseek on the smbd server side.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  50,62 3728,661534       53876     69207      9750 futex
  47,55 3502,690643          13 262302940           lseek

it looks, that lseek calls getting amplified by smbd, i.e. each call to
lseek at the client seems to be multiplied at large on the server side.


anybody there who may know the reason for that and how can we avoid this
or make qemu-img work more efficiently on a samba share ?

here you can see the massive amount of amplification by rate-counting
with pv:

root at pve-pc3:/mnt/pve/pve-cluster3-trash-cifs/images/112# stdbuf -oL
strace -f -tt -T qemu-img convert vm-112-disk-1.qcow2 -O qcow2
/rpool/data/test.qcow2 -p 2>&1 |stdbuf -oL grep lseek|stdbuf -oL pv -alr
 >/dev/null
2.07 /s] [1.84 /s]

root at backup-filer:~# strace -T -f -p 1890 -tt -T 2>&1 |grep lseek|pv
-alr  >/dev/null
10,86k/s] [8,73k/s]


strace looks like this:

client:

root at pve-pc3:/mnt/pve/pve-cluster3-trash-cifs/images/112# timeout 3
strace -f -tt -T qemu-img convert vm-112-disk-1.qcow2 -O qcow2
/rpool/data/test.qcow2 -p 2>&1|grep lseek
[pid 3457448] 13:19:51.838509 lseek(4, 0, SEEK_END) = 161086111744
<0.001223>
[pid 3457448] 13:19:51.853475 lseek(8, 0, SEEK_END) = 0 <0.000006>
[pid 3457448] 13:19:51.859434 lseek(8, 0, SEEK_END) = 199008 <0.000006>
[pid 3457448] 13:19:52.097934 lseek(4, 327680, SEEK_DATA <unfinished ...>
[pid 3457448] 13:19:52.154367 <... lseek resumed>) = -1 EIO
(Input/output error) <0.056417>
[pid 3457448] 13:19:52.154928 lseek(4, 1376256, SEEK_DATA <unfinished ...>
[pid 3457448] 13:19:52.201064 <... lseek resumed>) = -1 EIO
(Input/output error) <0.046125>
[pid 3457448] 13:19:52.201469 lseek(4, 465174528, SEEK_DATA <unfinished ...>
[pid 3457448] 13:19:52.245932 <... lseek resumed>) = -1 EIO
(Input/output error) <0.044452>
[pid 3457448] 13:19:52.250104 lseek(4, 1539047424, SEEK_DATA <unfinished
...>


samba server:

root at backup-filer:~# strace -T -f -p 1890 -tt -T 2>&1 |grep lseek |head
-n 20
[pid  1890] 13:19:52.100200 lseek(30, 327680, SEEK_DATA) = 327680 <0.000036>
[pid  1890] 13:19:52.100287 lseek(30, 327680, SEEK_HOLE) = 393216 <0.000032>
[pid  1890] 13:19:52.100370 lseek(30, 393216, SEEK_DATA) = 1310720
<0.000049>
[pid  1890] 13:19:52.100485 lseek(30, 1310720, SEEK_HOLE) = 2097152
<0.000034>
[pid  1890] 13:19:52.100573 lseek(30, 2097152, SEEK_DATA) = 465174528
<0.000056>
[pid  1890] 13:19:52.100682 lseek(30, 465174528, SEEK_HOLE) = 465305600
<0.000044>
[pid  1890] 13:19:52.100791 lseek(30, 465305600, SEEK_DATA) = 537133056
<0.000043>
[pid  1890] 13:19:52.100885 lseek(30, 537133056, SEEK_HOLE) = 537264128
<0.000033>
[pid  1890] 13:19:52.100986 lseek(30, 537264128, SEEK_DATA) = 1074135040
<0.000049>
[pid  1890] 13:19:52.101089 lseek(30, 1074135040, SEEK_HOLE) =
1074266112 <0.000034>
[pid  1890] 13:19:52.101187 lseek(30, 1074266112, SEEK_DATA) =
1539047424 <0.000059>
[pid  1890] 13:19:52.101296 lseek(30, 1539047424, SEEK_HOLE) =
1539178496 <0.000031>
[pid  1890] 13:19:52.101378 lseek(30, 1539178496, SEEK_DATA) =
1611005952 <0.000058>
[pid  1890] 13:19:52.101488 lseek(30, 1611005952, SEEK_HOLE) =
1611137024 <0.000033>
[pid  1890] 13:19:52.101574 lseek(30, 1611137024, SEEK_DATA) =
2148007936 <0.000040>
[pid  1890] 13:19:52.101664 lseek(30, 2148007936, SEEK_HOLE) =
2148139008 <0.000042>
[pid  1890] 13:19:52.101757 lseek(30, 2148139008, SEEK_DATA) =
2612920320 <0.000047>
[pid  1890] 13:19:52.101854 lseek(30, 2612920320, SEEK_HOLE) =
2613051392 <0.000032>
[pid  1890] 13:19:52.101937 lseek(30, 2613051392, SEEK_DATA) =
2685009920 <0.000040>
[pid  1890] 13:19:52.102026 lseek(30, 2685009920, SEEK_HOLE) =
2685140992 <0.000031>


regards
Roland