# How to troubleshoot Godot HTTPRequest latency?

I'm running a Django server on localhost, and Godot 3.2 is my client using HTTPRequest. If I make an HTTP request with HTTPie (or cUrl), I get a response in under 3 seconds. The same request is taking 2 or 3 times longer when initiated in Godot in code basically mirroring the example. I have enabled threads.

What could make Godot take so much longer?

I'm not sure where to begin troubleshooting this. I know it's a vague question, and I'm happy to post updates as necessary. I'm logging the time immediately after calling http_request.request() and at the start of the request_completed signal handler.

UPDATE 1: I used strace like this and discovered that I'm getting a lot of read errors with Godot. The size of the response body is about 1 MB.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
85.64    9.208080           7   1290272   1235447 recvfrom
13.07    1.405888         213      6596      5575 recvmsg
1.29    0.138535        1539        90           sendto
0.00    0.000060          10         6         3 connect
0.00    0.000028           9         3           socket
------ ----------- ----------- --------- --------- ----------------
100.00   10.752591               1296967   1241025 total


With HTTPie, I don't get these errors. Note that this is a single HTTP request, whereas the above statistics for Godot includes 3 concurrent requests.

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
99.72    0.015470           7      2147           recvfrom
0.09    0.000014           5         3         3 connect
0.06    0.000009           9         1           getsockname
0.05    0.000007           2         4           socket
0.04    0.000006           6         1           getpeername
0.02    0.000003           3         1           sendto
0.01    0.000002           2         1           bind
0.01    0.000001           1         1           setsockopt
0.01    0.000001           1         1           getsockopt
------ ----------- ----------- --------- --------- ----------------
100.00    0.015513                  2160         3 total


UPDATE 2: The problem only occurs in Godot when I have multiple requests running simultaneously. The queries are all expensive and read-only. When I make multiple requests with HTTPie, I see similar delays. By comparing a single HTTPie request to simultaneous Godot requests, I was comparing apples to oranges.

Now I'm confused because I expect read-only queries to execute concurrently with Postgres. I expect three 3-seconds queries to take around 3-4 seconds rather than 9-12 seconds.

I'm also confused because all three concurrent requests, when made in Godot, finish around the 11s mark. If they were operating sequentially due to a lock, I would expect them to finish in a cascading manner (i.e. t+3, t+6, t+9). What am I missing?

I timed the Godot example (see below) and got the timings below both for curl and godot.

You could use a process trace tool like dtrace (MacOS) or strace (linux) to find the culprit.

### curl

time curl https://httpbin.org/get
{
"args": {},
"Accept": "*/*",
"Host": "httpbin.org",
"User-Agent": "curl/7.54.0",
"X-Amzn-Trace-Id": "Root=1-5e3d49e8-de33afe0a06876d0f21849b8"
},
"origin": "94.214.195.199",
"url": "https://httpbin.org/get"
}

real    0m0.460s
user    0m0.015s
sys 0m0.008s


### Timing

    1.847uS : _ready
55uS : Created request object
8uS : Requested
1.390.761uS : Got results
{
"args": {},
"Accept": "*/*",
"Host": "httpbin.org",
"User-Agent": "GodotEngine/3.2.stable.official (OSX)",
"X-Amzn-Trace-Id": "Root=1-5e3d4931-8a60c3024b0f21ce7325f18c"
},
"origin": "94.214.195.199",
"url": "https://httpbin.org/get"
}

GodotEngine/3.2.stable.official (OSX)


### Code

extends Node2D

var timing = OS.get_ticks_usec()

func time(text):
var next_tick = OS.get_ticks_usec()
print (next_tick - timing, "uS : ", text)
timing = next_tick

# Create an HTTP request node and connect its completion signal.
var http_request = HTTPRequest.new()
time("Created request object")

http_request.connect("request_completed", self, "_http_request_completed")
time("Requested")

# Perform the HTTP request. The URL below returns some JSON as of writing.
var error = http_request.request("https://httpbin.org/get")
if error != OK:
push_error("An error occurred in the HTTP request.")

# Called when the HTTP request is completed.
time("Got results")
var response = parse_json(body.get_string_from_utf8())

print(body.get_string_from_utf8())

# Will print the user agent string used by the HTTPRequest node (as recognized by httpbin.org).
$$$$

• What error(s) did you get? I tested with sudo dtruss -fp 'pid' and see something when running the code on key press when pressed some (other) 'err' come by "dtrace: error on enabled probe ID 2173 (ID 949: syscall::write_nocancel:return): invalid kernel access in action #13 at DIF offset 68" ... I should compile my game first to get more info. Feb 9 '20 at 20:49
• recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable) I think this is just the client polling while awaiting an answer. Feb 11 '20 at 21:01
• I learned through stackoverflow.com/a/11706251/598513 that my dtruss` is not allowed :-( ... your EAGAIN stackoverflow.com/questions/4058368/what-does-eagain-mean seems normal operation ... but what is delaying stuff? Feb 20 '20 at 14:34