Обсуждение: 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 <unnamed>: SET extra_float_digits = 3
2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC Driver'
2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute <unnamed>: 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

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


> 
> 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 <unnamed>: SET extra_float_digits = 3
> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC
Driver'
> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute <unnamed>: 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
> Edoardo
> 
> 
> 

-- 
Adrian Klaver
adrian.klaver@aklaver.com

"David G. Johnston" <david.g.johnston@gmail.com> 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.

My first thought was that the output change occurs when the query
transitions from custom to generic plan.  However, since there are
no parameters involved the backend would go for a generic plan
immediately.  Having said that, I seem to recall that the JDBC driver
has its own notion of custom vs generic execution, so maybe the
issue is around there somewhere.

            regards, tom lane

> Il giorno 21 ago 2023, alle ore 18:45, Tom Lane <tgl@sss.pgh.pa.us> ha scritto:
>
> "David G. Johnston" <david.g.johnston@gmail.com> 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

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

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 <unnamed>: SET extra_float_digits = 3
> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC
Driver'
> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute <unnamed>: 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?

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
"<unnamed>" to "S_1".

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | hjp@hjp.at         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"

> Il giorno 21 ago 2023, alle ore 20:13, Peter J. Holzer <hjp-pgsql@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 <unnamed>: SET extra_float_digits = 3
>> 2023-08-21 11:51:50.634 CEST [1511] user@testdb LOG: execute <unnamed>: SET application_name = 'PostgreSQL JDBC
Driver'
>> 2023-08-21 11:51:50.644 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
>> 2023-08-21 11:51:50.648 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
>> 2023-08-21 11:51:50.649 CEST [1511] user@testdb LOG: execute <unnamed>: SELECT dim1 FROM number WHERE name='first'
>> 2023-08-21 11:51:50.650 CEST [1511] user@testdb LOG: execute <unnamed>: 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
> "<unnamed>" 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
absolutelyis) 

Edoardo

It has to do with the way the data is being transferred. When the driver switches to a named statement it also switches to binary mode which means data will be transferred in binary. 

In text we get -1, in binary we get -1.0

On 2023-08-21 17:31:06 -0400, Dave Cramer wrote:
> On Mon, 21 Aug 2023 at 17:17, Ron <ronljohnsonjr@gmail.com> wrote:
>
>     On 8/21/23 14:32, Dave Cramer wrote:
>
>     [snip]
>
>         It has to do with the way the data is being transferred. When the
>         driver switches to a named statement it also switches to binary mode
>         which means data will be transferred in binary. 
>
>         In text we get -1, in binary we get -1.0
>
>
>     That seems odd.  Why does it do that?
[...]
> whereas float8send sends the actual binary data on disk, hence -1.0

It should be noted that the binary representation is not "-1.0", but
something like
1 01111111 00000000000000000000000 (in binary or)
B    F   8    0   0   0   0   0    (in hex)
(big endian for better readability)

The decimal representation "-1.0" is created by the binary to string
conversion (Java's Float.toString()?). That could also produce "-1" or
"-1E0" or any other equivalent representation. The author of that
routine decided in include ".0" in the output, possibly to signify that
it's a floating point value, not an integer.

        hp

--
   _  | Peter J. Holzer    | Story must make more sense than reality.
|_|_) |                    |
| |   | hjp@hjp.at         |    -- Charles Stross, "Creative writing
__/   | http://www.hjp.at/ |       challenge!"