Обсуждение: Change of format of returned flat value after prepareThreshold

I have strange problem.

My code uses query:
SELECT (EXTRACT(EPOCH FROM timeofday()::timestamp(3))*1000) AS timestamp

I use it with prepareStatement()/executeQuery() methods and then
getString().

It worked very well with 9.3 version of JDBC driver and returns
numbers like:
1444912761727
This number is float, but when I get it via getString() method I see
it as large integer.

Now I upgraded JDBC driver to 9.4 and strange thing happened. After
sixth execution of this query I got those numbers in scientific notation:
1.444912761861E12

When I replaced prepareStatement()/executeQuery() with
createStatement()/executeQuery() getString() it always gives me large
integer.

I think preparation changed something because when I change
prepareThreshold
in connection string then change of format after value in
prepareThreshold.


Resuls of code with prepareStatement()/executeQuery() (for 9.3 I
stopped test after several secods by pressing Ctrl-C):

test JDBC
classpath=jars/postgresql-9.3-1103.jdbc41.jar:.
JDBC driver version is 'PostgreSQL 9.3 JDBC4.1 (build 1103)'; major:
9; minor: 3
column type: float8 (8)
epoch: 1444912748106; tries: 5337
epoch: 1444912750107; tries: 10648
epoch: 1444912752108; tries: 15654
^C

test JDBC
classpath=jars/postgresql-9.3-1104.jdbc41.jar:.
JDBC driver version is 'PostgreSQL 9.3 JDBC4.1 (build 1104)'; major:
9; minor: 3
column type: float8 (8)
epoch: 1444912754640; tries: 5357
epoch: 1444912756641; tries: 10571
epoch: 1444912758642; tries: 15804
epoch: 1444912760643; tries: 21079
^C

test JDBC
classpath=jars/postgresql-9.4-1202.jdbc41.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.1 (build 1202)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761327; tries: 6
!!!1.444912761328E12!!!


test JDBC
classpath=jars/postgresql-9.4-1202.jdbc42.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.2 (build 1202)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761460; tries: 6
!!!1.444912761461E12!!!


test JDBC
classpath=jars/postgresql-9.4-1203.jdbc41.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.1 (build 1203)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761594; tries: 6
!!!1.444912761594E12!!!


test JDBC
classpath=jars/postgresql-9.4-1203.jdbc42.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.2 (build 1203)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761727; tries: 6
!!!1.444912761728E12!!!


test JDBC
classpath=jars/postgresql-9.4-1204.jdbc41.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.1 (build 1204)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761860; tries: 6
!!!1.444912761861E12!!!


test JDBC
classpath=jars/postgresql-9.4-1204.jdbc42.jar:.
JDBC driver version is 'PostgreSQL 9.4 JDBC4.2 (build 1204)'; major:
9; minor: 4
column type: float8 (8)
last: 1444912761995; tries: 6
!!!1.444912761995E12!!!

I think something is wrong when suddenly string representation of
result changes. I know that float number can be represented with
scientific notation, but I think that those numbers can be returned as
large integers just like it was with 9.3 drivers or just like it is
with createStatement()/executeQuery().

Now I workaround it by casting returned float to bigint.

--
Regards,
Michał Niklas

>but I think that those numbers can be returned as large integers just like it was with 9.3 drivers or just like it is

I'm afraid it is not possible at jdbc driver level.
You need to change application code.

As far as I can see from your output, backend reports float8.
That means, we have just a "double" at the client side, and we have no
idea what string representation is "expected".

If you want a "epoch time", I would recommend using resultSet.getLong().
Additionally, you might want to cast the selected expression to int8,
so you do not mess with floating point numerics.

Is there a specific reason why you expect non-scientific output of a
_floating_ value out of .getString()?

Vladimir

W dniu 15.10.2015 o 17:34, Vladimir Sitnikov pisze:
>> but I think that those numbers can be returned as large integers
>> just like it was with 9.3 drivers or just like it is
>
> I'm afraid it is not possible at jdbc driver level. You need to
> change application code.

I have changed that query. One of programmer didn't know
Java well and used such query to get number of milliseconds
since epoch start (1970-01-01). I changed those codes
to use System.currentTimeMillis(). Problem disappeared.


> As far as I can see from your output, backend reports float8. That
> means, we have just a "double" at the client side, and we have no
> idea what string representation is "expected".

Of course I understand it.

