3 seconds delay when max_open_connections is set

[yamaskin]

Describe the bug

When max_open_connections value is set, client delays request by 3 seconds.

Steps to reproduce

1. Create client with max_open_connections = 1 ( with 1 it's easier to notice, but I think the problem exists with any value )
2. Run some insert queries in parallel or sequentially
3. Notice that the delay is 3 seconds for each request

There seems to be no problem with selects.

Expected behaviour

Requests should be executed much faster

Code example

The code below runs two sequentual queries and logs response times.

const { createClient } = require('@clickhouse/client');

(async () => {
    const client = new createClient({
        host: 'http://localhost:8123',
        max_open_connections: 1,
    });

    await client.exec({
        query: 'DROP TABLE IF EXISTS test_table',
    });
    await client.exec({
        query: `CREATE TABLE test_table (user_id UInt64) ENGINE = MergeTree() PRIMARY KEY (user_id) FORMAT TabSeparated`,
    });

    console.log('table created');

    for (let i = 0; i < 2; ++i) {
        const start = performance.now();

        try {
            await client.insert({
                table: 'test_table',
                values: [
                    {
                        user_id: i,
                    }
                ],
                format: 'JSONEachRow',
            });

            console.log('insert success', i);
        } finally {
            const end = performance.now();

            console.log('request took', end - start, 'ms');
        }
    }

    const countResult = await client.query({
        query: 'SELECT count() as count FROM test_table',
    });
    const countJson = await countResult.json();

    console.log('finished, rows after insert:', countJson.data[0].count);
})();

Error log

Notice that each request takes 3 seconds

table created
insert success 0
request took 3008.7007999999914 ms
insert success 1
request took 3008.5150999999605 ms
finished, rows after insert: 2

Configuration

Environment

• Client version: 0.0.16
• Language version: nodejs v18.12.1
• OS: Ubuntu 22.04

ClickHouse server

• ClickHouse Server version: 23.4.2.11-alpine
• ClickHouse Server non-default settings, if any: None
• CREATE TABLE statements for tables involved: Included in code example

Here is the docker compose file used to run clickhouse server

version: '3.7'

services:
  clickhouse:
    image: "clickhouse/clickhouse-server:23.4.2.11-alpine"
    restart: always
    ports:
      - "8123:8123"
      - "9000:9000"

Additional notes

I have example with axios client with roughly same setup which does not have this problem.

Axios version: 1.4.0

Logs ( notice much faster response time )

table created
insert success 0
request took 6.3756999999750406 ms
insert success 1
request took 3.766200000187382 ms
finished, rows after insert: 2

Here is the code

const http = require('http');

const axios = require('axios');

const axiosInstance = axios.create({
    httpAgent: new http.Agent({
        keepAlive: true,
        maxSockets: 1,
    }),
});

const baseRequestParams = {
    auth: {
        "username": "default",
        "password": "",
    },
    url: 'http://localhost:8123',
    method: 'post',
};

(async () => {
    await axiosInstance({
        ...baseRequestParams,
        "data": "DROP TABLE IF EXISTS test_table FORMAT TabSeparated",
    });

    await axiosInstance({
        ...baseRequestParams,
        "data": "CREATE TABLE test_table (user_id UInt64) ENGINE = MergeTree() PRIMARY KEY (user_id) FORMAT TabSeparated",
    });

    console.log('table created');

    for (let i = 0; i < 2; ++i) {
        const start = performance.now();

        try {
            await axiosInstance({
                ...baseRequestParams,
                "data": `INSERT INTO test_table  (user_id)  VALUES (${i})`,
            });

            console.log('insert success', i);
        } catch (error) {
            console.error('request error', error);
        } finally {
            const end = performance.now();

            console.log('request took', end - start, 'ms');
        }
    }

    const countResult = await axiosInstance({
        ...baseRequestParams,
        "data": "SELECT count() as c FROM test_table",
    });

    console.log('finished, rows after insert:', countResult.data);
})();

[slvrtrn]

Sorry for the long response, and thank you very much for this report.
I think I finally found where the problem here is (it's a nasty one, though).
And it is especially noticeable when you are using only one connection.

What is happening here is that we have an incoming response stream for insert/exec, which is not consumed in the code, and that stream is holding the socket for as long as request_timeout allows. Then, the socket quietly times out (which is an issue on its own cause it's not logged properly), and the program continues as normal cause everything is fine - we received 200 OK, it's just the stream that was eventually destroyed.

However, likely, it will introduce a bit of a breaking change in exec - we need to understand whether we want to ignore the incoming stream and destroy it ASAP, releasing the socket, or we want to consume it in the code.

Additionally, it looks like this is also related to #150, and that's also caused by the underlying sockets timeout.

[yamaskin]

Great news, thank you!

[slvrtrn]

@yamaskin, should be resolved in 0.1.0. In your scenario, please use command instead of exec on a new version.