From owner-freebsd-pkg@freebsd.org Mon Jun 13 23:28:32 2016 Return-Path: Delivered-To: freebsd-pkg@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 966F8AF0C88 for ; Mon, 13 Jun 2016 23:28:32 +0000 (UTC) (envelope-from mjguzik@gmail.com) Received: from mail-wm0-x242.google.com (mail-wm0-x242.google.com [IPv6:2a00:1450:400c:c09::242]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 22E212BEE for ; Mon, 13 Jun 2016 23:28:32 +0000 (UTC) (envelope-from mjguzik@gmail.com) Received: by mail-wm0-x242.google.com with SMTP id n184so18353010wmn.1 for ; Mon, 13 Jun 2016 16:28:32 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=date:from:to:subject:message-id:mime-version:content-disposition :user-agent; bh=ymN0gdjveUeNciZal9C238i64BzAVmhbidoHyTN4O8o=; b=lpeLNktZIDBC7sgMqGbpQLo+SCmLqcO5PsBqJHPynSPz5MszRiz5lZUfwZVQ+uUZYa VLd3RMeGchSu6iA6t+cE/NUMVU1MFhsB14Qn+moHBYz+wPYKcf9lFA6WcrzShPRycO86 DTzpYQSuuJZrWv0ol5d3nSqwiJyC+vbKzqIkw5V9D9r9uW7LWLNMx69jhLCPZ9WvdMRw CRJ0OI4Tp84q5SR5Tbjw+vhzqOZJ+0jD3A4D/p2GwHDkUs5wbKw9hLgt8QI59D04zk6t FBcsoHOA3OtWgP7X40x4H841Qb5y+hL9A1G3QF9OZLqmtvok9hxohQEWjzVmxxjKUl92 nxfw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:date:from:to:subject:message-id:mime-version :content-disposition:user-agent; bh=ymN0gdjveUeNciZal9C238i64BzAVmhbidoHyTN4O8o=; b=S1bCuA1zc+A2TE3UbI2xRd+ZBxAXEFrYCkzzyfXP9TgwynXpZbBT5iqqA/8l4DTf+k XuF4kQMOL0nZ3ECTvW5qhkFgqHp+e+N4yqDdxAuSKO1Z0+XW11MdAhwrKleSV5Pv+QTE hWIthUPQW2ad9Ug4nYG3BO9dykQErQayJiPiuP5ZyV+D0wuif9E71ltzo3JytL5qRpXM 07u60hQ4dFLU2Axm+sroiVqBA8uB/Hie+xogvXQY0RvKsFG+C51Nmv9Ks5MS0IF5Q//+ rBknUq+aFeK8Lo6K6dihFi99roNZ7+lIf68ZGa6Otcaihwx1ypG8ZRhQyYfVlkOjWz9x Gq3Q== X-Gm-Message-State: ALyK8tJM7fez8QwCWWkke5+21nP0YA76zoa9hmfxnjg0N0FXoEnpFaBuR6cfUjjL3/eHOg== X-Received: by 10.194.109.232 with SMTP id hv8mr3177065wjb.115.1465860510129; Mon, 13 Jun 2016 16:28:30 -0700 (PDT) Received: from dft-labs.eu (n1x0n-1-pt.tunnel.tserv5.lon1.ipv6.he.net. [2001:470:1f08:1f7::2]) by smtp.gmail.com with ESMTPSA id kp9sm29805421wjb.28.2016.06.13.16.28.29 for (version=TLS1_2 cipher=AES128-SHA bits=128/128); Mon, 13 Jun 2016 16:28:29 -0700 (PDT) Date: Tue, 14 Jun 2016 01:28:27 +0200 From: Mateusz Guzik To: freebsd-pkg@freebsd.org Subject: pkg vs namecache Message-ID: <20160613232827.GA6841@dft-labs.eu> MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Disposition: inline User-Agent: Mutt/1.5.21 (2010-09-15) X-BeenThere: freebsd-pkg@freebsd.org X-Mailman-Version: 2.1.22 Precedence: list List-Id: Binary package management and package tools discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 13 Jun 2016 23:28:32 -0000 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