The only thing I do not understand is:
why JDBC or database backend changes format of returned value
after my use count reaches prepareThreshold parameter.

If I set prepareThreshold=0 then I always get float in normal
notation.

If I set prepareThreshold=5 then I get float in normal
notation up to 5th try, and then from 6th try I get this
value in scientific notation.

If I set prepareThreshold=10 then I get float in normal
notation ut to 10th try, and then from 11th try I get this
value in scientific notation.

Why such change?

ResultSetMetaData do not changes and report that value
to be of float8 type (SQL_TYPE=8).

So what changed?

I do not observe this with JDBC drivers in version 9.3,
so I think something changed in driver code, but maybe
it is change in the database?

I use:
PostgreSQL 9.4.5 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
4.4.7 20120313 (Red Hat 4.4.7-16), 64-bit



> If you want a "epoch time", I would recommend using
> resultSet.getLong(). Additionally, you might want to cast the
> selected expression to int8, so you do not mess with floating point
> numerics.

At first I casted it to bigint, then I simplified code that now
is even more portable (as we work with other databases)
and now I use System.currentTimeMillis() :-)


> Is there a specific reason why you expect non-scientific output of
> a _floating_ value out of .getString()?

This code is part of our reporting engine where all results are read
by rs.getString(). I know that I could use ResultSetMetaData,
but getString() simply works.

I was looking for similar queries that behaves the same way,
i.e. changes format of returned value after use count reaches
prepareThreshold, but I was not able to find such query.

In my previous mail there was attachment with Java code
that shows that behaviour and shell script that tests
it with various JDBC drivers.

There is Jython code that does the same thing:

<code>

#!/usr/bin/env jython
# -*- coding: utf8 -*-

__version__ = '$Id: jdbc_pg_float_time.py 2521 2015-10-16 05:24:43Z mn $'

import sys
import time
import traceback

from java.sql import DriverManager
from java.lang import Class

Class.forName("org.postgresql.Driver")


def test(db_url, user, passwd):
    try:
        print("\n\n%s\n--------------" % (db_url))
        db = DriverManager.getConnection(db_url, user, passwd)
        try:
            pstmt = db.prepareStatement("SELECT version()")
            rs = pstmt.executeQuery()
            while rs.next():
                s = rs.getString(1)
                print(s)
            rs.close()
            pstmt.close()

            dbmi = db.getMetaData()
            print("JDBC driver version is '%s'; major: %s; minor: %s" %
(dbmi.getDriverVersion(), dbmi.getDriverMajorVersion(),
dbmi.getDriverMinorVersion()))

            last_s = ''
            i = 0
            t0 = time.time()
            while 1:
                i += 1
                pstmt = db.prepareStatement("SELECT (EXTRACT(EPOCH FROM
timeofday()::timestamp(3))*1000) AS timestamp")
                rs = pstmt.executeQuery()
                try:
                    if i == 1:
                        rsmd = rs.getMetaData()
                        type_id = rsmd.getColumnType(1)
                        type_name = rsmd.getColumnTypeName(1)
                        print('column type: %s (%d)' % (type_name, type_id))
                    while rs.next():
                        s = rs.getString('timestamp')
                        if s != last_s:
                            t2 = time.time()
                            if t2 - t0 > 2:
                                print('epoch: %s; tries: %d' % (s, i))
                                t0 = t2
                            if '.' in s:
                                print('last value: %s; try: %d' % (last_s, i))
                                print('%s !!!' % (s))
                                return
                            last_s = s
                finally:
                    rs.close()
                    pstmt.close()
        finally:
            db.close()
    except:
        print("there were errors!")
        s = traceback.format_exc()
        sys.stderr.write("%s\n" % (s))


test('jdbc:postgresql://test-baza.heuthesd:5494/isof_test?stringtype=unspecified&prepareThreshold=10',
'postgres', 'postgres')


</code>

And results on my machine:

jdbc:postgresql://test-baza.heuthesd:5494/isof_test?stringtype=unspecified&prepareThreshold=10
--------------
PostgreSQL 9.4.5 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
4.4.7 20120313 (Red Hat 4.4.7-16), 64-bit
JDBC driver version is 'PostgreSQL 9.4 JDBC4.2 (build 1204)'; major:
9; minor: 4
column type: float8 (8)
last value: 1444980175621; try: 11
1.444980175621E12 !!!


When you change prepareThreshold=10 to something else you will
get scientific format earlier or later.


