BAM! It looks like the second of our two nameserver entries in the global zone's /etc/resolv.conf is not pingable from this host (probably a routing or firewall issue). Once I removed it, packages started flying.
Looks like this issue is resolved, but I've certainly learned a lot from the exercise. Huge thanks to everyone for the valuable, informative responses! Justin -----Original Message----- From: Brian Utterback [mailto:[EMAIL PROTECTED] Sent: Thursday, May 22, 2008 1:24 PM To: Justin Lloyd Cc: [email protected] Subject: Re: [dtrace-discuss] Slow pkginstalls due to long door_calls to nscd Looking at the code for get_mntinfo, it looks like it is parsing the entries in the vfstab/mnttab and doing a lookup on the host for each entry that has a ":" in it. I think it is rather interesting that the pfiles shows an error indication on port 53. I think you may have a problem with your DNS lookups. Justin Lloyd wrote: > Here's some output from a little dtrace script that prints the stacks of > door_call() calls that take longer than 4 seconds: > > % sudo ./nscd_door.d > pid 17917 call to doorfs(4) took 15 seconds > pid 18029 call to doorfs(4) took 5 seconds > pid 18029 call to doorfs(4) took 15 seconds > pid 18029 call to doorfs(4) took 10 seconds > pid 18029 call to doorfs(4) took 15 seconds > pid 18146 call to doorfs(4) took 5 seconds > pid 18146 call to doorfs(4) took 15 seconds > ^C > > > 0xfeec6104 > 0xfee50070 > 0xfee5ef18 > 0xfee5d9fc > 0xff227da8 > 0xff226a90 > 0xff2241e8 > 0x338cc > 0x293e4 > 0x2a0c4 > 0x2a4b4 > 0x20f08 > 0x184a4 > 1 > > 0xfeec6104 > 0xfee50070 > 0xfee5ef18 > 0xfee5d9fc > 0xff227da8 > 0xff226a90 > 0xff2241e8 > 0x33894 > 0x293e4 > 0x2a0c4 > 0x2a4b4 > 0x20f08 > 0x184a4 > 1 > > 0xfeec6104 > 0xfee50070 > 0xfee5ef18 > 0xfee5d9fc > 0xff227da8 > 0xff226a90 > 0xff2241e8 > 0x338cc > 0x293e4 > 0x2a0c4 > 0x2a4b4 > 0x20f08 > 0x184a4 > 1 > > 0xfeec6104 > 0xfee50070 > 0xfee5ef18 > 0xfee5d9fc > 0xff227e78 > 0xff226ae8 > 0xff224118 > 0x33894 > 0x293e4 > 0x2a0c4 > 0x2a4b4 > 0x20f08 > 0x184a4 > 1 > > 0xfeec6104 > 0xfee50070 > 0xfee5ef18 > 0xfee5d9fc > 0xff227e78 > 0xff226ae8 > 0xff224118 > 0x338cc > 0x293e4 > 0x2a0c4 > 0x2a4b4 > 0x20f08 > 0x184a4 > 1 > > libc.so.1`_door_call+0x8 > libc.so.1`_nsc_trydoorcall_ext+0x1b8 > libc.so.1`_nsc_search+0xc0 > libc.so.1`nss_search+0x34 > libnsl.so.1`_switch_gethostbyname_r+0x58 > libnsl.so.1`_get_hostserv_inetnetdir_byname+0x844 > libnsl.so.1`getipnodebyname+0x1c4 > pkginstall`is_local_host+0x10 > pkginstall`0x293e4 > pkginstall`0x2a0c4 > pkginstall`get_mntinfo+0x80 > pkginstall`main+0x97c > pkginstall`_start+0x108 > 1 > > libc.so.1`_door_call+0x8 > libc.so.1`_nsc_trydoorcall_ext+0x1b8 > libc.so.1`_nsc_search+0xc0 > libc.so.1`nss_search+0x34 > libnsl.so.1`_switch_getipnodebyname_r+0x60 > libnsl.so.1`_get_hostserv_inetnetdir_byname+0x89c > libnsl.so.1`getipnodebyname+0xf4 > pkginstall`is_local_host+0x10 > pkginstall`0x293e4 > pkginstall`0x2a0c4 > pkginstall`get_mntinfo+0x80 > pkginstall`main+0x97c > pkginstall`_start+0x108 > 1 > [EMAIL PROTECTED]:~] > > -----Original Message----- > From: [EMAIL PROTECTED] > [mailto:[EMAIL PROTECTED] On Behalf Of Justin > Lloyd > Sent: Thursday, May 22, 2008 11:14 AM > To: Brian Utterback > Cc: [email protected] > Subject: Re: [dtrace-discuss] Slow pkginstalls due to long door_calls to > nscd > > Both lines are "files dns". > > I'll look into the nscd process, but first I'm doing some dtrace > analysis of the long ustacks to see which ones are taking a long time, > just to make sure the mdb stack I provided wasn't an outlier. > > Justin > > -----Original Message----- > From: Brian Utterback [mailto:[EMAIL PROTECTED] > Sent: Thursday, May 22, 2008 10:29 AM > To: Justin Lloyd > Cc: [email protected] > Subject: Re: [dtrace-discuss] Slow pkginstalls due to long door_calls to > nscd > > Okay, what does the host and ipnodes lines of your nsswitch.conf file > look like? You can also try the same pstack trick on the nscd process > to see where it is spending its time. > > Justin Lloyd wrote: >> This is strange: >> >> bash-3.00# pstop `pgrep pkginstall` >> bash-3.00# pstack `pgrep pkginstall` >> 24319: pkginstall -S -C -N pkgadd -R /zones/daf98/root -a >> /etc/lu/zones_pkgad >> feec6104 door (4, ffbfcef0, 6400, fe9e0000, 0, 3) >> bash-3.00# >> >> Based on the number of args, this appears to be a call to doorfs() > with >> a subcode of 3 (DOOR_CALL), leading to a tail call of door_call(4, >> ffbfcef0). However, it occurred to me to try mdb (with which I'm >> admittedly not an expert): >> >> bash-3.00# mdb -p `pgrep pkginstall` >> Loading modules: [ ld.so.1 libc.so.1 libnvpair.so.1 libavl.so.1 >> libuutil.so.1 libsysevent.so.1 libproc.so.1 ] >>> ::stack >> libc.so.1`_door_call+0xc(feef1668, ffbfd064, ffbfd060, ffbfd05c, >> ffbfcf74, fe9e0000) >> libc.so.1`_nsc_trydoorcall_ext+0x1b8(ffbfd064, ffbfd060, ffbfd05c, 0, > 0, >> deadbeed) >> libc.so.1`_nsc_search+0xc0(ff2a6848, ff223c14, 4, ffbfd138, fe9e0000, >> 7b1c8) >> libc.so.1`nss_search+0x34(ff2a6848, ff223c14, 4, ffbfd138, 1, 0) >> libnsl.so.1`_switch_getipnodebyname_r+0x60(ffbfd350, 78388, 7839c, > 2120, >> 2, 5) >> libnsl.so.1`_get_hostserv_inetnetdir_byname+0x89c(6, ffbfd270, > ffbfd268, >> 0, ffbfd204, ffbfd274) >> libnsl.so.1`getipnodebyname+0xf4(ffbfd350, 2, 5, ffbfd2ec, 1a, 2120) >> is_local_host+0x10(ffbfd350, 7014c, 5, 0, 63766673, 64617067) >> 0x293e4(763e8, 73, ffbfd354, 12, 1, 9) >> 0x2a0c4(ffbfe02c, ffbfe02c, 4f400, 4f400, 0, 77570) >> get_mntinfo+0x80(1, 0, 4f400, 0, ffbfe02c, 729e0) >> main+0x97c(19, ffbff76c, 73c00, ffbffa3f, 0, 0) >> _start+0x108(0, 0, 0, 0, 0, 0) >>> _door_call::dis >> libc.so.1`_door_call: mov 3, %o5 >> libc.so.1`_door_call+4: mov 0xc9, %g1 >> libc.so.1`_door_call+8: ta 8 >> libc.so.1`_door_call+0xc: blu -0xa2ca8 >> <libc.so.1`_cerror> >> libc.so.1`_door_call+0x10: nop >> libc.so.1`_door_call+0x14: retl >> libc.so.1`_door_call+0x18: nop >> >> The call in pkginstall to is_local_host() seems to be what is sparking >> the lookup. The beginning of my /etc/hosts has the following >> >> ::1 localhost >> 127.0.0.1 localhost loghost >> >> Is something wrong with that? >> >> Justin >> >> >> -----Original Message----- >> From: Brian Utterback [mailto:[EMAIL PROTECTED] >> Sent: Thursday, May 22, 2008 7:45 AM >> To: Justin Lloyd >> Cc: [email protected] >> Subject: Re: [dtrace-discuss] Slow pkginstalls due to long door_calls > to >> nscd >> >> Well, the simple way to find out is to stop it and look. Or even to >> not stop it. >> >> Since it is spending enough time in the door call for you to catch it >> with a truss, instead of running truss, try running pstack on the same > >> processes. I bet it will be immediately obvious what is being looked > >> up by the stack. >> >> Justin Lloyd wrote: >>> Hi all, >>> >>> I am installing a zone onto two different V445s running S10U4 and the > >>> zones are taking hours to install (about 1000 packages), that is, the > >>> problem is identical on both systems. A bit of trussing and dtracing >> has >>> shown that the pkginstalls being run by the zoneadm install are > making >>> door_call calls to nscd that are taking very long, so far observed to >> be >>> 5 to 40 seconds, but always in times divisible by 5 seconds (5, 10, >> 15, >>> etc.), leading to the thought that it is one or more name service >>> timeouts. Eventually, once the door_calls finish, the actual package >>> install is very quick. >>> >>> There may be a simple misconfiguration on both systems, but I can't >>> figure out what that might be. Additionally, I don't know why the >>> pkginstalls are making door_calls to begin with, and I'm not sure how >> to >>> figure that out. So that's one my main question: >>> >>> *** How can I find out exactly what the pkginstalls are asking > nscd >>> to resolve? *** >>> >>> Hopefully that will lead me (and the Sun engineer with whom I have a >>> case open) to an understanding of what is leading to the presumed >> timeouts. >>> FWIW, here's a partial truss with timestamps of an existing > pkginstall >>> process. Once it hit the ioctl(3,...) it flew through the package >>> installation. Note the times around the door_calls: 13, 10 and 15 >>> seconds (the first isn't a multiple of 5 since I started the truss >>> during the call). >>> >>> Base time stamp: ***** 1210181159*.9172 [ Wed May 7 17:25:59 GMT >> 2008 ] >>> door_call(4, 0xFFBFD030) (sleeping...) >>> >>> *****1210472*.1302 door_call(4, 0xFFBFD030) >> = 0 >>> 1210472.1306 open("/dev/udp6", O_RDONLY) = 5 >>> >>> 1210472.1310 ioctl(5, SIOCGLIFNUM, 0xFFBFD2DC) = 0 >>> >>> 1210472.1312 close(5) = 0 >>> >>> 1210472.1312 getuid() = 0 >> [0] >>> 1210472.1313 getuid() = 0 >> [0] >>> *****1210472*.1314 door_info(4, 0xFFBFCF88) >> = 0 >>> door_call(4, 0xFFBFD030) (sleeping...) >>> >>> *****1210482*.1503 door_call(4, 0xFFBFD030) >> = 0 >>> 1210482.1505 getuid() = 0 >> [0] >>> 1210482.1505 getuid() = 0 >> [0] >>> *****1210482*.1506 door_info(4, 0xFFBFCF88) >> = 0 >>> door_call(4, 0xFFBFD030) (sleeping...) >>> >>> *****1210497*.1802 door_call(4, 0xFFBFD030) >> = 0 >>> 1210497.1804 ioctl(3, (('m'<<8)|7), 0xFFBFD8EC) = 0 >>> >>> Thanks, >>> Justin >>> >>> >>> > ------------------------------------------------------------------------ >>> _______________________________________________ >>> dtrace-discuss mailing list >>> [email protected] > -- blu There are two rules in life: Rule 1- Don't tell people everything you know ---------------------------------------------------------------------- Brian Utterback - Solaris RPE, Sun Microsystems, Inc. Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom _______________________________________________ dtrace-discuss mailing list [email protected]
