Warmed up cache slows the query

[heaven]

The problem

Initial query on a cold cache executes faster than with a warmed one.

Reproduction

Here is the test I've been using

class TestDomain
  ROOT_NAMESERVERS = %w[
      a.root-servers.net
      b.root-servers.net
      c.root-servers.net
      d.root-servers.net
      e.root-servers.net
      f.root-servers.net
      g.root-servers.net
      h.root-servers.net
      i.root-servers.net
      j.root-servers.net
      k.root-servers.net
      l.root-servers.net
      m.root-servers.net
    ].freeze

  def name
    "example.com"
  end

  def recursive_query(type, ns: ROOT_NAMESERVERS)
    return [] unless ns.present?

    msg = nil
    puts "Time: #{Benchmark.realtime { msg = resolve_query(type, ns: ns, recurse: false, cache: ROOT_NAMESERVERS.intersect?(ns)) }}"
    return [] unless msg

    # The answer is received.
    return msg.answer.map { |rr| rr.rdata_to_string } if msg.answer.present?

    # Another layer of intermediaries.
    authority = msg.authority.
      find_all { |rr| rr.type == Dnsruby::Types.NS }.
      map(&:rdata).map(&:to_s).reject(&:blank?)
    return [] unless authority.present?

    recursive_query(type, ns: authority)
  end

  private

  def resolve_query(type, ns: nil, recurse: true, cache: true)
    puts "Caching: #{cache} | NS: #{ns.first}"

    resolver = Dnsruby::Resolver.
      new(recurse: recurse, do_caching: cache, retry_times: 2)

    resolver.nameserver = [ns].flatten.shift

    resolver.query(name, type)
  end
end

I tested this from a Rails console environment, and the numbers look strange:

Loading development environment (Rails 8.0.2)
3.4.2 :001 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.12582800001837313
Caching: false | NS: l.gtld-servers.net
Time: 0.12042500008828938
Caching: false | NS: a.iana-servers.net
Time: 0.12831000005826354
 => 0.3755820000078529

3.4.2 :002 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.21918399981223047
Caching: false | NS: l.gtld-servers.net
Time: 0.32541300007142127
Caching: false | NS: a.iana-servers.net
Time: 0.32564599998295307
 => 0.8710799999535084

3.4.2 :003 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.22562899999320507
Caching: false | NS: l.gtld-servers.net
Time: 0.3200809999834746
Caching: false | NS: a.iana-servers.net
Time: 0.3220410000067204
 => 0.8686989999841899

And even if you switch the caching to be always true, it is still kind of slow:

Loading development environment (Rails 8.0.2)
3.4.2 :001 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.1284089998807758
Caching: true | NS: l.gtld-servers.net
Time: 0.12005099980160594
Caching: true | NS: a.iana-servers.net
Time: 0.12974500004202127
 => 0.37913599982857704

3.4.2 :002 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.21118599991314113
 => 0.21136899990960956

3.4.2 :003 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.21160500007681549
 => 0.2118849998805672

I saw this once or twice, which seemed like the cache was hit, but in most cases, it doesn't seem to work.

3.4.2 :002 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
Time: 0.001236999873071909
 => 0.0012920000590384007

When the cache is cold, the query executed in 0.12582800001837313, with pre-warmed cache, the same query with do_cache: true took 0.21918399981223047 instead of 0.0012920000590384007 (which I saw when the cache actually hit). This is about 170 times slower than expected with a warmed cache.

The next queries also increased from 0.12042500008828938 to 0.32541300007142127, so also around 0.2 seconds slower. It feels that the existing cache adds around 0.2 seconds to each query, even those with do_cache: true.

[heaven]

I have updated the test script to benchmark each stage separately, and it seems nameserver resolution is what takes these extra 0.2 seconds.

