Why will the CPU time be different without using volatile?

Question

Code 1: In this code, I use the System.out.println(); to get the value changed by other thread instead of using volatile.

package edu.seu.juc.vol;

import edu.seu.juc.annotation.ThreadNotSafe;

import java.lang.management.ManagementFactory;

/**
 * @author: zs.sun
 * Create at: 2020/5/24 10:31
 * @Package: edu.seu.juc.vol
 * @ProjectName: af-study
 * @Description:
 */
@ThreadNotSafe
public class TestVolatile01 {
    public static void main(String[] args) {
        Long startTime = System.currentTimeMillis();

        ThreadDemo td = new ThreadDemo();
        new Thread(td).start();

        while (true) {
            if (td.isFlag()) {
                System.out.println("--------------------------");
                break;
            }
            System.out.println();  // to see the value changed by other thread
        }

        System.out.println("total: " + (System.currentTimeMillis() - startTime));
        System.out.println("CPU time: " + ManagementFactory.getThreadMXBean().getThreadCpuTime(Thread.currentThread().getId())
                / (1000 * 1000));
    }

    private static class ThreadDemo implements Runnable {
        private boolean flag = false;

        @Override
        public void run() {
            try {
                Thread.sleep(2000);
                flag = true;
                System.out.println("flag = " + isFlag());
            } catch (Exception e) {
                e.printStackTrace();
            }
        }

        public boolean isFlag() {
            return flag;
        }

        public void setFlag(boolean flag) {
            this.flag = flag;
        }
    }
}

Result1

...(some blank lines)

flag = true
--------------------------
total: 2010
CPU time: 875

Code 2: In this code, I use the volatile to get the value changed by other thread.

package edu.seu.juc.vol;

import edu.seu.juc.annotation.ThreadSafe;

import java.lang.management.ManagementFactory;

/**
 * @author: zs.sun
 * Create at: 2020/5/24 10:31
 * @Package: edu.seu.juc.vol
 * @ProjectName: af-study
 * @Description:
 */
@ThreadSafe
public class TestVolatile02 {
    public static void main(String[] args) {
        Long startTime = System.currentTimeMillis();

        ThreadDemo td = new ThreadDemo();
        new Thread(td).start();

        while (true) {
            if (td.isFlag()) {
                System.out.println("--------------------------");
                break;
            }
        }

        System.out.println("total: " + (System.currentTimeMillis() - startTime));
        System.out.println("CPU time: " + ManagementFactory.getThreadMXBean().getThreadCpuTime(Thread.currentThread().getId())
                / (1000 * 1000));
    }

    private static class ThreadDemo implements Runnable {
        private volatile boolean flag = false;

        @Override
        public void run() {
            try {
                Thread.sleep(2000);
                flag = true;
                System.out.println("flag = " + isFlag());
            } catch (Exception e) {
                e.printStackTrace();
            }
        }

        public boolean isFlag() {
            return flag;
        }

        public void setFlag(boolean flag) {
            this.flag = flag;
        }
    }

}

Result 2

--------------------------
total: 2005
flag = true
CPU time: 1968

Can anyone tell me why the CPU time is different? In my opinion, the main thread in both Codes keeps the CPU all the time, but the Code 1 keeps the absolutely less CPU time.

Answer 1

In Code 1, time spent in the OS Kernel to print the blank line (and maybe scroll the terminal window), is time not spent in the Java thread, so not all the CPU time is counted when printing.

The loop in Code 2 is a pure CPU loop, so all the time is spent by the Java thread.