--
Regards,
Michał Niklas

> I changed those codes to use System.currentTimeMillis().

>why JDBC or database backend changes format of returned value
>after my use count reaches prepareThreshold parameter.

We JDBC driver cannot ensure stable string representation of non-string data.
That might change as database improves. That might change as JDBC
driver improves.

>If I set prepareThreshold=5 then I get float in normal
>notation up to 5th try, and then from 6th try I get this
>value in scientific notation.

Well, that is thanks to usage of server-prepared statement.
In that mode, pgjdbc can use binary format of data transfer. It does
use binary mode for types it knows as it is more efficient to transfer
and parse.


>I do not observe this with JDBC drivers in version 9.3,

The thing is older versions did not manage to use server-prepared
statements for prepareStatement(); .call();
Recently pgjdbc learned to use server-prepared statement even in case
application does not care to reuse PreparedStatements:

http://stackoverflow.com/questions/32297503/whats-the-life-span-of-a-postgresql-server-side-prepared-statement/32300222#32300222

>then I simplified code that now
>is even more portable (as we work with other databases)

Can you share the code?

>but getString() simply works.

That is more or less similar to "sun.misc.Unsafe" API.
You want string, you get it. I believe there is no specification on
what .getString() should look like.

Vladimir

W dniu 16.10.2015 o 12:15, Vladimir Sitnikov pisze:
>> I changed those codes to use System.currentTimeMillis().
>
>> why JDBC or database backend changes format of returned value
>> after my use count reaches prepareThreshold parameter.
>
> We JDBC driver cannot ensure stable string representation of
> non-string data. That might change as database improves. That might
> change as JDBC driver improves.

I hope things improves :-)
I do not complain that this changed, just wanted to know
why this changed.


>> If I set prepareThreshold=5 then I get float in normal notation
>> up to 5th try, and then from 6th try I get this value in
>> scientific notation.
>
> Well, that is thanks to usage of server-prepared statement. In that
> mode, pgjdbc can use binary format of data transfer. It does use
> binary mode for types it knows as it is more efficient to transfer
> and parse.
>
>
>> I do not observe this with JDBC drivers in version 9.3,
>
> The thing is older versions did not manage to use server-prepared
> statements for prepareStatement(); .call(); Recently pgjdbc learned
> to use server-prepared statement even in case application does not
> care to reuse PreparedStatements:
>
http://stackoverflow.com/questions/32297503/whats-the-life-span-of-a-postgresql-server-side-prepared-statement/32300222#32300222


Thanks
>
for explanation.
That is what I was looking for.
I looked at change log and did not find this.



>> then I simplified code that now is even more portable (as we work
>> with other databases)
>
> Can you share the code?

My statement "more portable" was joke :-)
Idea to get number of milliseconds from database was terrible,
and it was simply mistake.
We love PostgreSQL, but for such thing Java and
System.currentTimeMillis() is much better.

This code was used to profile some piece of code.
It was very bad idea and ugly code, but it was the only
query I was able to find that show toString() format change.
And such format change was very mysterious for me.
Thanks for your help!


--
Regards,
Michał Niklas

> My statement "more portable" was joke :-)

There's an upcoming change that "fixes/improves" Timestamp/Date/Time
handling: https://github.com/pgjdbc/pgjdbc/pull/387

It would be good if you could test your app against current master branch.
It would be good if you could check if your way of Timestamp usage
happen to be tested in TimestampTest.java (that is the most robust way
of making sure your app will not be broken in the subsequent pgjdbc
releases).

Vladimir

W dniu 16.10.2015 o 12:15, Vladimir Sitnikov pisze:
> [...]
>> If I set prepareThreshold=5 then I get float in normal notation
>> up to 5th try, and then from 6th try I get this value in
>> scientific notation.
>
> Well, that is thanks to usage of server-prepared statement. In that
> mode, pgjdbc can use binary format of data transfer. It does use
> binary mode for types it knows as it is more efficient to transfer
> and parse.

OK, but I think string representation of such float should
not change during program life.

I tested JDBC driver with much simpler query:
SELECT 1445006113904::float8
so there is known, constant number.

Up to prepareThreshold I got: 1445006113904,
then I got: 1.445006113904E12

I think it is bug because I expect to have the same
string representation of such number regardless
of prepareThreshold. It may be normal or scientific
notation, but SELECT for known, constant parameters
should give the known output. Now output is inconsistent.

