Crystal: Slow HTTP::Client

[willcosgrove]

I've noticed a strange phenomenon while building a github client in Crystal. I noticed that the API requests were going pretty slowly, but usually only the first request made in the program, the rest all happened very quickly.

I wrote a short test program to see if I could reproduce the problem.

require "http/client"

client = HTTP::Client.new("https://api.github.com")

5.times do
  t = Time.now
  client.get("/emojis")
  puts Time.now - t
end

The output I'm seeing for this is:

00:00:03.1137930
00:00:00.0183150
00:00:00.0184680
00:00:00.0192650
00:00:00.0192780

Any ideas what could be causing this, and how I could possibly reduce the time of response on the first request?

[asterite]

The first request creates the socket, which has to do host resolution (a getaddrinfo C call). Once that's done it doesn't need to do it on subsequent requests.

By the way, "slow" is relative. For me the times are:

00:00:00.4284320
00:00:00.1794920
00:00:00.1926180
00:00:00.1816630
00:00:00.1876730

While in Ruby:

require "net/http"

uri = URI("https://api.github.com/emojis")

5.times do |i|
  time = Time.now
  Net::HTTP.get_response(uri)
  puts Time.now - time
end

Output:

0.794322
0.722982
0.75163
0.703808
0.741081

<joke>

You could also try to skip the first request:

require "http/client"

client = HTTP::Client.new("https://api.github.com")

6.times do |i|
  next if i == 0 # skip the first request

  t = Time.now
  client.get("/emojis")
  puts Time.now - t
end

</joke>

[willcosgrove]

Hmm, I wonder why it's running so slowly for me. curl finishes running in about half a second for me, as opposed to 3 seconds. 🤔

Thanks for your explanation and super fast response!

[asterite]

@willcosgrove One reason could be that curl uses C's getaddrinfo. I said something not quite right before, we also use getaddrinfo but from libevent. That might be causing the difference, but I'm not sure.

I guess if your program is a console app that is only supposed to be doing one request, that's bad because it makes the program really slow :-(

[willcosgrove]

Yeah, it's to power an Alfred workflow, but unfortunately it's a bit slow. I guess there's always

5.times do
  t = Time.now
  `curl -s https://api.github.com/emojis`
  puts Time.now - t
end

😁

[asterite]

I debugged this a bit but the getaddrinfo call doesn't seem to be the culprit. This line takes the extra time.

In my case curl and a Crystal program take about the same time. I don't know what could be the difference in your case.

[willcosgrove]

Interesting 🤔 I'll keep playing around with it, and see if I can figure out what's going on on my end. Thanks again for your help, above and beyond 🙇

I'll write back if I ever figure out what it is.

[willcosgrove]

Just for fun, I decided to change the benchmark to http://google.com to see if I got better or worse speed.

client = HTTP::Client.new("http://google.com")

5.times do
  t = Time.now
  client.get("/search")
  puts Time.now - t
end

Which fails to run:

getaddrinfo: nodename nor servname provided, or not known (Socket::Error)
[4434332290] *CallStack::unwind:Array(Pointer(Void)) +82
[4434332193] *CallStack#initialize<CallStack>:Array(Pointer(Void)) +17
[4434332152] *CallStack::new:CallStack +40
[4434506617] *Socket::Error@Exception#initialize<Socket::Error, String, Nil>:CallStack +41
[4434506548] *Socket::Error::new<String>:Socket::Error +100
[4434500395] *TCPSocket#initialize<TCPSocket, String, Int32, Float64?, Float64?>:Nil +1835
[4434498525] *TCPSocket::new<String, Int32, Float64?, Float64?>:TCPSocket +221
[4434490014] *HTTP::Client#socket<HTTP::Client>:(OpenSSL::SSL::Socket | TCPSocket+) +110
[4434489467] *HTTP::Client#exec_internal<HTTP::Client, HTTP::Request>:HTTP::Client::Response +43
[4434489394] *HTTP::Client#exec<HTTP::Client, HTTP::Request>:HTTP::Client::Response +34
[4434488877] *HTTP::Client#exec<HTTP::Client, String, String, Nil, Nil>:HTTP::Client::Response +29
[4434488839] *HTTP::Client#get<HTTP::Client, String>:HTTP::Client::Response +39
[4434293893] __crystal_main +37893
[4434302856] main +40

I can curl the address just fine, and I get the same error if I use https, or if I tack on the www subdomain. I've got no ideas as to why this won't work 😢

[asterite]

HTTP::Client.new accepts a host as argument, not an URI.

[willcosgrove]

:facepalm:

[willcosgrove]

So running it against google is super fast, but api.github.com is not.

Google

00:00:00.0945720
00:00:00.0523470
00:00:00.0506420
00:00:00.1770660
00:00:00.0519490

