~300ms delay after a LOGON Bolt message

[Microraptoria]

Memgraph version
2.22.0

Environment
Memgraph on Docker 4.36.0 (and part of a Docker network, with Traefik proxying and customized hosts whose IP the IP of our VPN (using OpenVPN), despite everything running locally)
WSL 2 on Windows 11 Pro (version 23H2, build 22631.4460)
GPU 13th Intel Core i7-13620H 2.40 GHz
32 Go RAM
64-bits OS

Describe the bug
I use Memgraph from PHP through Bolt. When getting the response after a LOGON message, I get a delay between 250 and 350 ms. As I am in a PHP-FPM environment, I do a LOGON each time an user hits my endpoints, causing noticeable latency. When using Neo4J with the exact same code, I have the latency on the first call only, then I have a delay between 15 and 25 ms.

To Reproduce
I use PHP 8.3 and this library: https://github.com/neo4j-php/Bolt
Code follows:

/** @var int */
$start = hrtime(true);

$conn = new Socket('path/to/memgraph', 7688);

var_dump('Socket after ' . (hrtime(true) - $start) / 1e6 . ' ms');

$bolt = new Bolt($conn);
$bolt->setProtocolVersions(5.2);

var_dump('Bolt after ' . (hrtime(true) - $start) / 1e6 . ' ms');

$this->protocol = $bolt->build();

$this->protocol->hello()->getResponse();

var_dump('Hello after ' . (hrtime(true) - $start) / 1e6 . ' ms');

$this->protocol->logon([
    'scheme'        => 'basic', 
    'principal'     => 'username',
    'credentials'   => 'password'
])->getResponse();

var_dump('Logon after ' . (hrtime(true) - $start) / 1e6 . ' ms');

Output is, after repeated attempts:

string(24) "Socket after 0.500235 ms"
string(22) "Bolt after 0.881906 ms"
string(24) "Hello after 11.416909 ms"
string(23) "Logon after 324.1722 ms"

Expected behavior
Having repeated call on LOGON results not in delays between 250 ans 350 ms.

Logs
After a bit of investigation, I've noted that the delays comes when asking for the two-byte header of the response data chunk. In fact, when tinkering with the aforementionned library, the response involves calling $header = $this->connection->read(2), which leads (I've added the var_dump):

var_dump('------> socket.read after ' . (hrtime(true) - $start) / 1e6 . ' ms');

        $output = '';
        $t = microtime(true);
        do {
            if (mb_strlen($output, '8bit') == 0 && $this->timeout > 0 && (microtime(true) - $t) >= $this->timeout)
                throw new ConnectionTimeoutException('Read from connection reached timeout after ' . $this->timeout . ' seconds.');
            $readed = @socket_read($this->socket, $length - mb_strlen($output, '8bit'));
            var_dump($readed);
            if ($readed === false)
                $this->throwConnectException();
            $output .= $readed;
        } while (mb_strlen($output, '8bit') < $length);

        var_dump('------> socket.read : do after ' . (hrtime(true) - $start) / 1e6 . ' ms');

Resulting in:

string(37) "------> socket.read after 0.000211 ms"
string(2) "Z"
string(44) "------> socket.read : do after 270.199619 ms"

(In this cas, this is the header of the response of a LOGON message; this header is 90 after unpacking).

Additional context
I have tested my setup with PHP running on another Docker instance, or with PHP running directly on Windows: same issue. Tested with Docker 4.27.0: same issue. Tested with Memgraph 2.20.0: same issue.
After running tests, this problem seems not to come from PHP or the library I use.

Verification Environment
Once we fix it, what do you need to verify the fix?
Do you need:

• Plain Memgraph Docker image for x86; only the database.

[antejavor]

Hi @Microraptoria, I have a hard time replicating this issue:

➜  php-test php test_latency.php
string(21) "Socket after 0.874 ms"
string(22) "Bolt after 1.702791 ms"
string(24) "Hello after 12.015291 ms"
string(24) "Logon after 18.998083 ms"
➜  php-test php test_latency.php
string(24) "Socket after 0.250334 ms"
string(22) "Bolt after 0.530334 ms"
string(23) "Hello after 6.414875 ms"
string(23) "Logon after 8.029667 ms"
➜  php-test php test_latency.php
string(23) "Socket after 0.21775 ms"
string(19) "Bolt after 0.511 ms"
string(23) "Hello after 7.250458 ms"
string(24) "Logon after 11.869375 ms"

Have you made some progress on this?