In attachment there is Jython code that on my machine
shows:

jdbc:postgresql://test-baza.heuthesd:5494/isof_test?stringtype=unspecified&prepareThreshold=2
--------------
PostgreSQL 9.4.5 on x86_64-unknown-linux-gnu, compiled by gcc (GCC)
4.4.7 20120313 (Red Hat 4.4.7-16), 64-bit
JDBC driver version is 'PostgreSQL 9.4 JDBC4.2 (build 1204)'; major:
9; minor: 4

testing with query: SELECT 1445006113904::float8

--- 1 ---
column type: float8 (8); java: java.lang.Double; precision: 17; scale: 17
getString(): 1445006113904
--- 2 ---
column type: float8 (8); java: java.lang.Double; precision: 17; scale: 17
getString(): 1445006113904
--- 3 ---
column type: float8 (8); java: java.lang.Double; precision: 17; scale: 17
getString(): 1.445006113904E12
        STRING FORMAT CHANGED!!!



--
Regards,
Michał Niklas

>On 9 October 2015 11:44  Michał Niklas wrote:
>
> > W dniu 16.10.2015 o 12:15, Vladimir Sitnikov pisze:
> > [...]
> >> If I set prepareThreshold=5 then I get float in normal notation
> >> up to 5th try, and then from 6th try I get this value in
> >> scientific notation.
> >
> > Well, that is thanks to usage of server-prepared statement. In that
> > mode, pgjdbc can use binary format of data transfer. It does use
> > binary mode for types it knows as it is more efficient to transfer
> > and parse.
>
> OK, but I think string representation of such float should
> not change during program life.

I understand that it can be confusing at first, but correctly functioning applications would not care.

> I tested JDBC driver with much simpler query:
> SELECT 1445006113904::float8
> so there is known, constant number.
>
> Up to prepareThreshold I got: 1445006113904,
> then I got: 1.445006113904E12

What you see is difference between PostgreSQL server side doing the
formatting vs the java Double.toString function doing the formatting.

Up to the threshold the call is really SELECT 1445006113904::float8::text
After that the jdbc driver requests the exact float8 bits (which is faster and takes up less space).
Because you request a String from result set instead of double the jdbc driver has to format the string.

If you want consistent String representation you need to do for example:
Double.toString(resultSet.getDouble())

An alternative is to request binary transfers from the first query, but this jdbc driver feature is
supposed to be more of a debug feature, because it slows down queries due to needing an extra
round-trip for each query.

If we consider this a bug then we just need to replicate the server side float to text formatter code
inside the jdbc driver instead of using Java built in formatters.

-Mikko

> OK, but I think string representation of such float should
> not change during program life.

Michal, pull requests are welcome.
Even though I do find that _a bit_ surprising behavior, I do not see
an easy way of fixing it.

> but this jdbc driver feature is
>supposed to be more of a debug feature, because it slows down queries due to needing an extra
>round-trip for each query.

Mikko, binary transfer should not be considered a "debug" feature.

In case the query is executed more than once (that is often happens
when using bind variables), jdbc driver skips prepare phase, it skips
sending query text, and it can use binary for faster encoding.

Vladimir

> > but this jdbc driver feature is
> >supposed to be more of a debug feature, because it slows down queries due to needing an extra
> >round-trip for each query.
>
> Mikko, binary transfer should not be considered a "debug" feature.

I know. I wrote the original jdbc driver binary transfer code because I wanted better performance.

But you clipped half of my sentence it stars with:

"An alternative is to request binary transfers from the first query" - meaning that the debug feature
is the performance killer that requests binary transfers for also the first query by doing a backend
round-trip to describe what kind of in/out parameters the operation contains - before executing the
actual statement.

It is currently used by jdbc driver unit test framework so that every operation need not be tried n
times in unit tests to verify that the binary transfers work for all operations.

-Mikko

>But you clipped half of my sentence it stars with:

Ah, I see now. Foreign language is hard to master.

>what it would take to enable more binary transfers. I played around with arrays, and that doesn't seem too onerous ?

I would definitely want binary transfer for Struct/Array support,
however, I would be nice to be able to use custom types.
You know, one day I requested a delay of a release so I could hack
binary support for structs. However, I do not have implementation that
I like yet.
My current answer to the question is:
https://github.com/pgjdbc/pgjdbc/issues/381#issuecomment-145971538

Vladimir