Tags: Debug, Network, Performance
I recently faced an interesting problem when the backup agent for HP DataProtector regularly encounter network performance problem. The problem arise on a global zone which hosts many non-global zones, each running its own instance of the HP DP agent. The network configuration is rather unusual: there are two network ports, one which connects to an administration VLAN, the other which carries the data and external customer network streams (using VLAN-tagging). Since the global zone is only use as an hypervisor of system's resources for the non-global zones, it just plumbs the data network port, but has no IP address assigned to it.
The fact is, the configuration sets the nodename as the hostname. But
the usable interface of the global zone which is in the administration
network use another name than the hostname: beastie-adm in the
following case, assuming the hostname was set to beastie.
So, now that I briefly describe the configuration of the server, lets see what happen at the network level from the global zone point of view when firing a remote telnet on the DataProtector agent TCP port (5555):
# snoop -d aggr2 -t d port 5555
Using device /dev/aggr2 (promiscuous mode)
0.00000 172.1.2.3 -> beastie-adm.domain.tld TCP D=5555 S=37228 Syn Seq=1117789660 Len=0 Win=65535 Options=
0.00005 beastie-adm.domain.tld -> 172.1.2.3 TCP D=37228 S=5555 Syn Ack=1117789661 Seq=808681264 Len=0 Win=49480 Options=
0.00500 172.1.2.3 -> beastie-adm.domain.tld TCP D=5555 S=37228 Ack=808681265 Seq=1117789661 Len=0 Win=65535
39.36365 beastie-adm.domain.tld ->172.1.2.3 TCP D=37228 S=5555 Push Ack=1117789661 Seq=808681265 Len=87 Win=49480
0.00014 beastie-adm.domain.tld -> 172.1.2.3 TCP D=37228 S=5555 Fin Ack=1117789661 Seq=808681352 Len=0 Win=49480
0.00587 172.1.2.3 -> beastie-adm.domain.tld TCP D=5555 S=37228 Ack=808681353 Seq=1117789661 Len=0 Win=65448
0.00092 172.1.2.3 -> beastie-adm.domain.tld TCP D=5555 S=37228 Fin Ack=808681353 Seq=1117789661 Len=0 Win=65448
0.00002 beastie-adm.domain.tld -> 172.1.2.3 TCP D=37228 S=5555 Ack=1117789662 Seq=808681353 Len=0 Win=49480
Ouch. Something is clearly wrong here: as can be seen in this trace, 40 seconds have been lost before establishing the connection. Snooping more largely on the interface show these requests:
[...]
beastie-adm.domain.tld -> nameserver.domain.tld DNS C beastie.domain.tld. Internet Addr ?
nameserver.domain.tld -> beastie-adm.domain.tld DNS R Error: 3(Name Error)
beastie-adm.domain.tld -> nameserver.domain.tld DNS C beastie. Internet Addr ?
nameserver.domain.tld -> beastie-adm.domain.tld DNS R Error: 2(Server Fail)
beastie-adm.domain.tld -> nameserver.domain.tld DNS C beastie. Internet Addr ?
nameserver.domain.tld -> beastie-adm.domain.tld DNS R Error: 2(Server Fail)
beastie-adm.domain.tld -> nameserver.domain.tld DNS C beastie.domain.tld. Internet Addr ?
nameserver.domain.tld -> beastie-adm.domain.tld DNS R Error: 3(Name Error)
beastie-adm.domain.tld -> nameserver.domain.tld DNS C beastie. Internet Addr ?
nameserver.domain.tld -> beastie-adm.domain.tld DNS R Error: 2(Server Fail)
[...]
Ok. Lets see what is the process corresponding to the HP DP agent doing during the connection tentative:
[...]
9431/1: sysinfo(SI_HOSTNAME, "beastie", 64) = 12
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getuid() = 0 [0]
9431/1: getuid() = 0 [0]
9431/1: door_info(3, 0x08047900) = 0
9431/1: door_call(3, 0x08047958) = 0
9431/1: getpid() = 9431 [473]
9431/1: lstat64("/var/opt/omni/log/debug.log", 0x080476F8) = 0
9431/1: open64("/var/opt/omni/log/debug.log", O_RDWR|O_APPEND|O_CREAT, 0666) = 4
9431/1: time() = 1269079436
9431/1: fstat64(4, 0x08046F30) = 0
9431/1: fstat64(4, 0x08046E70) = 0
9431/1: ioctl(4, TCGETA, 0x08046F04) Err#25 ENOTTY
9431/1: sigaction(SIGSEGV, 0x08047AF0, 0x08047B70) = 0
9431/1: sigaction(SIGSEGV, 0x08047AF0, 0x08047B70) = 0
9431/1: write(4, 0x08130DC4, 162) = 162
9431/1:
0 3 / 2 0 / 1 0 1 1 : 0 3 : 5 6 I N E T . 9 4 3 1 . 0
9431/1: [ " l i b / c m n / c o m m o n . c / m a i n / h s l _ d p 6
9431/1: 1 / h s l _ h p i t 2 _ 2 / 9 " : 1 2 7 4 ] A . 0 6 . 1 1 b
9431/1: 2 4 3
g e t h o s t b y n a m e ( ) f a i l e d , h _ e r
9431/1: r n o = 2 [ h o s t = h o s t n a m e , r e t r y = 5
9431/1: ]
9431/1: llseek(4, 0, SEEK_CUR) = 939002
9431/1: close(4)
[...]
By now it is clear that most of time spent by the agent was used trying
to resolve the hostname to an IP address (as logged to the
/var/opt/omni/log/debug.log debug log file). Since there is no IP
address declared for beastie as there is no network directly attached
to the global zone, there is no mapping defined for the hostname. Bingo.
So, in this case we decided to set the hostname locally (in the
/etc/hosts file) as an alias for the loopback entry. This way, the
information is resolved, and the agent will not timed-out performing the
gethostbyname(3NSL) syscall anyomore:
# getent hosts `beastie`
127.0.0.1 localhost loghost beastie
# snoop -d aggr2 -t d port 5555
Using device /dev/aggr2 (promiscuous mode)
0.00000 172.1.2.3 -> beastie-adm.occ.lan TCP D=5555 S=37237 Syn Seq=978964828 Len=0 Win=65535 Options=
0.00004 beastie-adm.occ.lan -> 172.1.2.3 TCP D=37237 S=5555 Syn Ack=978964829 Seq=1184861168 Len=0 Win=49480 Options=
0.00128 172.1.2.3 -> beastie-adm.occ.lan TCP D=5555 S=37237 Ack=1184861169 Seq=978964829 Len=0 Win=65535
10.00279 beastie-adm.occ.lan ->172.1.2.3 TCP D=37237 S=5555 Push Ack=978964829 Seq=1184861169 Len=87 Win=49480
0.00012 beastie-adm.occ.lan -> 172.1.2.3 TCP D=37237 S=5555 Fin Ack=978964829 Seq=1184861256 Len=0 Win=49480
0.00137 172.1.2.3 -> beastie-adm.occ.lan TCP D=5555 S=37237 Ack=1184861257 Seq=978964829 Len=0 Win=65448
0.00220 172.1.2.3 -> beastie-adm.occ.lan TCP D=5555 S=37237 Fin Ack=1184861257 Seq=978964829 Len=0 Win=65448
0.00002 beastie-adm.occ.lan -> 172.1.2.3 TCP D=37237 S=5555 Ack=978964830 Seq=1184861257 Len=0 Win=49480
So, the main question which remain is "Why need the HP DP agent to resolve specifically on the hostname, even if this name is not use apart the backup transaction?" I did not have any answer for this at this time...