Failure to send result to graphite server

Question

Failure to send result to graphite server

johnou opened this issue 9 years ago · 40 comments

During shutdown we are seeing the following exception.. could be related to the commons-pool upgrade?

2015-07-08 16:38:57,224 WARN  [jmxtrans-export-1] (org.jmxtrans.embedded.output.GraphiteWriter) Failure to send result to graphite server 'HostAndPort{host='graphite.xxx', port=2003}' with null
java.lang.IllegalStateException: Pool not open
    at org.apache.commons.pool2.impl.BaseGenericObjectPool.assertOpen(BaseGenericObjectPool.java:662)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:338)
    at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:278)
    at org.jmxtrans.embedded.output.GraphiteWriter.write(GraphiteWriter.java:144)
    at org.jmxtrans.embedded.Query.exportCollectedMetrics(Query.java:208)
    at org.jmxtrans.embedded.EmbeddedJmxTrans$2.run(EmbeddedJmxTrans.java:229)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

johnou commented 9 years ago

Cheers!

Answer 1 · 2015-07-08T22:07:03.000Z

This is the issue I intended to solve with PR #94 [Avoid write on closed output writer]

Answer 2 · 2015-07-08T22:16:35.000Z

Thanks @YannRobert for the answer. You are faster than I am. I'm sorry, I'm very busy with my day job this week :-)

Answer 3 · 2015-07-08T22:40:32.000Z

😊 No need to be fast on this one. Let's sleep on this, and come up with the right solution.

Answer 4 · 2015-07-21T22:54:15.000Z

I suspect that we have a thread safety issue. I am trying to reproduce.

Cyrille

Answer 5 · 2015-09-24T21:32:40.000Z

Shouldn't org.jmxtrans.embedded.EmbeddedJmxTrans.EmbeddedJmxTransShutdownHook#execute be trying to shutdown collectScheduledExecutor and exportScheduledExecutor before stopping the queries and writers?

Answer 6 · 2015-09-24T22:11:17.000Z

I am a bit confused looking at the code. Did you see problems during the shutdown phase? Any suggestion of a test case?
We would need a test case with slow writers.

Answer 7 · 2015-09-25T08:10:32.000Z

Well from what I can see EmbeddedJmxTransShutdownHook may run to gracefully shutdown embedded jmxtrans if stop is not invoked by "collecting and exporting metrics one last time", however if the shutdown hook is invoked and responsible for cleaning up the collect and export executors will continue to run and may try and collect and export after Query.stop has been invoked..

imo to fix the thread safety issues it may be enough just to mark collectMetrics, exportCollectedMetrics and stop in Query with the sync keyword or some other type of locking to provide thread safety, set a boolean in query when stop is invoked and check that in collectMetrics before adding to queryResults.

I'll try and find some time next week to contribute a patch but would be nice to hear your thoughts on the proposed solution.

Answer 8 · 2015-09-25T09:14:58.000Z

Hi @johnou, just a quick comment

the shutdown hook is not appropriate to run a long task, that's probably the reason why it does not take care of gracefully shutdown the Executors, as it may take a long of time
synchronizing Query class methods with synchronized keyword would be weird, as nothing justifies that a collectMetrics and an exportCollectedMetrics should be mutually exclusive. collectMetrics and an exportCollectedMetrics should be able to run concurrently, but they both need to be mutually exclusive with start and stop.
start and stop are global lifecycle "checkpoints". But we may have multiple Query Objects and multiples OutputWriter Objects, so applying a synchronization of each Object is overkill, and will have undesired results like contention.

Maybe you should consider trying PR #94 that already does the job.
In PR #94, OutputWriter Objects are aggregated together in an Object that is notified of the lifecycle, an makes a single entrypoint to all the OuputWriter write. So that only this entrypoint needs to be sychnronized to be mutally exclusive with start and stop.

I'll also shortly follow up on your comment #94 (diff)

Answer 9 · 2015-11-02T23:27:57.000Z

@YannRobert @cyrille-leclerc wdyt of something simple like this? johnou@7740246

Answer 10 · 2015-11-02T23:53:46.000Z

