View Issue Details

IDProjectCategoryView StatusLast Update
0000152Pgpool-IIBugpublic2016-12-16 15:48
ReporterochedruAssigned Tot-ishii 
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionreopened 
Product Version 
Target VersionFixed in Version 
Summary0000152: Error with JDBC memory_cache_enabled = on
DescriptionI am trying to use Pgpool 3.4.3 and 3.5.0 as an in-memory cache for the SELECTs I issue through JDBC (driver version 9.4-1204-jdbc42).
I get the following exception on the server side:

java.util.NoSuchElementException: null
    at java.util.ArrayDeque.removeFirst(ArrayDeque.java:280) ~[na:1.8.0_60]
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1841) ~[postgresql-9.4-1204-jdbc42.jar:9.4]
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173) ~[postgresql-9.4-1204-jdbc42.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:616) ~[postgresql-9.4-1204-jdbc42.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:466) ~[postgresql-9.4-1204-jdbc42.jar:9.4]
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:351) ~[postgresql-9.4-1204-jdbc42.jar:9.4]

The pgpool log reads:

Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_memqcache.c:532
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: fetch from memory cache
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DETAIL: query result found in the query cache, SELECT id, description FROM xxxx."MyTableName" 000000000000
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_memqcache.c:698
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: session context: setting skip reading from backends. DONE
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_session_context.c:228
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: session context: unsetting query in progress. DONE
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_session_context.c:209
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: ERROR: unable to read data from frontend
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DETAIL: EOF encountered with frontend
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_stream.c:261
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: session context: unsetting query in progress. DONE
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_session_context.c:209
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: pool_write: to backend: kind:X
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_stream.c:431
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: memcache discarding query cache array
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DETAIL: num_caches: 0
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_memqcache.c:2755
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: DEBUG: session context: unsetting query in progress. DONE
Oct 10 04:49:08 mydev pgpool[3736]: 2015-10-10 04:49:08: pid 3762: LOCATION: pool_session_context.c:209
Steps To ReproduceI have not yet reduced the testcase. I will keep you posted.
TagsNo tags attached.

Activities

ochedru

2015-10-13 22:35

reporter  

testcase152.zip (9,084 bytes)

ochedru

2015-10-13 22:36

reporter   ~0000584

Please find attached a testcase and my pgpool2 configuration. Tested with PostgreSQL 9.4 and pgpool2 3.4.3 (same result with 3.5.0). Just create a test database owned by user test, password test.
This is a simple maven project. The program will exit after about 15 iterations:
Exception in thread "main" java.util.NoSuchElementException
    at java.util.ArrayDeque.removeFirst(ArrayDeque.java:280)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1841)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:618)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:468)
    at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:353)
    at com.mycompany.pgpooltestcase.Main.main(Main.java:25)

t-ishii

2015-10-18 22:07

developer   ~0000593

I could not process your test case file by using mvn and modified it so that it could be compiled by using javac. So far, I was able to reproduce your problem.
I will investigate and get back if I could find the cause of the problem.

t-ishii

2015-10-19 13:28

developer   ~0000594

I don't know why but your Java program sends parse/bind/execute for 4 times but from the 5th iteration, it does not send parse message and reuses prepared statement created in the 4 th iteration. Unfortunately pgpool-II query cache code does not account the situation and creates incorrect cached data.

I have already committed the fix to 3.2 to 3.4 stable branches (master branch I have some problem and will fix later).

ochedru

2016-03-22 01:02

reporter   ~0000700

Thanks for fixing the issue in branches 3.2 and 3.4.
I am in the processing of testing branch 3.5 and it looks like the fix has not been merged.

t-ishii

2016-03-22 14:17

developer   ~0000701

Sounds strange. We added the case to our regression test in 3.5 and 3.5 seems passes the test.

/src/test/regression/tests/065.bug152

ochedru

2016-03-22 17:43

reporter   ~0000702

Indeed. I can reproduce the issue; I will try to setup a simple testcase and I will keep you updated. Thanks!

ochedru

2016-04-05 01:49

reporter   ~0000755

OK I could modify the regression test to make the problem resurface.
You just have to run pgpool in raw mode. (In 065.bug152/test.sh replace "for mode in s r" by "for mode in n".)

Output is then:

1
2
3
4
5
6
7
8
9
10
1
2
Exception in thread "main" java.util.NoSuchElementException
        at java.util.ArrayDeque.removeFirst(ArrayDeque.java:280)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1928)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:200)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161)
        at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
        at Main.main(Main.java:26)

Note I used the latest PostgreSQL JDBC driver (9.4.1208) and kept JDBC autocommit enabled (the default). If autocommit is explicitly turned off with con.setAutoCommit(false), the issue does not appear.

t-ishii

2016-04-05 08:20

developer   ~0000756

I have tried with 3.5.1 and it looks good. Can you please try with 3.5.1?

ochedru

2016-04-05 17:57

reporter   ~0000757

I can reproduce with 3.5.1 in raw mode as well, but only if I force the JDBC driver to issue server prepared statements sooner by setting prepareThreshold:

String url = "jdbc:postgresql://localhost:11000/test?prepareThreshold=1";

The log still looks like this:

server started
1
2
3
4
5
6
7
8
9
10
1
2
Exception in thread "main" java.util.NoSuchElementException
        at java.util.ArrayDeque.removeFirst(ArrayDeque.java:280)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1928)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:200)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161)
        at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
        at Main.main(Main.java:24)

t-ishii

2016-05-16 17:17

developer   ~0000821

Sorry for delay. Finally I had time to look into this. It seems pgpool-II was confused to handle describe message with query cache is on.

Attached "bug152.diff" should fix the problem (for against 3.5.x).

t-ishii

2016-05-16 17:18

developer  

bug152.diff (787 bytes)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 3126db3..35a9dac 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -1322,13 +1322,13 @@ POOL_STATUS Describe(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
     ereport(DEBUG1,
             (errmsg("Describe: waiting for master completing the query")));
 
-	nowait = (REPLICATION? false: true);
+	nowait = (STREAM? true: false);
 
 	pool_set_query_in_progress();
 	pool_extended_send_and_wait(query_context, "D", len, contents, 1, MASTER_NODE_ID, nowait);
 	pool_extended_send_and_wait(query_context, "D", len, contents, -1, MASTER_NODE_ID, nowait);
 
-	if (!REPLICATION)
+	if (STREAM)
 		pool_unset_query_in_progress();
 
 	return POOL_CONTINUE;
bug152.diff (787 bytes)

ochedru

2016-05-17 00:28

reporter   ~0000823

Last edited: 2016-05-17 00:29

View 2 revisions

Thank you for taking the time to provide a patch! It is indeed better with the fix, but I still get JDBC errors on the actual application w/ latest pgpool2 3.5.2.

The PostgreSQL JDBC driver 9.4.1208 returns this kind of error:

Caused by: org.postgresql.util.PSQLException: ERROR: unable to bind
  Detail: cannot get parse message "S_337"
        at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2284)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2003)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:200)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:424)
        at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:161)
        at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:114)
        at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:688)
        at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:629)
        ... 70 common frames omitted

I still have to reproduce and build a testcase.

t-ishii

2016-05-19 05:02

developer   ~0000826

Looking forward to getting your new test case.

t-ishii

2016-05-21 04:45

developer  

bug152-2.diff (1,146 bytes)
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 3126db3..cf259d5 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -1322,13 +1322,13 @@ POOL_STATUS Describe(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
     ereport(DEBUG1,
             (errmsg("Describe: waiting for master completing the query")));
 
-	nowait = (REPLICATION? false: true);
+	nowait = (STREAM? true: false);
 
 	pool_set_query_in_progress();
 	pool_extended_send_and_wait(query_context, "D", len, contents, 1, MASTER_NODE_ID, nowait);
 	pool_extended_send_and_wait(query_context, "D", len, contents, -1, MASTER_NODE_ID, nowait);
 
-	if (!REPLICATION)
+	if (STREAM)
 		pool_unset_query_in_progress();
 
 	return POOL_CONTINUE;
@@ -1396,7 +1396,7 @@ POOL_STATUS Close(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
 
 	pool_set_query_in_progress();
 
-	if (REPLICATION)
+	if (!STREAM)
 	{
 		pool_extended_send_and_wait(query_context, "C", len, contents, 1, MASTER_NODE_ID, false);
 		pool_extended_send_and_wait(query_context, "C", len, contents, -1, MASTER_NODE_ID, false);
bug152-2.diff (1,146 bytes)

t-ishii

2016-05-21 04:48

developer   ~0000832

I have found another defect in the code. "bug152-2.diff" is the patch to deal with the it (it includes previous patch). Could you try it out?

ochedru

2016-05-21 21:12

reporter   ~0000835

I have just tried it and there are no more exceptions so far! Thanks a lot for your support! I guess this bug can be closed.

t-ishii

2016-05-21 21:56

developer   ~0000836

Great! I really appreciate your cooperation. Will close this issue.

Issue History

Date Modified Username Field Change
2015-10-13 00:06 ochedru New Issue
2015-10-13 22:35 ochedru File Added: testcase152.zip
2015-10-13 22:36 ochedru Note Added: 0000584
2015-10-14 15:02 t-ishii Assigned To => t-ishii
2015-10-14 15:02 t-ishii Status new => assigned
2015-10-18 22:07 t-ishii Note Added: 0000593
2015-10-19 13:28 t-ishii Note Added: 0000594
2015-10-19 13:29 t-ishii Status assigned => resolved
2016-03-22 01:02 ochedru Note Added: 0000700
2016-03-22 01:02 ochedru Status resolved => feedback
2016-03-22 01:02 ochedru Resolution open => reopened
2016-03-22 14:17 t-ishii Note Added: 0000701
2016-03-22 17:43 ochedru Note Added: 0000702
2016-03-22 17:43 ochedru Status feedback => assigned
2016-03-30 11:47 t-ishii Status assigned => feedback
2016-04-05 01:49 ochedru Note Added: 0000755
2016-04-05 01:49 ochedru Status feedback => assigned
2016-04-05 08:20 t-ishii Note Added: 0000756
2016-04-05 08:20 t-ishii Status assigned => feedback
2016-04-05 17:57 ochedru Note Added: 0000757
2016-04-05 17:57 ochedru Status feedback => assigned
2016-05-16 17:17 t-ishii Note Added: 0000821
2016-05-16 17:18 t-ishii File Added: bug152.diff
2016-05-16 17:19 t-ishii Status assigned => feedback
2016-05-17 00:28 ochedru Note Added: 0000823
2016-05-17 00:28 ochedru Status feedback => assigned
2016-05-17 00:29 ochedru Note Edited: 0000823 View Revisions
2016-05-19 05:02 t-ishii Note Added: 0000826
2016-05-19 05:02 t-ishii Status assigned => feedback
2016-05-21 04:45 t-ishii File Added: bug152-2.diff
2016-05-21 04:48 t-ishii Note Added: 0000832
2016-05-21 21:12 ochedru Note Added: 0000835
2016-05-21 21:12 ochedru Status feedback => assigned
2016-05-21 21:56 t-ishii Note Added: 0000836
2016-05-21 21:57 t-ishii Status assigned => resolved