Here is what I changed

  def recursive_query(type, ns: ROOT_NAMESERVERS)
    return [] unless ns.present?

    msg = nil
    puts "Total Time: #{Benchmark.realtime { msg = resolve_query(type, ns: ns, recurse: false, cache: ROOT_NAMESERVERS.intersect?(ns)) }}\n\n"
    return [] unless msg

    # The answer is received.
    return msg.answer.map { |rr| rr.rdata_to_string } if msg.answer.present?

    # Another layer of intermediaries.
    authority = msg.authority.
      find_all { |rr| rr.type == Dnsruby::Types.NS }.
      map(&:rdata).map(&:to_s).reject(&:blank?)
    return [] unless authority.present?

    recursive_query(type, ns: authority)
  end

  private

  def resolve_query(type, ns: nil, recurse: true, cache: true)
    puts "Caching: #{cache} | NS: #{ns.first}"

    resolver = Dnsruby::Resolver.
      new(recurse: recurse, do_caching: cache, retry_times: 2)

    puts "NS Time: #{Benchmark.realtime { resolver.nameserver = [ns].flatten.shift }}"

    msg = nil
    puts "Query Time: #{Benchmark.realtime { msg = resolver.query(name, type) }}"
    msg
  end

And the test results look like this for the cold cache

3.4.2 :001 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
NS Time: 0.016321999952197075
Query Time: 0.10944900009781122
Total Time: 0.12633099989034235

Caching: false | NS: l.gtld-servers.net
NS Time: 0.008028999902307987
Query Time: 0.11202199989929795
Total Time: 0.12025399995036423

Caching: false | NS: a.iana-servers.net
NS Time: 0.010720999911427498
Query Time: 0.11658800020813942
Total Time: 0.12754000001586974

 => 0.375002000015229

And here's the warmed cache:

3.4.2 :002 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
NS Time: 0.1039650000166148
Query Time: 0.11170100001618266
Total Time: 0.21583200013265014

Caching: false | NS: l.gtld-servers.net
NS Time: 0.21175600006245077
Query Time: 0.12205000012181699
Total Time: 0.334084999980405

Caching: false | NS: a.iana-servers.net
NS Time: 0.207888999953866
Query Time: 0.12519000004976988
Total Time: 0.33330099983140826

 => 0.8838959999848157

Looks like do_cache: false also disables the NS resolution cache. And there is some inconsistency, because the first time the cache was used even for subsequent calls, the second time it didn't hit.

[alexdalitz]

Hi @heaven - thanks for making this new issue!

I'm afraid I'm busy until at least Monday, so won't be able to look at this until then.

Thanks!

[alexdalitz]

Hi @heaven - sorry for the delay getting back to this.

I have the following output for do_caching = true :

Caching: true | NS: a.root-servers.net
NS Time: 0.01598199998261407
Query Time: 0.015979999967385083
Total Time: 0.0320260000298731

Caching: true | NS: a.root-servers.net
NS Time: 0.0007140000234358013
Query Time: 0.01610800001071766
Total Time: 0.016869999992195517

Caching: true | NS: a.root-servers.net
NS Time: 0.0007949999999254942
Query Time: 0.016983000037726015
Total Time: 0.017902000050526112```

And the following output for do_caching = false : 

``` % ruby -I lib benchmark_cache.rb
Caching: false | NS: a.root-servers.net
NS Time: 0.03167699999175966
Query Time: 0.016294999979436398
Total Time: 0.048051999998278916

Caching: false | NS: a.root-servers.net
NS Time: 0.0008239999879151583
Query Time: 0.016466000000946224
Total Time: 0.017346000007819384

Caching: false | NS: a.root-servers.net
NS Time: 0.0008099999977275729
Query Time: 0.01907700003357604
Total Time: 0.020018999988678843```

I think it's clear that the NS record is cached, regardless of whether do_caching is true or false!

This is because, as I wrote in the other issue, the name server resolution is done by a new Resolver which is created internally, using the default system-configured nameservers, and with do_caching = true. So these queries will _always_ use the cache, as these results show.

[heaven]

@alexdalitz, no worries at all. By coincidence, I've got completely overwhelmed with another project at the moment, but I will get back to this issue, hopefully next week.

[alexdalitz]

Here are some results from using a normal Resolver, created anew for each query (but having already queried example.com first, to get the nameservers resolved) :

Query Time: 0.005731999990530312
Query Time: 0.000248999975156039
Query Time: 0.00019700004486367106```

And for no caching : 
```Cache false
Query Time: 0.006139999954029918
Query Time: 0.005058999988250434
Query Time: 0.005689000012353063```

