BUG: endless lseek(.., SEEK_END) from select queries on x64 builds

[Markus Schulz]

hello,

i have a strange and reproducible bug with some select queries and 64bit
postgresql builds (works fine on 32bit builds).
The postgres process will run with 100% cpu-load (no io-wait) and strace
will show endless lseek(..., SEEK_END) calls on one table for minutes.
lseek(28, 0, SEEK_END) = 26697728
lseek(28, 0, SEEK_END) = 26697728
lseek(28, 0, SEEK_END) = 26697728
...
the file-descriptor 28 points to the file for the webapps_base.Acquisition
table (see query/plan below).

Now the details:

The Query:
select count(ac.ID) as col_0_0_ from
webapps_base.Acquisition ac,
webapps_base.SalesPartnerStructure struc
where
struc.fk_SalesPartner_child=ac.fk_SalesPartner_ID
and struc.fk_SalesPartner_parent=200
and (ac.CreationDate between '2012-02-01' and '2013-01-31')
and ac.acquisitiondepot='STANDARD'
and ('2013-01-31' between struc.ValidFrom
and coalesce(struc.ValidTo, '2013-01-31'))

The Plan:
"Aggregate (cost=32617.11..32617.12 rows=1 width=8) (actual time=204.180..204.180 rows=1 loops=1)"
" -> Merge Join (cost=32232.01..32598.26 rows=7543 width=8) (actual time=172.882..202.218 rows=21111 loops=1)"
" Merge Cond: (ac.fk_salespartner_id = struc.fk_salespartner_child)"
" -> Sort (cost=5582.60..5635.69 rows=21235 width=16) (actual time=28.920..31.121 rows=21204 loops=1)"
" Sort Key: ac.fk_salespartner_id"
" Sort Method: quicksort Memory: 1763kB"
" -> Bitmap Heap Scan on acquisition ac (cost=395.26..4056.43 rows=21235 width=16) (actual time=3.064..15.868 rows=21223 loops=1)"
" Recheck Cond: ((creationdate >= '2012-02-01'::date) AND (creationdate <= '2013-01-31'::date))"
" Filter: ((acquisitiondepot)::text = 'STANDARD'::text)"
" -> Bitmap Index Scan on index_acquistion_creationdate (cost=0.00..389.95 rows=21267 width=0) (actual time=2.890..2.890 rows=21514 loops=1)"
" Index Cond: ((creationdate >= '2012-02-01'::date) AND (creationdate <= '2013-01-31'::date))"
" -> Sort (cost=26648.60..26742.61 rows=37606 width=8) (actual time=143.952..152.808 rows=131713 loops=1)"
" Sort Key: struc.fk_salespartner_child"
" Sort Method: quicksort Memory: 8452kB"
" -> Bitmap Heap Scan on salespartnerstructure struc (cost=3976.80..23790.79 rows=37606 width=8) (actual time=13.279..64.681 rows=114772 loops=1)"
" Recheck Cond: (fk_salespartner_parent = 200)"
" Filter: (('2013-01-31'::date >= validfrom) AND ('2013-01-31'::date <= COALESCE(validto, '2013-01-31'::date)))"
" -> Bitmap Index Scan on index_parent_salespartner (cost=0.00..3967.39 rows=114514 width=0) (actual time=13.065..13.065 rows=116479 loops=1)"
" Index Cond: (fk_salespartner_parent = 200)"
"Total runtime: 205.397 ms"

as you can see the query runs fine.
I can run this query from a bash-psql-while-loop/jdbc-cli-tool
endless without any problems.
so far so good.

But now i run the same query from:

JBoss EAP 5.1.2 with connection pooling and xa-datasource/two-phase-commits
(transactions on multiple datasources needed)
*and* *<prepared-statement-cache-size>1000</prepared-statement-cache-size>*

i can run the query four times with good performance and after that postgresql
starts with the strange lseek() behavior.
The query needs more then a minute to complete and during execution the
postgres process runs at 100% cpu load with lseek calls (straced).
If i flush the connection pool (close all open connections from the jboss
jmx-console) it works again for four calls.
These problem applies only to 64bit builds. If i run a 32bit postgresql
server it works fine.

We have tested the following environments:

- Debian Squeeze 64bit with Postgresql 9.1.[5,6,7] -> Bad behavior
- Debian Wheezy 64bit with Postgresql 9.1.8 64bit -> Bad behavior
- Ubuntu 12.04 LTS 64bit with Postgresql 9.1.8 64bit -> Bad behavior
- Windows 7 x64 with Postgresql 9.1.8 64bit -> Bad behavior
- Debian Wheezy 64bit with EnterpriseDB 9.2 64bit -> Bad behavior

- Debian Wheezy 64bit with Postgresql 9.1.8 32bit -> Good behavior
- Debian Wheezy 32bit with Postgresql 9.1.8 32bit -> Good behavior

as you can see all 64bit builds of postgresql are affected (independent from os-arch).

If i disable the prepared-statement-cache-size (remove it from -ds.xml)
it works on 64bit build too.

regards,
msc

[Heikki Linnakangas]

Post by Markus Schulz
i can run the query four times with good performance and after that postgresql
starts with the strange lseek() behavior.

By default, the JDBC driver re-plans the prepared statement for the
first 4 invocations of the query. On the fifth invocation, it switches
to using a generic plan, which will be reused on subsequent invocations.
See http://jdbc.postgresql.org/documentation/head/server-prepare.html.
The generic plan seems to perform much worse in this case. You can
disable that mechanism and force re-planning the query every time by
setting the "prepareThreshold=0" parameter on the data source.

You could check what the generic plan looks like by taking the query
used in the java program, with the parameter markers, and running
EXPLAIN on that.

PostgreSQL version 9.2 might work better in this case. It has some
smarts in the server to generate parameter-specific plans even when
prepared statements are used, if the planner thinks a specific plan will
be faster.

- Heikki

[Markus Schulz]

Post by Heikki Linnakangas

Post by Markus Schulz
i can run the query four times with good performance and after that
postgresql starts with the strange lseek() behavior.

By default, the JDBC driver re-plans the prepared statement for the
first 4 invocations of the query. On the fifth invocation, it switches
to using a generic plan, which will be reused on subsequent invocations.

that sounds really interesting and i would try to change my java-jdbc-test-cli
program according to that, but ...

Post by Heikki Linnakangas
See http://jdbc.postgresql.org/documentation/head/server-prepare.html.
The generic plan seems to perform much worse in this case. You can
disable that mechanism and force re-planning the query every time by
setting the "prepareThreshold=0" parameter on the data source.

it wouldn't explain why the same jboss runs fine with a 32bit postgresql
server (i switched only the datasource to another server with exactly the same
database).

Post by Heikki Linnakangas
You could check what the generic plan looks like by taking the query
used in the java program, with the parameter markers, and running
EXPLAIN on that.

how can i do this?
I've tried the following in my ejb-test-function to:

String query = "..."
entitymanager.createNativeQuery(query)...;
entitymanager.createNativeQuery("EXPLAIN ANALYZE " + query)...;

but the second createNativeQuery call runs fast every time and will show the
same plan and the first hangs after the fourth call to this function.

Post by Heikki Linnakangas
PostgreSQL version 9.2 might work better in this case. It has some
smarts in the server to generate parameter-specific plans even when
prepared statements are used, if the planner thinks a specific plan will
be faster.
- Debian Wheezy 64bit with EnterpriseDB 9.2 64bit -> Bad behavior

we tried postgresql 9.2 too

Post by Heikki Linnakangas
- Heikki

regards,
msc

[Heikki Linnakangas]

Post by Markus Schulz

Post by Heikki Linnakangas
You could check what the generic plan looks like by taking the query
used in the java program, with the parameter markers, and running
EXPLAIN on that.

how can i do this?
String query = "..."
entitymanager.createNativeQuery(query)...;
entitymanager.createNativeQuery("EXPLAIN ANALYZE " + query)...;
but the second createNativeQuery call runs fast every time and will show the
same plan and the first hangs after the fourth call to this function.

You can take the query, replace the ? parameter markers with $1, $2, and
so forth, and explain it with psql like this:

prepare foo (text) as select * from mytable where id = $1;
explain analyze execute foo ('foo');

On 9.2, though, this will explain the specific plan for those
parameters, so it might not be any different from what you already
EXPLAINed.

- Heikki

[Tom Lane]

Post by Heikki Linnakangas
You can take the query, replace the ? parameter markers with $1, $2, and
prepare foo (text) as select * from mytable where id = $1;
explain analyze execute foo ('foo');
On 9.2, though, this will explain the specific plan for those
parameters, so it might not be any different from what you already
EXPLAINed.

You can tell whether you're getting a generic or custom plan by noting
whether the explain output contains $n symbols or the values you put in.
In 9.2, the first five attempts will always produce custom plans, but
on the sixth and subsequent attempts you will get a generic plan, if
the plancache logic decides that it's not getting any benefit out of
custom plans. Here's a trivial example:

regression=# prepare foo(int) as select * from tenk1 where unique1 = $1;
PREPARE
regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = 42)
(2 rows)

regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = 42)
(2 rows)

regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = 42)
(2 rows)

regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = 42)
(2 rows)

regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = 42)
(2 rows)

regression=# explain execute foo(42);
QUERY PLAN
-----------------------------------------------------------------------------
Index Scan using tenk1_unique1 on tenk1 (cost=0.29..8.30 rows=1 width=244)
Index Cond: (unique1 = $1)
(2 rows)

It's switched to a generic plan after observing that the custom plans
weren't any cheaper. Once that happens, subsequent attempts will use
the generic plan. (Of course, in a scenario where the custom plans do
provide a benefit, it'll keep using those.)

regards, tom lane

[Stephen Frost]

Markus,

Post by Markus Schulz
as you can see the query runs fine.
I can run this query from a bash-psql-while-loop/jdbc-cli-tool
endless without any problems.
so far so good.

[...]

Post by Markus Schulz
JBoss EAP 5.1.2 with connection pooling and xa-datasource/two-phase-commits
(transactions on multiple datasources needed)
*and* *<prepared-statement-cache-size>1000</prepared-statement-cache-size>*
i can run the query four times with good performance and after that postgresql
starts with the strange lseek() behavior.

It sounds like your bash script and JBoss are doing something different.
Would it be possible for you to turn on log_statements = 'all' in PG,
see what's different, and then update the bash/psql script to do exactly
what JBoss does, and see if you can reproduce it that way?

It certainly looks like a PG bug, but it'd be a lot easier to debug with
a simple, well-defined test case which shows the failure.

Thanks!

Stephen