Thread: BUG #13979: Strange pg_stat_statements results with PREPARE/EXECUTE

The following bug has been logged on the website:

Bug reference:      13979
Logged by:          Kasahara Tatsuhito
Email address:      kasahara.tatsuhito@gmail.com
PostgreSQL version: 9.5.1
Operating system:   RHEL
Description:

Hi, I noticed that in some cases pg_stat_statements shows strange results.
(example)

=# CREATE TABLE tt(c1 int);
=# INSERT INTO tt SELECT generate_series(1,10);
=# SELECT pg_stat_statements_reset();

Then, performed simple SELECTs via java. (see the end of this mail)
After that, I got the following pg_stat_statements result, and ISTM it's
reasonable.

=# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
'%tt%';
  queryid  | calls |             query
-----------+-------+--------------------------------
 575935600 |    10 | SELECT * FROM tt WHERE c1 = $1


Next, reset the pg_stat_statements and performed PREPARE and EXECUTE via
psql.

=# SELECT pg_stat_statements_reset();
=# PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
=# EXECUTE p1(1);
=# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
'%tt%';
  queryid  | calls |                       query
-----------+-------+----------------------------------------------------
 575935600 |     1 | PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
(1 row)

Then, performed same SELECTs via java.
After that,  I got a bit strange pg_stat_statements result..

=# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
'%tt%';
  queryid  | calls |                       query
-----------+-------+----------------------------------------------------
 575935600 |    11 | PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
(1 row)


I'm not sure it's expected behaviors, but seems a bug.

Best regards,

// Java Test code
import java.lang.*;
import java.sql.*;

class Test {
    public static void main(String[] args) {
            String driver = "org.postgresql.Driver";
            String url =
"jdbc:postgresql://localhost/postgres?user=postgres&ApplicationName=my_jdbc_test";
        try{
            Connection con = DriverManager.getConnection(url);
            con.setAutoCommit(false);
            String sql1 = "SELECT * FROM tt WHERE c1 = ?";
            PreparedStatement ps1 = con.prepareStatement(sql1);

            for (int i=1; i<=10; i++) {
                ps1.setInt(1,i);
                ResultSet rs = ps1.executeQuery();
                while(rs.next()){
                    System.out.println("results c1:" + rs.getInt(1));
                }
            }

            con.commit();
            ps1.close();
            con.close();
            }catch (Exception e){
                e.printStackTrace();
            }
    }
}

On Tuesday, February 23, 2016, <kasahara.tatsuhito@gmail.com> wrote:

> The following bug has been logged on the website:
>
> Bug reference:      13979
> Logged by:          Kasahara Tatsuhito
> Email address:      kasahara.tatsuhito@gmail.com <javascript:;>
> PostgreSQL version: 9.5.1
> Operating system:   RHEL
> Description:
>
> Hi, I noticed that in some cases pg_stat_statements shows strange results.
> (example)
>
> =# CREATE TABLE tt(c1 int);
> =# INSERT INTO tt SELECT generate_series(1,10);
> =# SELECT pg_stat_statements_reset();
>
> Then, performed simple SELECTs via java. (see the end of this mail)
> After that, I got the following pg_stat_statements result, and ISTM it's
> reasonable.
>
> =# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
> '%tt%';
>   queryid  | calls |             query
> -----------+-------+--------------------------------
>  575935600 |    10 | SELECT * FROM tt WHERE c1 = $1
>
>
> Next, reset the pg_stat_statements and performed PREPARE and EXECUTE via
> psql.
>
> =# SELECT pg_stat_statements_reset();
> =# PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
> =# EXECUTE p1(1);
> =# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
> '%tt%';
>   queryid  | calls |                       query
> -----------+-------+----------------------------------------------------
>  575935600 |     1 | PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
> (1 row)
>
> Then, performed same SELECTs via java.
> After that,  I got a bit strange pg_stat_statements result..
>
> =# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
> '%tt%';
>   queryid  | calls |                       query
> -----------+-------+----------------------------------------------------
>  575935600 |    11 | PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
> (1 row)
>
>
> I'm not sure it's expected behaviors, but seems a bug.
>
> Best regards,
>
> // Java Test code
> import java.lang.*;
> import java.sql.*;
>
> class Test {
>     public static void main(String[] args) {
>             String driver = "org.postgresql.Driver";
>             String url =
>
> "jdbc:postgresql://localhost/postgres?user=postgres&ApplicationName=my_jdbc_test";
>         try{
>             Connection con = DriverManager.getConnection(url);
>             con.setAutoCommit(false);
>             String sql1 = "SELECT * FROM tt WHERE c1 = ?";
>             PreparedStatement ps1 = con.prepareStatement(sql1);
>
>             for (int i=1; i<=10; i++) {
>                 ps1.setInt(1,i);
>                 ResultSet rs = ps1.executeQuery();
>                 while(rs.next()){
>                     System.out.println("results c1:" + rs.getInt(1));
>                 }
>             }
>
>             con.commit();
>             ps1.close();
>             con.close();
>             }catch (Exception e){
>                 e.printStackTrace();
>             }
>     }
> }
>
>
You need to tell people what exactly you think is strange/what you would
expect to see.

