samba - Nov 2024 - Slow reply to "smbclient -NL localhost" : strace

On 06/11/2024 08:04, Michael Tokarev wrote:
> Take a closer look at strace.? You've already noticed
> the recv() call takes a noticeable time, - find all of
> them.
>
> BTW, in your strace output you omitted some important
> pieces, for example, it isn't visible what FD#5 corresponds
> to, since you omitted its creation/open.
>
> The prob might not be the (host) name resolution of smbclient,
> but on the receiving side too. Or might be something else
> entirely. 
Here's the output of "strace --relative-timestamps -o 
strace.smbclient.log smbclient -NL 127.0.0.1" :

https://pastebin.com/raw/v3hFY5DB

06.11.2024 12:32, Gilles via samba ?????:
> On 06/11/2024 08:04, Michael Tokarev wrote:
>> Take a closer look at strace.? You've already noticed
>> the recv() call takes a noticeable time, - find all of
>> them.
>>
>> BTW, in your strace output you omitted some important
>> pieces, for example, it isn't visible what FD#5 corresponds
>> to, since you omitted its creation/open.
>>
>> The prob might not be the (host) name resolution of smbclient,
>> but on the receiving side too. Or might be something else
>> entirely. 
> 
> Here's the output of "strace --relative-timestamps -o
strace.smbclient.log smbclient -NL 127.0.0.1" :
> 
> https://pastebin.com/raw/v3hFY5DB
So, as you can see yourself, there are 2 interesting places (adding some
context):

0.000442 writev(4, [{iov_base="\0\0\0\204", iov_len=4},
{iov_base="\376SMB@\0\1\0\0\0\0\0\5\0\1\0\20\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0"...,
iov_len=64},
{iov_base="9\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\237\1\2\0\0\0\0\0"...,
iov_len=56}, {iov_base="s\0r\0v\0s\0v\0c\0", iov_len=12}], 4) = 136
8.996581 recv(4, "\0\0\0\230", 4, 0) = 4

Here, fd#4 is a tcp connection to samba server on 127.0.0.1 (port 445).

And next,

0.000367 writev(4, [{iov_base="\0\0\0\300", iov_len=4},
{iov_base="\376SMB@\0\1\0\0\0\0\0\v\0\1\0\20\0\0\0\0\0\0\0\5\0\0\0\0\0\0\0"...,
iov_len=64},
{iov_base="9\0\0\0\27\300\21\0\32
2\1\324\354\0\0\0\0\\\247\217\275\0\0\0\0x\0\0\0H\0\0\0"..., iov_len=56}, 
{iov_base="\5\0\v\3\20\0\0\0H\0\0\0\1\0\0\0\270\20\270\20\0\0\0\0\1\0\0\0\0\0\1\0"...,
iov_len=72}], 4) = 19
6
0.000685 recv(4, "\0\0\0I", 4, 0)  = 4
0.000346 recv(4,
"\376SMB@\0\0\0\3\1\0\0\v\0\1\0\23\0\0\0\0\0\0\0\5\0\0\0\0\0\0\0"...,
73, 0) = 73
2.421371 recv(4, "\0\0\0\264", 4, 0) = 4

using the same socket.

The first case (with 9sec delay) happens right after smbclient printed
headings for the share list, and issued a list-shares smb command to
the server (whatever it is).  The server replied after 9s only.

BTW, I see a small delay exactly in this place on my test machine with
a single test share, - on first access smbclient has a small delay in
this same exact place, but on subsequent accesses it's instant.  After
a minute or so, next access also has the same slight delay in this very
place - again, it matches what you're seeing.

So it *is* samba (smbd) being slow replying to the list of shares command,
and caches something for some small amount of time.

Now it would be interesting to see what smbd is doing here.  It is a
bit more tricky, but you can use strace still (try strace -ff against
the listening smbd, and run smbclient - strace will create several files,
one of which will correspond to smbd in question).

/mjt