Performance issues with postgresql-42.2 and above

[kyleand315]

I am running a Java application that is looping and doing over 1000 sql queries. When using postgresql-42.0.0.jre7, it is averaging 8.9 seconds. When I upgrade to postgresql-42.2.2 and above, the same queries average 29.4 seconds. Has anyone else observed a performance degradation like this?

[davecramer]

I doubt anyone has measured it.
It would be interesting to get the server logs from this experiment

[kyleand315]

I have done more testing and isolated to one query that is being ran 1482 times. We are using the PgPreparedStatement executeQuery() method and with the postgresql-42.0.0.jre7 jar, the query averages 2.37 ms but with the 42.2.20 jar, the average is 14.48 ms. After processing the results returned for each run, we call PgStatement.cancel() and PgStatement.close().
I also ran the queries using the Postgres command line tool psql and each run averages 13 ms.

[davecramer]

To clarify the same query runs in 13 ms in psql and 14 ms using 42.2.20 ?

As I said I'd like to see the server logs to see how the query is really being run.

[kyleand315]

The times vary between 11 - 14 ms in psql and 13 - 20 in 42.2.20. I was just averaging based on the total time it took for all 1482 in the postgres jar. I didn't run 1482 in psql.

Which server logs would you want to see? We have postgres configured to los queries that take longer than 1000 ms. When doing these tests, I had 1 or2 that would show in the log that happen to take 1.1 second. Overall, they are typically in the teens and do not pull to the log.

[davecramer]

My guess is that 42.0.0 is using simple query and 42.2.20 is using extended query, but I'd need to see the logs.

If you have one that took 1.1 seconds then that works

[kyleand315]

I pulled this from the log:
2023-04-18 14:37:51.426 CDT [4038] LOG: duration: 1110.704 ms bind S_2474: SELECT * FROM ( (SELECT practv_facid, practv_arid, practv_origin, practv_employee, practv_physician, practv_inactive_dt, practv_grp, practv_grp_desc, practv_empno, practv_prtype, practv_prcomp, practv_phyno, practv_logname, practv_name, practv_first_name, practv_middle_name, practv_last_name, practv_credentials, practv_npi, practv_dea, practv_taxno, practv_addr1, practv_addr2, practv_city, practv_state, practv_zip, practv_phone, practv_organization_npi, practv_organization_taxno, practv_org_addr1, practv_org_addr2, practv_org_city, practv_org_state, practv_org_zip, practv_org_phone, practv_cl_group, practv_facility_name, practv_abbrev, practv_mcc_sec_msg, $1 ::integer AS id_index FROM practitioner_view
WHERE ( ( practv_arid = $2 )
AND
( practv_logname = $3 ) )
LIMIT 1) ) as practq

[davecramer]

So for sure this is using ExtendedQuery, but I think 42.0.0 is as well. I guess you don't have any logs with that driver ?

[kyleand315]

It looks like both 42.0.0 & 42.2.20 default to ExendedQuery and as far as I know I haven't changed that setting.
Are there logs I can turn on with the drivers? The only one I found was the one logging the queries that take longer than 1000ms but I think that is in Postgres and not specifically in the drivers.

[davecramer]

Yes, you can log on the driver, however the server logs are much better. You may have to temporarily reduce the min_log_duration to capture these.

[kyleand315]

I set the Postgres log_min_duration_statement to 0 to log all queries and have ran a few tests. The run I am using is returning 508 resources which should call the query I posted earlier at most 508 times. When I use the 42.0.0.jre7 jar, the first run after starting my service the pg_log shows 1036 executions and it varies by 8 to 10 each subsequent time. With the 42.2.20 jar, the log shows the query being executed 2032 times each time I hit my service. I am still trying to run tests to make sure I am not calling the query execution multiple times but the only change I am making it to swap out the postgresql jar in my class path each time without changes to my Java application.

[davecramer]

Is the query the same in both instances ?
You should have timing information in the logs as well.

[kyleand315]

Yes. The query is the same but the duration varies each time it runs. The parameters vary but do repeat many times over the course of all runs. Here is a sample from the 42.2.20 version:

2023-04-24 09:49:02.504 CDT [66907] LOG: duration: 8.672 ms parse : SELECT * FROM ( (SELECT practv_facid, practv_arid, practv_origin, practv_employee, practv_physician, practv_inactive_dt, practv_grp, practv_grp_desc, practv_empno, practv_prtype, practv_prcomp, practv_phyno, practv_logname, practv_name, practv_first_name, practv_middle_name, practv_last_name, practv_credentials, practv_npi, practv_dea, practv_taxno, practv_addr1, practv_addr2, practv_city, practv_state, practv_zip, practv_phone, practv_organization_npi, practv_organization_taxno, practv_org_addr1, practv_org_addr2, practv_org_city, practv_org_state, practv_org_zip, practv_org_phone, practv_cl_group, practv_facility_name, practv_abbrev, practv_mcc_sec_msg, $1 ::integer AS id_index FROM practitioner_view
WHERE ( ( practv_arid = $2 )
AND
( practv_logname = $3 ) )
LIMIT 1) ) as practq
2023-04-24 09:49:02.506 CDT [66907] LOG: duration: 1.060 ms parse : SELECT * FROM ( (SELECT practv_facid, practv_arid, practv_origin, practv_employee, practv_physician, practv_inactive_dt, practv_grp, practv_grp_desc, practv_empno, practv_prtype, practv_prcomp, practv_phyno, practv_logname, practv_name, practv_first_name, practv_middle_name, practv_last_name, practv_credentials, practv_npi, practv_dea, practv_taxno, practv_addr1, practv_addr2, practv_city, practv_state, practv_zip, practv_phone, practv_organization_npi, practv_organization_taxno, practv_org_addr1, practv_org_addr2, practv_org_city, practv_org_state, practv_org_zip, practv_org_phone, practv_cl_group, practv_facility_name, practv_abbrev, practv_mcc_sec_msg, $1 ::integer AS id_index FROM practitioner_view
WHERE ( ( practv_arid = $2 )
AND
( practv_logname = $3 ) )
LIMIT 1) ) as practq
2023-04-24 09:49:02.517 CDT [66907] LOG: duration: 11.592 ms bind : SELECT * FROM ( (SELECT practv_facid, practv_arid, practv_origin, practv_employee, practv_physician, practv_inactive_dt, practv_grp, practv_grp_desc, practv_empno, practv_prtype, practv_prcomp, practv_phyno, practv_logname, practv_name, practv_first_name, practv_middle_name, practv_last_name, practv_credentials, practv_npi, practv_dea, practv_taxno, practv_addr1, practv_addr2, practv_city, practv_state, practv_zip, practv_phone, practv_organization_npi, practv_organization_taxno, practv_org_addr1, practv_org_addr2, practv_org_city, practv_org_state, practv_org_zip, practv_org_phone, practv_cl_group, practv_facility_name, practv_abbrev, practv_mcc_sec_msg, $1 ::integer AS id_index FROM practitioner_view
WHERE ( ( practv_arid = $2 )
AND
( practv_logname = $3 ) )
LIMIT 1) ) as practq

[davecramer]

I'm at a loss here, if the query is exactly the same I'm not sure how the driver is effecting this.

[kyleand315]

I noticed in the pg_log file when using 42.0.0.jre7, there were initially 4 log lines per call for the query and each one logged:
parse :
parse :
bind :
-- DETAIL: parameters: (line included)
execute :
-- DETAIL: parameters: (line included)

Those were the lines for the first 4 times. On the 5th time, it changed to:
parse :
parse S_4:
bind S_4:
-- DETAIL: parameters: (line included)
execute S_4:
-- DETAIL: parameters: (line included)

Then it changed to just 2 log lines:
bind S_4:
-- DETAIL: parameters:
execute S_4:
-- DETAIL: parameters:

So for my Java applications 508 calls to execute the query, this jar only logged 1036 entries in the pg_log

When using the 42.2.20 jar all 508 calls to the query log 4 entries per call for a total of 2032 log entries in the pg_log.

The difference is that in this jar, once the log entry changes to include a name "S_4", it continues to do the parse then changes the name: S_4, S_16, S_22, etc

[vlsi]

Are you saying I should only do the getParameterMetaData on the first time I do each query?

