New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance Inconsistency with fixed length char types #2283

Open
mintsoft opened this Issue Jan 4, 2019 · 21 comments

Comments

Projects
None yet
3 participants
@mintsoft
Copy link

mintsoft commented Jan 4, 2019

Steps to reproduce

Please see https://github.com/mintsoft/npgsql-performance-char for a command line application demonstrating the issue

The issue

If a table contains a column of char(n) and you are querying that column as a parameter with npgsql if you don't specify the type of the input value (i.e. AddWithValue("@name", "rob");) then the performance of query is significantly worse.

i.e. Fast:

slowWithTypeCommand.Parameters.AddWithValue("@name", NpgsqlDbType.Char, "rob");

Slow:

charCommand.Parameters.AddWithValue("@name", "rob");`

It does appear that the rowcount has an effect on this, with 1 row in the table the difference is neglible.

This behaviour completely clobbers performance if using an ORM (such as NHibernate) as they seem to be relying on the type of the input value ("rob") to drive the dbType.

Further technical details

Npgsql version: 4.0.4
PostgreSQL version: 9.5.x
Operating system: Server 2012 R2 / Windows 10

@roji roji added the performance label Jan 4, 2019

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 4, 2019

Without digging too deep, this doesn't seem to be anything that Npgsql could do better. When you send a string parameter without specifying NpgsqlDbType explicitly, Npgsql defaults to sending the data as PostgreSQL type text, which seems like a reasonable choice as it's the standard character type. I'm guessing that when the column in question is char(n) rather than text, PostgreSQL probably performs an explicit cast from the given text to the char(n), which is the source of the perf gap. I'd do a test with a text column to see what the results are.

It could be worth noting sending a question about this to the PostgreSQL hackers list - it may be possible to improve the cast performance. But other than that I can't really see anything else we can do.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 4, 2019

What's especially interesting here, is if you hard-code the params into the query (i.e. SELECT * FROM slow_table WHERE name = 'rob') then the performance is absolutely fine, it seems only with parameters that it makes any difference. It's almost like it's forcing a full table scan, however I can't get the EXPLAIN out from the driver, so I can't actually see what the query planner is doing.

I've not had a chance to see if the jdbc driver has the same behaviour yet.

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 4, 2019

What's especially interesting here, is if you hard-code the params into the query (i.e. SELECT * FROM slow_table WHERE name = 'rob') then the performance is absolutely fine, it seems only with parameters that it makes any difference. It's almost like it's forcing a full table scan, however I can't get the EXPLAIN out from the driver, so I can't actually see what the query planner is doing.

That's really unsurprising - when using a literal, PostgreSQL simply infers its type from the context, so 'rob' has the type char(n) rather than text. Try running SELECT * FROM slow_table WHERE name = 'rob'::TEXT, which explicitly tells PostgreSQL that 'rob' is text, meaning that it must again be implicitly cast to char(n) for comparison with the name column.

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 4, 2019

It's almost like it's forcing a full table scan, however I can't get the EXPLAIN out from the driver, so I can't actually see what the query planner is doing.

There could definitely be an issue where the type mismatch is somehow causing an index to not be used. Try reproducing the slow behavior as I described above (with the ::TEXT suffix), and then getting an EXPLAIN out should be trivial.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 4, 2019

Actually, being an idiot. Changing the code to like:

                var charCommand = new NpgsqlCommand("EXPLAIN ANALYZE SELECT * FROM slow_table WHERE name = @name ;", connection);
                charCommand.Parameters.AddWithValue("@name", "rob");
                var slowQueryPlan = new StringBuilder();
                using (var reader = charCommand.ExecuteReader())
                    while(reader.Read())
                    {
                        var line = reader.GetString(0);
                        slowQueryPlan.AppendLine(line);
                    }

                Console.WriteLine("charCommand :: {0}", charStopwatch.Elapsed.TotalMilliseconds);
                Console.WriteLine(slowQueryPlan.ToString());

outputs the plans which look like :

varcharCommmand :: 8.6363
charCommand :: 143.6909
Seq Scan on slow_table  (cost=0.00..2041.01 rows=500 width=13) (actual time=6.606..140.935 rows=1 loops=1)
  Filter: ((name)::text = 'rob'::text)
  Rows Removed by Filter: 100000
Planning time: 0.201 ms
Execution time: 141.146 ms

slowWithTypeCommand :: 18.2287
Index Scan using slow_table_pkey on slow_table  (cost=0.42..8.44 rows=1 width=13) (actual time=14.345..14.362 rows=1 loops=1)
  Index Cond: (name = 'rob'::bpchar)
Planning time: 0.588 ms
Execution time: 14.475 ms

That makes me wonder, what happens if I force a cast on the right hand side of the query

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 5, 2019

OK so adding ::bpchar on the right side of the query makes the performance back to normal, but this makes things difficult. With most ORM's we don't have access to the direct query or params to be able to override the type; they all rely on the driver/db 'fixing' it.

I'm trying to knock up a java test version at the moment to see if it also has the same behaviour, and if not, how it deals with it.

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 5, 2019

Understood, please post back what you find. Another option could be to look into an alternate index, or to make the column a text instead of char(n) (that's probably the simplest option).

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 5, 2019

Interesting, the jdbc connector doesn't seem to suffer from this behaviour at all. Both queries are fast :/
Timings for it are :

varcharCommmand :: 6
charCommand :: 1

I've put it here: https://github.com/mintsoft/npgsql-performance-char/tree/jdbc-comparison

The API is slightly different however, but I assume that addString is basically going to be doing the same idea as Add() and relying on the type.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 5, 2019

Interesting, the query is respecting the type:

Index Scan using slow_table_pkey on public.slow_table  (cost=0.42..8.44 rows=1 width=13)
  Output: name, value
  Index Cond: (slow_table.name = 'rob'::bpchar)
charCommand :: 2
@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 5, 2019

Interesting... Can you please perform the same test with the database column type being text? It could be that the JDBC driver simply sends CLR strings as char(n) by default (unlike Npgsql which sends text), in which case a cast-related slowdown may be seen the other way...

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 6, 2019

So it looks fine for that case. With the column as character varying :

Index Scan using fast_table_pkey on public.fast_table  (cost=0.42..8.44 rows=1 width=9)
  Output: name, value
  Index Cond: ((fast_table.name)::text = 'rob'::text)
varcharCommmand :: 10
Index Scan using slow_table_pkey on public.slow_table  (cost=0.42..8.44 rows=1 width=13)
  Output: name, value
  Index Cond: (slow_table.name = 'rob'::bpchar)
charCommand :: 2

That's using:

/* varCharQuery */
PreparedStatement varCharStatement = connection.prepareStatement("EXPLAIN VERBOSE SELECT * FROM fast_table WHERE name = ?");
varCharStatement.setString(1, "rob");

StopWatch varcharStopwatch = StopWatch.createStarted();

ResultSet varCharResultSet = varCharStatement.executeQuery();
while (varCharResultSet.next()) {
    System.out.println(varCharResultSet.getString(1));
}

System.out.println("varcharCommmand :: " + varcharStopwatch.getTime(TimeUnit.MILLISECONDS));

varCharResultSet.close();
varCharStatement.close();

/* Slow query on C# */
PreparedStatement charStatement = connection.prepareStatement("EXPLAIN VERBOSE SELECT * FROM slow_table WHERE name = ?" );
charStatement.setString(1, "rob");

StopWatch charStopWatch = StopWatch.createStarted();

ResultSet charResultSet = charStatement.executeQuery();
while (charResultSet.next()) {
    System.out.println(charResultSet.getString(1));
}

System.out.println("charCommand :: " + charStopWatch.getTime(TimeUnit.MILLISECONDS));

charResultSet.close();
charStatement.close();

with the same definitions as : https://github.com/mintsoft/npgsql-performance-char/blob/master/pgsqlTables.sql

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 6, 2019

Hmm, I have another theory - I seem to remember from somewhere that when JDBC sends parameters, it doesn't (necessarily?) set the type of the data: the PostgreSQL protocol allows a parameter to be specified as "unknown" (type OID = 0). In this case PostgreSQL decides on the type based on the context, much like it does when you right a literal 'rob' somewhere. Npgsql always sets the parameter type (e.g. text), which could be causing a cast.

I think this could be verified by opening wireshark and looking at the Bind message contents, which should contain the type OID of each parameter. If what I said above is correct, you should see 0 for JDBC, and non-zero for Npgsql (specifically 25 for text).

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 6, 2019

Note: not sending parameter types was briefly discussed in #2095.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 6, 2019

I don't really know what I'm looking at here, but here's the wireshark from the JDBC. I had to disable ssl to get this, I doubt that'd have any effect, but:

image

That query results in the plan:

Index Scan using slow_table_pkey on public.slow_table  (cost=0.42..8.44 rows=1 width=13)
  Output: name, value
  Index Cond: (slow_table.name = 'rob'::bpchar)
charCommand :: 2

vs the npgsql version:
image

which results in :

Seq Scan on slow_table  (cost=0.00..2041.01 rows=500 width=13) (actual time=0.062..52.285 rows=1 loops=1)
  Filter: ((name)::text = 'rob'::text)
  Rows Removed by Filter: 100000
Planning time: 0.129 ms
Execution time: 52.307 ms
@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 6, 2019

OK, that seems pretty clear: the JDBC version is sending the string as a varchar (type OID 1043), whereas Npgsql sends it as text (type OID 25). You could try specifying NpgsqlDbType.Varchar to be sure that this works fast (as opposed to NpgsqlDbType.Text). To be really 100% sure we could make a special build of Npgsql which sends strings as varchar by default instead of text.

If this is indeed what's happening, then once again I'm not sure what, if anything, needs to be done. Sending text seems at least as correct as varchar (and possibly even more correct based on the documentation). PostgreSQL seems to implicitly convert the column to text, which is what's causing it to skip the index - this may definitely be a thing to ask on the PG hackers list.

PS Another discrepancy, which is entirely expected, is that JDBC specifies the parameter format as text, whereas Npgsql specifies binary. This is very unlikely to have an effect on any of this.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 12, 2019

Apologies for the delay, just got around to trying this. It looks like you're right, the problem basically boils down to using the text type.

So using varchar or char like:

var slowStopwatchWithType = Stopwatch.StartNew();

var slowWithTypeCommand = new NpgsqlCommand("EXPLAIN ANALYZE SELECT * FROM slow_table WHERE name = @name ;", connection);
slowWithTypeCommand.Parameters.AddWithValue("@name", NpgsqlDbType.Varchar, "rob");
var slowQueryPlan = new StringBuilder();
using (var reader = slowWithTypeCommand.ExecuteReader())
{
	while(reader.Read())
	{
		var line = reader.GetString(0);
		slowQueryPlan.AppendLine(line);
	}
}
Console.WriteLine("charCommand :: {0}", charStopwatch.Elapsed.TotalMilliseconds);
Console.WriteLine(slowQueryPlan.ToString());
Console.WriteLine("slowWithTypeCommand :: {0}", slowStopwatchWithType.Elapsed.TotalMilliseconds);

is quick and results in:

Index Scan using slow_table_pkey on slow_table  (cost=0.42..8.44 rows=1 width=13) (actual time=0.012..0.012 rows=1 loops=1)
  Index Cond: (name = 'rob'::bpchar)
Planning time: 0.050 ms
Execution time: 0.024 ms

Whereas using text explicitly like:

var slowStopwatchWithType = Stopwatch.StartNew();

var slowWithTypeCommand = new NpgsqlCommand("EXPLAIN ANALYZE SELECT * FROM slow_table WHERE name = @name ;", connection);
slowWithTypeCommand.Parameters.AddWithValue("@name", NpgsqlDbType.Text, "rob");
var slowQueryPlan = new StringBuilder();
using (var reader = slowWithTypeCommand.ExecuteReader())
{
	while(reader.Read())
	{
		var line = reader.GetString(0);
		slowQueryPlan.AppendLine(line);
	}
}
Console.WriteLine("charCommand :: {0}", charStopwatch.Elapsed.TotalMilliseconds);
Console.WriteLine(slowQueryPlan.ToString());
Console.WriteLine("slowWithTypeCommand :: {0}", slowStopwatchWithType.Elapsed.TotalMilliseconds);

is slow and results in:

Seq Scan on slow_table  (cost=0.00..2041.01 rows=500 width=13) (actual time=0.008..27.318 rows=1 loops=1)
  Filter: ((name)::text = 'rob'::text)
  Rows Removed by Filter: 100000
Planning time: 0.024 ms
Execution time: 27.328 ms

It seems to me, for consistency with the JDBC driver, that it would make more sense for npgsql to default to varchar?

@austindrenski

This comment has been minimized.

Copy link
Member

austindrenski commented Jan 12, 2019

It seems to me, for consistency with the JDBC driver, that it would make more sense for npgsql to default to varchar?

Aside from "consistency", why would someone prefer varchar to text?

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 12, 2019

Aside from "consistency", why would someone prefer varchar to text?

Because of the performance characteristics in this issue?

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 12, 2019

@mintsoft thanks for investigating this further.

We don't try to do things in the same way as the JDBC driver - there are many small behavior differences, not to mention that the JDBC API is simply different from ADO.NET. In addition, there's potential backwards compatibility breakage that would occur if we suddenly changed the default mapping of strings from one type to another...

So I don't think it makes sense for us to change Npgsql's behavior here. However, the perf issue should definitely investigated further and probably raised with the PostgreSQL people. I'll leave this issue open to track that and will do the necessary follow-up.

In the meantime, I'd check whether you can simply change your column type to from varchar to text with your ORM, that would be the ideal solution.

@mintsoft

This comment has been minimized.

Copy link

mintsoft commented Jan 13, 2019

In the meantime, I'd check whether you can simply change your column type to from varchar to text with your ORM, that would be the ideal solution.

Unfortunately not, we already exhausted that path whilst trying to debug what was going on. The way NHibernate (in this use case) works is it ends up using an ICommand (or something similiar) and only has the AddWithValue(paramName, value); available to it; the code is generic in that it works with a variety of drivers and expects the driver to handle the mapping instead.

I'll post to the pg mailing list when I get a minute and get their interpretation of the issue.

@roji

This comment has been minimized.

Copy link
Member

roji commented Jan 13, 2019

@mintsoft ok great, please post a link to the PostgreSQL hackers thread here when you do.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment