alexdalitz / dnsruby

Dnsruby is a feature-complete DNS(SEC) client for Ruby, as used by many of the world's largest DNS registries and the OpenDNSSEC project
Other
197 stars 77 forks source link

Weird performance of second query (100ms, always) #200

Open ahmeij opened 4 hours ago

ahmeij commented 4 hours ago

I'm trying to use dnsruby in a higher performance environment and I'm running into issues when a second query is fired, I have reduced it to a very simple test that seems to show the problem, I tried multiple versions including the latest version on ruby 3.1 and ruby 3.3. Also tested with many different dns servers and environments.

require "dnsruby"
Dnsruby::TheLog.level = Logger::DEBUG

def testme
  domain1 = "example.com"
  domain2 = "example.net"

  start_time = Time.now
  resolver = Dnsruby::Resolver.new
  resolver.query(domain1)
  puts "First query time: #{Time.now - start_time} seconds"

  start_time = Time.now
  resolver = Dnsruby::Resolver.new
  resolver.query(domain2)
  puts "Second query time: #{Time.now - start_time} seconds"
end

testme
testme

Output

D, [2024-11-15T18:57:31.126417 #471251] DEBUG -- : Resolver : sending message
D, [2024-11-15T18:57:31.126554 #471251] DEBUG -- : Nameservers = 10.1.99.89, 10.1.99.90
I, [2024-11-15T18:57:31.126607 #471251]  INFO -- : Config - nameservers : 10.1.99.89, 10.1.99.90,  domain : empty, search : b101-1.sover.in,  ndots : 1 port : 53
D, [2024-11-15T18:57:31.126624 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.89
D, [2024-11-15T18:57:31.126659 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.90
D, [2024-11-15T18:57:31.126715 #471251] DEBUG -- : Sending msg to 10.1.99.89
D, [2024-11-15T18:57:31.126842 #471251] DEBUG -- : CACHE found

D, [2024-11-15T18:57:31.126883 #471251] DEBUG -- : Sending cached answer to client

D, [2024-11-15T18:57:31.126897 #471251] DEBUG -- : Pushing response to client queue direct from resolver or validator
D, [2024-11-15T18:57:31.226447 #471251] DEBUG -- : Handling good response
First query time: 0.100203648 seconds
D, [2024-11-15T18:57:31.226647 #471251] DEBUG -- : Resolver : sending message
D, [2024-11-15T18:57:31.226845 #471251] DEBUG -- : Nameservers = 10.1.99.89, 10.1.99.90
I, [2024-11-15T18:57:31.226925 #471251]  INFO -- : Config - nameservers : 10.1.99.89, 10.1.99.90,  domain : empty, search : b101-1.sover.in,  ndots : 1 port : 53
D, [2024-11-15T18:57:31.226950 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.89
D, [2024-11-15T18:57:31.226986 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.90
D, [2024-11-15T18:57:31.227043 #471251] DEBUG -- : Sending msg to 10.1.99.89
D, [2024-11-15T18:57:31.227169 #471251] DEBUG -- : CACHE found

D, [2024-11-15T18:57:31.227184 #471251] DEBUG -- : Sending cached answer to client

D, [2024-11-15T18:57:31.227192 #471251] DEBUG -- : Pushing response to client queue direct from resolver or validator
D, [2024-11-15T18:57:31.326655 #471251] DEBUG -- : Handling good response
Second query time: 0.100214808 seconds
=> nil
irb(main):021> D, [2024-11-15T18:57:32.228216 #471251] DEBUG -- : Try stop select loop
D, [2024-11-15T18:57:32.228304 #471251] DEBUG -- : Deleted 1 non-persistent sockets, 0 persistent sockets remain.
D, [2024-11-15T18:57:32.228323 #471251] DEBUG -- : Stopping select loop

Notice the 100+ ms response time of the second query

alexdalitz commented 4 hours ago

It looks like both queries are being answered from the cache?Sent from my iPhoneOn 15 Nov 2024, at 18:59, Andre Meij @.***> wrote: I'm trying to use dnsruby in a higher performance environment and I'm running into issues when a second query is fired, I have reduced it to a very simple test that seems to show the problem, I tried multiple versions including the latest version on ruby 3.1 and ruby 3.3. Also tested with many different dns servers and environments. require "dnsruby" Dnsruby::TheLog.level = Logger::DEBUG

def testme domain1 = "example.com" domain2 = "example.net"

start_time = Time.now resolver = Dnsruby::Resolver.new resolver.query(domain1) puts "First query time: #{Time.now - start_time} seconds"

start_time = Time.now resolver = Dnsruby::Resolver.new resolver.query(domain2) puts "Second query time: #{Time.now - start_time} seconds" end

testme testme

Output D, [2024-11-15T18:57:31.126417 #471251] DEBUG -- : Resolver : sending message D, [2024-11-15T18:57:31.126554 #471251] DEBUG -- : Nameservers = 10.1.99.89, 10.1.99.90 I, [2024-11-15T18:57:31.126607 #471251] INFO -- : Config - nameservers : 10.1.99.89, 10.1.99.90, domain : empty, search : b101-1.sover.in, ndots : 1 port : 53 D, [2024-11-15T18:57:31.126624 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.89 D, [2024-11-15T18:57:31.126659 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.90 D, [2024-11-15T18:57:31.126715 #471251] DEBUG -- : Sending msg to 10.1.99.89 D, [2024-11-15T18:57:31.126842 #471251] DEBUG -- : CACHE found

D, [2024-11-15T18:57:31.126883 #471251] DEBUG -- : Sending cached answer to client

D, [2024-11-15T18:57:31.126897 #471251] DEBUG -- : Pushing response to client queue direct from resolver or validator D, [2024-11-15T18:57:31.226447 #471251] DEBUG -- : Handling good response First query time: 0.100203648 seconds D, [2024-11-15T18:57:31.226647 #471251] DEBUG -- : Resolver : sending message D, [2024-11-15T18:57:31.226845 #471251] DEBUG -- : Nameservers = 10.1.99.89, 10.1.99.90 I, [2024-11-15T18:57:31.226925 #471251] INFO -- : Config - nameservers : 10.1.99.89, 10.1.99.90, domain : empty, search : b101-1.sover.in, ndots : 1 port : 53 D, [2024-11-15T18:57:31.226950 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.89 D, [2024-11-15T18:57:31.226986 #471251] DEBUG -- : InternalResolver setting server to 10.1.99.90 D, [2024-11-15T18:57:31.227043 #471251] DEBUG -- : Sending msg to 10.1.99.89 D, [2024-11-15T18:57:31.227169 #471251] DEBUG -- : CACHE found

D, [2024-11-15T18:57:31.227184 #471251] DEBUG -- : Sending cached answer to client

D, [2024-11-15T18:57:31.227192 #471251] DEBUG -- : Pushing response to client queue direct from resolver or validator D, [2024-11-15T18:57:31.326655 #471251] DEBUG -- : Handling good response Second query time: 0.100214808 seconds => nil irb(main):021> D, [2024-11-15T18:57:32.228216 #471251] DEBUG -- : Try stop select loop D, [2024-11-15T18:57:32.228304 #471251] DEBUG -- : Deleted 1 non-persistent sockets, 0 persistent sockets remain. D, [2024-11-15T18:57:32.228323 #471251] DEBUG -- : Stopping select loop

Notice the 100+ ms response time of the second query

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you are subscribed to this thread.Message ID: @.***>

ahmeij commented 1 hour ago

Yes, that is the interesting thing, it is not the actual lookup that is slowing down, it looks like it has something to do with the communication between the resolver and the requesting thread.

The time is eaten after this logline: "Pushing response to client queue direct from resolver or validator"

alexdalitz commented 1 hour ago

Yes fair enough - I’ll take a look at it and get back to you over the next few days.Thanks!Sent from my iPhoneOn 15 Nov 2024, at 22:02, Andre Meij @.***> wrote: Yes, that is the interesting thing, it is not the actual lookup that is slowing down, it looks like it has something to do with the communication between the resolver and the requesting thread

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you commented.Message ID: @.***>