Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
Hello Bert, Any ideas why it takes so long? Rerun with --trace enabled and check what is happening. With some study, it should be clear what it is waiting for. did that already before, but still did not found anything helpful there. Below is a new trace. btw, I am using 3.5.1 (package pdns-recursor-3.5.1-1.el6.x86_64). Thanks, Shamus - /etc/init.d/pdns-recursor start Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS recursor 3.5.1 (C) 2001-2013 PowerDNS.COM BV (May 3 2013, 20:04:33, gcc 4.4.7 20120313 (Red Hat 4.4.7-3)) starting up Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to redistribute it according to the terms of the GPL version 2. Jun 23 12:30:12 server pdns_recursor[11064]: Operating in 64 bits mode Jun 23 12:30:12 server pdns_recursor[11064]: Reading random entropy from '/dev/urandom' Jun 23 12:30:12 server pdns_recursor[11064]: Only allowing queries from: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10 Jun 23 12:30:12 server pdns_recursor[11064]: Will not send queries to: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10, 0.0.0.0, :: Jun 23 12:30:12 server pdns_recursor[11064]: NOT using IPv6 for outgoing queries - set 'query-local-address6=::' to enable Jun 23 12:30:12 server pdns_recursor[11064]: Redirecting queries for zone '.' to: 8.8.8.8:53 Jun 23 12:30:12 server pdns_recursor[11064]: Inserting rfc 1918 private space zones Jun 23 12:30:12 server pdns_recursor[11064]: Not decreasing socket buffer size from 229376 to 20 Jun 23 12:30:12 server pdns_recursor[11064]: Listening for UDP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Enabled TCP data-ready filter for (slight) DoS protection Jun 23 12:30:12 server pdns_recursor[11064]: Listening for TCP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Calling daemonize, going to background Jun 23 12:30:12 server pdns_recursor[11065]: Set effective group id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Set effective user id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Launching 2 threads Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Enabled 'epoll' multiplexer Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking '.|NS' Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking '.|NS' Jun 23 12:30:12 server pdns_recursor[11065]: .: Got 13 answers from -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 6ms Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|d.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|l.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|c.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|g.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|h.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|b.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: Got 13 answers from -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 6ms Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|d.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|l.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .:
Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
What about giving the full dig output too? My bet is you're actually experiencing some sort of huge delay starting up dig or resolving localhost, use @127.0.0.1 instead and see if the time goes away. Does your /etc/hosts contain 'localhost'? Have you modified your nsswitch.conf? (Assuming standard *nix like system) On Sun, Jun 23, 2013 at 3:58 AM, Shamus Smith smithsha...@yahoo.de wrote: Hello Bert, Any ideas why it takes so long? Rerun with --trace enabled and check what is happening. With some study, it should be clear what it is waiting for. did that already before, but still did not found anything helpful there. Below is a new trace. btw, I am using 3.5.1 (package pdns-recursor-3.5.1-1.el6.x86_64). Thanks, Shamus - /etc/init.d/pdns-recursor start Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS recursor 3.5.1 (C) 2001-2013 PowerDNS.COM BV (May 3 2013, 20:04:33, gcc 4.4.7 20120313 (Red Hat 4.4.7-3)) starting up Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to redistribute it according to the terms of the GPL version 2. Jun 23 12:30:12 server pdns_recursor[11064]: Operating in 64 bits mode Jun 23 12:30:12 server pdns_recursor[11064]: Reading random entropy from '/dev/urandom' Jun 23 12:30:12 server pdns_recursor[11064]: Only allowing queries from: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10 Jun 23 12:30:12 server pdns_recursor[11064]: Will not send queries to: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10, 0.0.0.0, :: Jun 23 12:30:12 server pdns_recursor[11064]: NOT using IPv6 for outgoing queries - set 'query-local-address6=::' to enable Jun 23 12:30:12 server pdns_recursor[11064]: Redirecting queries for zone '.' to: 8.8.8.8:53 Jun 23 12:30:12 server pdns_recursor[11064]: Inserting rfc 1918 private space zones Jun 23 12:30:12 server pdns_recursor[11064]: Not decreasing socket buffer size from 229376 to 20 Jun 23 12:30:12 server pdns_recursor[11064]: Listening for UDP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Enabled TCP data-ready filter for (slight) DoS protection Jun 23 12:30:12 server pdns_recursor[11064]: Listening for TCP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Calling daemonize, going to background Jun 23 12:30:12 server pdns_recursor[11065]: Set effective group id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Set effective user id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Launching 2 threads Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Enabled 'epoll' multiplexer Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking '.|NS' Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP 8.8.8.8:53, asking '.|NS' Jun 23 12:30:12 server pdns_recursor[11065]: .: Got 13 answers from -8.8.8.8:53 (8.8.8.8), rcode=0, aa=0, in 6ms Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|d.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|l.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|c.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|g.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer '.|NS|h.root-servers.net.' from '.' nameservers? YES! Jun 23 12:30:12 server pdns_recursor[11065]: .: accept answer
Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
Thanks for your answer. The full dig output was in the first posting. I have not modified nsswitch.conf and /etc/hosts contains only this: 127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4 ::1 localhost localhost.localdomain localhost6 localhost6.localdomain6 And you were right! When using dig www.google.com @127.0.0.1 it takes just 0.021 seconds. But I still do not have a clue why, do you? When using another recursor (Dnsmasq) there is no time difference when using @localhost or @127.0.0.1. Thanks, Shamus Von: Michael Loftis mlof...@wgops.com An: Shamus Smith smithsha...@yahoo.de CC: bert hubert bert.hub...@netherlabs.nl; pdns-users@mailman.powerdns.com pdns-users@mailman.powerdns.com Gesendet: 18:44 Sonntag, 23.Juni 2013 Betreff: Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor What about giving the full dig output too? My bet is you're actually experiencing some sort of huge delay starting up dig or resolving localhost, use @127.0.0.1 instead and see if the time goes away. Does your /etc/hosts contain 'localhost'? Have you modified your nsswitch.conf? (Assuming standard *nix like system) On Sun, Jun 23, 2013 at 3:58 AM, Shamus Smith smithsha...@yahoo.de wrote: Hello Bert, Any ideas why it takes so long? Rerun with --trace enabled and check what is happening. With some study, it should be clear what it is waiting for. did that already before, but still did not found anything helpful there. Below is a new trace. btw, I am using 3.5.1 (package pdns-recursor-3.5.1-1.el6.x86_64). Thanks, Shamus - /etc/init.d/pdns-recursor start Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS recursor 3.5.1 (C) 2001-2013 PowerDNS.COM BV (May 3 2013, 20:04:33, gcc 4.4.7 20120313 (Red Hat 4.4.7-3)) starting up Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to redistribute it according to the terms of the GPL version 2. Jun 23 12:30:12 server pdns_recursor[11064]: Operating in 64 bits mode Jun 23 12:30:12 server pdns_recursor[11064]: Reading random entropy from '/dev/urandom' Jun 23 12:30:12 server pdns_recursor[11064]: Only allowing queries from: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10 Jun 23 12:30:12 server pdns_recursor[11064]: Will not send queries to: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10, 0.0.0.0, :: Jun 23 12:30:12 server pdns_recursor[11064]: NOT using IPv6 for outgoing queries - set 'query-local-address6=::' to enable Jun 23 12:30:12 server pdns_recursor[11064]: Redirecting queries for zone '.' to: 8.8.8.8:53 Jun 23 12:30:12 server pdns_recursor[11064]: Inserting rfc 1918 private space zones Jun 23 12:30:12 server pdns_recursor[11064]: Not decreasing socket buffer size from 229376 to 20 Jun 23 12:30:12 server pdns_recursor[11064]: Listening for UDP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Enabled TCP data-ready filter for (slight) DoS protection Jun 23 12:30:12 server pdns_recursor[11064]: Listening for TCP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Calling daemonize, going to background Jun 23 12:30:12 server pdns_recursor[11065]: Set effective group id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Set effective user id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Launching 2 threads Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun 23 12:30:12 server pdns_recursor[11065]: Enabled 'epoll' multiplexer Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: No cache hit for '.|NS', trying to find an appropriate NS record Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Cache consultations done, have 1 NS to contact Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Nameservers: -8.8.8.8:53(0.00ms) Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying to resolve NS '-8.8.8.8:53' (1/1) Jun 23 12:30:12 server pdns_recursor[11065]: .: Domain has hardcoded nameserver(s) Jun 23 12:30:12 server pdns_recursor[11065]: .: Resolved '.' NS -8.8.8.8:53 to: 8.8.8.8 Jun 23 12:30:12 server pdns_recursor[11065]: .: Trying IP
Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
Hi, what does your recursor.conf look like? I'm only guessing here but as you are obviously forwarding all queries to 8.8.8.8 there is one thing that people tend to get the wrong idea about which is using forward-zones instead of forward-zones-recurse which does not set the Recursion Desired (RD) bit when forwarding the queries as it is meant to be pointed against authoritative Nameservers instead of recursive ones. Not exactly sure how that would explain a 1s delay though. Stefan ___ Pdns-users mailing list Pdns-users@mailman.powerdns.com http://mailman.powerdns.com/mailman/listinfo/pdns-users
Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
On Sunday, June 23, 2013, Shamus Smith wrote: Thanks for your answer. The full dig output was in the first posting. I have not modified nsswitch.conf and /etc/hosts contains only this: No, only the +short is in any of your responses, when I say full output I mean without +short - there's a hint of timing information in the full dig output. We have teh time it took for the entire command to execute but we don't have the actual RTT of the DNS query. It'll indicate the query time, as well as whom it sent the query too IE what @localhost was resolved to prior to dig starting it's own query - which I think it uses gethostent or one of the other get* calls. 127.0.0.1 localhost localhost.localdomain localhost4 localhost4.localdomain4 ::1 localhost localhost.localdomain localhost6 localhost6.localdomain6 And you were right! When using dig www.google.com @127.0.0.1 it takes just 0.021 seconds. But I still do not have a clue why, do you? My *guess* or hunch is that your internal OS stack gethostent, getaddrinfo, etc, is failing/falling over somehow or in some form. It shouldn't be talking to anything in resolv.conf but if it is then the later response about correctly having the RD bit set or not because of the configuration could explain the different behavior with dnsmasq. Normally it should be consulting your local files first, finding an answer, and immediately returning. But if there's something funny going on it might not be. Other issues can occur if you have LDAP user databases/etc, or even if you've got some heavy swapping/paging going on it'll take a while to start up any command that isn't already fully in cache/RAM. All that is why I asked for the timing information from dig, which it runs *after* any of that could get into the way. When using another recursor (Dnsmasq) there is no time difference when using @localhost or @127.0.0.1. Thanks, Shamus I don't think anything other than /etc/hosts should get involved but your stall pretty clearly appears to be happening during the resolution of the @localhost and not the round trip to the world and through the pdns recursor. What about giving the full dig output too? My bet is you're actually experiencing some sort of huge delay starting up dig or resolving localhost, use @127.0.0.1 instead and see if the time goes away. Does your /etc/hosts contain 'localhost'? Have you modified your nsswitch.conf? (Assuming standard *nix like system) On Sun, Jun 23, 2013 at 3:58 AM, Shamus Smith smithsha...@yahoo.de wrote: Hello Bert, Any ideas why it takes so long? Rerun with --trace enabled and check what is happening. With some study, it should be clear what it is waiting for. did that already before, but still did not found anything helpful there. Below is a new trace. btw, I am using 3.5.1 (package pdns-recursor-3.5.1-1.el6.x86_64). Thanks, Shamus - /etc/init.d/pdns-recursor start Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS recursor 3.5.1 (C) 2001-2013 PowerDNS.COM BV (May 3 2013, 20:04:33, gcc 4.4.7 20120313 (Red Hat 4.4.7-3)) starting up Jun 23 12:30:12 server pdns_recursor[11064]: PowerDNS comes with ABSOLUTELY NO WARRANTY. This is free software, and you are welcome to redistribute it according to the terms of the GPL version 2. Jun 23 12:30:12 server pdns_recursor[11064]: Operating in 64 bits mode Jun 23 12:30:12 server pdns_recursor[11064]: Reading random entropy from '/dev/urandom' Jun 23 12:30:12 server pdns_recursor[11064]: Only allowing queries from: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10 Jun 23 12:30:12 server pdns_recursor[11064]: Will not send queries to: 127.0.0.0/8, 10.0.0.0/8, 100.64.0.0/10, 169.254.0.0/16, 192.168.0.0/16, 172.16.0.0/12, ::1/128, fe80::/10, 0.0.0.0, :: Jun 23 12:30:12 server pdns_recursor[11064]: NOT using IPv6 for outgoing queries - set 'query-local-address6=::' to enable Jun 23 12:30:12 server pdns_recursor[11064]: Redirecting queries for zone '.' to: 8.8.8.8:53 Jun 23 12:30:12 server pdns_recursor[11064]: Inserting rfc 1918 private space zones Jun 23 12:30:12 server pdns_recursor[11064]: Not decreasing socket buffer size from 229376 to 20 Jun 23 12:30:12 server pdns_recursor[11064]: Listening for UDP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Enabled TCP data-ready filter for (slight) DoS protection Jun 23 12:30:12 server pdns_recursor[11064]: Listening for TCP queries on 127.0.0.1:53 Jun 23 12:30:12 server pdns_recursor[11064]: Calling daemonize, going to background Jun 23 12:30:12 server pdns_recursor[11065]: Set effective group id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Set effective user id to 497 Jun 23 12:30:12 server pdns_recursor[11065]: Launching 2 threads Jun 23 12:30:12 server pdns_recursor[11065]: Done priming cache with root hints Jun
Re: [Pdns-users] 1 sec delay before DNS-answer at pdns-recursor
On Sun, Jun 23, 2013 at 5:40 PM, Michael Loftis mlof...@wgops.com wrote: I don't think anything other than /etc/hosts should get involved but your stall pretty clearly appears to be happening during the resolution of the @localhost and not the round trip to the world and through the pdns recursor. Which is to say I don't think that pdns-recursor is at fault for your slow dig resolution time...your OS stack I believe is failing elsewhere. -- Genius might be described as a supreme capacity for getting its possessors into trouble of all kinds. -- Samuel Butler ___ Pdns-users mailing list Pdns-users@mailman.powerdns.com http://mailman.powerdns.com/mailman/listinfo/pdns-users
