In Async environment, why http.get is too slow?

[mephistobooks]

Hi, ioquatix.
Thank you for your great async-related gems. And I would like to ask a question here.

Running the code followings:

#
#
#
require 'net/http'
require 'async'

#
def http_new
  uri  = URI.parse "https://www.google.co.jp"
  http_obj = Net::HTTP.new(uri.host, uri.port)
  http_obj.use_ssl = true
  http_obj
end
def http_get( http_obj )
  ret = http_obj.get("/index.html")
  ret
end

#
hobj = http_new

#
puts "test 1"
    response = nil
    t = Async::Clock.now
    response = http_get(hobj)
    t = Async::Clock.now - t
    puts "message: #{response.message} in #{t} sec."

puts "test 2"
    response = nil
    t = Async::Clock.now
    Sync {
      response = http_get(hobj)
    }
    t = Async::Clock.now - t
    puts "message: #{response.message} in #{t} sec."

puts "test 3"
    response = nil
    t = Async::Clock.now
    Sync {
      Thread.new{ response = http_get(hobj) }.join
    }
    t = Async::Clock.now - t
    puts "message: #{response.message} in #{t} sec."

We get:

test 1
message: OK in 0.20697699999436736 sec.
test 2
message: OK in 10.215283999918029 sec.
test 3
message: OK in 0.17304600006900728 sec.

Why test 2 is too slow (x50 slower than test 1)...?
(test 3 is my work around for Async, but i cannot understand why the performance is improved. 🧐)

---

My environments are:
$ uname -a
Darwin clt-m1.local 24.0.0 Darwin Kernel Version 24.0.0: Tue Sep 24 23:36:26 PDT 2024; root:xnu-11215.1.12~1/RELEASE_ARM64_T8103 arm64
$ ruby -v
ruby 3.3.0 (2023-12-25 revision 5124f9ac75) [arm64-darwin22]
$ gem list|grep async
async (2.17.0, 2.12.1)
$ gem list|grep net-http
net-http (default: 0.4.0)

[ioquatix]

This result looks unusual so I’ll need to investigate it.

[ioquatix]

Does the issue still show up on 3.3.6?

[mephistobooks]

Yes, it does. I tried on 3.3.6 and the result is same as below:

$ ruby -v            
ruby 3.3.6 (2024-11-05 revision 75015d4c1f) [arm64-darwin24]
$ gem list|grep async
async (2.21.0)
$ ruby test.rb       
test 1
message: OK in 0.19581900001503527 sec.
test 2
message: OK in 10.230330999940634 sec.
test 3
message: OK in 0.18720699998084456 sec.

[ioquatix]

Okay, I'm taking a look now.

[ioquatix]

Oddly enough, this works quite okay for me:

> bundle exec ruby ./test.rb
test 1
message: OK in 0.778305999992881 sec.
test 2
message: OK in 0.5207999999984168 sec.
test 3
message: OK in 0.5286329999944428 sec.

Can you tell me the performance of the following:

require 'benchmark'
require 'resolv'

Benchmark.measure{pp Resolv.getaddresses("www.google.co.jp")}

[mephistobooks]

ok. this is the result. (puts Benchmark.measure{ ... })

$ ruby -v
ruby 3.3.6 (2024-11-05 revision 75015d4c1f) [arm64-darwin24]

$ ruby test-resolve.rb
["142.250.207.99", "2404:6800:400a:805::2003"]
  0.004809   0.002977   0.007786 ( 10.053067)

It also takes 10 sec... (´・ω・｀)

[ioquatix]

Sorry for the slow response, I had a lot of things to sort out.

So, what it looks like is something odd with the DNS on your computer being extremely slow, or Ruby's resolver being extremely slow.

Are you able to tell me what is in your /etc/resolv.conf?

[mephistobooks]

Thank you for your response.
Yes. /etc/resolv.conf is default (generated by macOS...?).

#
# macOS Notice
#
# This file is not consulted for DNS hostname resolution, address
# resolution, or the DNS query routing mechanism used by most
# processes on this system.
#
# To view the DNS configuration used by this system, use:
#   scutil --dns
#
# SEE ALSO
#   dns-sd(1), scutil(8)
#
# This file is automatically generated.
#
nameserver 2402:6b00:8e95:b500:a612:42ff:fee5:7a38
nameserver 192.168.0.1

---

Now I added 8.8.8.8 by System Settings.app and did sudo killall -HUP mDNSResponder, but still same result... it takes 10 sec.

Current /etc/resolv.conf is:

#
# This file is automatically generated.
#
nameserver 2402:6b00:8e95:b500:a612:42ff:fee5:7a38
nameserver 192.168.0.1
nameserver 8.8.8.8

[ioquatix]

Is 2402:6b00:8e95:b500:a612:42ff:fee5:7a38 contactable?

[ioquatix]

How long does:

dig @2402:6b00:8e95:b500:a612:42ff:fee5:7a38 www.google.co.jp

take?

[mephistobooks]

Oh! i deleted IPv6 one, it become fine!!!

$ time dig @2402:6b00:8e95:b500:a612:42ff:fee5:7a38 www.google.co.jp

; <<>> DiG 9.10.6 <<>> @2402:6b00:8e95:b500:a612:42ff:fee5:7a38 www.google.co.jp
; (1 server found)
;; global options: +cmd
;; connection timed out; no servers could be reached
dig @2402:6b00:8e95:b500:a612:42ff:fee5:7a38 www.google.co.jp  0.00s user 0.01s system 0% cpu 15.033 total

(10 sec.)

---

I deleted IPv6 DNS and sorted:

#
# This file is automatically generated.
#
nameserver 8.8.8.8
nameserver 192.168.0.1

$ ruby test.rb 
test 1
message: OK in 0.20589399989694357 sec.
test 2
message: OK in 0.2133009999524802 sec. <<improved!!!
test 3
message: OK in 0.15515200002118945 sec.

Thank you very much, ioquatix-san. I deeply apologize for causing you any trouble.
(but why Thread.new{ ... }.join can work well... I cannot understand)

[ioquatix]

The reason is probably the resolver implementation is different.

Async currently uses Ruby's pure ruby resolv implementation. My guess is it does the following:

1. Try to contact IPv6 resolver = 10 second timeout.
2. Try to contact IPv4 resolver = address resolved

Total time = 10s + a little.

Ruby itself (without async) uses the OS provided resolver, which may do this:

1. Try to contact both IPv6 and IPv4 resolver at the same time.
2. IPv4 resolver responds with address, request to IPv6 dropped.

Total time = a little.

We should probably fix Async to handle this case better. So the reason why Thread.new{...}.join is working better is due to Ruby's native resolver vs the operating system provided resolver having different behaviour, and specifically having different behaviour when there are non-responding servers.

[ioquatix]

Also, it was no trouble and I'm glad the problem is fixed. There is definitely something we can improve in Async by improving the resolver.