Github API

00:00:03.1578220
00:00:00.0203440
00:00:00.0192260
00:00:00.0189720
00:00:00.0190000

I have no idea why that would be, but I'm certain it has nothing to do with Crystal 😄

[willcosgrove]

I figured out the solution to my problem. I still haven't figured out what the problem is though 😅

I ran tcpdump on my Google and Github test programs.

Here's the tcpdump output from Google's run

15:27:54.005556 IP (tos 0x0, ttl 64, id 32962, offset 0, flags [none], proto UDP (17), length 72)
    10.0.1.1.domain > 10.0.1.3.62058: [udp sum ok] 20267 q: A? gOOgle.COm. 1/0/0 gOOgle.COm. [2m15s] A 216.58.218.206 (44)
15:27:54.019624 IP (tos 0x0, ttl 64, id 32963, offset 0, flags [none], proto UDP (17), length 84)
    10.0.1.1.domain > 10.0.1.3.62058: [udp sum ok] 9556 q: AAAA? gOoGlE.coM. 1/0/0 gOoGlE.coM. [2m57s] AAAA 2607:f8b0:4000:803::200e (56)
15:27:54.036549 IP (tos 0x0, ttl 55, id 16600, offset 0, flags [none], proto TCP (6), length 60)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [S.], cksum 0x8512 (correct), seq 1016783385, ack 2475710327, win 42540, options [mss 1430,sackOK,TS val 1235688791 ecr 883352850,nop,wscale 7], length 0
15:27:54.056018 IP (tos 0x0, ttl 55, id 18830, offset 0, flags [none], proto TCP (6), length 52)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [.], cksum 0x57f4 (correct), seq 1, ack 131, win 341, options [nop,nop,TS val 1235688810 ecr 883352865], length 0
15:27:54.058048 IP (tos 0x0, ttl 55, id 60859, offset 0, flags [none], proto TCP (6), length 1470)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [.], cksum 0x7721 (correct), seq 1:1419, ack 131, win 341, options [nop,nop,TS val 1235688812 ecr 883352865], length 1418
15:27:54.058402 IP (tos 0x0, ttl 55, id 29611, offset 0, flags [none], proto TCP (6), length 1470)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [.], cksum 0xe498 (correct), seq 1419:2837, ack 131, win 341, options [nop,nop,TS val 1235688812 ecr 883352865], length 1418
15:27:54.058813 IP (tos 0x0, ttl 55, id 42174, offset 0, flags [none], proto TCP (6), length 1218)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [P.], cksum 0x953a (correct), seq 2837:4003, ack 131, win 341, options [nop,nop,TS val 1235688812 ecr 883352865], length 1166
15:27:54.114525 IP (tos 0x0, ttl 55, id 14482, offset 0, flags [none], proto TCP (6), length 111)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [P.], cksum 0x5acd (correct), seq 4003:4062, ack 457, win 350, options [nop,nop,TS val 1235688869 ecr 883352925], length 59
15:27:54.132994 IP (tos 0x0, ttl 55, id 28391, offset 0, flags [none], proto TCP (6), length 52)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [.], cksum 0x407f (correct), seq 4062, ack 1895, win 372, options [nop,nop,TS val 1235688888 ecr 883352936], length 0
15:27:54.164296 IP (tos 0x0, ttl 55, id 64906, offset 0, flags [none], proto TCP (6), length 729)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [P.], cksum 0x020a (correct), seq 4062:4739, ack 1895, win 372, options [nop,nop,TS val 1235688919 ecr 883352936], length 677
15:27:54.183512 IP (tos 0x0, ttl 55, id 45808, offset 0, flags [none], proto TCP (6), length 52)
    dfw06s47-in-f14.1e100.net.https > 10.0.1.3.53908: Flags [F.], cksum 0x3d79 (correct), seq 4739, ack 1896, win 372, options [nop,nop,TS val 1235688938 ecr 883352981], length 0

and Github's:

15:29:10.574884 IP (tos 0x0, ttl 64, id 63287, offset 0, flags [none], proto UDP (17), length 60)
    10.0.1.3.56868 > 10.0.1.1.domain: [udp sum ok] 22046+ A? aPi.gitHub.COm. (32)
15:29:10.574936 IP (tos 0x0, ttl 64, id 4862, offset 0, flags [none], proto UDP (17), length 60)
    10.0.1.3.56868 > 10.0.1.1.domain: [udp sum ok] 37656+ AAAA? ApI.gItHuB.CoM. (32)
15:29:10.589307 IP (tos 0x0, ttl 64, id 1023, offset 0, flags [none], proto UDP (17), length 76)
    10.0.1.1.domain > 10.0.1.3.56868: [udp sum ok] 22046 q: A? aPi.gitHub.COm. 1/0/0 aPi.gitHub.COm. [2s] A 192.30.252.127 (48)
