activemq-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Piotr Klimczak (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (AMQ-5543) Broker logs show repeated "java.lang.IllegalSt​ateException: Timer already cancelled." lines
Date Thu, 21 May 2015 14:11:00 GMT

    [ https://issues.apache.org/jira/browse/AMQ-5543?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14554314#comment-14554314
] 

Piotr Klimczak edited comment on AMQ-5543 at 5/21/15 2:10 PM:
--------------------------------------------------------------

Just faced same problem on 5.11.1.

Logs are full of:
XXXX-XX-XX XX:XX:32,416 | WARN  | Transport Connection to: tcp://127.0.0.1:49807 failed: java.io.IOException:
Timer already cancelled. | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
NIO Worker 92939

Before it happened we've seen in logs:

        INFO   | jvm 1    | XXXXXXXXXXXXXXX:21 |  WARN | Transport Connection to: tcp://XXXXXXXXXXXX:35328
failed: java.io.IOException: unable to create new native thread
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:24 | Exception in thread "ActiveMQ InactivityMonitor
WriteCheckTimer" java.lang.OutOfMemoryError: unable to create new native thread
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:24 |       at java.lang.Thread.start0(Native Method)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:24 |       at java.lang.Thread.start(Thread.java:714)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:24 |       at java.util.concurrent.ThreadPoolExecutor.addWorker(ThreadPoolExecutor.java:949)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:24 |       at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1371)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:25 |       at org.apache.activemq.transport.AbstractInactivityMonitor.writeCheck(AbstractInactivityMonitor.java:158)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:25 |       at org.apache.activemq.transport.AbstractInactivityMonitor$2.run(AbstractInactivityMonitor.java:122)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:25 |       at org.apache.activemq.thread.SchedulerTimerTask.run(SchedulerTimerTask.java:33)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:25 |       at java.util.TimerThread.mainLoop(Timer.java:555)
        INFO   | jvm 1    | XXXXXXXXXXXXXXX:25 |       at java.util.TimerThread.run(Timer.java:505)

Then only "Timer already cancelled".

Anyway it is quite strange we run out of native threads as we have set: org.apache.activemq.UseDedicatedTaskRunner=false
which I believe should optimise the number of threads.

We are using about 300-700 parallel connections.


was (Author: nannou9):
Just faced same problem on 5.11.1.
All logs rotated, nothing useful.
Just hundreds of megs of: 
XXXX-XX-XX XX:XX:32,416 | WARN  | Transport Connection to: tcp://127.0.0.1:49807 failed: java.io.IOException:
Timer already cancelled. | org.apache.activemq.broker.TransportConnection.Transport | ActiveMQ
NIO Worker 92939

It has started during runtime.
There was no shutdown request and indeed it is not related to other issues found.
Unfortunately no clue what could be the cause and how to reproduce.

> Broker logs show repeated "java.lang.IllegalSt​ateException: Timer already cancelled."
lines
> --------------------------------------------------------------------------------------------
>
>                 Key: AMQ-5543
>                 URL: https://issues.apache.org/jira/browse/AMQ-5543
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Transport
>    Affects Versions: 5.10.0
>            Reporter: Tim Bain
>
> One of our brokers running 5.10.0 spewed over 1 million of the following exceptions to
the log over a 2-hour period:
> Transport Connection to: tcp://127.0.0.1:xxxxx failed: java.io.IOException: Unexpected
error occurred: java.lang.IllegalStateException: Timer already cancelled.
> Clients were observed to hang on startup (which we believe means they were unable to
connect to the broker) until it was rebooted, after which we haven't seen the exception again.
> Once the exceptions started, there were no stack traces or other log lines that would
indicate anything else about the cause, just those messages repeating.  The problems started
immediately (a few milliseconds) after an EOFException in the broker logs; we see those EOFExceptions
pretty often and they've never before resulted in "Timer already cancelled" exceptions, so
that might indicate what got us into a bad state but then again it might be entirely unrelated.
> I searched JIRA and the mailing list archives for similar issues, and although there
are a lot of incidences of "Timer already cancelled" exceptions, none of them exactly match
our situation.
> * http://activemq.2283324.n4.nabble.com/Producer-connections-keep-breaking-td4671152.html
describes repeated copies of the line in the logs and is the closest parallel I've found,
but it sounded like messages were still getting passed, albeit more slowly than normal, whereas
the developer on my team who hit this said he didn't think any messages were getting sent.
 But it's the closest match of the group.
> * AMQ-5508 has a detailed investigation into the root cause of the problem that Pero
Atanasov saw, but his scenario occurred only on broker shutdown, whereas our broker was not
shutting down at the time, and it wasn't clear that the log line repeated for him.
> * http://activemq.2283324.n4.nabble.com/Timer-already-cancelled-and-KahaDB-Recovering-checkpoint-thread-after-death-td4676684.html
has repeated messages like I'm seeing, but appears to be specific to KahaDB which I'm not
using (we use non-persistent messages only).
> * AMQ-4805 has the same inner exception but not the full log line, and it shows a full
stack trace whereas I only see the one line without the stack trace.
> * http://activemq.2283324.n4.nabble.com/can-t-send-message-Timer-already-cancelled-td4680175.html
appears to see the exception on the producer when sending rather than on the broker.
> The only thing that we observed that might be related was that earlier in the broker's
uptime, the developer who was running it ran up against his maxProc limit and wasn't able
to create new native threads.  That didn't result in any issues in the broker logs at the
time (we only hit these issues several hours later), so I'm skeptical that it's related given
that there are lots of other things that cause "Timer already cancelled" exceptions as evidenced
by the partial list above, but it could be.



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

Mime
View raw message