Fork me on GitHub
#clojure-dev
<
2020-02-27
>
andy.fingerhut21:02:49

I will do some more checking to verify what is going on, but I'm using criterium to benchmark some single-threaded code, and seeing 400% CPU utilization reported, and I believe there is very little GC time going on. I know that if there were a lot of GC going on, that can take advantage of multiple threads and CPU cores, so perhaps the root cause of what I am seeing is GC time that isn't reported in my current reporting of GC time. Just curious if other than GC, folks know why this might be happening.

andy.fingerhut22:02:02

I used the Ctrl-\ trick in the terminal where the JVM was running to dump thread details, and it appears there are 8 GC threads that are getting significant CPU time when I sampled the process twice about 10 seconds apart, while macOS's Activity Monitor was reporting 300 to 400% CPU utilization for the JVM process that entire 10 seconds. So looks like whatever I am using to report GC time is not counting that. I am using the JVM's GarbageCollectorMXBean API to get GC time, so it is a bit disappointing if it is leaving all of this significant GC time unreported.

andy.fingerhut22:02:54

Curious if anyone knows of a better way to get GC time/counts from within a JVM process that would include that time.

seancorfield22:02:59

Activity Monitor is weird. It always reports things as the sum of the % on each CPU so it can be up to "800%" on an 8 core box. Most things sensibly report % cpu in terms of total capacity.

jumar12:02:22

This is a pretty normal behavior

seancorfield22:02:29

So 25% cpu reported by the JVM can be 400% cpu reported by Activity Monitor 😞

andy.fingerhut22:02:29

Ubuntu Linux 'top' also reports %CPU > 100 on multi-core machine, similar to Activity Monitor. Repeating my experiments on Linux in case there are any noticeable differences.

andy.fingerhut22:02:07

I don't think I am using anything in the JVM to report %cpu measurements, only "time spend doing GC", which is very near 0

seancorfield22:02:11

htop is a more useful tool than top, or so folks keep telling me...

andy.fingerhut22:02:11

htop on Linux is showing me separate lines for each JVM thread, which is nice, and separate %cpu numbers for each, but also reporting a total that is > 100%cpu for the process as a whole, which I'm assuming is using more than 1 CPU core full time, on average. In line with same total number reported by top for total CPU time of the JVM process as a whole.

andy.fingerhut22:02:28

The main thing that seems poorly reported here is the GarbageCollectorMXBean JVM API for telling me how much total time is spent in GC is often saying 0, for many seconds in a row, while 2 to 4 cores are fully pegged, and Ctrl-\ says GC threads are using very much larger than 0 CPU time.

Alex Miller (Clojure team)22:02:29

seems like this discussion should be in #java not #clojure-dev

Alex Miller (Clojure team)22:02:45

so I can not pay attention to it :)

😂 4