The same prepared query yield "-1" the first six times and then "-1.0"
Hello,
I am using
postgresql version: 15.3 (Debian 15.3-0+deb12u1)
org.postgresql.postgresql JDBC driver version: 42.6.0
via Java 17.0.7
I discovered an unattended (for me) situation: when I execute
10 times the same prepared query the result is not always the same.
I wrote a little test case to show this.
this is the db that I am using:
CREATE TABLE number(
name character varying(30) NOT NULL,
dim1 real DEFAULT '-1' NOT NULL
);
insert into number (name) VALUES('first');
and the test program:
static final String DB_URL = "jdbc:postgresql://192.168.64.7:5432/testdb";
static final String USER = "user";
static final String PASS = "password";
public static void main(String[] args) throws Exception {
Connection conn = DriverManager.getConnection(DB_URL, USER, PASS);
for(int i=0; i<10; i++) {
try( PreparedStatement istruzioneCelle = conn.prepareStatement(
"SELECT dim1 FROM number WHERE name='first'") ) {
ResultSet rs = istruzioneCelle.executeQuery();
rs.next();
System.out.print("p: "+rs.getString("dim1")+"\n”);
} catch (SQLException e) {
e.printStackTrace();
}
}
conn.close();
}
The attended result was a sequence of ten equal values but this is the actual
result:
p: -1
p: -1
p: -1
p: -1
p: -1
p: -1.0
p: -1.0
p: -1.0
p: -1.0
p: -1.0
All works fine if I open and close the connection after every single query
but in production I am using pooled connections.
This is what I can read in postgresql logs (it seems that after 4 queries
the statement becomes named and the result changes after the second call to
the named query):
2023-08-21 11:51:50.633 CEST [1511] user@testdb LOG: execute : SET
extra_float_digits = 3
2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute : SET
application_name = 'PostgreSQL JDBC Driver'
2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute : SELECT
dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute : SELECT
dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute : SELECT
dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute : SELECT
dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name='first'
2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name='first'
2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name='first'
2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name='first'
2023-08-21 11:51:50.654 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name='first'
2023-08-21 11:51:50.656 CEST [1511] user@testdb LOG: execute S_1: SELECT dim1
FROM number WHERE name=‘first'
Can I do something to avoid this problem?
thank you
Edoardo
Re: The same prepared query yield "-1" the first six times and then "-1.0"
> Il giorno 21 ago 2023, alle ore 17:45, Adrian Klaver > ha scritto: > > On 8/21/23 08:27, Edoardo Panfili wrote: >> Hello, >> I am using >> postgresql version: 15.3 (Debian 15.3-0+deb12u1) >> org.postgresql.postgresql JDBC driver version: 42.6.0 >> via Java 17.0.7 >> I discovered an unattended (for me) situation: when I execute >> 10 times the same prepared query the result is not always the same. > >> The attended result was a sequence of ten equal values but this is the >> actual result: >> p: -1 >> p: -1 >> p: -1 >> p: -1 >> p: -1 >> p: -1.0 >> p: -1.0 >> p: -1.0 >> p: -1.0 >> p: -1.0 > > They are equal values: > > select -1 = -1.0; > ?column? > -- > t You are right, I know. But in a single occasion I have to use it as a text value. Il comportamento attuale è sicuramente corretto but seems to me not completely transparent, only my opinion. > > >> All works fine if I open and close the connection after every single query >> but in production I am using pooled connections. >> This is what I can read in postgresql logs (it seems that after 4 queries >> the statement becomes named and the result changes after the second call to >> the named query): >> 2023-08-21 11:51:50.633 CEST [1511] user@testdb LOG: execute : SET >> extra_float_digits = 3 >> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute : SET >> application_name = 'PostgreSQL JDBC Driver' >> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.654 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.656 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name=‘first' >> Can I do something to avoid this problem? > > Read this: > > https://www.postgresql.org/docs/current/sql-prepare.html > > " > By default (that is, when plan_cache_mode is set to auto), the server will > automatically choose whether to use a generic or custom plan for a prepared > statement that has parameters. The current rule for this is that the first > five executions are done with custom plans and the average estimated cost of > those plans is calculated. Then a generic plan is created and its estimated > cost is compared to the average custom-plan cost. Subsequent executions use > the generic plan if its cost is not so much higher than the average > custom-plan cost as to make repeated replanning seem preferable. > > This heuristic can be overridden, forcing the server to use either generic or > custom plans, by setting plan_cache_mode to force_generic_plan or > force_custom_plan respectively. This setting is primarily useful if the > generic plan's cost estimate is badly off for some reason, allowing it to be > chosen even though its actual cost is much more than that of a custom plan. > " Thank you for the link! I did a try setting “plan_cache_mode” but it seems nothing change, and my test query (not production one obviously) has no parameter and in this occasion “if the prepared statement has no parameters, then this is moot and a generic plan is always used.” Also using variables in query nothing changes. I will work again on it. Thank you again. Edoardo
Re: The same prepared query yield "-1" the first six times and then "-1.0"
> Il giorno 21 ago 2023, alle ore 17:50, David G. Johnston
> ha scritto:
>
>
> On Mon, Aug 21, 2023 at 8:28 AM Edoardo Panfili
> mailto:edoardo.panf...@iisgubbio.edu.it>>
> wrote:
>>
>>dim1 real DEFAULT '-1' NOT NULL
>>
>> System.out.print("p: "+rs.getString("dim1")+"\n”);
>>
>> Can I do something to avoid this problem?
>
> Use the type appropriate getter, not getString, to retrieve the value of the
> underlying real typed column.
I know, but in this occasion I need to use text value.
>
> Otherwise, I agree this seems like a bug, probably in the JDBC driver, though
> one pertains to style as opposed to semantics since both answers are
> technically correct.
I will try, thank you
Edoardo
Re: The same prepared query yield "-1" the first six times and then "-1.0"
> Il giorno 21 ago 2023, alle ore 18:45, Tom Lane ha > scritto: > > "David G. Johnston" writes: >> Otherwise, I agree this seems like a bug, probably in the JDBC driver, >> though one pertains to style as opposed to semantics since both answers are >> technically correct. > > I don't see any such behavior change in psql, so I agree that this is > probably something to ask about on the JDBC list. I’m going to ask there, thank you Edoardo
Re: The same prepared query yield "-1" the first six times and then "-1.0"
> Il giorno 21 ago 2023, alle ore 20:13, Peter J. Holzer ha > scritto: > > On 2023-08-21 17:27:20 +0200, Edoardo Panfili wrote: >> The attended result was a sequence of ten equal values but this is the >> actual result: >> p: -1 >> p: -1 >> p: -1 >> p: -1 >> p: -1 >> p: -1.0 >> p: -1.0 >> p: -1.0 >> p: -1.0 >> p: -1.0 > [...] >> 2023-08-21 11:51:50.633 CEST [1511] user@testdb LOG: execute : SET >> extra_float_digits = 3 >> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute : SET >> application_name = 'PostgreSQL JDBC Driver' >> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute : >> SELECT dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.654 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name='first' >> 2023-08-21 11:51:50.656 CEST [1511] user@testdb LOG: execute S_1: SELECT >> dim1 FROM number WHERE name=‘first' > > Are these outputs from the same run? Yes > > I notice that the output from the program switches after 5 queries from > "-1" to "-1-0", but the logged query name switches after 4 queries from > "" to "S_1”. You’re right. It seem a JDBC side problem. I am doing some tests using suggestions from pgsql-jdbc list. What sounds strange to me is that switching from “mode_X” to “mode_Y” I obtain different representation of the same value, I know the value is semantically the same.. but… in some way I like to see.. "a perfect postgresql env” (as it absolutely is) Edoardo
Re: The same prepared query yield "-1" the first six times and then "-1.0"
> Il giorno 21 ago 2023, alle ore 21:37, Dave Cramer
> ha scritto:
>
>
>
> On Mon, 21 Aug 2023 at 14:42, Edoardo Panfili <mailto:edoard...@gmail.com>> wrote:
>>
>>
>> > Il giorno 21 ago 2023, alle ore 20:13, Peter J. Holzer > > <mailto:hjp-pg...@hjp.at>> ha scritto:
>> >
>> > On 2023-08-21 17:27:20 +0200, Edoardo Panfili wrote:
>> >> The attended result was a sequence of ten equal values but this is the
>> >> actual result:
>> >> p: -1
>> >> p: -1
>> >> p: -1
>> >> p: -1
>> >> p: -1
>> >> p: -1.0
>> >> p: -1.0
>> >> p: -1.0
>> >> p: -1.0
>> >> p: -1.0
>> > [...]
>> >> 2023-08-21 11:51:50.633 CEST [1511] user@testdb LOG: execute :
>> >> SET extra_float_digits = 3
>> >> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute :
>> >> SET application_name = 'PostgreSQL JDBC Driver'
>> >> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute :
>> >> SELECT dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute :
>> >> SELECT dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute :
>> >> SELECT dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute :
>> >> SELECT dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.651 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.653 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.654 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name='first'
>> >> 2023-08-21 11:51:50.656 CEST [1511] user@testdb LOG: execute S_1: SELECT
>> >> dim1 FROM number WHERE name=‘first'
>> >
>> > Are these outputs from the same run?
>> Yes
>>
>> >
>> > I notice that the output from the program switches after 5 queries from
>> > "-1" to "-1-0", but the logged query name switches after 4 queries from
>> > "" to "S_1”.
>>
>> You’re right. It seem a JDBC side problem. I am doing some tests using
>> suggestions from pgsql-jdbc list.
>>
>> What sounds strange to me is that switching from “mode_X” to “mode_Y” I
>> obtain different representation of the same value,
>>
>> I know the value is semantically the same.. but… in some way I like to see..
>> "a perfect postgresql env” (as it absolutely is)
>>
>> Edoardo
>>
>
> I have confirmed that this behaviour is by design either by postgres or the
> driver. When postgres provides us the data using text mode we see -1
>
> (psql)
> select * from number ;
> name | dim1
> ---+--
> first | -1
>
> This is the way the data is presented by the text output function.
And I expected to obtain the same from the JDBC connection
> In binary mode we see -1.0. This is an artifact of the binary output function.
>
> If ResultSet.getDouble is used the data is the same ... -1 for both text and
> binary
>
> Using getString we see the problem.
>
> So you have a few options to stop this: Set prepareThreshold to 0 and the
> driver will not switch to named statements or binary,
Properties props = new Properties();
props.setProperty("prepareThreshold", "0");
Connection conn = DriverManager.getConnection(
"jdbc:postgresql://192.168.64.7:5432/testdb?user=user&password=password”,
props);
Obtains “-1” all the times
> Or remove double from binary transfer.
Thank you
Edoardo
