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);
    }
}
Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s