15:29:10.593813 IP (tos 0x0, ttl 64, id 1024, offset 0, flags [none], proto UDP (17), length 60)
    10.0.1.1.domain > 10.0.1.3.56868: [udp sum ok] 37656 q: AAAA? ApI.gItHuB.CoM. 0/0/0 (32)
15:29:10.593882 IP (tos 0x0, ttl 64, id 36001, offset 0, flags [none], proto UDP (17), length 66)
    10.0.1.3.56868 > 10.0.1.1.domain: [udp sum ok] 40414+ AAAA? API.GitHUb.Com.LOCal. (38)
15:29:13.637865 IP (tos 0x0, ttl 51, id 57787, offset 0, flags [none], proto TCP (6), length 60)
    api.github.com.https > 10.0.1.3.53937: Flags [S.], cksum 0xf7f6 (correct), seq 3885450099, ack 737112447, win 14240, options [mss 1436,sackOK,TS val 1064519166 ecr 883423693,nop,wscale 10], length 0
15:29:13.689893 IP (tos 0x0, ttl 51, id 63469, offset 0, flags [none], proto TCP (6), length 1476)
    api.github.com.https > 10.0.1.3.53937: Flags [.], cksum 0xecbb (correct), seq 1:1425, ack 131, win 15, options [nop,nop,TS val 1064519179 ecr 883423733], length 1424
15:29:13.690669 IP (tos 0x0, ttl 51, id 62958, offset 0, flags [none], proto TCP (6), length 1305)
    api.github.com.https > 10.0.1.3.53937: Flags [P.], cksum 0xc6f7 (correct), seq 1425:2678, ack 131, win 15, options [nop,nop,TS val 1064519179 ecr 883423733], length 1253
15:29:13.812324 IP (tos 0x0, ttl 51, id 1778, offset 0, flags [none], proto TCP (6), length 111)
    api.github.com.https > 10.0.1.3.53937: Flags [P.], cksum 0x4279 (correct), seq 2678:2737, ack 457, win 16, options [nop,nop,TS val 1064519210 ecr 883423846], length 59
15:29:13.865525 IP (tos 0x0, ttl 51, id 21749, offset 0, flags [none], proto TCP (6), length 52)
    api.github.com.https > 10.0.1.3.53937: Flags [.], cksum 0x4b1b (correct), seq 2737, ack 1911, win 19, options [nop,nop,TS val 1064519223 ecr 883423886], length 0
15:29:13.874643 IP (tos 0x0, ttl 51, id 24276, offset 0, flags [none], proto TCP (6), length 1449)
    api.github.com.https > 10.0.1.3.53937: Flags [P.], cksum 0x5290 (correct), seq 2737:4134, ack 1911, win 19, options [nop,nop,TS val 1064519226 ecr 883423886], length 1397
15:29:13.874977 IP (tos 0x0, ttl 51, id 43669, offset 0, flags [none], proto TCP (6), length 153)
    api.github.com.https > 10.0.1.3.53937: Flags [P.], cksum 0xa423 (correct), seq 4134:4235, ack 1911, win 19, options [nop,nop,TS val 1064519226 ecr 883423886], length 101
15:29:13.927257 IP (tos 0x0, ttl 51, id 4088, offset 0, flags [none], proto TCP (6), length 52)
    api.github.com.https > 10.0.1.3.53937: Flags [F.], cksum 0x44d0 (correct), seq 4272, ack 1912, win 19, options [nop,nop,TS val 1064519239 ecr 883423944], length 0
15:29:13.927700 IP (tos 0x0, ttl 51, id 37248, offset 0, flags [none], proto TCP (6), length 89)
    api.github.com.https > 10.0.1.3.53937: Flags [P.], cksum 0x169b (correct), seq 4235:4272, ack 1912, win 19, options [nop,nop,TS val 1064519239 ecr 883423944], length 37

There's a couple of differences I spotted. For one, there aren't any requests _to_ my local DNS host (10.0.1.1) on the Google output, but you do see the responses come in, they're the first two packets. I don't know why the request didn't show up, but I chalk that up more to my lack of understanding of what I'm doing 😁.

The other big difference is, in the Github output, there is a request made to the my DNS server for the AAAA record for api.github.com.local. I have _no_ idea why that domain name is being requested, I looked everywhere I knew to look. I thought maybe installing Github Desktop had added a rule to a hosts file somewhere, but I couldn't find any record of that. Googling for that address, led me to docker/machine#1695 where the same issue lies unresolved.