I think it's clear that the cache is working as intended.

In your example above, I think you are querying the root name server for example.com - the root server is clearly not authoritative for that, nor is it a recursive resolver. So, it can't put any records in the ANSWER section - only some NS records in the ADDITIONAL section. Only responses with an ANSWER section of more than zero records will get cached - so your queries are missing the cache entirely.

So, I don't think there is a problem with the cache, and I would like to close this issue, if you're happy?

Thanks!

[heaven]

Hi, this is the result I am seeing consistently – the second time I run the same command, it is 2 times slower than the first one. Once I restart the rails console, the first call is fast again, all the consecutive calls are slower. This is reproducible and there is definitely a problem somewhere.

And this is 100% related to the internal cache, because if I replace this line (only cache the response of the roots)

puts "Total Time: #{Benchmark.realtime { msg = resolve_query(type, ns: ns, recurse: false, cache: ROOT_NAMESERVERS.intersect?(ns)) }}\n\n"

With this (never cache)

puts "Total Time: #{Benchmark.realtime { msg = resolve_query(type, ns: ns, recurse: false, cache: false) }}\n\n"

The results are consistens and the slowdown doesn't happen.

You can close the issue, if you want, but there is a 100% bug with the caching implementation, which, when enabled for the first query, and disabled for the consecutive ones, makes resolver twice slower.

This is the place where it becomes slow

puts "NS Time: #{Benchmark.realtime { resolver.nameserver = [ns].flatten.shift }}"

First run

NS Time: 0.012378999963402748
NS Time: 0.00802099984139204
NS Time: 0.010696999728679657

Consecutive runs

NS Time: 0.10749199986457825
NS Time: 0.2093299999833107
NS Time: 0.20785799995064735

The degradation is severe, 10-26 times.

And here is the worst part, if I change this line to always cache

puts "Total Time: #{Benchmark.realtime { msg = resolve_query(type, ns: ns, recurse: false, cache: true) }}\n\n"

It still doesn't work consisnently

The first call took 0.5767140001989901, which looks normal, aligns with the previous results. the second one looks great! Like it should when everything is cached 0.0030559999868273735. But then all the consecutive results become slower 0.21197299985215068.

[alexdalitz]

@heaven Like I said above, I think your test code is faulty!

The results I quoted above were from making a new Resolver (and running a query to make sure the nameservers were all resolved), and then querying for a domain name. I think they clearly show that the cache is working!

[alexdalitz]

I've modified your test code to make it run a proper test. It's a complete mess as a result (it would probably have been better to have made a new one) but here it is :

require 'dnsruby'

class TestDomain
  def name
    "dalitz.co.uk"
  end

  def run_three_tests(type)
    cache = false

    print ("Cache #{cache}\n")

    resolver = Dnsruby::Resolver.new
    resolver.do_caching = cache

    resolver.query("example.com", "A") # make sure the nameservers are resolved

    3.times { recursive_query(type, resolver: resolver, cache: cache)}
  end

  def recursive_query(type, resolver: nil, cache: nil)

    msg = nil
      msg = resolve_query(type: type, cache: cache)
    return [] unless msg

    # The answer is received.
    return msg.answer.map { |rr| rr.rdata_to_string } if msg.answer

  end

  private

  def resolve_query(type: "A", cache: nil)

    resolver = Dnsruby::Resolver.new
    resolver.do_caching = cache

    resolver.query("example.com", type) # make sure the nameservers are resolved

    msg = nil
    puts "Query Time: #{Benchmark.realtime { msg = resolver.query(name, type) }}"
    msg
  end
end

TestDomain.new.run_three_tests("A")

This is the result :

Query Time: 0.022447000024840236
Query Time: 0.005083999945782125
Query Time: 0.005191000062040985
 => 3 ```

I think the cache is working just fine!

As I explained above, your test code contained several issues which stopped it from doing what I think you thought it was doing.

Hopefully we can now close this issue?

Thanks!

[heaven]

Except that it doesn't do what we need 😀

The cache doesn't work in our case and the test I provided is exactly what we are doing – querying the roots (that list of 13 global servers), there we look for the TLDs, then we go through any other intermediaries, down until we reach the authoritative domain nameservers. I don't see where it is faulthy, to my understanding it is absolutely legit.

But, even your test fails if you run TestDomain.new.run_three_tests("A") multiple times. Check out the timings:

Loading development environment (Rails 8.0.2)
3.4.2 :001 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.0863149999640882
Query Time: 0.007639000192284584
Query Time: 0.008301999885588884
 => 3
3.4.2 :002 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.10572999995201826
Query Time: 0.10700799990445375
Query Time: 0.11030899966135621
 => 3
3.4.2 :003 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.10483400011435151
Query Time: 0.10665600001811981
Query Time: 0.10675500007346272
 => 3

(this is 1.73.1)

And it looks like master got better

Loading development environment (Rails 8.0.2)
3.4.2 :001 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.007819000165909529
Query Time: 0.0075159999541938305
Query Time: 0.007120999973267317
 => 3
3.4.2 :002 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.005912000313401222
Query Time: 0.0057020001113414764
Query Time: 0.006378999911248684
 => 3
3.4.2 :003 > TestDomain.new.run_three_tests("A")
Cache false
Query Time: 0.007638999726623297
Query Time: 0.007510000374168158
Query Time: 0.006839999929070473
 => 3

(this is master)

[alexdalitz]

Hmmmm......

3.3.5 :031 > TestDomain.new.run_three_tests("A")
3.3.5 :032 > 
Cache true
Query Time: 0.004255000036209822
Query Time: 0.00017499993555247784
Query Time: 0.00017499993555247784
 => 3 
3.3.5 :033 > TestDomain.new.run_three_tests("A")
Cache true
Query Time: 0.10545000014826655
Query Time: 0.10160399996675551
Query Time: 0.10188099998049438
 => 3 
3.3.5 :034 > TestDomain.new.run_three_tests("A")
Cache true
Query Time: 0.10536299995146692
Query Time: 0.10522400005720556
Query Time: 0.10207899985834956
 => 3 

I can see there is a problem here - thanks for your persistence!

I'm a little busy right now, but I'll try to look at this next week.

Thanks!

[alexdalitz]

Hi @heaven - thanks so much for sticking with this one!
The problem (which I have now fixed in master) was that, when the select thread was stopped (after a second or so of inactivity), all the open sockets were deleted - including the pipe-lining socket which was used to wake the select thread up (for example, if a cache entry was found). This meant that the wakeup signal was not received, so the select() call had to time out (currently about 0.1 seconds) before the response was handled.
I now get results like :

3.3.5 :037 > TestDomain.new.run_three_tests("dalitz.co.uk", "A")
3.3.5 :038 >
Cache true
Query Time: 0.004098000004887581
Query Time: 0.00019700010307133198
Query Time: 0.00017399992793798447
=> 3
3.3.5 :039 > TestDomain.new.run_three_tests("dalitz.co.uk", "A")
3.3.5 :040 >
Cache true
Query Time: 0.00042699999175965786
Query Time: 0.00034399982541799545
Query Time: 0.0003450000658631325
=> 3
3.3.5 :041 > TestDomain.new.run_three_tests("dalitz.co.uk", "A")
Cache true
Query Time: 0.00025800010189414024
Query Time: 0.00022600009106099606
Query Time: 0.00030399998649954796

which I think shows that the problem is fixed.

Could you please check out master and see if it works for you?

Once you're happy with it, I will make a new release.

Thanks again!

[alexdalitz]

@heaven Here are the results from your original test :

3.3.5 :199 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
=> 0.026787000009790063
3.3.5 :200 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
=> 0.019549000076949596
3.3.5 :201 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
=> 0.02007699990645051
3.3.5 :202 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
=> 0.019807999953627586
3.3.5 :203 > Benchmark.realtime { TestDomain.new.recursive_query("NS") }
Caching: true | NS: a.root-servers.net
=> 0.01752300001680851

[heaven]

@alexdalitz Hi, and hanks for your great efforts. I will retest from my end, hopefully by tomorrow or wednesday, but the numbers look great, now they look like the cache is actually doing its job.

[alexdalitz]

Hi @heaven - have you had a chance to test this, please? It's worth noting that I've made a small change to master, so it would be worth pulling again before testing. Thanks!