Category: jvm

Java – monitoring cpu and system load of multi-threaded application via OperatingSystemMXBean

1. All CPU cores busy executing busy loop (cpu intensive)

Per documentation: Java exposes java.lang.management.OperatingSystemMXBean interface with

  • double getSystemCpuLoad() returning the “recent cpu usage” for the whole system with range [0.0,1.0] where 0.0 means that all CPUs were idle, 1.0 means that all CPUs were actively running 100% of the observed time, and -1.0 when recent cpu usage is not available. The value for system load could be high not only when JVM process heavily uses that but also if other no-JVM processes generate high CPU load
  • double getProcessCpuLoad() returning “recent cpu usage” for the Java Virtual Machine process with range [0.0,1.0] value 0.0 means that none of the CPUs were running threads (application and JVM internal threads) from the JVM process, 1.0 means that all CPUs were actively running threads from the JVM 100% of the observed time, and -1.0 when recent cpu usage is not available
  • public class MonitorAllCoresCpuLoad {
    
      private static volatile boolean hasAnyWorkerFinished = false;
    
      public static void main(String[] args) throws Exception {
        OperatingSystemMXBean operatingSystemMXBean = ManagementFactory.getOperatingSystemMXBean();
        int workersCount = Runtime.getRuntime().availableProcessors();
        CyclicBarrier barrier 
                 = new CyclicBarrier(workersCount + 1); // + 1 to include main thread measuring CPU load
        for (int i = 0; i < workersCount; i++) {
          createAndStartWorker(barrier); //use barrier to start all workers at the same time as main thread
        }
        barrier.await();
        System.out.println("All workers and main thread started");
        while (!hasAnyWorkerFinished) { // stop measuring if at least one of workers finished
          getAndPrintCpuLoad(operatingSystemMXBean);
          TimeUnit.MILLISECONDS.sleep(100);
        }
        System.out.println("One of workers finished");
      }
    
        private static void createAndStartWorker(CyclicBarrier cyclicBarrier) {
            new Thread(() -> {
                try {
                    cyclicBarrier.await();
                    for (long i = 0L; i < 19999999999L; i++) { // 6s
                        // Thread 100% time as RUNNABLE, taking 1/(n cores) of JVM/System overall CPU
                    }
                    hasAnyWorkerFinished = true;
                    System.out.println(Thread.currentThread().getName() + " finished");
                } catch (Exception e) {
                    e.printStackTrace();
                }
            }).start();
    
        }
    
        private static void getAndPrintCpuLoad(OperatingSystemMXBean mxBean) {
           // need to use reflection as the impl class is not visible
           for (Method method : mxBean.getClass().getDeclaredMethods()) {
             method.setAccessible(true);
             String methodName = method.getName();
             if (methodName.startsWith("get") && methodName.contains("Cpu") && methodName.contains("Load")
                     && Modifier.isPublic(method.getModifiers())) {
    
                 Object value;
                 try {
                     value = method.invoke(mxBean);
                 } catch (Exception e) {
                     value = e;
                 }
                 System.out.println(methodName + " = " + value);
             }
          }
          System.out.println("");
        }
    }
    

    Busy loop: all cores busy
    getProcessCpuLoad = 0.9968879402893512
    getSystemCpuLoad = 1.0

    Note: The main thread responsible for printing CPU load was not able to get CPU time (no CPU load printed) when I was running more worker threads than CPU cores on my laptop (Windows 7 os).

    2. One of cores executing busy loop (cpu intensive)

    Busy loop: one of four cores busy
    getProcessCpuLoad = 0.24999679493343077
    getSystemCpuLoad = 0.2571523807692343

    Note that is my laptop was only running JVM the system and JVM process CPU usage was 1/4 = 0.25%.

    3. Sleeping loop

    getProcessCpuLoad = 0.0
    getSystemCpuLoad = 0.014311079773084212

    4. Slow network I/O
    4 core Windows 7 laptop, java program running 10 threads executing http rq over slow network:

    public class FluentFormLoginAuthorizationMultiThreadedTest {
        
        private static final Logger LOGGER = 
            LoggerFactory.getLogger(FluentFormLoginAuthorizationMultiThreadedTest.class);
        private static final int COUNT = 10;
        private static volatile boolean hasAnyThreadFinished = false;
    
        public static void main(String[] args) throws Exception {
          OperatingSystemMXBean operatingSystemMXBean = ManagementFactory.getOperatingSystemMXBean();
    
          Executor executor = Executor.newInstance()
                  .auth(new HttpHost("myhost", 8090), Settings.USERNAME, Settings.PASSWORD);
            
          TimeUnit.SECONDS.sleep(10); // give time to collect via JVisualVM
          CyclicBarrier barrier = new CyclicBarrier(COUNT + 1); // + 1 for main thread to monitor CPU load
          for (int i = 0; i < COUNT; i++) {
              new Thread(() ->  run(executor, barrier)).start();;
          }
    
          barrier.await();
          System.out.println("All threads started");
          while (!hasAnyThreadFinished) {
              printCpuLoad(operatingSystemMXBean);
              TimeUnit.MILLISECONDS.sleep(100);
          }
          System.out.println("One of thread finished");
        }
    
        private static void run(Executor executor, CyclicBarrier cyclicBarrier) {
            String content;
            try {
                cyclicBarrier.await();
                LOGGER.debug("Started");
    
                content = executor
                        .execute(Request.Get("http://myhost:8090/view?pattern=INFO&path=/apps/logs/*"))
                        .returnContent()
                        .asString();
    
                hasAnyThreadFinished = true;
                //System.err.println(content);
                LOGGER.debug("Stopped");
            } catch (Exception e) {
                e.printStackTrace();
            }
        }
    
        private static void printCpuLoad(OperatingSystemMXBean mxBean) {
          for (Method method : mxBean.getClass().getDeclaredMethods()) {
            method.setAccessible(true);
            String methodName = method.getName();
            if (methodName.startsWith("get") && methodName.contains("Cpu") && methodName.contains("Load")
                    && Modifier.isPublic(method.getModifiers())) {
    
                Object value;
                try {
                   value = method.invoke(mxBean);
                } catch (Exception e) {
                    value = e;
                }
                System.out.print(methodName + "," + value + ",");
            }
          }
          System.out.println("");
        }
    }
    

    Results:

    getProcessCpuLoad getSystemCpuLoad
    min 0.007357802 0.017761006
    max 0.022199061 0.11305298
    avg 0.017429555 0.051268221

    10-threads-calling-slow-network-IO-http-rq

    Notice that all 10 threads that executed http request are shown on JVisualVM as 100% running. That means that 100% of their time they are in RUNNABLE state. But it does not necessary mean that all of them are using all the CPU cores in 100%. In our case average process cpu load is 1.7%, system cpu load 5% (aggregate for all cores, where load of 1.0 we had when all CPU were fully used).

    “Thread-10” #24 prio=5 os_prio=0 tid=0x0000000058b0f800 nid=0x2258 runnable [0x000000005bd0e000]
    java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)

    org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)

    at http.client.FluentFormLoginAuthorizationMultiThreadedTest.run(FluentFormLoginAuthorizationMultiThreadedTest.java:50)
    at http.client.FluentFormLoginAuthorizationMultiThreadedTest.lambda$0(FluentFormLoginAuthorizationMultiThreadedTest.java:31)
    at http.client.FluentFormLoginAuthorizationMultiThreadedTest$$Lambda$4/152005629.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:745)

    Java – monitoring elapsed, CPU, user and system time

    Sleeping waiting (Thread.sleep())

    public class SleepingThread {
        public static void main(String[] args) throws InterruptedException {
            StopWatch stopWatch = new StopWatch();
            stopWatch.start();
    
            TimeUnit.NANOSECONDS.sleep(3000000000L); // 3s
    
            stopWatch.stop();
            System.out.println(stopWatch);
        }
    }
    

    User (app code only) time: 0 ms (0.00%)
    System (os code on behalf app e.g.I/O) time: 0 ms (0.00%)
    CPU (total CPU spent for app) time: 0 ms (0.00%)
    Elapsed time: 3000 ms (100.00%)

    “main” #1 prio=5 os_prio=0 tid=0x0000000001c5e000 nid=0x16dc waiting on condition [0x00000000025af000]
    java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at java.lang.Thread.sleep(Thread.java:340)
    at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
    at com.bawi.threads.cpu.SleepingThread.main(SleepingThread.java:11)

    Waiting (Object.wait())

    public class WaitingThread {
        public static void main(String[] args) throws InterruptedException {
            Object monitor = new Object();
            new Thread(() -> {
                synchronized (monitor) {
                    try {
                        StopWatch stopWatch = new StopWatch();
                        stopWatch.start();
    
                        monitor.wait();
    
                        stopWatch.stop();
                        System.out.println(stopWatch);
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            }).start();
            TimeUnit.NANOSECONDS.sleep(3000000000L); // 3s
            synchronized(monitor) {
                monitor.notify();
            }
        }
    }
    

    User (app code only) time: 0 ms (0.00%)
    System (os code on behalf app e.g.I/O) time: 0 ms (0.00%)
    CPU (total CPU spent for app) time: 0 ms (0.00%)
    Elapsed time: 2998 ms (100.00%)

    “Thread-0” #10 prio=5 os_prio=0 tid=0x0000000058b5b000 nid=0x162c in Object.wait() [0x00000000595ae000]
    java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    – waiting on (a java.lang.Object)
    at java.lang.Object.wait(Object.java:502)
    at com.bawi.threads.cpu.SynchronizedWaitingThread.lambda$0(SynchronizedWaitingThread.java:16)
    – locked (a java.lang.Object)
    at com.bawi.threads.cpu.SynchronizedWaitingThread$$Lambda$1/321001045.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:745)

    Parked waiting (LockSupport.park())

    public class ParkedThread {
        public static void main(String[] args) throws InterruptedException {
            Lock lock = new ReentrantLock();
            lock.lock();
            new Thread(() -> {
                StopWatch stopWatch = new StopWatch();
                stopWatch.start();
    
                lock.lock();
    
                stopWatch.stop();
                System.out.println(stopWatch);
            }).start();
            TimeUnit.NANOSECONDS.sleep(3000000000L); // 3s
            lock.unlock();
        }
    }
    

    User (app code only) time: 0 ms (0.00%)
    System (os code on behalf app e.g.I/O) time: 0 ms (0.00%)
    CPU (total CPU spent for app) time: 0 ms (0.00%)
    Elapsed time: 3010 ms (100.00%)

    “Thread-0” #10 prio=5 os_prio=0 tid=0x0000000058abf000 nid=0x3c0 waiting on condition [0x0000000059a4e000]
    java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    – parking to wait for (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
    at com.bawi.threads.cpu.ParkedThread.lambda$0(ParkedThread.java:17)
    at com.bawi.threads.cpu.ParkedThread$$Lambda$1/471910020.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:745)

    Blocked (on object monitor)

    public class BlockedThread {
        public static void main(String[] args) throws InterruptedException {
            Object monitor = new Object();
            new Thread(() -> {
                StopWatch stopWatch = new StopWatch();
                stopWatch.start();
    
                synchronized (monitor) {
                }
    
                stopWatch.stop();
                System.out.println(stopWatch);
            }).start();
            synchronized (monitor) {
                TimeUnit.NANOSECONDS.sleep(5000000000L); // 5s
            }
        }
    }
    

    User (app code only) time: 0 ms (0.00%)
    System (os code on behalf app e.g.I/O) time: 0 ms (0.00%)
    CPU (total CPU spent for app) time: 0 ms (0.00%)
    Elapsed time: 4993 ms (100.00%)

    “Thread-0” #10 prio=5 os_prio=0 tid=0x0000000058f8c800 nid=0x1ddc waiting for monitor entry [0x0000000059d1e000]
    java.lang.Thread.State: BLOCKED (on object monitor)
    at com.bawi.threads.cpu.BlockedThread.lambda$0(BlockedThread.java:14)
    – waiting to lock (a java.lang.Object)
    at com.bawi.threads.cpu.BlockedThread$$Lambda$1/321001045.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:745)

    Disc IO operation

    public class WritingFile {
        private static final String LINE = "abcdefghijklmnopqrstuwvxyzABCDEFGHIJKLMNOPQRSUWVXYZ\r\n";
        public static void main(String[] args) throws IOException {
            Path path = Paths.get("target/data.txt");
            Files.deleteIfExists(path);
            Files.createFile(path);
            BufferedWriter bufferedWriter = Files.newBufferedWriter(path, StandardOpenOption.APPEND);
            StopWatch stopWatch = new StopWatch();
            stopWatch.start();
    
            for (int i = 0; i < 29999999; i++) { // generates 1.7GB file 
                bufferedWriter.write(i + LINE); // without this line it takes 3ms
            }
    
            stopWatch.stop();
            System.out.println(stopWatch);
        }
    }
    

    User (app code only) time: 5023 ms (23.71%)
    System (os code on behalf app e.g.I/O) time: 1950 ms (9.21%)
    CPU (total CPU spent for app) time: 6973 ms (32.92%)
    Elapsed time: 21181 ms (100.00%)

    “main” #1 prio=5 os_prio=0 tid=0x000000000035e000 nid=0x2158 runnable [0x000000000259e000]
    java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
    at sun.nio.ch.FileDispatcherImpl.write(FileDispatcherImpl.java:75)
    at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
    at sun.nio.ch.IOUtil.write(IOUtil.java:65)
    at sun.nio.ch.FileChannelImpl.write(FileChannelImpl.java:211)
    – locked (a java.lang.Object)
    at java.nio.channels.Channels.writeFullyImpl(Channels.java:78)
    at java.nio.channels.Channels.writeFully(Channels.java:101)
    at java.nio.channels.Channels.access$000(Channels.java:61)
    at java.nio.channels.Channels$1.write(Channels.java:174)
    – locked (a java.nio.channels.Channels$1)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
    at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
    – locked (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
    at java.io.BufferedWriter.flushBuffer(BufferedWriter.java:129)
    – locked (a java.io.OutputStreamWriter)
    at java.io.BufferedWriter.write(BufferedWriter.java:230)
    – locked (a java.io.OutputStreamWriter)
    at java.io.Writer.write(Writer.java:157)
    at com.bawi.threads.cpu.WritingFile.main(WritingFile.java:23)

    Network IO operation

    public class FluentFormLoginAuthorizationTest {
        public static void main(String[] args) throws Exception {
            Executor executor = Executor.newInstance()
                    .auth(new HttpHost("myhost", 8090), Settings.USERNAME, Settings.PASSWORD);
    
            StopWatch stopWatch = new StopWatch();
            stopWatch.start();
    
            String content = executor
                    .execute(Request.Get("http://myhost:8090/view?pattern=XYZ&path=/apps/tkt-hub/logs/"))
                    .returnContent()
                    .asString();
    
            stopWatch.stop();
            System.out.println(stopWatch);
            //System.out.println(content);
        }
    }
    

    User (app code only) time: 78 ms (0.85%)
    System (os code on behalf app e.g.I/O) time: 46 ms (0.51%)
    CPU (total CPU spent for app) time: 124 ms (1.37%)
    Elapsed time: 9127 ms (100.00%)

    “main” #1 prio=5 os_prio=0 tid=0x00000000021fe000 nid=0x2214 runnable [0x000000000260e000]
    java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
    at java.net.SocketInputStream.read(SocketInputStream.java:170)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:139)
    at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:155)
    at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:284)

    Infinite loop

        public static void main(String[] args) {
            StopWatch stopWatch = new StopWatch();
            stopWatch.start();
    
            for (long i = 0L; i < 9999999999L; i++) { // 6s
             // Thread running 100%, taking 1/(n cores) of JVM/System overall CPU
            }
    
            stopWatch.stop();
            System.out.println(stopWatch);
        }
    

    User (app code only) time: 3166 ms (99.44%)
    System (os code on behalf app e.g.I/O) time: 0 ms (0.00%)
    CPU (total CPU spent for app) time: 3166 ms (99.44%)
    Elapsed time: 3184 ms (100.00%)

    “main” #1 prio=5 os_prio=0 tid=0x0000000001c9e000 nid=0x1e4c runnable [0x000000000241f000]
    java.lang.Thread.State: RUNNABLE
    at com.bawi.threads.cpu.InfiniteLoop.main(InfiniteLoop.java:9)

    Heavy CPU calculation

    public class HeavyCpuCalculation {
        public static void main(String[] args) {
            StopWatch stopWatch = new StopWatch();
            stopWatch.start();
    
            for (int j = 0; j < 10000; j++) { 
                BigDecimal n = BigDecimal.ONE;
                BigDecimal i = BigDecimal.ONE;
                BigDecimal max = BigDecimal.valueOf(1600L);
                while (i.compareTo(max) <= 0) {
                    n = n.multiply(i);
                    i = i.add(BigDecimal.ONE);
                }
            }
    
            stopWatch.stop();
            System.out.println(stopWatch);
        }
    }
    

    User (app code only) time: 5304 ms (97.01%)
    System (os code on behalf app e.g.I/O) time: 93 ms (1.71%)
    CPU (total CPU spent for app) time: 5397 ms (98.72%)
    Elapsed time: 5467 ms (100.00%)

    “main” #1 prio=5 os_prio=0 tid=0x000000000213d800 nid=0x1078 runnable [0x00000000023ef000]
    java.lang.Thread.State: RUNNABLE
    at com.bawi.threads.cpu.HeavyCpuCalculation.main(HeavyCpuCalculation.java:17)

    import java.lang.management.ManagementFactory;
    import java.lang.management.ThreadMXBean;
    import java.util.concurrent.TimeUnit;
    
    public class StopWatch {
    
        private final ThreadMXBean bean;
        private long startCpuTime;
        private long startUserTime;
        private long startNano;
        private long stopCpuTime;
        private long stopUserTime;
        private long stopNano;
    
        public StopWatch() {
            bean = ManagementFactory.getThreadMXBean();
        }
    
        public void start() {
            startCpuTime = bean.getCurrentThreadCpuTime();
            startUserTime = bean.getCurrentThreadUserTime();
            startNano = System.nanoTime();
        }
    
        public void stop() {
            stopCpuTime = bean.getCurrentThreadCpuTime();
            stopUserTime = bean.getCurrentThreadUserTime();
            stopNano = System.nanoTime();
        }
    
        @Override
        public String toString() {
            long elapsedNano = stopNano - startNano;
            long cpuTime = stopCpuTime - startCpuTime;
            long userTime = stopUserTime - startUserTime;
            long systemTime = cpuTime - userTime;
            return 
                String.format("User (app code only) time:                   %d ms (%,.2f%%)\n", 
                 TimeUnit.NANOSECONDS.toMillis(userTime), (double)userTime/elapsedNano * 100) +
                String.format("System (os code on behalf app e.g.I/O) time: %d ms (%,.2f%%)\n", 
                 TimeUnit.NANOSECONDS.toMillis(systemTime), (double)systemTime/elapsedNano * 100) +
                String.format("CPU (total CPU spent for app) time:          %d ms (%,.2f%%)\n", 
                 TimeUnit.NANOSECONDS.toMillis(cpuTime),  (double)cpuTime/elapsedNano * 100) +
                String.format("Elapsed time:                                %d ms (%,.2f%%)\n", 
                 TimeUnit.NANOSECONDS.toMillis(elapsedNano), 100d);
        }
    }