Thread: The same prepared query yield "-1" the first six times and then "-1.0"

The same prepared query yield "-1" the first six times and then "-1.0"

From
Edoardo Panfili
Date:
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




Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Adrian Klaver
Date:
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




Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
"David G. Johnston"
Date:

On Mon, Aug 21, 2023 at 8:28 AM Edoardo Panfili <edoardo.panfili@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.

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.

David J.

"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



Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Edoardo Panfili
Date:


Il giorno 21 ago 2023, alle ore 17:45, Adrian Klaver <adrian.klaver@aklaver.com> 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 <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 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"

From
Edoardo Panfili
Date:


Il giorno 21 ago 2023, alle ore 17:50, David G. Johnston <david.g.johnston@gmail.com> ha scritto:


On Mon, Aug 21, 2023 at 8:28 AM Edoardo Panfili <edoardo.panfili@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"

From
Edoardo Panfili
Date:

> 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




Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Pavel Stehule
Date:


po 21. 8. 2023 v 19:52 odesílatel Edoardo Panfili <edoardo.panfili@iisgubbio.edu.it> napsal:


> 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

Maybe it is switch from client side prepared statements to server side prepared statements


I don't use Java, so I don't know more

Regards

Pavel


Edoardo



Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Rob Sargent
Date:
On 8/21/23 11:17, Edoardo Panfili wrote:
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

You appear to have two code paths in your application.  The one that needs the string version of the answer should do the conversion of the numeric value.
rjs

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
"Peter J. Holzer"
Date:
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!"

Attachment

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Edoardo Panfili
Date:

> 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





Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Dave Cramer
Date:



On Mon, 21 Aug 2023 at 12:46, Tom Lane <tgl@sss.pgh.pa.us> wrote:
"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


Tom,

It's because we also switch to binary at that point and don't parse text any more. I agree though it shouldn't happen.

Dave 

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Dave Cramer
Date:



On Mon, 21 Aug 2023 at 15:12, Edoardo Panfili <edoardo.panfili@iisgubbio.edu.it> wrote:


Il giorno 21 ago 2023, alle ore 17:45, Adrian Klaver <adrian.klaver@aklaver.com> 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 <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 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.

It has nothing to do with this. Yes the generic plan will be used but that does not change the output.
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

Dave

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Dave Cramer
Date:


On Mon, 21 Aug 2023 at 14:42, Edoardo Panfili <edoardopa@gmail.com> wrote:


> 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 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.

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, Or remove double from binary transfer.

Regards, 

Dave 
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?

--
Born in Arizona, moved to Babylonia.

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Dave Cramer
Date:


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?

If we look at float8out_internal (text output)  https://github.com/postgres/postgres/blob/6fde2d9a005a5bc04aa059d3faeb865c8dd322ce/src/backend/utils/adt/float.c#L536 and the comment about extra float digits which states 

If >0, use shortest-decimal format for output; this is both the default and
allows for compatibility with clients that explicitly set a value here to
get round-trip-accurate results. If 0 or less, then use the old, slow,
decimal rounding method.

-1 would be the shortest-decimal format. 

whereas float8send sends the actual binary data on disk, hence -1.0

Dave
--
Born in Arizona, moved to Babylonia.

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
"Peter J. Holzer"
Date:
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!"

Attachment

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Edoardo Panfili
Date:


Il giorno 21 ago 2023, alle ore 21:37, Dave Cramer <davecramer@postgres.rocks> ha scritto:



On Mon, 21 Aug 2023 at 14:42, Edoardo Panfili <edoardopa@gmail.com> wrote:


> 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 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

Re: The same prepared query yield "-1" the first six times and then "-1.0"

From
Dave Cramer
Date:


On Tue, 22 Aug 2023 at 01:54, Edoardo Panfili <edoardopa@gmail.com> wrote:


Il giorno 21 ago 2023, alle ore 21:37, Dave Cramer <davecramer@postgres.rocks> ha scritto:



On Mon, 21 Aug 2023 at 14:42, Edoardo Panfili <edoardopa@gmail.com> wrote:


> 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 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(

Obtains “-1” all the times

You do give up the advantage of named statements which is that DESCRIBE won't be necessary, but that does appear to be less of a problem than returning a different representation.

Dave