View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0000152 | Pgpool-II | Bug | public | 2015-10-13 00:06 | 2016-12-16 15:48 |
| Reporter | ochedru | Assigned To | t-ishii | ||
| Priority | normal | Severity | major | Reproducibility | always |
| Status | resolved | Resolution | reopened | ||
| Summary | 0000152: Error with JDBC memory_cache_enabled = on | ||||
| Description | I 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 Reproduce | I have not yet reduced the testcase. I will keep you posted. | ||||
| Tags | No tags attached. | ||||
|
|
|
|
|
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) |
|
|
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. |
|
|
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). |
|
|
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. |
|
|
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 |
|
|
Indeed. I can reproduce the issue; I will try to setup a simple testcase and I will keep you updated. Thanks! |
|
|
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. |
|
|
I have tried with 3.5.1 and it looks good. Can you please try with 3.5.1? |
|
|
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) |
|
|
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). |
|
|
|
|
|
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. |
|
|
Looking forward to getting your new test case. |
|
|
|
|
|
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? |
|
|
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. |
|
|
Great! I really appreciate your cooperation. Will close this issue. |
| 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 | |
| 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 |