@johnou did you reproduce the bug with embedded-jmxtrans:1.1.1?
The change 4f1ce2c should have fixed thread safety issues on stop().

Can you share with us details to reproduce if you still face a problem?

Cyrille

Answer 11 · 2015-11-03T00:40:18.000Z

wow, totally missed that commit. I'll give it a shot and get back to you.

Answer 12 · 2015-11-03T08:41:34.000Z

Thanks @johnou!

Answer 13 · 2015-11-03T12:21:43.000Z

@cyrille-leclerc unfortunately still an issue with embedded-jmxtrans:1.1.1 here is the updated stacktrace.

Failure to send result to graphite server 'HostAndPort{host='graphite.varoke.net', port=2003}' with null
java.lang.IllegalStateException: Pool not open
at org.apache.commons.pool2.impl.BaseGenericObjectPool.assertOpen(BaseGenericObjectPool.java:662)
at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:338)
at org.apache.commons.pool2.impl.GenericKeyedObjectPool.borrowObject(GenericKeyedObjectPool.java:278)
at org.jmxtrans.embedded.output.GraphiteWriter.write(GraphiteWriter.java:181)
at org.jmxtrans.embedded.Query.exportCollectedMetrics(Query.java:208)
at org.jmxtrans.embedded.EmbeddedJmxTrans$2.run(EmbeddedJmxTrans.java:262)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)

Answer 14 · 2015-11-03T13:46:34.000Z

@cyrille-leclerc iirc shutdown hooks are invoked in reverse, therefore when running a spring application the embedded-jmxtrans shut down hook would run before @PreDestroy, in which case it may be enough to invoke state.set(State.STOPPED); in the shutdown hook.. 00258d0

Answer 15 · 2015-11-07T19:45:09.000Z

@johnou This should fix the shutdown problem. I found a problem, invoking the shutdown hook from stop() does not work, the logic is different.

Can you test https://github.com/jmxtrans/embedded-jmxtrans/tree/better-shut-down ?

Answer 16 · 2015-11-08T21:00:21.000Z

@cyrille-leclerc I had to move the logger call to inside the try for it to build the package, will try it out soon.

[INFO] --- findbugs-maven-plugin:3.0.1:check (default) @ embedded-jmxtrans ---
[INFO] BugInstance size is 1
[INFO] Error size is 0
[INFO] Total bugs: 1
[INFO] org.jmxtrans.embedded.EmbeddedJmxTrans.stop() does not release lock on all exception paths [org.jmxtrans.embedded.EmbeddedJmxTrans] At EmbeddedJmxTrans.java:[line 254]

Answer 17 · 2015-11-08T23:39:16.000Z

@johnou thanks, I fixed it and I did amend the commit.

Answer 18 · 2015-11-09T12:12:28.000Z

@cyrille-leclerc looking a lot better, but now it throws IllegalStateException on shutdown.

2015-11-09 12:05:47,958 INFO  [Thread-0] (com.sulake.common.spring.ClassPathXmlServiceApplicationContext) Closing com.sulake.common.spring.ClassPathXmlServiceApplicationContext@de0a01f: startup date [Mon Nov 09 09:53:06 UTC 2015]; root o
f context hierarchy
2015-11-09 12:05:47,963 INFO  [EmbeddedJmxTransShutdownHook-Thread-26] (org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook) Execute shutdown hook...
2015-11-09 12:05:47,963 INFO  [EmbeddedJmxTransShutdownHook-Thread-26] (org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook) Collect metrics...
2015-11-09 12:05:47,967 INFO  [EmbeddedJmxTransShutdownHook-Thread-26] (org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook) Export collected metrics...
2015-11-09 12:05:47,967 INFO  [EmbeddedJmxTransShutdownHook-Thread-26] (org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook) Metrics successfully collected and exported by the shutdown hook
2015-11-09 12:06:09,472 INFO  [Thread-0] (com.sulake.common.spring.ScheduledThreadPoolExecutorFactory) threadPoolExecutorFactory: stopping executor
2015-11-09 12:06:09,472 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop ...
2015-11-09 12:06:09,473 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Unregister shutdown hook
2015-11-09 12:06:09,473 WARN  [Thread-0] (org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook) Failure to remove ShutdownHook
java.lang.IllegalStateException: Shutdown in progress
        at java.lang.ApplicationShutdownHooks.remove(ApplicationShutdownHooks.java:82)
        at java.lang.Runtime.removeShutdownHook(Runtime.java:239)
        at org.jmxtrans.embedded.EmbeddedJmxTrans$EmbeddedJmxTransShutdownHook.unregisterFromRuntime(EmbeddedJmxTrans.java:120)
        at org.jmxtrans.embedded.EmbeddedJmxTrans.stop(EmbeddedJmxTrans.java:263)
        at org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans.destroy(SpringEmbeddedJmxTrans.java:48)
        at org.jmxtrans.embedded.spring.EmbeddedJmxTransFactory.destroy(EmbeddedJmxTransFactory.java:243)
        at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:261)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:578)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:554)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:972)
        at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:523)
        at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:979)
        at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1000)
        at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:976)
        at org.springframework.context.support.AbstractApplicationContext$1.run(AbstractApplicationContext.java:895)
2015-11-09 12:06:09,473 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Collect metrics...
2015-11-09 12:06:09,476 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Export metrics...
2015-11-09 12:06:09,477 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Set state to STOPPING
2015-11-09 12:06:09,477 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Shutdown collectScheduledExecutor ...
2015-11-09 12:06:09,478 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) collectScheduledExecutor successfully shutdown
2015-11-09 12:06:09,478 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Shutdown exportScheduledExecutor ...
2015-11-09 12:06:09,478 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) exportScheduledExecutor successfully shutdown
2015-11-09 12:06:09,478 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop queries...
2015-11-09 12:06:09,479 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop output writers...
2015-11-09 12:06:09,479 INFO  [Thread-0] (org.jmxtrans.embedded.output.GraphiteWriter) Stop GraphiteWriter connected to 'HostAndPort{host='xx.xx.net', port=2003}' ...
2015-11-09 12:06:09,480 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Set state to STOPPED
2015-11-09 12:06:09,480 INFO  [Thread-0] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stopped

Answer 19 · 2015-11-09T15:49:54.000Z

@johnou @cyrille-leclerc I think you really should consider #94

Answer 20 · 2015-11-09T16:29:25.000Z

@johnou hmm, I didn't expect the shutdown hook to be called before the shutdown hook of Spring Framework.

I am fixing this but I suspect that the Spring context is not "shutdown" through the "standard" lifecycle

@YannRobert thanks, I think there was a problem isolated in the lifecycle handling and that the last "WARN" is an expected call of EmbeddedJmxTrans.stop() after the invocation of the shutdown hook. I am hardening this.

Answer 21 · 2015-11-09T16:48:23.000Z

@cyrille-leclerc that's what I explained in my previous comment, shutdown hooks are invoked in reverse, as the embedded jmxtrans shutdown hook is registered last (during spring context init) it is executed first when the JVM is being shut down.

The Spring context is being shutdown through the standard lifecycle, org.springframework.context.support.AbstractApplicationContext#registerShutdownHook is invoked on bootstrap and then send sigterm to the java PID to init shutdown.

Answer 22 · 2015-11-09T20:51:14.000Z

@johnou I think I get it now. It works on the Spring demo app https://github.com/jmxtrans/embedded-jmxtrans-samples/tree/master/embedded-jmxtrans-webapp-coktail

Can you please test?

Answer 23 · 2015-11-09T21:02:44.000Z

hi @cyrille-leclerc did you just force push a complete different project into master?

Answer 24 · 2015-11-09T22:20:01.000Z

I hope not, let le check
On Nov 9, 2015 10:02 PM, "Yann ROBERT" notifications@github.com wrote:

hi @cyrille-leclerc https://github.com/cyrille-leclerc did you just
force push a complete different project into master?

—
Reply to this email directly or view it on GitHub
#99 (comment)
.

Answer 25 · 2015-11-09T22:27:53.000Z

@YannRobert thank you very much! Did I revert properly? I made a mistake working on the demo app.

Cyrille

Answer 26 · 2015-11-09T23:02:05.000Z

yes @cyrille-leclerc the master branch is good now

Answer 27 · 2015-11-09T23:11:24.000Z

Thanks, I have protected the master branch against this kind of mistake
On Nov 10, 2015 12:02 AM, "Yann ROBERT" notifications@github.com wrote:

yes @cyrille-leclerc https://github.com/cyrille-leclerc the master
branch is good now

—
Reply to this email directly or view it on GitHub
#99 (comment)
.

Answer 28 · 2015-11-10T00:11:50.000Z

@cyrille-leclerc I created a basic project which demonstrates how I use Spring and embedded-jmxtrans here https://github.com/johnou/embedded-jmxtrans-test

Answer 29 · 2015-11-10T08:24:39.000Z

Thanks @johnou, my tests with 5572859 are successful, the shutdown logs are clean.

Can you confirm?

2015-11-10 09:18:55,631 INFO  [Thread-2] (org.springframework.context.support.ClassPathXmlApplicationContext) Closing org.springframework.context.support.ClassPathXmlApplicationContext@7de26db8: startup date [Tue Nov 10 09:18:24 CET 2015]; root of context hierarchy 
2015-11-10 09:18:55,631 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop... 
2015-11-10 09:18:55,631 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Unregister shutdown hook 
2015-11-10 09:18:55,631 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Collect metrics... 
2015-11-10 09:18:55,631 INFO  [Thread-2] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop... 
2015-11-10 09:18:55,633 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Export metrics... 
TestStats.TestCount 1 1447143535
TestStats.TestCount 1 1447143535
jvm.memorypool.Metaspace.Usage.committed 17039360 1447143505
jvm.memorypool.Metaspace.Usage.used 16542992 1447143505
jvm.memorypool.PS_Old_Gen.Usage.committed 89653248 1447143505
jvm.memorypool.PS_Old_Gen.Usage.used 410984 1447143505
jvm.memorypool.Compressed_Class_Space.Usage.committed 2097152 1447143505
jvm.memorypool.Compressed_Class_Space.Usage.used 1953904 1447143505
jvm.memorypool.PS_Survivor_Space.Usage.committed 5242880 1447143505
jvm.memorypool.PS_Survivor_Space.Usage.used 5219520 1447143505
jvm.memorypool.PS_Eden_Space.Usage.committed 34078720 1447143505
jvm.memorypool.PS_Eden_Space.Usage.used 22557344 1447143505
jvm.memorypool.Code_Cache.Usage.committed 4128768 1447143505
jvm.memorypool.Code_Cache.Usage.used 4110144 1447143505
jvm.memorypool.Metaspace.Usage.committed 17301504 1447143535
jvm.memorypool.Metaspace.Usage.used 16834152 1447143535
jvm.memorypool.PS_Old_Gen.Usage.committed 89653248 1447143535
jvm.memorypool.PS_Old_Gen.Usage.used 410984 1447143535
jvm.memorypool.Compressed_Class_Space.Usage.committed 2097152 1447143535
jvm.memorypool.Compressed_Class_Space.Usage.used 1988024 1447143535
jvm.memorypool.PS_Survivor_Space.Usage.committed 5242880 1447143535
jvm.memorypool.PS_Survivor_Space.Usage.used 5219520 1447143535
jvm.memorypool.PS_Eden_Space.Usage.committed 34078720 1447143535
jvm.memorypool.PS_Eden_Space.Usage.used 24534200 1447143535
jvm.memorypool.Code_Cache.Usage.committed 4390912 1447143535
jvm.memorypool.Code_Cache.Usage.used 4330496 1447143535
jvm.memorypool.Metaspace.Usage.committed 17301504 1447143535
jvm.memorypool.Metaspace.Usage.used 16871616 1447143535
jvm.memorypool.PS_Old_Gen.Usage.committed 89653248 1447143535
jvm.memorypool.PS_Old_Gen.Usage.used 410984 1447143535
jvm.memorypool.Compressed_Class_Space.Usage.committed 2097152 1447143535
jvm.memorypool.Compressed_Class_Space.Usage.used 1992416 1447143535
jvm.memorypool.PS_Survivor_Space.Usage.committed 5242880 1447143535
jvm.memorypool.PS_Survivor_Space.Usage.used 5219520 1447143535
jvm.memorypool.PS_Eden_Space.Usage.committed 34078720 1447143535
jvm.memorypool.PS_Eden_Space.Usage.used 26352104 1447143535
jvm.memorypool.Code_Cache.Usage.committed 4390912 1447143535
jvm.memorypool.Code_Cache.Usage.used 4350912 1447143535
jmxtrans.jmxtrans.ExportDurationInNanos 0 1447143535
jmxtrans.jmxtrans.ExportedMetricsCount 0 1447143535
jmxtrans.jmxtrans.CollectionCount 10 1447143535
jmxtrans.jmxtrans.ExportCount 0 1447143535
jmxtrans.jmxtrans.CollectedMetricsCount 41 1447143535
jmxtrans.jmxtrans.CollectionDurationInNanos 15827795 1447143535
jmxtrans.jmxtrans.ExportDurationInNanos 0 1447143535
jmxtrans.jmxtrans.ExportedMetricsCount 0 1447143535
jmxtrans.jmxtrans.CollectionCount 18 1447143535
jmxtrans.jmxtrans.ExportCount 0 1447143535
jmxtrans.jmxtrans.CollectedMetricsCount 76 1447143535
jmxtrans.jmxtrans.CollectionDurationInNanos 19461099 1447143535
jvm.memory.HeapMemoryUsage.committed 128974848 1447143505
jvm.memory.HeapMemoryUsage.used 28187848 1447143505
jvm.memory.NonHeapMemoryUsage.committed 23265280 1447143505
jvm.memory.NonHeapMemoryUsage.used 22649688 1447143505
jvm.memory.HeapMemoryUsage.committed 128974848 1447143535
jvm.memory.HeapMemoryUsage.used 30164704 1447143535
jvm.memory.NonHeapMemoryUsage.committed 23789568 1447143535
jvm.memory.NonHeapMemoryUsage.used 23164584 1447143535
jvm.memory.HeapMemoryUsage.committed 128974848 1447143535
jvm.memory.HeapMemoryUsage.used 31982608 1447143535
jvm.memory.NonHeapMemoryUsage.committed 23789568 1447143535
jvm.memory.NonHeapMemoryUsage.used 23225272 1447143535
jvm.runtime.Uptime 1799 1447143505
jvm.runtime.Uptime 31800 1447143535
jvm.runtime.Uptime 32037 1447143535
jvm.gc.PS_Scavenge.CollectionTime 8 1447143505
jvm.gc.PS_Scavenge.CollectionCount 1 1447143505
jvm.gc.PS_MarkSweep.CollectionTime 0 1447143505
jvm.gc.PS_MarkSweep.CollectionCount 0 1447143505
jvm.gc.PS_Scavenge.CollectionTime 8 1447143535
jvm.gc.PS_Scavenge.CollectionCount 1 1447143535
jvm.gc.PS_MarkSweep.CollectionTime 0 1447143535
jvm.gc.PS_MarkSweep.CollectionCount 0 1447143535
jvm.gc.PS_Scavenge.CollectionTime 8 1447143535
jvm.gc.PS_Scavenge.CollectionCount 1 1447143535
jvm.gc.PS_MarkSweep.CollectionTime 0 1447143535
jvm.gc.PS_MarkSweep.CollectionCount 0 1447143535
jvm.thread.ThreadCount 7 1447143505
jvm.thread.ThreadCount 7 1447143535
jvm.thread.ThreadCount 10 1447143535
jvm.os.ProcessCpuTime 2494391000 1447143505
jvm.os.CommittedVirtualMemorySize 6257758208 1447143505
jvm.os.OpenFileDescriptorCount 46 1447143505
jvm.os.FreePhysicalMemorySize 21626880 1447143505
jvm.os.SystemLoadAverage 3.74072265625 1447143505
jvm.os.FreeSwapSpaceSize 474742784 1447143505
jvm.os.ProcessCpuTime 2703058000 1447143535
jvm.os.CommittedVirtualMemorySize 6256685056 1447143535
jvm.os.OpenFileDescriptorCount 46 1447143535
jvm.os.FreePhysicalMemorySize 81866752 1447143535
jvm.os.SystemLoadAverage 3.3505859375 1447143535
jvm.os.FreeSwapSpaceSize 398458880 1447143535
jvm.os.ProcessCpuTime 2711543000 1447143535
jvm.os.CommittedVirtualMemorySize 6259867648 1447143535
jvm.os.OpenFileDescriptorCount 46 1447143535
jvm.os.FreePhysicalMemorySize 72134656 1447143535
jvm.os.SystemLoadAverage 3.3505859375 1447143535
jvm.os.FreeSwapSpaceSize 398458880 1447143535
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Set state to STOPPING 
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Shutdown collectScheduledExecutor ... 
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) collectScheduledExecutor successfully shutdown 
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Shutdown exportScheduledExecutor ... 
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) exportScheduledExecutor successfully shutdown 
2015-11-10 09:18:55,639 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop queries... 
2015-11-10 09:18:55,640 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stop output writers... 
2015-11-10 09:18:55,640 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Set state to STOPPED 
2015-11-10 09:18:55,640 INFO  [EmbeddedJmxTransShutdownHook-Thread-1] (org.jmxtrans.embedded.spring.SpringEmbeddedJmxTrans) Stopped 
2015-11-10 09:18:55,640 INFO  [Thread-2] (org.springframework.jmx.export.annotation.AnnotationMBeanExporter) Unregistering JMX-exposed beans on shutdown 
2015-11-10 09:18:55,640 INFO  [Thread-2] (org.springframework.jmx.export.annotation.AnnotationMBeanExporter) Unregistering JMX-exposed beans

Answer 30 · 2015-11-10T08:48:58.000Z

The sample project does not make use of org.jmxtrans.embedded.output.GraphiteWriter so you won't be able to reproduce, even with latest released version. You will also want to test the shutdown while the OutputWriter is writing.

Answer 31 · 2015-11-10T09:18:02.000Z

@YannRobert the sample project was just to show the lifecycle of Spring and embedded-jmxtrans, not to reproduce errors with writing during shutdown.

@cyrille-leclerc I will try a new snapshot soon and let you know how it goes.

Answer 32 · 2015-11-10T09:25:57.000Z

@johnou same same, I looked at the lifecycle and it sounds good to me. Please let me know

Answer 33 · 2015-11-10T10:43:16.000Z

Cyrille, I had a look at the code in branch https://github.com/jmxtrans/embedded-jmxtrans/commits/better-shut-down (I think you should create a PR by the way, so that is easier to comment and reference in the long term)

I fail to understand why you would prefer this code, over the one from PR #94.

Putting all of the synchronization and state management logic in org.jmxtrans.embedded.EmbeddedJmxTrans is not ideal.

I would really prefer the synchronization logic to be located in a dedicated class (that is OutputWriterSet in PR #94). If it's only the naming of this class that you don't like, I can easily rename it.

The concerned being on the export, we only need to synchronize the OutputWriters usage, and not also the metric collection.

Also, I have other issues that I had to address in the framework, like PR #98 [Dont discard metrics on exception while exporting] and #97 [Export batching]
Having an intermediate object handling the synchronization and state (like OutputWriterSet) really helps addressing this (that's why #98 and #97 depend on #94, and I would appreciate not having to write those changes again).

Could you please comment on #94 and explain what's wrong with it ? It's running in production for almost 5 months without a problem.

Thank you Cyrille

PS : those PR #98 and #97 changesets look really messed up in GH web UI, is it before of the force push on master?

Answer 34 · 2015-11-10T10:47:28.000Z

@cyrille-leclerc lgtm, no more errors on shutdown.

2015-11-10 10:11:22,925 INFO main Created EmbeddedJmxTrans with configuration [classpath:jmxtrans.json, classpath:jvm-memorypool.json, classpath:org/jmxtrans/embedded/config/jmxtrans-internals.json, classpath:org/jmxtrans/embedded/config/jvm-sun-hotspot.json])
2015-11-10 10:11:22,925 INFO main Start...
2015-11-10 10:11:22,949 INFO main Start Graphite writer connected to 'HostAndPort{host='xxx', port=2003}'...
2015-11-10 10:11:22,950 INFO main Protocol unspecified, default protocol 'TCP' will be used.
2015-11-10 10:11:23,020 INFO main Start queries and output writers...
2015-11-10 10:11:23,028 INFO main EmbeddedJmxTrans started
2015-11-10 10:11:23,028 INFO main Automatic configuration reloading is disabled.
2015-11-10 10:11:23,633 INFO main Application context initialized
...
2015-11-10 10:41:58,117 INFO Thread-0 Closing com.sulake.common.spring.ClassPathXmlServiceApplicationContext@de0a01f: startup date [Tue Nov 10 10:11:05 UTC 2015]; root of context hierarchy
2015-11-10 10:41:58,119 INFO EmbeddedJmxTransShutdownHook-Thread-33 Stop...
2015-11-10 10:41:58,120 INFO EmbeddedJmxTransShutdownHook-Thread-33 Unregister shutdown hook
2015-11-10 10:41:58,120 INFO EmbeddedJmxTransShutdownHook-Thread-33 Collect metrics...
2015-11-10 10:41:58,136 INFO EmbeddedJmxTransShutdownHook-Thread-33 Export metrics...
2015-11-10 10:41:58,137 INFO EmbeddedJmxTransShutdownHook-Thread-33 Set state to STOPPING
2015-11-10 10:41:58,137 INFO EmbeddedJmxTransShutdownHook-Thread-33 Shutdown collectScheduledExecutor ...
2015-11-10 10:41:58,138 INFO EmbeddedJmxTransShutdownHook-Thread-33 collectScheduledExecutor successfully shutdown
2015-11-10 10:41:58,138 INFO EmbeddedJmxTransShutdownHook-Thread-33 Shutdown exportScheduledExecutor ...
2015-11-10 10:41:58,138 INFO EmbeddedJmxTransShutdownHook-Thread-33 exportScheduledExecutor successfully shutdown
2015-11-10 10:41:58,143 INFO EmbeddedJmxTransShutdownHook-Thread-33 Stop queries...
2015-11-10 10:41:58,144 INFO EmbeddedJmxTransShutdownHook-Thread-33 Stop output writers...
2015-11-10 10:41:58,144 INFO EmbeddedJmxTransShutdownHook-Thread-33 Stop GraphiteWriter connected to 'HostAndPort{host='xxxx', port=2003}' ...
2015-11-10 10:41:58,146 INFO EmbeddedJmxTransShutdownHook-Thread-33 Set state to STOPPED
2015-11-10 10:41:58,146 INFO EmbeddedJmxTransShutdownHook-Thread-33 Stopped

Answer 35 · 2015-11-10T13:03:33.000Z

@johnou thanks for the good news

@YannRobert

I am afraid you are right, my terrible mistake yesterday seem to have damaged your pull requests. Hopefully, your repo https://github.com/YannRobert/embedded-jmxtrans still has you code with the right history
I will create a PR for the changes of https://github.com/jmxtrans/embedded-jmxtrans/commits/better-shut-down
I will re-explain why I preferred to follow the path of the OutputWriterSet.java that you have chosen in your proposal AvoidWriteOnClosedOutputWriter and why I prefer to locate all the concurrent logic in EmbeddedJmxTrans.java. I am very busy today, I may do it during the bank holiday in FR tomorrow.

Answer 36 · 2015-11-28T15:49:03.000Z

Fixed with #110

Answer 37 · 2015-11-28T16:02:22.000Z

@cyrille-leclerc problems pushing 1.1.2 to central Maven?

Answer 38 · 2015-11-29T10:43:35.000Z

Thanks @johnou , I forgot to validate on oss.sonatype.org. It should be sync on Maven Central shortly.

Answer 39 · 2015-11-29T22:03:45.000Z

@johnou thanks!