High CPU usage of Glowroot-Aggregator thread

[amir169]

We're using glowroot version 0.14.0 for our app with the default configuration (profiling interval and other stuffs).
The problem is it's using almost 5 percent of the CPU of the host machine, which is too much, and according to top tool, I can see the thread is Glowroot-Aggregator.

Here's a picture of the top command result:

The app is idle and is almost doing nothing, Doing like 5-6 transactions per seconds and they're all a lightweight health check:

The command that is used to run the app is:

/opt/java/openjdk/bin/java -Djdk.util.zip.disableZip64ExtraFieldValidation=true -Dglowroot.multi.dir=true -Dglowroot.agent.id=glowagent -Dglowroot.conf.dir=/tmp/glowroot/conf -Dglowroot.tmp.dir=/tmp/glowroot/tmp -Dglowroot.log.dir=/app/data/glowroot/logs -Dglowroot.data.dir=/app/data/glowroot/data -javaagent:/opt/glowroot/glowroot.jar -Djava.awt.headless=true -Djava.security.egd=file:/dev/./urandom -Xmx512m -jar /app/app.jar

Things that I tried to reduce the CPU usage:

1. Increasing the profiling interval from 1000 to 10000 milliseconds
2. Unchecking Capture JVM thread stats
3. Removing all the previous data of glowroot (almost 300 MB)

But none of them helped.

If more data is needed (like json files of configurations), please let me know.

Thank you in advance!

[Nowheresly]

Hi,
thanks for the report.
Maybe could you try to use jcmd to generate a thread dump and see exactly the the Glowroot-Aggregate-Processing thread.
Please not this thread dump can as well be consulted from glowroot (JVM > Thread Dump).

With jcmd:
jcmd <pid> Thread.print

Maybe could you post several thread dumps (only the part related to the thread Glowroot-Aggregate-Processing) ?

[amir169]

I failed to attach jcmd but using the glow root thread dump, I tried multiple times and only got this:

...

"Glowroot-Aggregate-Processing" #17
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Thread.sleep(Native Method)
        at java.lang.Thread.sleep(Thread.java:344)
        at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:446)
        at org.glowroot.agent.impl.TransactionProcessor$TransactionProcessorLoop.processOne(TransactionProcessor.java:208)
        at org.glowroot.agent.impl.TransactionProcessor$TransactionProcessorLoop.run(TransactionProcessor.java:193)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(Thread.java:840)

"Glowroot-Aggregate-Flushing" #18
   java.lang.Thread.State: WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on java.util.concurrent.LinkedBlockingQueue@951c14b
        at java.lang.Object.wait(Object.java:338)
        at org.glowroot.agent.impl.TransactionProcessor$AggregateFlushingLoop.run(TransactionProcessor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(Thread.java:840)

...

[amir169]

Also got this after a few minutes:

...

"Glowroot-Aggregate-Processing" #17
   java.lang.Thread.State: RUNNABLE
        at java.lang.Thread.sleep(Native Method)
        at java.lang.Thread.sleep(Thread.java:344)
        at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:446)
        at org.glowroot.agent.impl.TransactionProcessor$TransactionProcessorLoop.processOne(TransactionProcessor.java:208)
        at org.glowroot.agent.impl.TransactionProcessor$TransactionProcessorLoop.run(TransactionProcessor.java:193)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(Thread.java:840)
...

Same stacktrace, different state.
I tried many times and I saw TIMED_WAITING state, only one time this was RUNNABLE.
It's strange because according to the TIME+ column in the following picture, it's definitely using CPU and it's not just temporary peaks.

[amalzahn]

In another project was a similar issue I think:
camunda/camunda#14187

There the problem was a loop that called sleep() in 1ms interval. It looks like Glowroot is doing the same. In a VM environment like docker sleep() seems to use more CPU - so they added an option to increase the interval to 10-100ms to reduce CPU.

[Nowheresly]

A new beta has been released.

https://github.com/glowroot/glowroot/releases/tag/v0.14.2-beta.3

Please let us know if it helps.