BUG #13979: Strange pg_stat_statements results with PREPARE/EXECUTE

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

​What do you think the following statement does?

​
PreparedStatement ps1 = con.prepareStatement(sql1);

​David J.
​

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs

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

--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs