Odd dtrace output while browsing directories

[anodos]

I'm experimenting with dtrace for smbd trying to troubleshoot why my directory browsing in CIFS is going so slow.
I first started with dtrace -n 'syscall:::entry /execname=="smbd"/ { @[probefunc] = count(); }'
and browsed around a few directories.

Code:

dtrace: description 'syscall:::entry ' matched 1048 probes

  readlink                                                          1
  statfs                                                            1
  dup2                                                              2
  exit                                                              4
  fork                                                              4
  recvfrom                                                          4
  sigreturn                                                         4
  sysarch                                                           4
  thr_self                                                          4
  umask                                                             4
  thr_new                                                           7
  getpid                                                            8
  pipe                                                              8
  thr_exit                                                          8
  wait4                                                             8
  mmap                                                              9
  getgroups                                                        10
  munmap                                                           10
  sigaction                                                        20
  chdir                                                            38
  sigprocmask                                                      78
  __sysctl                                                        104
  setgroups                                                       104
  setregid                                                        178
  setreuid                                                        178
  getegid                                                         362
  lseek                                                           408
  fstatfs                                                         627
  extattr_list_fd                                                1453
  close                                                          2627
  open                                                           2647
  fstat                                                          3661
  madvise                                                        4080
  getdirentries                                                  5801
  __getcwd                                                       7049
  pread                                                          9724
  write                                                          9732
  __acl_get_file                                                12626
  _umtx_op                                                      19441
  writev                                                        21313
  lstat                                                         27333
  extattr_list_file                                             49988
  geteuid                                                       51808
  poll                                                          52408
  read                                                          62132
  stat                                                          73656
  extattr_get_file                                             110919
  fcntl                                                        211500
[root@C_GRINDER] ~#

It's pretty clear that fcntl is getting called quite a lot.

I have no idea what this means and so I ran: dtrace -n 'syscall:::entry /execname=="smbd"/ {printf("%s %s",execname,copyinstr(arg0)); }'

and my scrollback buffer blew up when I clicked on a single directory (I copied only a small piece of it here)

Code:

dtrace: error on enabled probe ID 859 (ID 52731: syscall:freebsd:fstat:entry): invalid address (0x11e) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x111) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x109) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x109) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x111) in action #2 at DIF offset 12
  2  53049           extattr_get_file:entry smbd ANNOYING DIRECTORY
  2  53049           extattr_get_file:entry smbd ANNOYING DIRECTORY
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x111) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 956 (ID 52537: syscall:freebsd:fcntl:entry): invalid address (0x111) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 1023 (ID 52403: syscall:freebsd:geteuid:entry): invalid address (0xff) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 620 (ID 53209: syscall:freebsd:extattr_list_fd:entry): invalid address (0x11e) in action #2 at DIF offset 12
  2  52729                       stat:entry smbd ANNOYING DIRECTORY
dtrace: error on enabled probe ID 1023 (ID 52403: syscall:freebsd:geteuid:entry): invalid address (0xff) in action #2 at DIF offset 12
  2  53211          extattr_list_file:entry smbd ANNOYING DIRECTORY
  2  52729                       stat:entry smbd ANNOYING DIRECTORY
dtrace: error on enabled probe ID 927 (ID 52595: syscall:freebsd:writev:entry): invalid address (0x123) in action #2 at DIF offset 12
  2  52771                       poll:entry smbd
  2  52771                       poll:entry smbd $
dtrace: error on enabled probe ID 1045 (ID 52359: syscall:freebsd:read:entry): invalid address (0x123) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 1045 (ID 52359: syscall:freebsd:read:entry): invalid address (0x123) in action #2 at DIF offset 12
  2  52363                       open:entry smbd /mnt/Tank/ANNOYING SHARE/.zfs/snapshot
dtrace: error on enabled probe ID 660 (ID 53129: syscall:freebsd:fstatfs:entry): invalid address (0x11f) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 852 (ID 52745: syscall:freebsd:getdirentries:entry): invalid address (0x11f) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 852 (ID 52745: syscall:freebsd:getdirentries:entry): invalid address (0x11f) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 579 (ID 53291: syscall:freebsd:lseek:entry): invalid address (0x11f) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 1042 (ID 52365: syscall:freebsd:close:entry): invalid address (0x11f) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 927 (ID 52595: syscall:freebsd:writev:entry): invalid address (0x123) in action #2 at DIF offset 12
  2  52771                       poll:entry smbd
  2  52771                       poll:entry smbd $
dtrace: error on enabled probe ID 1045 (ID 52359: syscall:freebsd:read:entry): invalid address (0x123) in action #2 at DIF offset 12
dtrace: error on enabled probe ID 1045 (ID 52359: syscall:freebsd:read:entry): invalid address (0x123) in action #2 at DIF offset 12

Did I find something interesting or am I holding dtrace wrong?

Edit: after a bit more reading and thinking I realized I was doing things wrong. :)

 

[dlavigne]

after a bit more reading and thinking I realized I was doing things wrong. :)

Can you post what is right in case another user wishes to try the same thing?

 

[anodos]

Well, my dtrace syntax for the last command wasn't right. What I was really wanting was the output from truss which in the case of my samba browsing (with syntax "truss -D -p [pid of smbd] -o [output file] ) would be as follows for a typical file:

Code:

0.000003749 geteuid()                = 65534 (0xfffe)
0.000016219 extattr_list_file(0x81149d820,0x1,0x81142d560,0x400,0x7fffffffc768,0x0) = 10 (0xa)
0.000018045 stat("ANNOYING DIRECTORY/StupidFile.HatesYourFace",{ mode=-rw-rw-rw- ,inode=299333,size=2367107,blksize=131072 }) = 0 (0x0)
0.014813391 extattr_get_file(0x81149d760,0x1,0x800d330a1,0x0,0x0,0x1) = 56 (0x38)
0.000018577 extattr_get_file(0x81149d760,0x1,0x800d330a1,0x7fffffffc800,0x100,0x1) = 56 (0x38)
0.000007027 fcntl(18,F_SETLKW,0x7fffffffc6b0)    = 0 (0x0)
0.000006133 fcntl(18,F_SETLKW,0x7fffffffc710)    = 0 (0x0)

Which if I parse it correctly involves the following steps:

• Get user ID [geteuid]
• Get a list of attributes present in the requested namespace [extattr_list_file]
• Get information about file [stat]
• Get extended attributes [extattr_get_file]
• Get more extended attributes [extattr_get_file]
• Do something involving a lock in samba4/locking.tdb [fcntl]
• Do something else involving a lock in samba4/locking.tdb [fcntl]

For reference regarding fcntl / locks / freebsd see discussion here: https://lists.samba.org/archive/samba-technical/2013-May/092551.html But the part that takes an annoyingly long time is the first call of "extattr_get_file". My guess is that disabling the "store dos attributes" parameter in smb.conf is stopping this from happening, but I ran out of debugging time today. Note that all of the above steps are performed for every file in the directory you are browsing as well as a few random surrounding ones. Today is an "I hate samba" day. :)

As a side-note, does anyone else here compulsively feel the need to close parentheses?

 

[L]

So how did you syntax finally look? I have been trying to write that script for weeks to just watch the process of smbd:) I think this is really interesting how many fcntl are being called. Might be able to find time spent in fcntl with something like this script

#!/usr/sbin/dtrace -s
/*
* Show time in syscall
*/
#pragma D option quiet
syscall::fcntl:entry
{
self->t1 = timestamp;
}
syscall::fcntl:return
/self->t1/
{
printf("write took %d us\n",(timestamp - self->t1)/1000);
self->t1 = 0;
}


Or get a stack trace at the call..
#!/usr/sbin/dtrace -s
/*
* Drill down into acroread - get a stack trace for each pollsys call
*/
syscall::fcntl:entry
/execname == "smbd" /
{
ustack()
}

These are scripts from solaris, they should work the same

 

[anodos]

So how did you syntax finally look? I have been trying to write that script for weeks to just watch the process of smbd:) I think this is really interesting how many fcntl are being called. Might be able to find time spent in fcntl with something like this script [snip]

Time spent in fcntl wasn't that bad. The performance pig is extattr_get_file. Stack trace on fcntl isn't particularly enlightening. If you look at my truss output, the "18" indicates the file descriptor for the file that fcntl is locking. You can use "fstat | grep 18" to find the inode number of the file. Once you have that you can use find to locate it. In this case, it was "/mnt/Tank/.system/samba4/locking.tdb". If you look at samba's documentation here you will realize that locking.tdb "stores share mode and oplock information".

The more concerning thing is that truss output shows extattr_get_file is called twice per file. Retrieving xattrs on ZFS on FreeBSD is really slow (think a lada full of elephants going uphill slow). I'm not sure why samba needs to call this so frequently (110,000 times for a folder containing a few thousand files!)

 

[BaT]

The more concerning thing is that truss output shows extattr_get_file is called twice per file. Retrieving xattrs on ZFS on FreeBSD is really slow (think a lada full of elephants going uphill slow). I'm not sure why samba needs to call this so frequently (110,000 times for a folder containing a few thousand files!)

This is because that extattr_get_file() API is crap. It does blindly accept any buffer size as a parameter and happily fill it up without any indication in case of overflow. So, if your xattr is 16Kb and you supplied only 8Kb buffer - it'll fill it up to 8Kb and you'll never know that the read was incomplete.
To work around this we have first to call this function with 0 buffer, in which case the function will return desired size for the buffer. After that we can allocate such a buffer and pass it for the second call to extattr_get_file().
Those who designed this API didn't think about implications of it's usage, unfortunately.

 

[anodos]

This is because that extattr_get_file() API is crap. It does blindly accept any buffer size as a parameter and happily fill it up without any indication in case of overflow. So, if your xattr is 16Kb and you supplied only 8Kb buffer - it'll fill it up to 8Kb and you'll never know that the read was incomplete.
To work around this we have first to call this function with 0 buffer, in which case the function will return desired size for the buffer. After that we can allocate such a buffer and pass it for the second call to extattr_get_file().
Those who designed this API didn't think about implications of it's usage, unfortunately.

Thanks for the explanation Timur. It's hilarious that I was doing much the same analysis again today. Honestly, this issue (slow dir listing) has been my #1 Freenas pet peeve since I first started using it. Then again, you committed code related to get_ea_value() in 2005 or something, right? So I guess we've both suffered. ;)