ping time regression?

[jungle-boogie]

Hi,

I have two machines running mylg. One I just updated to test #39 and another built on the 14th of November.

Even though the response time for each ping is around 55ms, the whole ping request took about 30 seconds to complete the whole request:

% /usr/bin/time sudo mylg ping yahoo.com
PING yahoo.com (2001:4998:c:a06::2:4008): 56 data bytes
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=0 time=58.901061 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=1 time=63.529582 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=2 time=59.052757 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=3 time=54.948603 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=4 time=56.835715 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=5 time=56.326712 ms

--- yahoo.com ping statistics ---
6 packets transmitted,  6 packets received, 0% packet loss
round-trip min/avg/max = 54.949/56.758/63.530 ms
       31.74 real         0.44 user         0.03 sys

from the build on the 14th:

% /usr/bin/time sudo mylg ping -c 6 yahoo.com
PING yahoo.com (2001:4998:c:a06::2:4008): 56 data bytes
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=0 time=42.963146 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=1 time=50.286668 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=2 time=42.983244 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=3 time=44.244642 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=4 time=42.963250 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=5 time=42.910109 ms

--- yahoo.com ping statistics ---
6 packets transmitted,  6 packets received, 0% packet loss
round-trip min/avg/max = 42.910/43.327/50.287 ms
        5.86 real         0.48 user         0.00 sys

I'll update the 14th build to the most recent and see what occurs.

[jungle-boogie]

Well it seems to be machine specific as updating to from the 14th to the latest worked fine:

% /usr/bin/time sudo bin/mylg ping -c 6 yahoo.com
PING yahoo.com (2001:4998:c:a06::2:4008): 56 data bytes
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=0 time=45.887550 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=1 time=47.157329 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=2 time=45.181935 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=3 time=49.573529 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=4 time=42.725590 ms
64 bytes from 2001:4998:c:a06::2:4008 icmp_seq=5 time=45.531101 ms

--- yahoo.com ping statistics ---
6 packets transmitted,  6 packets received, 0% packet loss
round-trip min/avg/max = 42.726/45.375/49.574 ms
        5.81 real         0.44 user         0.03 sy

[jungle-boogie]

Any suggestions?

[mehrdadrad]

@jungle-boogie I haven't changed the ping code recently, the last change date is Sep 15. 31 seconds is weird and no idea why as the response time was ~56 ms per each.

[jungle-boogie]

thanks for checking, @mehrdadrad. This is something very specific to my machine but I don't know how to profile go to find the issue. This also happens when running directly as root (without sudo) so it's pretty weird.

[gummiboll]

@jungle-boogie: DNS-resolution issue with that machine?

[jungle-boogie]

@gummiboll,

But would the response time from each packet be so small? ping without mylg also works fine:

% /usr/bin/time ping -c 5 yahoo.com
PING yahoo.com (206.190.36.45): 56 data bytes
64 bytes from 206.190.36.45: icmp_seq=0 ttl=52 time=59.344 ms
64 bytes from 206.190.36.45: icmp_seq=1 ttl=52 time=57.601 ms
64 bytes from 206.190.36.45: icmp_seq=2 ttl=52 time=59.317 ms
64 bytes from 206.190.36.45: icmp_seq=3 ttl=52 time=58.847 ms
64 bytes from 206.190.36.45: icmp_seq=4 ttl=52 time=61.031 ms

--- yahoo.com ping statistics ---
5 packets transmitted, 5 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 57.601/59.228/61.031/1.101 ms
        4.28 real         0.00 user         0.00 sys

traceroute completes well:

% /usr/bin/time sudo ./bin/gopath/bin/mylg trace yahoo.com
trace route to yahoo.com (2001:4998:44:204::a7), 30 hops max
1  2600:8801:2a7f:ffff::1111 [ASN 22773/ASN-CXA-ALL-CCI-22773-RDC] 7.681 ms 11.249 ms 9.045 ms
2  2001:578:604::2:502 [ASN 22773/ASN-CXA-ALL-CCI-22773-RDC] 9.021 ms 8.805 ms 9.156 ms
3  2001:578:602::12 [ASN 22773/ASN-CXA-ALL-CCI-22773-RDC] 9.668 ms 10.361 ms 10.649 ms
4  2001:578:1:0:172:17:249:78 [ASN 22773/ASN-CXA-ALL-CCI-22773-RDC] 37.033 ms 35.276 ms 41.188 ms
5  2001:4998:f005:1ff:: [ASN 10310/YAHOO-1] 30.857 ms 30.468 ms  *
6  ae-4.pat1.dnx.yahoo.com. (2001:4998:f005:2::1) [ASN 10310/YAHOO-1] 62.361 ms 61.574 ms 61.104 ms
7  ae-6.pat2.nez.yahoo.com. (2001:4998:f000:204::) [ASN 10310/YAHOO-1] 74.516 ms 67.970 ms  *
8  2001:4998:f000:210::1 [ASN 10310/YAHOO-1] 65.706 ms 63.447 ms 63.697 ms
9  2001:4998:44:fc1a::1 [ASN 36646/YAHOO-NE1] 82.325 ms 64.846 ms 67.984 ms
10 v6.e17-1.fab1-1-gdc.ne1.yahoo.com. (2001:4998:44:fa00::1) [ASN 36646/YAHOO-NE1] 66.745 ms 68.460 ms 69.528 ms
11 2001:4998:44:da02::1 [ASN 36646/YAHOO-NE1] 67.579 ms 67.966 ms 76.245 ms
12 ir1.fp.vip.ne1.yahoo.com. (2001:4998:44:204::a7) [ASN 36646/YAHOO-NE1] 65.590 ms 65.639 ms 65.468 ms
       17.50 real         0.62 user         0.08 sys

[jungle-boogie]

Also when I don't have root access:

% /usr/bin/time mylg ping yahoo.com
PING yahoo.com (2001:4998:44:204::a7): 56 data bytes
listen ip6:ipv6-icmp : socket: operation not permitted icmp_seq=0
listen ip6:ipv6-icmp : socket: operation not permitted icmp_seq=0
listen ip6:ipv6-icmp : socket: operation not permitted icmp_seq=0
listen ip6:ipv6-icmp : socket: operation not permitted icmp_seq=0

--- yahoo.com ping statistics ---
4 packets transmitted,  0 packets received, 100% packet loss
        3.66 real         0.43 user         0.03 sys

[gummiboll]

@jungle-boogie The individual response times for each ping could still be small if most of the time was spent resolving the hostname. IIRC mylg ping resolves the domain first and then starts to ping the ip-address.

But since it worked without any issue with the "real" ping, that was probably not the problem.