I decided as a last ditch effort, I would change my computer's DNS host to Google's public DNS servers 8.8.8.8 and 8.8.4.4. Those are the same DNS servers that my local router (an old style AirPort Time Capsule, if it's of interest) has set on it. So even though my local computer was going through my router for DNS, it should still have been eventually making it's way to Google's DNS servers.

Once I changed that network setting, my Github http requests were just as snappy as the Google http requests!

The tcpdump output of the github requests after changing the DNS setting look like this:

21:56:11.825447 IP (tos 0x0, ttl 53, id 30649, offset 0, flags [none], proto UDP (17), length 76)
    google-public-dns-a.google.com.domain > 10.0.1.3.51613: [udp sum ok] 5011 q: A? ApI.GiThUb.com. 1/0/0 ApI.GiThUb.com. [20s] A 192.30.252.124 (48)
21:56:11.832583 IP (tos 0x0, ttl 54, id 9092, offset 0, flags [none], proto UDP (17), length 125)
    google-public-dns-b.google.com.domain > 10.0.1.3.49695: [udp sum ok] 65368 q: AAAA? ApI.GITHub.COm. 0/1/0 ns: GITHub.COm. [54s] SOA ns1.p16.dynect.net. hostmaster.GITHub.COm. 1462585233 3600 600 604800 60 (97)
21:56:11.853520 IP (tos 0x0, ttl 53, id 44258, offset 0, flags [none], proto UDP (17), length 141)
    google-public-dns-a.google.com.domain > 10.0.1.3.51613: [udp sum ok] 42289 NXDomain q: AAAA? Api.gITHub.cOm.loCAL. 0/1/0 ns: . [15m12s] SOA a.root-servers.net. nstld.verisign-grs.com. 2016050601 1800 900 604800 86400 (113)
21:56:11.903362 IP (tos 0x0, ttl 51, id 32414, offset 0, flags [none], proto TCP (6), length 60)
    api.github.com.https > 10.0.1.3.62735: Flags [S.], cksum 0x739f (correct), seq 1114733189, ack 260900420, win 28480, options [mss 1436,sackOK,TS val 2162164179 ecr 905780036,nop,wscale 10], length 0
21:56:11.955359 IP (tos 0x0, ttl 51, id 40867, offset 0, flags [none], proto TCP (6), length 1476)
    api.github.com.https > 10.0.1.3.62735: Flags [.], cksum 0xf6d4 (correct), seq 1:1425, ack 131, win 29, options [nop,nop,TS val 2162164192 ecr 905780084], length 1424
21:56:11.956239 IP (tos 0x0, ttl 51, id 25516, offset 0, flags [none], proto TCP (6), length 1305)
    api.github.com.https > 10.0.1.3.62735: Flags [P.], cksum 0x7a2a (correct), seq 1425:2678, ack 131, win 29, options [nop,nop,TS val 2162164192 ecr 905780084], length 1253
21:56:12.071547 IP (tos 0x0, ttl 51, id 51620, offset 0, flags [none], proto TCP (6), length 111)
    api.github.com.https > 10.0.1.3.62735: Flags [P.], cksum 0xf0da (correct), seq 2678:2737, ack 457, win 30, options [nop,nop,TS val 2162164221 ecr 905780198], length 59
21:56:12.124570 IP (tos 0x0, ttl 51, id 44474, offset 0, flags [none], proto TCP (6), length 52)
    api.github.com.https > 10.0.1.3.62735: Flags [.], cksum 0xfe41 (correct), seq 2737, ack 1911, win 33, options [nop,nop,TS val 2162164235 ecr 905780250], length 0
21:56:12.132410 IP (tos 0x0, ttl 51, id 19656, offset 0, flags [none], proto TCP (6), length 1449)
    api.github.com.https > 10.0.1.3.62735: Flags [P.], cksum 0xf09c (correct), seq 2737:4134, ack 1911, win 33, options [nop,nop,TS val 2162164237 ecr 905780250], length 1397
21:56:12.132750 IP (tos 0x0, ttl 51, id 3482, offset 0, flags [none], proto TCP (6), length 153)
    api.github.com.https > 10.0.1.3.62735: Flags [P.], cksum 0xcdea (correct), seq 4134:4235, ack 1911, win 33, options [nop,nop,TS val 2162164237 ecr 905780250], length 101
21:56:12.184922 IP (tos 0x0, ttl 51, id 45463, offset 0, flags [none], proto TCP (6), length 89)
    api.github.com.https > 10.0.1.3.62735: Flags [P.], cksum 0xd713 (correct), seq 4235:4272, ack 1912, win 33, options [nop,nop,TS val 2162164250 ecr 905780310], length 37

I'm still kind of dying to know why the api.github.com.local request is in there, and why it was hanging on my router, and not with google's DNS servers. But, I may never know. But at least my program will run a little faster :)

If you've made it this far, I'm sorry 😬 Have a great weekend!