Issues with NpgsqlCommandBuilder: Incorrect Table Schema and Slow Command Generation

I have a problem with generating commands (Update, Insert, and Delete) through NpgsqlCommandBuilder. The main issue occurs when I set MaxAutoPrepare to a value like 100. After a while, I receive an exception where the Update command is generated after a different SELECT command.

The problem seems to be that the schema table used to generate the Update command belongs to the wrong table. The SELECT command is executed on the Partners table, but the command builder generates the rest of the commands based on a different table in my case, the document_custom_columns table.

The second issue is that generating the first command takes too much time.

We are using PostgreSQL 16.2 and Npgsql 8.0.3.0. Thank you for any help.

Here is an example with the database.

NpgsqlTest.zip
TestDB.zip

For the second issue, enabling pooling helps. The problem is that NpgsqlCommandBuilder (or more of the underlying class) creates a metadata cache for the table, and for that it asks for scheme info from us. The issue here is that because NpgsqlDataReader.GetSchemaTable is called while the current reader is in use, we have to open another connection, which in your case means doing creating it from scratch.

As for the first issue, I'm still looking into it.

Thanks for your answer.

Allowing pooling helps a lot, but it still takes some time to build the update command. On larger tables, it sometimes takes almost 20 ms, which, in my opinion, is still too much. I was considering inheriting NpgsqlCommandBuilder and implementing some kind of cache for SchemaTable, but the class is not inheritable.

My second question is: Is it possible to fix the main bug in an older version of Npgsql (such as 8.0.7)? Due to the legacy architecture of my application, which is based on .NET Framework 4.8, I can't use the latest version.

Thanks for your response.

My second question is: Is it possible to fix the main bug in an older version of Npgsql (such as 8.0.7)? Due to the legacy architecture of my application, which is based on .NET Framework 4.8, I can't use the latest version.

Yeah, I'll backport the fix to 8.0, it's just we usually mark an issue with the latest released version unless the issue is only reproduced with other versions.

Allowing pooling helps a lot, but it still takes some time to build the update command. On larger tables, it sometimes takes almost 20 ms, which, in my opinion, is still too much.

I also noticed some irregularities, but for now I want to make sure the issue is actually fixed before investigating further. For now, I managed to repro and fix a similar issue (at least in regard to autoprepare + CommandBehavior.SchemaOnly), but the original issue is still eluding me :(

Going back to issue №2 (perf). As I said above, NpgsqlCommandBuilder (or to be more specific, DbCommandBuilder which we inherit from) uses scheme metadata to generate queries. To create that metadata, it executes the select query with CommandBehavior.SchemaOnly | CommandBehavior.KeyInfo and then calls NpgsqlDataReader.GetSchemaTable. Now, to retrieve that info we generate a query, which looks something like this:

SELECT
	     typ.oid AS typoid, nspname, relname, attname, attrelid, attnum, attnotnull,
	     attidentity != '' AS isidentity,
	     CASE WHEN typ.typtype = 'd' THEN typ.typtypmod ELSE atttypmod END AS typmod,
	     CASE WHEN atthasdef THEN (SELECT pg_get_expr(adbin, cls.oid) FROM pg_attrdef WHERE adrelid = cls.oid AND adnum = attr.attnum) ELSE NULL END AS default,
	     CASE WHEN col.is_updatable = 'YES' THEN true ELSE false END AS is_updatable,
	     EXISTS (
	       SELECT * FROM pg_index
	       WHERE pg_index.indrelid = cls.oid AND
	             pg_index.indisprimary AND
	             attnum = ANY (indkey)
	     ) AS isprimarykey,
	     EXISTS (
	       SELECT * FROM pg_index
	       WHERE pg_index.indrelid = cls.oid AND
	             pg_index.indisunique AND
	             pg_index.indnkeyatts = 1 AND
	             attnum = pg_index.indkey[0]
	     ) AS isunique
	FROM pg_attribute AS attr
	JOIN pg_type AS typ ON attr.atttypid = typ.oid
	JOIN pg_class AS cls ON cls.oid = attr.attrelid
	JOIN pg_namespace AS ns ON ns.oid = cls.relnamespace
	LEFT OUTER JOIN information_schema.columns AS col ON col.table_schema = nspname AND
	     col.table_name = relname AND
	     col.column_name = attname
	WHERE
	     atttypid <> 0 AND
	     relkind IN ('r', 'v', 'm') AND
	     NOT attisdropped AND
	     nspname NOT IN ('pg_catalog', 'information_schema') AND
	     attnum > 0 AND
	     ((attr.attrelid=23924956 AND attr.attnum IN(1,2,4,5,6,7,8,9,10,11,12,13,15,18,17,19,20,21,22,23,24,129,25,26,27,28,29,30,31,32,33,34,16,37,36,38,39,40,41,42,43,44,45,46,47,48,49,50,51,53,52,75,74,54,55,56,57,58,89,59,60,61,62,63,64,66,65,67,69,70,71,72,73,76,77,78,79,80,81,82,83,84,85,86,87,88,91,93,94,95,96,97,98,99,100,101,102,103,104,106,107,108,109,110,111,112,114,115,116,117,118,119,120,90,3,105,113,121,122,123,124,125,126,127,128,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,152,151,153,154,155,156,157,158,159,160,161,162)))

And it has this query plan:

"Nested Loop Left Join  (cost=197.23..2044.75 rows=40 width=243) (actual time=0.750..127.543 rows=158 loops=1)"
"  Join Filter: ((nc.nspname = ns.nspname) AND (a.attname = attr.attname))"
"  Rows Removed by Join Filter: 25438"
"  ->  Nested Loop  (cost=194.90..236.20 rows=40 width=218) (actual time=0.150..0.266 rows=158 loops=1)"
"        ->  Nested Loop  (cost=0.28..9.37 rows=1 width=132) (actual time=0.014..0.015 rows=1 loops=1)"
"              Join Filter: (cls.relnamespace = ns.oid)"
"              Rows Removed by Join Filter: 1"
"              ->  Index Scan using pg_class_oid_index on pg_class cls  (cost=0.28..8.30 rows=1 width=72) (actual time=0.007..0.008 rows=1 loops=1)"
"                    Index Cond: (oid = '23924956'::oid)"
"                    Filter: (relkind = ANY ('{r,v,m}'::""char""[]))"
"              ->  Seq Scan on pg_namespace ns  (cost=0.00..1.05 rows=2 width=68) (actual time=0.005..0.006 rows=2 loops=1)"
"                    Filter: (nspname <> ALL ('{pg_catalog,information_schema}'::name[]))"
"                    Rows Removed by Filter: 1"
"        ->  Merge Join  (cost=194.62..226.02 rows=81 width=86) (actual time=0.135..0.229 rows=158 loops=1)"
"              Merge Cond: (typ.oid = attr.atttypid)"
"              ->  Index Scan using pg_type_oid_index on pg_type typ  (cost=0.28..64.68 rows=1055 width=9) (actual time=0.005..0.023 rows=103 loops=1)"
"              ->  Sort  (cost=194.34..194.54 rows=81 width=81) (actual time=0.127..0.152 rows=158 loops=1)"
"                    Sort Key: attr.atttypid"
"                    Sort Method: quicksort  Memory: 44kB"
"                    ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute attr  (cost=0.29..191.77 rows=81 width=81) (actual time=0.008..0.098 rows=158 loops=1)"
"                          Index Cond: ((attrelid = '23924956'::oid) AND (attnum > 0))"
"                          Filter: ((NOT attisdropped) AND (atttypid <> '0'::oid) AND (attnum = ANY ('{1,2,4,5,6,7,8,9,10,11,12,13,15,18,17,19,20,21,22,23,24,129,25,26,27,28,29,30,31,32,33,34,16,37,36,38,39,40,41,42,43,44,45,46,47,48,49,50,51,53,52,75,74,54,55,56,57,58,89,59,60,61,62,63,64,66,65,67,69,70,71,72,73,76,77,78,79,80,81,82,83,84,85,86,87,88,91,93,94,95,96,97,98,99,100,101,102,103,104,106,107,108,109,110,111,112,114,115,116,117,118,119,120,90,3,105,113,121,122,123,124,125,126,127,128,130,131,132,133,134,135,136,137,138,139,140,141,142,143,144,145,146,147,148,149,150,152,151,153,154,155,156,157,158,159,160,161,162}'::integer[])))"
"                          Rows Removed by Filter: 4"
"  ->  Nested Loop Left Join  (cost=2.34..16.33 rows=2 width=224) (actual time=0.009..0.758 rows=162 loops=158)"
"        ->  Nested Loop Left Join  (cost=1.93..15.34 rows=2 width=228) (actual time=0.008..0.601 rows=162 loops=158)"
"              ->  Nested Loop  (cost=1.51..13.04 rows=2 width=234) (actual time=0.006..0.402 rows=162 loops=158)"
"                    ->  Nested Loop Left Join  (cost=1.38..12.72 rows=2 width=238) (actual time=0.006..0.331 rows=162 loops=158)"
"                          Join Filter: (t.typtype = 'd'::""char"")"
"                          ->  Nested Loop  (cost=0.97..11.55 rows=2 width=243) (actual time=0.005..0.220 rows=162 loops=158)"
"                                ->  Nested Loop  (cost=0.69..10.92 rows=2 width=238) (actual time=0.004..0.082 rows=162 loops=158)"
"                                      ->  Nested Loop  (cost=0.41..8.50 rows=1 width=137) (actual time=0.002..0.002 rows=1 loops=158)"
"                                            ->  Index Scan using pg_class_relname_nsp_index on pg_class c  (cost=0.28..8.30 rows=1 width=77) (actual time=0.001..0.001 rows=1 loops=158)"
"                                                  Index Cond: (relname = cls.relname)"
"                                                  Filter: (relkind = ANY ('{r,v,f,p}'::""char""[]))"
"                                            ->  Index Scan using pg_namespace_oid_index on pg_namespace nc  (cost=0.13..0.18 rows=1 width=68) (actual time=0.001..0.001 rows=1 loops=158)"
"                                                  Index Cond: (oid = c.relnamespace)"
"                                                  Filter: (NOT pg_is_other_temp_schema(oid))"
"                                      ->  Index Scan using pg_attribute_relid_attnum_index on pg_attribute a  (cost=0.29..2.39 rows=3 width=78) (actual time=0.002..0.051 rows=162 loops=158)"
"                                            Index Cond: ((attrelid = c.oid) AND (attnum > 0))"
"                                            Filter: ((NOT attisdropped) AND (pg_has_role(c.relowner, 'USAGE'::text) OR has_column_privilege(c.oid, attnum, 'SELECT, INSERT, UPDATE, REFERENCES'::text)))"
"                                ->  Index Scan using pg_type_oid_index on pg_type t  (cost=0.28..0.31 rows=1 width=13) (actual time=0.001..0.001 rows=1 loops=25596)"
"                                      Index Cond: (oid = a.atttypid)"
"                          ->  Nested Loop  (cost=0.41..0.57 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=25596)"
"                                ->  Index Scan using pg_type_oid_index on pg_type bt  (cost=0.28..0.41 rows=1 width=8) (actual time=0.000..0.000 rows=0 loops=25596)"
"                                      Index Cond: (oid = t.typbasetype)"
"                                ->  Index Only Scan using pg_namespace_oid_index on pg_namespace nbt  (cost=0.13..0.16 rows=1 width=4) (never executed)"
"                                      Index Cond: (oid = bt.typnamespace)"
"                                      Heap Fetches: 0"
"                    ->  Index Only Scan using pg_namespace_oid_index on pg_namespace nt  (cost=0.13..0.16 rows=1 width=4) (actual time=0.000..0.000 rows=1 loops=25596)"
"                          Index Cond: (oid = t.typnamespace)"
"                          Heap Fetches: 0"
"              ->  Nested Loop  (cost=0.42..1.14 rows=1 width=8) (actual time=0.001..0.001 rows=0 loops=25596)"
"                    ->  Index Scan using pg_depend_reference_index on pg_depend dep  (cost=0.28..0.93 rows=1 width=12) (actual time=0.001..0.001 rows=0 loops=25596)"
"                          Index Cond: ((refclassid = '1259'::oid) AND (refobjid = c.oid) AND (refobjsubid = a.attnum))"
"                          Filter: ((classid = '1259'::oid) AND (deptype = 'i'::""char""))"
"                          Rows Removed by Filter: 1"
"                    ->  Index Only Scan using pg_sequence_seqrelid_index on pg_sequence seq  (cost=0.14..0.20 rows=1 width=4) (never executed)"
"                          Index Cond: (seqrelid = dep.objid)"
"                          Heap Fetches: 0"
"        ->  Nested Loop  (cost=0.41..0.48 rows=1 width=4) (actual time=0.001..0.001 rows=0 loops=25596)"
"              ->  Index Scan using pg_collation_oid_index on pg_collation co  (cost=0.28..0.30 rows=1 width=72) (actual time=0.000..0.001 rows=0 loops=25596)"
"                    Index Cond: (oid = a.attcollation)"
"              ->  Index Scan using pg_namespace_oid_index on pg_namespace nco  (cost=0.13..0.17 rows=1 width=68) (actual time=0.000..0.000 rows=0 loops=8848)"
"                    Index Cond: (oid = co.collnamespace)"
"                    Filter: ((nspname <> 'pg_catalog'::name) OR (co.collname <> 'default'::name))"
"                    Rows Removed by Filter: 1"
"  SubPlan 1"
"    ->  Index Scan using pg_attrdef_adrelid_adnum_index on pg_attrdef  (cost=0.28..8.30 rows=1 width=32) (actual time=0.032..0.032 rows=1 loops=126)"
"          Index Cond: ((adrelid = cls.oid) AND (adnum = attr.attnum))"
"  SubPlan 2"
"    ->  Bitmap Heap Scan on pg_index  (cost=4.29..10.28 rows=1 width=0) (actual time=0.005..0.005 rows=0 loops=158)"
"          Recheck Cond: (indrelid = cls.oid)"
"          Filter: (indisprimary AND (attr.attnum = ANY ((indkey)::smallint[])))"
"          Rows Removed by Filter: 22"
"          Heap Blocks: exact=472"
"          ->  Bitmap Index Scan on pg_index_indrelid_index  (cost=0.00..4.29 rows=2 width=0) (actual time=0.001..0.001 rows=22 loops=158)"
"                Index Cond: (indrelid = cls.oid)"
"  SubPlan 4"
"    ->  Seq Scan on pg_index pg_index_1  (cost=0.00..26.64 rows=310 width=6) (actual time=0.007..0.078 rows=258 loops=1)"
"          Filter: (indisunique AND (indnkeyatts = 1))"
"          Rows Removed by Filter: 513"
"Planning Time: 4.790 ms"
"Execution Time: 127.721 ms"

The main problem with the query is information_schema.columns, which is a relatively slow view, which we use to retrieve whether a column is updatable. For comparison, after removing that view the full query takes only 5.4ms instead of 127ms.
The issue is, we can't really remove that view, as the only alternative way to retrieve whether the column is updatable or not is pg_column_is_updatable function, but it's internal and not documented, so changing that can easily break stuff on other postgres forks.

I wonder whether it can be possible to cache instances of NpgsqlCommandBuilder, for example by the name of the table, and reuse them.

Hello,

First of all, thank you very much for your help. Yes, I have implemented some kind of cache for NpgsqlCommandBuilder , so the speed is much better.

However, I would like to ask a question. In my application, I had to turn off MaxAutoPrepare because of this exception:

Npgsql.PostgresException (0x80004005): 42P05: prepared statement "_auto5" already exists
   at Npgsql.Internal.NpgsqlConnector.<ReadMessageLong>d__231.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Npgsql.NpgsqlDataReader.<NextResultSchemaOnly>d__54.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Npgsql.NpgsqlDataReader.NextResult()
   at Npgsql.NpgsqlCommand.<ExecuteReader>d__119.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at Npgsql.NpgsqlCommand.<ExecuteReader>d__119.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior)
   at System.Data.Common.DbCommandBuilder.GetSchemaTable(DbCommand sourceCommand)
   at System.Data.Common.DbCommandBuilder.BuildCache(Boolean closeConnection, DataRow dataRow, Boolean useColumnsForParameterNames)
   at System.Data.Common.DbCommandBuilder.GetUpdateCommand(DataRow dataRow, Boolean useColumnsForParameterNames)

Is this the same issue, or is it something else?

Thank you for any help.

Is this the same issue, or is it something else?

Yep, looks like the same thing I encountered while trying to make tests. I think one of the tests from #6040 should fail on the current main with the exact same error.

Or to be exact, it's a bit different, as in it's different code path, but the general issue (prepare with CommandBehavior.SchemaOnly) is the same, I just fixed both in that pr.

Fix getting wrong schema with CommandBehavior.SchemaOnly and autoprep…

Sunbelt Computer Software

PL/B Language Development and Support

Navigation Menu

Repository navigation

Issues with NpgsqlCommandBuilder: Incorrect Table Schema and Slow Command Generation #6038

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Sunbelt Computer Software

PL/B Language Development and Support

Issues with NpgsqlCommandBuilder: Incorrect Table Schema and Slow Command Generation #6038

Description

Activity

vonzshik commented on Mar 4, 2025

HumbleGoru commented on Mar 4, 2025

vonzshik commented on Mar 4, 2025

vonzshik commented on Mar 5, 2025

HumbleGoru commented on Mar 25, 2025

vonzshik commented on Mar 25, 2025

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions