pfiles slow on sockets (v2)

README.md

Illumos pfiles

pfiles(1) is slow when gathering information about sockets.

This patch (https://www.illumos.org/issues/5397) sped it up immensely, but it is still slower than it should be. Looking at the time spent in syscalls when pfiles(1) is run from the patch we can see this:

  pwrite                                                    355720528
  write                                                     842822775
  pread                                                    1979864413
  readlink                                                43978668288

Fixing readlink cut off 43 seconds from a ~46 second run (awesome!) but there is still ~2 seconds spent in pread. Using the same node process from that issue (attached) we can start a node process with 100 open sockets, and then use dtrace to see what is going on with pread. Assume 2 terminals, one to run the node script and the other to run dtrace.

$ node sockets.js 100
opened 100 sockets, pid = 2799
# dtrace -n 'syscall::pread:entry /pid == $target/ { @[fds[arg0].fi_pathname] = count(); }' -c 'pfiles 2799'
  /proc/2799/status                                                 6
  /proc/2799/lwp/agent/lwpstatus                                 5505
  /proc/2799/as                                                 23777

For a node program with 100 open sockets, pfiles calls pread on /proc/<pid>/as 23k times, and /proc/<pid>/lwp/agent/lwpstatus 5k times.

23k / 100 sockets = 230 times a socket (speculation) 5k / 100 sockets = 50 times a socket (same)

Digging in a little deeper, we can see what is triggering the syscall execution

# dtrace -n 'syscall::pread:entry /pid == $target/ { @[fds[arg0].fi_pathname, ustack()] = count(); }' -c 'pfiles 3164'
... last 4 ...

 /proc/3164/as                                     
             libc.so.1`__pread+0xa
             libproc.so.1`Pread_live+0x27
             libproc.so.1`Pread+0x28
             libproc.so.1`Psyscall_copyoutargs+0x16a
             libproc.so.1`Psyscall+0x52a
             libproc.so.1`pr_getsockopt+0x116
             pfiles`show_sockopts+0x79
             pfiles`dosocket+0x63
             pfiles`show_file+0x34a
             libproc.so.1`Pfdinfo_iter+0x6c
             pfiles`show_files+0x4b
             pfiles`main+0x1b6
             pfiles`_start+0x6c
            1300
 /proc/3164/lwp/agent/lwpstatus                    
             libc.so.1`__pread+0xa
             libproc.so.1`Pstopstatus+0x162
             libproc.so.1`Pwait+0x1c
             libproc.so.1`Psyscall+0x415
             libproc.so.1`pr_getsockopt+0x116
             pfiles`show_sockopts+0x79
             pfiles`dosocket+0x63
             pfiles`show_file+0x34a
             libproc.so.1`Pfdinfo_iter+0x6c
             pfiles`show_files+0x4b
             pfiles`main+0x1b6
             pfiles`_start+0x6c
            1300
 /proc/3164/lwp/agent/lwpstatus                    
             libc.so.1`__pread+0xa
             libproc.so.1`Pstopstatus+0x162
             libproc.so.1`Pwait+0x1c
             libproc.so.1`execute+0x11a
             libproc.so.1`Psyscall+0x2f8
             libproc.so.1`pr_getsockopt+0x116
             pfiles`show_sockopts+0x79
             pfiles`dosocket+0x63
             pfiles`show_file+0x34a
             libproc.so.1`Pfdinfo_iter+0x6c
             pfiles`show_files+0x4b
             pfiles`main+0x1b6
             pfiles`_start+0x6c
            1300
 /proc/3164/as                                     
             libc.so.1`__pread+0xa
             libproc.so.1`Pread_live+0x27
             libproc.so.1`Pread+0x28
             libproc.so.1`Psyscall+0x4f4
             libproc.so.1`pr_getsockopt+0x116
             pfiles`show_sockopts+0x79
             pfiles`dosocket+0x63
             pfiles`show_file+0x34a
             libproc.so.1`Pfdinfo_iter+0x6c
             pfiles`show_files+0x4b
             pfiles`main+0x1b6
             pfiles`_start+0x6c
            2600

(side note) Also I patced show_sockopts (the last function called by pfiles.c before entering libproc) to increment a static int every time it was called to verify that it was indeed being called 100 times and not more.

This means, that 100 calls to show_sockopts is resulting in >= 100 calls to pr_getsockopt which is resulting in multiple preads on the same file.

Looking at /proc/<pid>/as for this process with 100 sockets it is about 26M big, which makes sense that pread is being used to avoid reading the whole file into memory.

Update: according to proc(4) this is the address space file, meaning it will be as big as the process RSS, so reading the whole thing into memory is not really an option here.

sockets.js

#!/usr/bin/env node
var net = require('net');
var num = +process.argv[2] || 1000;
for (var i = 0; i < num; i++)
  net.connect(80, 'daveeddy.com');
console.log('opened %d sockets, pid = %d', num, process.pid);