David J.

2016-02-23 23:36 GMT+09:00 David G. Johnston <david.g.johnston@gmail.com>:
> You need to tell people what exactly you think is strange/what you would
> expect to see.
Yeah.

So I expected following result after performing second time "SELECT *
FROM tt WHERE c1 = $1" in a  previous e-mail.

=# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
'%tt%';
  queryid  | calls |                       query
-----------+-------+----------------------------------------------------
 575935600 |    1| PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
 other-queryid |    10 | SELECT * FROM tt WHERE c1 = $1;
(2 row)

But actually SELECT was counted  as PREPARE in pg_stat_statements.
That's what I thought strange.

It seems to me that "<query>" and "PREPARE <query>" always have same queryid.
Therefore should I consider these queries as the same one ?

--
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com

On Tue, Feb 23, 2016 at 8:24 AM, Kasahara Tatsuhito <
kasahara.tatsuhito@gmail.com> wrote:

> 2016-02-23 23:36 GMT+09:00 David G. Johnston <david.g.johnston@gmail.com>=
:
> > You need to tell people what exactly you think is strange/what you woul=
d
> > expect to see.
> Yeah.
>
> So I expected following result after performing second time "SELECT *
> FROM tt WHERE c1 =3D $1" in a  previous e-mail.
>
> =3D# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIK=
E
> '%tt%';
>   queryid  | calls |                       query
> -----------+-------+----------------------------------------------------
>  575935600 |    1| PREPARE p1(int) AS SELECT * FROM tt WHERE c1 =3D $1;
>  other-queryid |    10 | SELECT * FROM tt WHERE c1 =3D $1;
> (2 row)
>
> But actually SELECT was counted  as PREPARE in pg_stat_statements.
> That's what I thought strange.
>
> It seems to me that "<query>" and "PREPARE <query>" always have same
> queryid.
> Therefore should I consider these queries as the same one ?
>
>
=E2=80=8BWhat do you think the following statement does?

=E2=80=8B
PreparedStatement ps1 =3D con.prepareStatement(sql1);

=E2=80=8BDavid J.
=E2=80=8B

Kasahara Tatsuhito <kasahara.tatsuhito@gmail.com> writes:
> So I expected following result after performing second time "SELECT *
> FROM tt WHERE c1 = $1" in a  previous e-mail.

> =# SELECT queryid, calls, query FROM pg_stat_statements WHERE query LIKE
> '%tt%';
>   queryid  | calls |                       query
> -----------+-------+----------------------------------------------------
>  575935600 |    1| PREPARE p1(int) AS SELECT * FROM tt WHERE c1 = $1;
>  other-queryid |    10 | SELECT * FROM tt WHERE c1 = $1;
> (2 row)

> But actually SELECT was counted  as PREPARE in pg_stat_statements.
> That's what I thought strange.

What's in the query field is whatever source string the query was created
from.  In the case of a prepared statement, we could potentially show
either the PREPARE or the EXECUTE, but the former was deemed much more
useful.  There's no logic in there to invent a string that was never
actually submitted to the engine.

            regards, tom lane

Hi,

2016-02-24 0:32 GMT+09:00 David G. Johnston <david.g.johnston@gmail.com>:
> What do you think the following statement does?
>
> PreparedStatement ps1 = con.prepareStatement(sql1);
I think above statement would performed "PREAPRE".
But sometimes those were counted as PREPARE, or  sometimes were
counted as normal SELECT.
So, I was little confused...

But I see it's a restrictions of current postgres's design.

Best regards,
--
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com

Hi,

2016-02-24 0:38 GMT+09:00 Tom Lane <tgl@sss.pgh.pa.us>:
> What's in the query field is whatever source string the query was created
> from.  In the case of a prepared statement, we could potentially show
> either the PREPARE or the EXECUTE, but the former was deemed much more
> useful.  There's no logic in there to invent a string that was never
> actually submitted to the engine.
Thanks for your explanation.
I got it.

Anyway in the real cases, I think we would not encounter those
case(like my samples) so much.
--
Tatsuhito Kasahara
kasahara.tatsuhito _at_ gmail.com