[Hawkular-dev] Memory-usage of Hawkular-services

Hey, tl;dr: we need to investigate heap usage - especially in the case of compression kicking in - it looks like there could be a memory leak. Compression timing seems mostly ok. I originally wanted to see how more feeds influence the metrics compression timing. So I started the server with -Xmx512m as I did in all the weeks before and pointed a few feeds at the server - to see it crash with OOME shortly after the compression started. Now I restarted the server with -Xmx1024m and also -XX:MaxMetaspaceSize=512m (up from 256m before) and am running the server now with 1 feed for a day. To be continued below ... ( Time is in GMT, which is 2h off of my local time) hawkular_1 | 15:00:44,764 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 15:00:45,452 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 687 ms hawkular_1 | 17:00:44,757 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 17:00:46,796 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 2039 ms hawkular_1 | 19:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 19:00:47,293 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 2541 ms hawkular_1 | 21:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 21:00:46,267 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1517 ms hawkular_1 | 23:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 23:00:45,472 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 722 ms hawkular_1 | 01:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 01:00:46,241 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1492 ms hawkular_1 | 03:00:44,747 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 03:00:45,780 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1033 ms hawkular_1 | 05:00:44,746 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 05:00:45,781 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1034 ms hawkular_1 | 07:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 07:00:46,386 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1636 ms hawkular_1 | 09:00:44,748 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 09:00:45,682 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 934 ms hawkular_1 | 11:00:44,750 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 11:00:46,339 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1589 ms hawkular_1 | 13:00:44,748 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 13:00:45,880 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 1132 ms Looking at the memory usage I see the memory usage there is often a peak in heap usage around and after the compression - looking at the accumulated GC-time also shows heavy GC activity. I guess the peak in heap usage (and thus committed heap) comes from promoting objects from young generation into old during the compression and then later after compression is over, they are garbage collected, so that heap usage goes down and the system is able to free some memory. Starting at around 4:10pm (2pm in the above output) I am running with 10 extra feeds (hawkfly on an external box) While it looks like there is a slowly growing non-heap, it was growing a lot when the 10 extra feeds connected. Also it looks like it is growing a bit more each time compression kicks in ("non-heap") The first compression run with 11 feeds did not take too long, the next was hawkular_1 | 17:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 17:00:50,277 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 5528 ms Which used a lot more memory than before. Non-heap was able to reclaim some memory though. hawkular_1 | 19:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 19:00:50,093 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 5341 ms hawkular_1 | 21:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 21:00:49,465 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 4714 ms hawkular_1 | 23:00:44,753 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 23:00:48,925 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 4171 ms hawkular_1 | 01:00:44,750 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 01:00:48,554 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 3803 ms hawkular_1 | 03:00:44,761 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 03:00:48,659 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 3898 ms hawkular_1 | 05:00:44,748 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 05:00:49,134 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 4385 ms hawkular_1 | 07:00:44,755 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 07:00:49,831 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 5076 ms hawkular_1 | 09:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 09:00:49,508 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 4757 ms Now at 11:20 (9:20 for above logs) I started 5 more feeds (with a 2min sleep between starts) hawkular_1 | 11:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 11:00:49,751 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 5002 ms hawkular_1 | 13:00:44,749 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 13:00:56,594 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 11845 ms hawkular_1 | 15:00:44,754 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 15:00:53,985 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 9231 ms And another 5 starting at 17:12 (15:00 in above logs timezone) hawkular_1 | 17:00:44,768 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 17:00:57,824 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 13056 ms And another 5 starting at 19:57 (17:57 in above log timezone ) hawkular_1 | 19:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution hawkular_1 | 19:01:24,401 WARN org.apache.activemq.artemis.ra AMQ152007: Thread Thread[TearDown/ActiveMQActivation,5,] could not be finished hawkular_1 | 19:01:40,918 WARN org.apache.activemq.artemis.ra AMQ152007: Thread Thread[TearDown/ActiveMQActivation,5,default-threads] could not be finished hawkular_1 | 19:02:04,619 WARN org.apache.activemq.artemis.ra AMQ152007: Thread Thread[TearDown/ActiveMQActivation,5,default-threads] could not be finished hawkular_1 | 19:02:22,423 WARN org.apache.activemq.artemis.ra AMQ152007: Thread Thread[TearDown/ActiveMQActivation,5,default-threads] could not be finished hawkular_1 | 19:02:30,247 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 105495 ms This took almost 2 minutes, where the server was non-responsive 21:00:44,753 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution 21:01:06,520 INFO org.hawkular.metrics.core.jobs.CompressData Finished compressing data in 21767 ms 23:00:44,751 INFO org.hawkular.metrics.core.jobs.CompressData Starting execution And here it went south and the server more or less died with OOME exceptions (it is still responding to queries, and potentially even ingesting new data, but the scheduler seems not to run anymore. I can imagine that once the OOME happened, the scheduler thread died, freeing up memory that the compression job held and which then allowed the server itself to continue. But it certainly is in an unusable state. This is the final "one day" with "max" values plotted:  The peaks at compression time for heap-max (green line) are clearly visible.