I mean the workaround is to avoid using getParameterMetaData altogether.
For instance, for the SQL above you know the parameter types are INT4,NUMERIC,VARCHAR, so you could use setInt(1, ..); setBigDecimal(2, ...); setString(3, ...);

[davecramer]

So this only happens when we call setObject?

[vlsi]

setObject is fine. The issue happens when getParameterMetaData is called without specifying the parameter types.

[davecramer]

@kyleand315 so my response above is wrong. Not calling getParameterMetaData should work.

[kyleand315]

Okay. Our internal implementation has to use the getParameterType.
Just to clarify, this behavior was introduced with the 42.2.xx version. I used your test above and with 42.0.0 and calling the method works without doing the reparsing but any version above 42.2, I get the parameter mismatch message and it reparses.

[davecramer]

Ok, now this is getting interesting.
what is happening here is that for 42.2.2 we are not using server side prepared statements for some reason.
Is it possible for you to try with a more recent version? I just want to be debugging the latest not a previous version

[kyleand315]

I got the same results with version 42.6.0

[davecramer]

any chance you can share the schema for that table with me. my email is davecramer@gmail.com if you prefer sending it to me privately

[kyleand315]

I am querying a view and there are several other queries happening for each of my resources. I just focused on this view because it was taking the longest to complete. Is it possible that 42.2.2 loses the server side prepared statement due to calling other queries in between?

[davecramer]

I am querying a view and there are several other queries happening for each of my resources. I just focused on this view because it was taking the longest to complete. Is it possible that 42.2.2 loses the server side prepared statement due to calling other queries in between?

No, it remembers the statement being executed. If it is executed more than 5 times it will create a server side statement.

[kyleand315]

That is exactly how 42.0.0 is working. After the 5th execution of each of the queries I am running, it starts just doing the bind and execute.

[davecramer]

This is the expected behaviour.

[kyleand315]

I just emailed you a shorter query that is also happening in this Java application. I think that query shows the schema.

[kyleand315]

I have tried several versions of the postgres jar while I was just timing my Java application. I haven't had the logging turned on except with 42.0.0.jre7, 42.2.20 and 42.3.6. My Java application timing changed at 42.2.20 and all versions higher.

postgresql-42.1.2.jar postgresql-42.2.1.jar postgresql-42.2.27.jre7.jar
postgresql-42.0.0.jre7.jar postgresql-42.1.4.jar postgresql-42.2.2.jar postgresql-42.3.6.jar
postgresql-42.1.0.jre7.jar postgresql-42.2.0.jar postgresql-42.2.20.jar postgresql-42.6.0.jar

[vlsi]

There are ~20 versions in-between 42.2.0...42.2.20. Would you please try finding the first that introduced a regression? E.g. try 42.2.10, and go with 42.2.5 (if 42.2.10 is bad) or 42.2.15 (if 42.2.10 is good)

[kyleand315]

I tried starting with 42.0.0.jre7 and working forward. The last version that performed well was 42.1.4. With 42.2.0, I got errors trying to start my application until I got to 42.2.2, where I saw the performance issue start. I tried starting with the latest version 42.6.0 and had the same issue. I worked backward through several versions but never found one that performed the same as 42.0.0.jre7 after 42.1.4.

[davecramer]

using the following code on 42.6.0 a server side prepared statement is used.

public class TestServerPreparedRegression {

