pgjdbc/pgjdbc GitHub issues and pull requests (mirror)
help / color / mirror / Atom feed[pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
17+ messages / 7 participants
[nested] [flat]
* [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-19 20:02 "jamesagnew (@jamesagnew)" <[email protected]>
0 siblings, 0 replies; 17+ messages in thread
From: jamesagnew (@jamesagnew) @ 2025-02-19 20:02 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
**Describe the issue**
I have a Java-based server using Postgresql as a persistence layer that occasionally gets into a state where it is completely unable to perform any new JDBC calls, requiring a JVM restart to bring it back. Once the driver is in this state, any attempt to execute any SQL statement is aborted immediately with the message: java.lang.IllegalStateException: Timer already cancelled
I have observed that this always starts when the server experiences an OutOfMemoryException while processing a resultset. Obviously that shouldn't happen and that's a separate issue, but I don't think an OOM should result in the driver becoming unusable either.
Shortly after an OOM, I typically see an exception with the following stack trace in my logs (presumably the JVM is unstable at this point while the GC tries to recover):
```
Caused by: org.postgresql.util.PSQLException: SSL error: Broken pipe
at org.postgresql.ssl.MakeSSL.convert(MakeSSL.java:53)
at org.postgresql.core.v3.ConnectionFactoryImpl.enableSSL(ConnectionFactoryImpl.java:638)
at org.postgresql.core.v3.ConnectionFactoryImpl.tryConnect(ConnectionFactoryImpl.java:201)
at org.postgresql.core.v3.ConnectionFactoryImpl.openConnectionImpl(ConnectionFactoryImpl.java:268)
at org.postgresql.core.ConnectionFactory.openConnection(ConnectionFactory.java:54)
at org.postgresql.jdbc.PgConnection.<init>(PgConnection.java:273)
at org.postgresql.Driver.makeConnection(Driver.java:446)
at org.postgresql.Driver.connect(Driver.java:298)
at org.apache.commons.dbcp2.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:52)
at org.apache.commons.dbcp2.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:414)
```
The exception above appears once, and then from that moment onward, all JDBC calls fail with the following stack trace:
```
Caused by: java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Timer.java:409)
at java.base/java.util.Timer.schedule(Timer.java:205)
at org.postgresql.jdbc.PgConnection.addTimerTask(PgConnection.java:1351)
at org.postgresql.jdbc.PgStatement.startTimer(PgStatement.java:995)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:516)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:194)
at org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:137)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.
java:123)
at org.apache.commons.dbcp2.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.
java:123)
```
**Driver Version?**
This is occurring on 42.7.4 but this behaviour has been observed on a number of older versions as well over the last 6 months.
**Java Version?**
openjdk version "17.0.7" 2023-04-18 LTS
OpenJDK Runtime Environment Corretto-17.0.7.7.1 (build 17.0.7+7-LTS)
OpenJDK 64-Bit Server VM Corretto-17.0.7.7.1 (build 17.0.7+7-LTS, mixed mode, sharing)
**OS Version?**
Ubuntu 24.04.2 LTS
**PostgreSQL Version?**
PostgreSQL 16.6 (Ubuntu 16.6-0ubuntu0.24.04.1) on x86_64-pc-linux-gnu
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 13:29 "davecramer (@davecramer)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: davecramer (@davecramer) @ 2025-02-21 13:29 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
Thanks for the report. I would imagine that the OOM is related and when the connection fails we are left in the unusable state
@vlsi we should probably prioritize this.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 13:36 "bokken (@bokken)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: bokken (@bokken) @ 2025-02-21 13:36 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
OutOfMemory is an Error not an Exception.
If the pgjdbc driver can be more resilient, that is great. However
consumers should strongly consider the jvm option/flag to shutdown on OOME
because so many things can end up in an unexpected state.
On Fri, Feb 21, 2025 at 7:30 AM Dave Cramer ***@***.***>
wrote:
> Thanks for the report. I would imagine that the OOM is related and when
> the connection fails we are left in the unusable state
> @vlsi <https://github.com/vlsi; we should probably prioritize this.
>
> —
> Reply to this email directly, view it on GitHub
> <https://github.com/pgjdbc/pgjdbc/issues/3530#issuecomment-2674559211;,
> or unsubscribe
> <https://github.com/notifications/unsubscribe-auth/AAW3U3I5KNGIFCSDMRKREKL2Q4S63AVCNFSM6AAAAABXPBWUM2...;
> .
> You are receiving this because you are subscribed to this thread.Message
> ID: ***@***.***>
> [image: davecramer]*davecramer* left a comment (pgjdbc/pgjdbc#3530)
> <https://github.com/pgjdbc/pgjdbc/issues/3530#issuecomment-2674559211;
>
> Thanks for the report. I would imagine that the OOM is related and when
> the connection fails we are left in the unusable state
> @vlsi <https://github.com/vlsi; we should probably prioritize this.
>
> —
> Reply to this email directly, view it on GitHub
> <https://github.com/pgjdbc/pgjdbc/issues/3530#issuecomment-2674559211;,
> or unsubscribe
> <https://github.com/notifications/unsubscribe-auth/AAW3U3I5KNGIFCSDMRKREKL2Q4S63AVCNFSM6AAAAABXPBWUM2...;
> .
> You are receiving this because you are subscribed to this thread.Message
> ID: ***@***.***>
>
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 13:56 "davecramer (@davecramer)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: davecramer (@davecramer) @ 2025-02-21 13:56 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> OutOfMemory is an Error not an Exception.
>
> If the pgjdbc driver can be more resilient, that is great. However
> consumers should strongly consider the jvm option/flag to shutdown on OOME
> because so many things can end up in an unexpected state.
> […](#)
I think the OOM is on the server. If that is correct then we should be able to recover from that.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 14:50 "vlsi (@vlsi)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: vlsi (@vlsi) @ 2025-02-21 14:50 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
@jamesagnew , Just wondering: do you have a reproducer for the issue?
By the way, the stacktraces do not match the line numbers from 42.7.5. Could you please provide a coherent version number + stacktrace pair?
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 15:03 "bokken (@bokken)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: bokken (@bokken) @ 2025-02-21 15:03 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> I think the OOM is on the server. If that is correct then we should be able to recover from that.
I think when he refers to "the server" he means his jvm.
> I have a Java-based server...
> I have observed that this always starts when the server experiences an OutOfMemoryException...
> presumably the JVM is unstable at this point while the GC tries to recover...
I do not believe this has anything to do with the postgresql database instance.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-21 15:53 "jamesagnew (@jamesagnew)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: jamesagnew (@jamesagnew) @ 2025-02-21 15:53 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> the stacktraces do not match the line numbers from 42.7.5. Could you please provide a coherent version number + stacktrace pair?
My apologies, we upgraded to 42.7.5 this week but the stack traces are from last week. The stack traces are from 42.7.4.
> I do not believe this has anything to do with the postgresql database instance.
Correct, when I say "the server" I'm referring to the JVM which is hosting the PG JDBC driver. It is the one experiencing an OOM.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-23 11:27 "davecramer (@davecramer)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: davecramer (@davecramer) @ 2025-02-23 11:27 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> > the stacktraces do not match the line numbers from 42.7.5. Could you please provide a coherent version number + stacktrace pair?
>
> My apologies, we upgraded to 42.7.5 this week but the stack traces are from last week. The stack traces are from 42.7.4.
>
> > I do not believe this has anything to do with the postgresql database instance.
>
> Correct, when I say "the server" I'm referring to the JVM which is hosting the PG JDBC driver. It is the one experiencing an OOM.
In which case I agree with @bokken that this is an error that probably should not be recovered from
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-02-24 05:53 "vlsi (@vlsi)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: vlsi (@vlsi) @ 2025-02-24 05:53 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
Even though OOM is hard to recover from, it is worth double-checking if there's a bug with Timer sharing logic.
@jamesagnew , do OOM stacktraces have anything to do with pgjdbc?
Frankly, it looks like we release the timer in two cases: an explicit connection close or a connection close triggered by leak detector.
In both cases, we cancel the shared if `refCount.decrementAndGet()` returns `0`. We have `refCount.incrementAndGet()` in `getTimer()`, so I do not see a bug there.
---
At the same time, it looks like `java.util.Timer` cancels if any task throws an uncaught exception. It might indeed be the case, however, `org.postgresql.jdbc.StatementCancelTimerTask#run` ignores `SQLException`, so it should be more-or-less safe..
Could you please double-check if there's an uncaught exception from the timer thread?
It could be something like `Exception in thread "PostgreSQL-JDBC-SharedTimer-`...
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-06-06 10:12 "lfgcampos (@lfgcampos)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: lfgcampos (@lfgcampos) @ 2025-06-06 10:12 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
We faced an outage related to this (my assumption) when we upgraded from `42.7.4` to `42.7.6`.
Stacktrace is as follow:
```
Caused by: java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Unknown Source)
at java.base/java.util.Timer.schedule(Unknown Source)
at org.postgresql.jdbc.PgConnection.addTimerTask(PgConnection.java:1363)
at org.postgresql.jdbc.PgStatement.startTimer(PgStatement.java:993)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:435)
at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:196)
at org.postgresql.jdbc.PgPreparedStatement.execute(PgPreparedStatement.java:182)
```
we are still investigating but sharing this earlier in case it helps anything!
as soon as I get more info, I will update here as well
----
update1:
I also found this on our logs, which seems somehow related
```
NullPointerException
Cannot read the array length because the return value of "org.postgresql.util.internal.Nullness.castNonNull(Object)" is null
...
org.postgresql.core.QueryExecutorBase in sendQueryCancel at line 199
org.postgresql.jdbc.PgConnection in cancelQuery at line 1220
org.postgresql.jdbc.PgStatement in cancel at line 926
org.postgresql.jdbc.PgStatement in cancelIfStillNeeded at line 1003
org.postgresql.jdbc.StatementCancelTimerTask in run at line 36
java.util.TimerThread in mainLoop
java.util.TimerThread in run
```
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-07-28 09:03 "pantam-bhaskar (@pantam-bhaskar)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: pantam-bhaskar (@pantam-bhaskar) @ 2025-07-28 09:03 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
Hi Team,
We are also facing same issue in our production instances. We are using version 42.7.5. We have to restart JVM to bring back our services.
Stack Trace:
```
java.lang.IllegalStateException: Timer already cancelled.
at java.base/java.util.Timer.sched(Timer.java:398)
at java.base/java.util.Timer.schedule(Timer.java:194)
at org.postgresql.jdbc.PgConnection.addTimerTask(PgConnection.java:1351)
at org.postgresql.jdbc.PgStatement.startTimer(PgStatement.java:996)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:516)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356)
at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317)
at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:266)
```
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-07-30 09:35 "davecramer (@davecramer)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: davecramer (@davecramer) @ 2025-07-30 09:35 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> Hi Team, We are also facing same issue in our production instances. We are using version 42.7.5. We have to restart JVM to bring back our services.
>
> Stack Trace:
>
> ```
> java.lang.IllegalStateException: Timer already cancelled.
> at java.base/java.util.Timer.sched(Timer.java:398)
> at java.base/java.util.Timer.schedule(Timer.java:194)
> at org.postgresql.jdbc.PgConnection.addTimerTask(PgConnection.java:1351)
> at org.postgresql.jdbc.PgStatement.startTimer(PgStatement.java:996)
> at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:516)
> at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434)
> at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356)
> at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341)
> at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317)
> at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:266)
> ```
Do you also have a corresponding OOM Exception ?
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-08-05 09:01 "pantam-bhaskar (@pantam-bhaskar)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: pantam-bhaskar (@pantam-bhaskar) @ 2025-08-05 09:01 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
> Do you also have a corresponding OOM Exception ?
Hi @davecramer
No, we haven't encountered OOM Exception but I found I/O Exception before "Timer already cancelled" Exception.
```
Caused by: org.postgresql.util.PSQLException: An I/O error occurred while sending to the backend.
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:399)
at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:517)
at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:434)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:356)
at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:341)
at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:317)
at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:266)
at com.org.datamanger.query.execution.JdbcExternalQueryExecutorImpl.fetchResultSet(JdbcExternalQueryExecutorImpl.java:1050)
at com.org.datamanger.query.execution.JdbcExternalQueryExecutorImpl.executeQuery(JdbcExternalQueryExecutorImpl.java:166)
... 8 common frames omitted
Caused by: java.io.EOFException: null
at org.postgresql.core.PGStream.receiveChar(PGStream.java:478)
at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2174)
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:372)
... 16 common frames omitted
```
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-08-11 06:58 "wangkaish (@wangkaish)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: wangkaish (@wangkaish) @ 2025-08-11 06:58 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
Hi @davecramer
We have also encountered a similar issue. After a Java OOM, when attempting to operate on the database, we receive the message “Timer already cancelled.” Normally, when we encounter an OOM exception, the system can recover on its own, but this time it did not. Each recovery attempt fails due to “Timer already cancelled.”
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-08-11 10:07 "davecramer (@davecramer)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: davecramer (@davecramer) @ 2025-08-11 10:07 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
@wangkaish OOM is a special case and in almost every case the application should be restarted. https://www.baeldung.com/java-shutting-down-outofmemoryerror
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-08-20 02:19 "wangkaish (@wangkaish)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: wangkaish (@wangkaish) @ 2025-08-20 02:19 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
@davecramer Yes, OOM is a special case — it signals memory allocation failure and starts throwing exceptions. Normally, the temporary variables allocated in the thread would then be reclaimed, and the system should have a chance to recover.
The problem we are facing is that even after memory usage drops, the system still cannot recover. We have no other workaround at the moment, and may need to consider implementing our own delayed scheduler to handle queryTimeout.
^ permalink raw reply [nested|flat] 17+ messages in thread
* Re: [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled
@ 2025-08-20 09:10 "vlsi (@vlsi)" <[email protected]>
15 siblings, 0 replies; 17+ messages in thread
From: vlsi (@vlsi) @ 2025-08-20 09:10 UTC (permalink / raw)
To: pgjdbc/pgjdbc <[email protected]>
I found one of the cases that might trigger "timer already cancelled" error: https://github.com/pgjdbc/pgjdbc/pull/3778
For instance, it would heal @lfgcampos' "NPE from StatementCancelTimerTask in run"
case: https://github.com/pgjdbc/pgjdbc/issues/3530#issuecomment-2948773054
I'm not sure if there are the other cases though
^ permalink raw reply [nested|flat] 17+ messages in thread
end of thread, other threads:[~2025-08-20 09:10 UTC | newest]
Thread overview: 17+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2025-02-19 20:02 [pgjdbc/pgjdbc] issue #3530: JDBC Shared Timer set to cancelled "jamesagnew (@jamesagnew)" <[email protected]>
2025-02-21 13:29 ` "davecramer (@davecramer)" <[email protected]>
2025-02-21 13:36 ` "bokken (@bokken)" <[email protected]>
2025-02-21 13:56 ` "davecramer (@davecramer)" <[email protected]>
2025-02-21 14:50 ` "vlsi (@vlsi)" <[email protected]>
2025-02-21 15:03 ` "bokken (@bokken)" <[email protected]>
2025-02-21 15:53 ` "jamesagnew (@jamesagnew)" <[email protected]>
2025-02-23 11:27 ` "davecramer (@davecramer)" <[email protected]>
2025-02-24 05:53 ` "vlsi (@vlsi)" <[email protected]>
2025-06-06 10:12 ` "lfgcampos (@lfgcampos)" <[email protected]>
2025-07-28 09:03 ` "pantam-bhaskar (@pantam-bhaskar)" <[email protected]>
2025-07-30 09:35 ` "davecramer (@davecramer)" <[email protected]>
2025-08-05 09:01 ` "pantam-bhaskar (@pantam-bhaskar)" <[email protected]>
2025-08-11 06:58 ` "wangkaish (@wangkaish)" <[email protected]>
2025-08-11 10:07 ` "davecramer (@davecramer)" <[email protected]>
2025-08-20 02:19 ` "wangkaish (@wangkaish)" <[email protected]>
2025-08-20 09:10 ` "vlsi (@vlsi)" <[email protected]>
This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox