Date: Tue, 14 Jun 2016 01:28:27 +0200 From: Mateusz Guzik <mjguzik@gmail.com> To: freebsd-pkg@freebsd.org Subject: pkg vs namecache Message-ID: <20160613232827.GA6841@dft-labs.eu>
next in thread | raw e-mail | index | archive | help
Hello,
it is not a secret that poudriere builds expose a lot of contention in
the kernel.
I performed several tests few months back. On a 24-way machine, once all
distfiles are downloaded, the top contending lock belongs to the
namecache. The namecache is unfortunately protected with one big lock
taken in shared or exclusive mode. I have a WIP patch which introduces
fine grained locking and in effect pushes it way down. It is unlikely to
hit 11.0, but 11.1 is an option.
Regardless, if performance is a concern, userspace should not do
unnecessary stuff (which in this case means hammering the namecache for
no reason).
Playing around with dtrace e.g. like this:
dtrace -n 'vfs:namecache:: { @[execname] = count(); } tick-30s {
exit(0); }'
shows that pkg-static is amongst top namecache users and further
inspection suggests that several (if not most) lookups are unnecessary.
For any path-based operation, each component needs to be looked up.
Lookups of non-cached files add entries, which blocks other consumers.
Note that the startup procedure for dynamically linked binaries is
wasteful to an extent and it may beget fixed later.
With this out of the way, let's have a look what pkg 1.8.4_1 does when
prompted to install rexima-1.4. I only left entries I consider
suspicious + enough context to see what's up.
Would be nice if this stuff got fixed. Thaks.
63984: __getcwd("/root",1024) = 0 (0x0)
Why?
63984: open("/etc/pkg/",O_NONBLOCK|O_DIRECTORY|O_CLOEXEC,041673240) = 4 (0x4)
63984: fstatfs(4,{ fstypename=zfs,mntonname=/,mntfromname=zrootmjg,fsid=a294c20dde42cb7d }) = 0 (0x0)
63984: getdirentries(0x4,0x80305f000,0x1000,0x80305c268) = 72 (0x48)
63984: getdirentries(0x4,0x80305f000,0x1000,0x80305c268) = 0 (0x0)
63984: close(4) = 0 (0x0)
63984: __getcwd("/root",1024) = 0 (0x0)
Another __getcwd. If the first one was really needed (was it?), the
result should be remembered. This particular run got 7 getcwds in total,
bigger packages take more.
63984: lstat("/etc",{ mode=drwxr-xr-x ,inode=17,size=113,blksize=7680 }) = 0 (0x0)
63984: lstat("/etc/pkg",{ mode=drwxr-xr-x ,inode=36,size=4,blksize=4096 }) = 0 (0x0)
63984: lstat("/etc/pkg/FreeBSD.conf",{ mode=-rw-r--r-- ,inode=321637,size=436,blksize=4096 }) = 0 (0x0)
63984: stat("/etc/pkg/FreeBSD.conf",{ mode=-rw-r--r-- ,inode=321637,size=436,blksize=4096 }) = 0 (0x0)
63984: openat(AT_FDCWD,"/etc/pkg/FreeBSD.conf",O_RDONLY,00) = 4 (0x4)
Why not just open the file. If some kind of includes are supported, you
can do the last stat and then compare inode + device id pairs.
63984: munmap(0x80064f000,436) = 0 (0x0)
63984: open("/usr/local/etc/pkg/repos/",O_NONBLOCK|O_DIRECTORY|O_CLOEXEC,041673240) ERR#2 'No such file or directory'
63984: stat("/var/db/pkg",{ mode=drwxr-xr-x ,inode=78,size=5,blksize=4096 }) = 0 (0x0)
63984: eaccess("/var/db/pkg",R_OK|W_OK) = 0 (0x0)
63984: stat("/var/db/pkg/local.sqlite",{ mode=-rw-r--r-- ,inode=4755,size=11584512,blksize=131072 }) = 0 (0x0)
63984: eaccess("/var/db/pkg/local.sqlite",R_OK|W_OK) = 0 (0x0)
63984: stat("/var/db/pkg/repo-FreeBSD.sqlite",{ mode=-rw-r--r-- ,inode=323679,size=46235648,blksize=131072 }) = 0 (0x0)
63984: eaccess("/var/db/pkg/repo-FreeBSD.sqlite",R_OK|W_OK) = 0 (0x0)
63984: stat("/var/db/pkg",{ mode=drwxr-xr-x ,inode=78,size=5,blksize=4096 }) = 0 (0x0)
63984: eaccess("/var/db/pkg",R_OK|W_OK) = 0 (0x0)
63984: stat("/var/db/pkg/repo-FreeBSD.sqlite",{ mode=-rw-r--r-- ,inode=323679,size=46235648,blksize=131072 }) = 0 (0x0)
63984: eaccess("/var/db/pkg/repo-FreeBSD.sqlite",R_OK|W_OK) = 0 (0x0)
63984: write(1,"Updating FreeBSD repository cata"...,41) = 41 (0x29)
63984: statfs("/var/db/pkg",{ fstypename=zfs,mntonname=/,mntfromname=zrootmjg,fsid=a294c20dde42cb7d }) = 0 (0x0)
63984: access("/var/db/pkg/FreeBSD.meta",R_OK) = 0 (0x0)
63984: __getcwd("/root",1024) = 0 (0x0)
63984: lstat("/var",{ mode=drwxr-xr-x ,inode=58,size=25,blksize=4096 }) = 0 (0x0)
63984: lstat("/var/db",{ mode=drwxr-xr-x ,inode=72,size=22,blksize=4096 }) = 0 (0x0)
63984: lstat("/var/db/pkg",{ mode=drwxr-xr-x ,inode=78,size=5,blksize=4096 }) = 0 (0x0)
63984: lstat("/var/db/pkg/FreeBSD.meta",{ mode=-rw-r--r-- ,inode=323678,size=246,blksize=4096 }) = 0 (0x0)
63984: stat("/var/db/pkg/FreeBSD.meta",{ mode=-rw-r--r-- ,inode=323678,size=246,blksize=4096 }) = 0 (0x0)
63984: openat(AT_FDCWD,"/var/db/pkg/FreeBSD.meta",O_RDONLY,00) = 4 (0x4)
Again, several passes over /var/db/pkg.
63984: stat("/etc/nsswitch.conf",{ mode=-rw-r--r-- ,inode=14316,size=255,blksize=4096 }) = 0 (0x0)
63984: open("/etc/nsswitch.conf",O_CLOEXEC,0666) = 7 (0x7)
63984: ioctl(7,TIOCGETA,0xffff90f0) ERR#25 'Inappropriate ioctl for device'
63984: fstat(7,{ mode=-rw-r--r-- ,inode=14316,size=255,blksize=4096 }) = 0 (0x0)
63984: read(7,"#\n# nsswitch.conf(5) - name ser"...,4096) = 255 (0xff)
63984: read(7,0x80305f000,4096) = 0 (0x0)
63984: access("/usr/local/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/compat/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/gcc5/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/perl5/5.20/mach/CORE/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm36/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm37/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/casper/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_compat.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/compat/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/gcc5/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/perl5/5.20/mach/CORE/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm36/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm37/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/casper/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_nis.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/compat/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/gcc5/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/perl5/5.20/mach/CORE/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm36/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm37/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/casper/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_files.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/compat/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/gcc5/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/lib/perl5/5.20/mach/CORE/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm36/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/local/llvm37/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/casper/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
63984: access("/usr/lib/nss_dns.so.1",F_OK) ERR#2 'No such file or directory'
Now that's a bummer, but likely not a pkg issue.
63984: mkdir("/tmp",0777) ERR#17 'File exists'
Why?
63984: getpid() = 63984 (0xf9f0)
63984: stat("/tmp",{ mode=drwxrwxrwt ,inode=4,size=76,blksize=16384 }) = 0 (0x0)
63984: open("/tmp/packagesite.yaml.txz.DlhH4v",O_RDWR|O_CREAT|O_EXCL,0600) = 5 (0x5)
63984: unlink("/tmp/packagesite.yaml.txz.DlhH4v") = 0 (0x0)
63984: unlink("") ERR#2 'No such file or directory'
?
3984: stat("/etc/nsswitch.conf",{ mode=-rw-r--r--
,inode=14316,size=255,blksize=4096 }) = 0 (0x0)
63984: geteuid() = 0 (0x0)
63984: open("/etc/spwd.db",O_CLOEXEC,00) = 12 (0xc)
63984: fstat(12,{ mode=-rw------- ,inode=319614,size=40960,blksize=40960
}) = 0 (0x0)
63984: read(12,"\0\^F\^Ua\0\0\0\^B\0\0\^D\M-R\0"...,260) = 260 (0x104)
63984: pread(0xc,0x803064000,0x1000,0x6000) = 4096 (0x1000)
63984: pread(0xc,0x803063000,0x1000,0x4000) = 4096 (0x1000)
63984: close(12) = 0 (0x0)
63984: stat("/etc/nsswitch.conf",{ mode=-rw-r--r--
,inode=14316,size=255,blksize=4096 }) = 0 (0x0)
63984: open("/etc/group",O_CLOEXEC,0666) = 12 (0xc)
63984: fstat(12,{ mode=-rw-r--r-- ,inode=319611,size=500,blksize=4096 })
= 0 (0x0)
63984: lseek(12,0x0,SEEK_CUR) = 0 (0x0)
63984: lseek(12,0x0,SEEK_SET) = 0 (0x0)
63984: read(12,"# $FreeBSD$\n#\nwheel:*:0:root\n"...,4096) = 500 (0x1f4)
63984: close(12) = 0 (0x0)
This repeats itself a lot. I wonder if that's an iffeciency in libc or
pkg.
63984: ioctl(1,TIOCGETA,0xffffced0) = 0 (0x0)
63984: write(1,"[1/1] Extracting rexima-1.4: 0"...,33) = 33 (0x21)
63984: mkdirat(11,"usr",0755) ERR#17 'File exists'
63984: mkdirat(11,"usr/local",0755) ERR#17 'File exists'
63984: mkdirat(11,"usr/local/bin",0755) ERR#17 'File exists'
63984: openat(11,"usr/local/bin/rexima.DcozrktiDx8Y",O_WRONLY|O_CREAT|O_EXCL,0755) = 12 (0xc)
63984: fstat(12,{ mode=-rwxr-xr-x ,inode=4182,size=0,blksize=131072 }) = 0 (0x0)
why fstat?
In the common case you can expect these directories to already be there.
So how about instead you try the open first and only if it fails you try
to create the tree. But you start trying from the top (here: "bin").
63984:
fstatat(11,"usr/local/bin/rexima",0x7fffffffd5f0,AT_SYMLINK_NOFOLLOW)
ERR#2 'No such file or directory'
63984:
renameat(11,"usr/local/bin/rexima.DcozrktiDx8Y",11,"usr/local/bin/rexima")
= 0 (0x0)
Why not just replace?
--
Mateusz Guzik <mjguzik gmail.com>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20160613232827.GA6841>