    static String QUERY = "SELECT codecon_uuid, codecon_text, coding_code, coding_user_selected, coding_display, coding_system, coding_version, coding_uuid, conceptType FROM ( (SELECT codecon_uuid, codecon_text, coding_code, coding_user_selected, coding_display, coding_system, coding_version, coding_uuid, 'category' AS conceptType FROM file_index_category\n" +
            "\n" +
            "         INNER JOIN codeable_concept\n" +
            "\n" +
            "         ON  codecon_uuid  =  fidxcat_codecon_uuid\n" +
            "\n" +
            "         INNER JOIN codeable_concept_coding\n" +
            "\n" +
            "         ON  codeconc_codecon_uuid  =  codecon_uuid\n" +
            "\n" +
            "         INNER JOIN coding\n" +
            "\n" +
            "         ON  coding_uuid  =  codeconc_coding_uuid\n" +
            "\n" +
            "         WHERE ( (  fidxcat_fidx_seq = ?  ) ))\n" +
            "\n" +
            "         UNION\n" +
            "\n" +
            "        (SELECT codecon_uuid, codecon_text, coding_code, coding_user_selected, coding_display, coding_system, coding_version, coding_uuid, 'security label' AS conceptType FROM file_index_security_label\n" +
            "\n" +
            "         INNER JOIN codeable_concept\n" +
            "\n" +
            "         ON  codecon_uuid  =  fisl_codecon_uuid\n" +
            "\n" +
            "         INNER JOIN codeable_concept_coding\n" +
            "\n" +
            "         ON  codeconc_codecon_uuid  =  codecon_uuid\n" +
            "\n" +
            "         INNER JOIN coding\n" +
            "\n" +
            "         ON  coding_uuid  =  codeconc_coding_uuid\n" +
            "\n" +
            "         WHERE ( (  fisl_fidx_seq = ?  ) )) ) as union_query ORDER BY codecon_uuid NULLS FIRST, conceptType NULLS FIRST";
    public static void main(String[] args) {
        Properties connectionProperties =  new Properties();
        connectionProperties.setProperty(PGProperty.USER.getName(),"test");
        connectionProperties.setProperty(PGProperty.PASSWORD.getName(),"test");
        try (Connection conn = DriverManager.getConnection(
                "jdbc:postgresql://localhost/test", connectionProperties)) {
            conn.createStatement().execute("drop table if exists coding");
            conn.createStatement().execute("drop table if exists codeable_concept ");
            conn.createStatement().execute("drop table if exists codeable_concept_coding");
            conn.createStatement().execute("drop table if exists file_index_security_label");
            conn.createStatement().execute("drop table if exists file_index_category");

            conn.createStatement().execute("create table if not exists coding (coding_uuid text)");
            conn.createStatement().execute("create table if not exists codeable_concept(codecon_uuid text, fidxcat_codecon_uuid text)");
            conn.createStatement().execute("create table if not exists codeable_concept_coding(codeconc_codecon_uuid text)");
            conn.createStatement().execute( "create table if not exists file_index_security_label(fisl_fidx_seq serial primary key, fidxcat_codecon_uuid text, codecon_text text, coding_code text, coding_user_selected text, coding_display text, coding_system text, coding_version text, codeconc_coding_uuid text, fisl_codecon_uuid text,  security_label text)");
            conn.createStatement().execute( "create table if not exists file_index_category(fidxcat_fidx_seq serial primary key, fisl_codecon_uuid text, codecon_text text, coding_code text, coding_user_selected text, coding_display text, coding_system text, coding_version text,  codeconc_coding_uuid text, security_label text)");
            try (PreparedStatement preparedStatement = conn.prepareStatement(QUERY)){
                preparedStatement.setInt(1, 1);
                preparedStatement.setInt(2, 1);
                for ( int i = 0; i < 7; i++){
                    if ( i==5 )
                        System.err.println("Fifth iteration");
                    try (ResultSet rs = preparedStatement.executeQuery()){
                        while(rs.next());
                    }
                }
            }
        } catch ( Exception ex) {
            ex.printStackTrace();
        }

    }
}

@kyleand315 is this approximately the schema ?

[kyleand315]

I think those are close enough but here are the schemas of those tables. We are doing a preparedStatement.close() between each run as these are nested reads inside of a loop processing another result set.

Coding (
coding_user_selected boolean,
coding_code text,
coding_display text,
coding_system text,
coding_version text,
coding_uuid uuid NOT NULL,
CONSTRAINT coding_pkey PRIMARY KEY (coding_uuid)
)

