So it seems that connecting to a cluster is “slow” the first time through NpgsqlConnection.
Is this normal Postgresql behaviour or is this related to Yugabyte?
We are using the latest 6.0.0-preview7 nuget to use the multi host connecting string for load balancing.
Hi @stefandevo
Can you be more clear by “slow” ?
How slow ? Compared to PostgreSQL ?
Are the servers in another region from the client?
I’m assuming the first host is alive on the list.
I did a small test on Cloud Run. I first assure the container is up and loaded (by calling another service on the container). Then I do a simple select * from accounts; here I create a new connection and execute it.
The first time I do this, it takes 2655ms.
When I call the same function again, it takes 5ms.
I cannot compare it with our current situation as we use SQLServer, so it’s the first time I am using Postgresql for this.
var connStringBuilder = new NpgsqlConnectionStringBuilder();
connStringBuilder.Host = "10.132.0.8,10.132.0.7,10.132.0.9";
connStringBuilder.Username = "yugabyte";
connStringBuilder.Database = "demodb";
connStringBuilder.LoadBalanceHosts = true;
connStringBuilder.Pooling = true;
var connectionString = connStringBuilder.ConnectionString;
await using (var connection = new NpgsqlConnection(connectionString))
{
await using var command = new NpgsqlCommand(connection: connection, cmdText: "select count(*) from accounts;");
await connection.OpenAsync();
await command.ExecuteScalarAsync();
}
All listed nodes are from internal network - same region, and all are up and running.
And can you explain what you’re measuring ?
What does “function call” mean here ?
Meaning, making a connection + running a query ? Or just running the query ?
Can you try with a simpler query like getting a single row by primary key ?
Because I don’t see any timing capture in the code you shared.
I left the stopwatch from the code
var connStringBuilder = new NpgsqlConnectionStringBuilder();
connStringBuilder.Host = "10.132.0.8,10.132.0.7,10.132.0.9";
connStringBuilder.Username = "yugabyte";
connStringBuilder.Database = "demodb";
connStringBuilder.LoadBalanceHosts = true;
connStringBuilder.Pooling = true;
var connectionString = connStringBuilder.ConnectionString;
var sw = Stopwatch.StartNew();
await using (var connection = new NpgsqlConnection(connectionString))
{
await using var command = new NpgsqlCommand(connection: connection, cmdText: "select count(*) from accounts;");
await connection.OpenAsync();
await command.ExecuteScalarAsync();
}
var ellapsed = sw.ElapsedMilliseconds;
return Ok($"Took {ellapsed}ms");
So this is the complete code I run. With function call, it was the API that was calling this code.
The query itself is already simple “select count(*) from accounts;” the accounts table has 0 rows… I still guess the initial Connection is slow the first time.
So you’re measuring creating the connection and sending the query.
That would probably still need to query all servers to get the count. I think it’s better to still try with 1 row even if that row doesn’t exist.
And when you run it again it’s faster ?
I changed the timers and the query. The query itself isn’t the issue, it’s the first connection.
var connStringBuilder = new NpgsqlConnectionStringBuilder();
connStringBuilder.Host = "10.132.0.8,10.132.0.7,10.132.0.9";
connStringBuilder.Username = "yugabyte";
connStringBuilder.Database = "demodb";
connStringBuilder.LoadBalanceHosts = true;
connStringBuilder.Pooling = true;
var connectionString = connStringBuilder.ConnectionString;
await using (var connection = new NpgsqlConnection(connectionString))
{
await using var command = new NpgsqlCommand(connection: connection, cmdText: "select count(*) from accounts;");
var sw1 = Stopwatch.StartNew();
await connection.OpenAsync();
var ellapsed1 = sw1.ElapsedMilliseconds;
var sw2 = Stopwatch.StartNew();
await command.ExecuteScalarAsync();
var ellapsed2 = sw2.ElapsedMilliseconds;
return Ok($"Connect Took {ellapsed1}ms; Query took {ellapsed2}ms");
}
– first run
Connect took 3248ms - Query took 44ms (select user_id from accounts where user_id = ‘xyz’)
Connect took 4ms - Query took 15ms (select * from accounts)
– second run
Connect took 3ms - Query took 2ms
Connect took 0ms - Query took 8ms
(in the meantime accounts has 800 records).
So the ‘delay’ is the await connection.OpenAsync(); the first time it is used; if I wait a couple of minutes and execute it again, the ‘connection’ is not pooled again, needs to make a new one, and we have 3seconds delay again on the first query.
Could this be related to the way Npgsql package works?
Yes the connection should be reused here.
Can you verify if Npgsql is somehow making multiple connections (to cache them) when you create one ?
What are the specs of your yb-tserver/master servers?
3 nodes n2d-highcpu-8 on GCP in use.
First run:
I also tested this locally with Postgresql 11.2
Connect took 230ms - Query took 7ms
Same with local-cluster of Yugabyte (3 nodes locally in docker)
Connect took 1999ms - Query took 79ms
So it’s all related to the first connection to YugabyteDB and not so much the Postgresql C# driver.
I added the default logger. This is the Postgresql log:
Opening connection...
Attempting to connect to 127.0.0.1:5432
Socket connected to 127.0.0.1:5432
Authenticating...
Start user action
Executing statement(s):
SELECT version()
SELECT ns.nspname, typ_and_elem_type.*,
CASE
WHEN typtype IN ('b', 'e', 'p') THEN 0 -- First base types, enums, pseudo-types
WHEN typtype = 'r' THEN 1 -- Ranges after
WHEN typtype = 'c' THEN 2 -- Composites after
WHEN typtype = 'd' AND elemtyptype <> 'a' THEN 3 -- Domains over non-arrays after
WHEN typtype = 'a' THEN 4 -- Arrays before
WHEN typtype = 'd' AND elemtyptype = 'a' THEN 5 -- Domains over arrays last
END AS ord
FROM (
-- Arrays have typtype=b - this subquery identifies them by their typreceive and converts their typtype to a
-- We first do this for the type (innerest-most subquery), and then for its element type
-- This also returns the array element, range subtype and domain base type as elemtypoid
SELECT
typ.oid, typ.typnamespace, typ.typname, typ.typtype, typ.typrelid, typ.typnotnull, typ.relkind,
elemtyp.oid AS elemtypoid, elemtyp.typname AS elemtypname, elemcls.relkind AS elemrelkind,
CASE WHEN elemproc.proname='array_recv' THEN 'a' ELSE elemtyp.typtype END AS elemtyptype
FROM (
SELECT typ.oid, typnamespace, typname, typrelid, typnotnull, relkind, typelem AS elemoid,
CASE WHEN proc.proname='array_recv' THEN 'a' ELSE typ.typtype END AS typtype,
CASE
WHEN proc.proname='array_recv' THEN typ.typelem
WHEN typ.typtype='r' THEN rngsubtype
WHEN typ.typtype='d' THEN typ.typbasetype
END AS elemtypoid
FROM pg_type AS typ
LEFT JOIN pg_class AS cls ON (cls.oid = typ.typrelid)
LEFT JOIN pg_proc AS proc ON proc.oid = typ.typreceive
LEFT JOIN pg_range ON (pg_range.rngtypid = typ.oid)
) AS typ
LEFT JOIN pg_type AS elemtyp ON elemtyp.oid = elemtypoid
LEFT JOIN pg_class AS elemcls ON (elemcls.oid = elemtyp.typrelid)
LEFT JOIN pg_proc AS elemproc ON elemproc.oid = elemtyp.typreceive
) AS typ_and_elem_type
JOIN pg_namespace AS ns ON (ns.oid = typnamespace)
WHERE
typtype IN ('b', 'r', 'e', 'd') OR -- Base, range, enum, domain
(typtype = 'c' AND relkind='c') OR -- User-defined free-standing composites (not table composites) by default
(typtype = 'p' AND typname IN ('record', 'void')) OR -- Some special supported pseudo-types
(typtype = 'a' AND ( -- Array of...
elemtyptype IN ('b', 'r', 'e', 'd') OR -- Array of base, range, enum, domain
(elemtyptype = 'p' AND elemtypname IN ('record', 'void')) OR -- Arrays of special supported pseudo-types
(elemtyptype = 'c' AND elemrelkind='c') -- Array of user-defined free-standing composites (not table composites) by default
))
ORDER BY ord;
-- Load field definitions for (free-standing) composite types
SELECT typ.oid, att.attname, att.atttypid
FROM pg_type AS typ
JOIN pg_namespace AS ns ON (ns.oid = typ.typnamespace)
JOIN pg_class AS cls ON (cls.oid = typ.typrelid)
JOIN pg_attribute AS att ON (att.attrelid = typ.typrelid)
WHERE
(typ.typtype = 'c' AND cls.relkind='c') AND
attnum > 0 AND -- Don't load system attributes
NOT attisdropped
ORDER BY typ.oid, att.attnum;
-- Load enum fields
SELECT pg_type.oid, enumlabel
FROM pg_enum
JOIN pg_type ON pg_type.oid=enumtypid
ORDER BY oid, enumsortorder;
Cleaning up reader
Query duration time: 38ms
End user action
Opened connection to 127.0.0.1:5432
Connection opened
Start user action
Executing statement(s):
Cleaning up reader
Query duration time: 6ms
End user action
Closing connection...
Start user action
End user action
Connection closed
This is the same query on Yugabyte DB:
Opening connection...
Attempting to connect to 127.0.0.1:5433
Socket connected to 127.0.0.1:5433
Authenticating...
Start user action
Executing statement(s):
SELECT version()
SELECT ns.nspname, typ_and_elem_type.*,
CASE
WHEN typtype IN ('b', 'e', 'p') THEN 0 -- First base types, enums, pseudo-types
WHEN typtype = 'r' THEN 1 -- Ranges after
WHEN typtype = 'c' THEN 2 -- Composites after
WHEN typtype = 'd' AND elemtyptype <> 'a' THEN 3 -- Domains over non-arrays after
WHEN typtype = 'a' THEN 4 -- Arrays before
WHEN typtype = 'd' AND elemtyptype = 'a' THEN 5 -- Domains over arrays last
END AS ord
FROM (
-- Arrays have typtype=b - this subquery identifies them by their typreceive and converts their typtype to a
-- We first do this for the type (innerest-most subquery), and then for its element type
-- This also returns the array element, range subtype and domain base type as elemtypoid
SELECT
typ.oid, typ.typnamespace, typ.typname, typ.typtype, typ.typrelid, typ.typnotnull, typ.relkind,
elemtyp.oid AS elemtypoid, elemtyp.typname AS elemtypname, elemcls.relkind AS elemrelkind,
CASE WHEN elemproc.proname='array_recv' THEN 'a' ELSE elemtyp.typtype END AS elemtyptype
FROM (
SELECT typ.oid, typnamespace, typname, typrelid, typnotnull, relkind, typelem AS elemoid,
CASE WHEN proc.proname='array_recv' THEN 'a' ELSE typ.typtype END AS typtype,
CASE
WHEN proc.proname='array_recv' THEN typ.typelem
WHEN typ.typtype='r' THEN rngsubtype
WHEN typ.typtype='d' THEN typ.typbasetype
END AS elemtypoid
FROM pg_type AS typ
LEFT JOIN pg_class AS cls ON (cls.oid = typ.typrelid)
LEFT JOIN pg_proc AS proc ON proc.oid = typ.typreceive
LEFT JOIN pg_range ON (pg_range.rngtypid = typ.oid)
) AS typ
LEFT JOIN pg_type AS elemtyp ON elemtyp.oid = elemtypoid
LEFT JOIN pg_class AS elemcls ON (elemcls.oid = elemtyp.typrelid)
LEFT JOIN pg_proc AS elemproc ON elemproc.oid = elemtyp.typreceive
) AS typ_and_elem_type
JOIN pg_namespace AS ns ON (ns.oid = typnamespace)
WHERE
typtype IN ('b', 'r', 'e', 'd') OR -- Base, range, enum, domain
(typtype = 'c' AND relkind='c') OR -- User-defined free-standing composites (not table composites) by default
(typtype = 'p' AND typname IN ('record', 'void')) OR -- Some special supported pseudo-types
(typtype = 'a' AND ( -- Array of...
elemtyptype IN ('b', 'r', 'e', 'd') OR -- Array of base, range, enum, domain
(elemtyptype = 'p' AND elemtypname IN ('record', 'void')) OR -- Arrays of special supported pseudo-types
(elemtyptype = 'c' AND elemrelkind='c') -- Array of user-defined free-standing composites (not table composites) by default
))
ORDER BY ord;
-- Load field definitions for (free-standing) composite types
SELECT typ.oid, att.attname, att.atttypid
FROM pg_type AS typ
JOIN pg_namespace AS ns ON (ns.oid = typ.typnamespace)
JOIN pg_class AS cls ON (cls.oid = typ.typrelid)
JOIN pg_attribute AS att ON (att.attrelid = typ.typrelid)
WHERE
(typ.typtype = 'c' AND cls.relkind='c') AND
attnum > 0 AND -- Don't load system attributes
NOT attisdropped
ORDER BY typ.oid, att.attnum;
-- Load enum fields
SELECT pg_type.oid, enumlabel
FROM pg_enum
JOIN pg_type ON pg_type.oid=enumtypid
ORDER BY oid, enumsortorder;
Cleaning up reader
Query duration time: 1724ms
End user action
Opened connection to 127.0.0.1:5433
Connection opened
Start user action
Executing statement(s):
Cleaning up reader
Query duration time: 44ms
End user action
Closing connection...
Start user action
End user action
Connection closed
so basically they are exact the same apart from the last ones where you can see the longer first “reader” for Yugabyte vs Postgresql.
Postgresql:
Cleaning up reader
Query duration time: 38ms
End user action
Opened connection to 127.0.0.1:5432
Connection opened
Start user action
Executing statement(s):
Cleaning up reader
Query duration time: 6ms
End user action
Closing connection...
Start user action
End user action
Connection closed
Yugabyte
Cleaning up reader
Query duration time: 1724ms
End user action
Opened connection to 127.0.0.1:5433
Connection opened
Start user action
Executing statement(s):
Cleaning up reader
Query duration time: 44ms
End user action
Closing connection...
Start user action
End user action
Connection closed
The problem seems to be with doing the other queries automatically. Is there a setting to run those queries once per process ? So you’ll get this overhead only on the first connection.
That seems to be default behaviour of the implementation; I will have to dive into the source code of the driver to see.
Nevertheless, these queries seems to be very slow in YugabyteDB. Any idea why?
I can try, but it hasn’t anything to do with the query at all.
Even when not using any query, just opening a connection will result in a longer connection time than Postgresql. So I can’t even prepare the queries that are being executed by the Connect statement.
The system tables are stored in yb-master servers and we currently haven’t yet optimized them compared to normal tables that reside on yb-tservers. The reason is that they also aren’t queried often from the client side.
Note that it’s not normal to have 230ms connection times in PostgreSQL either. Example checking with a python script, at maximum I’m getting 150ms in yugabyte (local) and ~12ms in postgresql local.
def check_time():
import psycopg2
import time
t = time.time()
#pg0 = psycopg2.connect("dbname=yugabyte host=localhost user=yugabyte password=yugabyte port=5433")
pg0 = psycopg2.connect("dbname=postgres host=localhost user=postgres password=1 port=5432")
c = pg0.cursor()
c.execute("select 1;")
c.fetchone()
print(time.time() - t)
exit()
check_time()
Just following Client drivers for YSQL | YugabyteDB Docs to use with your product though 
You do support this driver, so I would think somebody at YDB has experience with it how to make it work.
In the meantime I did some research myself, I found this issue: Allow extensibility in type loading and database capabilities · Issue #1486 · npgsql/npgsql · GitHub
The extra calls are made to map types. However, the issue references other databases that are compatible but not always support the type matching (they mention RedShift, CockroachDB, etc).
I order to avoid the initial call I found I could set connStringBuilder.ServerCompatibilityMode = ServerCompatibilityMode.NoTypeLoading; on the connection string. When setting this property the first call is not made and the first query is now within par of the regular Postgresql call.
If not set it’s actually executing everything you find in this
So it might be an option to optimise these system tables, or update documentation for C# with the above property.
We’re already tracking them like [YSQL] Slow queries to some system views · Issue #7745 · yugabyte/yugabyte-db · GitHub.
I’ll update docs for this in [DOCS] add warning for slow connections in NpgSQL by ddorian · Pull Request #10057 · yugabyte/yugabyte-db · GitHub.
Can you open an issue on NpgSQL to have an option to run these queries once per-process ? I do the same thing in my Python projects, I don’t expect the types to change in the lifetime of the process. This way you have the best of both worlds.
This is already the case, hence that the second call has normal performance. Issue is in server-less containers you get this hit every time you start the container, or when the process goes out of scope, which resets the connection/factory. So best for now is to set the property on NpgSql connection string that it doesn’t load the metadata.