为什么不使用易失性CPU的时间会有所不同？

Question

代码1：在这段代码中，我使用System.out.println();获取由其他线程更改的值，而不是使用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

代码2：在这段代码中，我使用volatile获取其他线程更改的值。

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

}

结果2

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

有人能告诉我CPU时间为什么不同吗？在我看来，这两个代码中的主线程始终保持CPU，但是代码1保持绝对较少的CPU时间。

Answer 1

在代码1中，在OS内核中打印空行(并可能滚动终端窗口)所花费的时间不是在Java线程上花费的时间，所以在打印时并不计算所有的CPU时间。

代码2中的循环是一个纯CPU循环，所以所有的时间都是由Java线程花费的。