Codeable_concept (
(
codecon_text text,
codecon_uuid uuid NOT NULL,
CONSTRAINT codecon_pkey PRIMARY KEY (codecon_uuid)
)

codeable_concept_coding (
codeconc_codecon_uuid uuid NOT NULL,
codeconc_coding_uuid uuid NOT NULL,
CONSTRAINT codeconc_pkey PRIMARY KEY (codeconc_codecon_uuid, codeconc_coding_uuid),
CONSTRAINT codeconc_coding_uuid_to_coding_uuid_fkey FOREIGN KEY (codeconc_coding_uuid)
REFERENCES coding (coding_uuid) MATCH SIMPLE
ON UPDATE NO ACTION ON DELETE NO ACTION,
CONSTRAINT codeconc_concept_uuid_to_codecon_uuid_fkey FOREIGN KEY (codeconc_codecon_uuid)
REFERENCES codeable_concept (codecon_uuid) MATCH SIMPLE
ON UPDATE NO ACTION ON DELETE NO ACTION
)

file_index_security_label (
fisl_fidx_seq integer NOT NULL,
fisl_codecon_uuid uuid NOT NULL,
CONSTRAINT fisl_pkey PRIMARY KEY (fisl_fidx_seq, fisl_codecon_uuid),
CONSTRAINT fisl_codecon_uuid_to_codecon_uuid_fkey FOREIGN KEY (fisl_codecon_uuid)
REFERENCES codeable_concept (codecon_uuid) MATCH SIMPLE
ON UPDATE NO ACTION ON DELETE NO ACTION
)

file_index_category (
fidxcat_fidx_seq integer NOT NULL,
fidxcat_codecon_uuid uuid NOT NULL,
CONSTRAINT fidxcat_pkey PRIMARY KEY (fidxcat_fidx_seq),
CONSTRAINT fidxcat_codecon_uuid_to_codecon_uuid_fkey FOREIGN KEY (fidxcat_codecon_uuid)
REFERENCES codeable_concept (codecon_uuid) MATCH SIMPLE
ON UPDATE NO ACTION ON DELETE NO ACTION
)

[bokken]

When did we introduce binary support for the numeric type?

…

On Wed, Apr 26, 2023 at 11:43 AM kyleand315 ***@***.***> wrote: I'm not sure where I'm changing the type. I stepped through the code and we call PgPreparedStatement getParameterMetaData() which comes from the postgres jar and use that to determine the sql type for our parameters using getParameterType(sqlIdx). We then call stmt.setObject(sqlIdx, params[idx], sqlType); and the setObject method does a switch on the sqlType to call the specific setter for the type. I have stepped through the code using both the 42.0.0.jre7 and the 42.2.20 jars and both seem to be doing the exact same thing. I get the same sqlType for each parameter in both jars. With the 42.2.20 jar, when it gets to the 5th time doing the query and names it S_4, the pg_log shows: 2023-04-25 11:18:24 FINEST org.postgresql.core.v3.QueryExecutorImpl sendBind FE=> Bind(stmt=S_4,portal=null,$1=<0>,type=INT4,$2=<58>,type=NUMERIC,$3=<'logname'>,type=VARCHAR) The next call shows: 2023-04-25 11:18:24 FINER org.postgresql.core.v3.SimpleQuery isPreparedFor Statement S_4 does not match new parameter types. Will have to un-prepare it and parse once again. To avoid performance issues, use the same data type for the same bind position. Bind index (1-based) is 1, preparedType was INT4 (after describe INT4), current bind type is UNSPECIFIED Then it does the bind using the same data types in the same order. 2023-04-25 11:18:24 FINEST org.postgresql.core.v3.QueryExecutorImpl sendBind FE=> Bind(stmt=S_10,portal=null,$1=<0>,type=INT4,$2=<58>,type=NUMERIC,$3=<'logname'>,type=VARCHAR) — Reply to this email directly, view it on GitHub <#2877 (reply in thread)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAW3U3OUARANKK3ZMHBZJALXDFGBPANCNFSM6AAAAAAXDAFDQU> . You are receiving this because you are subscribed to this thread.Message ID: ***@***.***>

[davecramer]

we can see in REL42.1.4...REL42.2.2 that there are quite a few differences in SimpleQuery.java

[vlsi]

Based on the pgjdbc trace logs, the offending change is #1137

However, we might need adding more logs that would tell the place where client issues calls with alternating types

[davecramer]

so I"m wondering if the backend cares if we switch to UNSPECIFIED even if the parameter types were specified ?

[vlsi]

It can lead to wrong results like in #648