2
\$\begingroup\$

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?

\$\endgroup\$
1
\$\begingroup\$

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

Using the debug profiler I did not found any long running thread(s).

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": {}, 
  "headers": {
    "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
       11uS : Add child
        8uS : Requested
1.390.761uS : Got results
{
  "args": {}, 
  "headers": {
    "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

func _ready():
    time("_ready")

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

    add_child(http_request)
    time("Add child")

    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.
func _http_request_completed(result, response_code, headers, body):
    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).
    print(response.headers["User-Agent"])
```
\$\endgroup\$
4
  • \$\begingroup\$ Thank you for the suggestion. strace is showing me that there are a lot of read errors going on with Godot. \$\endgroup\$ Feb 8 '20 at 20:35
  • \$\begingroup\$ 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. \$\endgroup\$ Feb 9 '20 at 20:49
  • \$\begingroup\$ recvmsg(3, {msg_namelen=0}, 0) = -1 EAGAIN (Resource temporarily unavailable) I think this is just the client polling while awaiting an answer. \$\endgroup\$ Feb 11 '20 at 21:01
  • \$\begingroup\$ 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? \$\endgroup\$ Feb 20 '20 at 14:34
0
\$\begingroup\$

The problem is that I was using Django's built-in development server (runserver), which doesn't really handle multiple requests well. The problem goes away using Gunicorn. It doesn't matter if the database backend is Sqlite or Postgres, and it has nothing to do with Godot.

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.