线程池中的任务为什么先执行的，反而打印的开始时间靠后

Question

先附上我的代码：

public class App 
{
    public static void main( String[] args )
    {
        ExecutorService mExecutorService = Executors.newFixedThreadPool(220);

        for (int i = 0; i < 1000; i++){
            int a = i;
            Runnable runnable = () -> {
                try {
                    DateFormat mDateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss:SSSS");
                    System.out.println(mDateFormat.format(new Date(System.currentTimeMillis())) + String.format("运行%d号任务",a));

                    Thread.sleep(1000000);

                    System.out.println(mDateFormat.format(new Date(System.currentTimeMillis())) + String.format("运行%d号任务完成",a));
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            };
            mExecutorService.execute(runnable);
        }
        mExecutorService.shutdown();
    }
}

我看到打印出来的结果是这样的(截取部分)

2017-09-06 00:05:27:0931运行4号任务
2017-09-06 00:05:27:0929运行51号任务
2017-09-06 00:05:27:0929运行70号任务
2017-09-06 00:05:27:0932运行134号任务
2017-09-06 00:05:27:0932运行45号任务
2017-09-06 00:05:27:0928运行3号任务
2017-09-06 00:05:27:0928运行67号任务
2017-09-06 00:05:27:0932运行57号任务
2017-09-06 00:05:27:0929运行58号任务
2017-09-06 00:05:27:0929运行179号任务
2017-09-06 00:05:27:0932运行69号任务
2017-09-06 00:05:27:0928运行148号任务
2017-09-06 00:05:27:0933运行42号任务
2017-09-06 00:05:27:0933运行101号任务
2017-09-06 00:05:27:0928运行168号任务
2017-09-06 00:05:27:0933运行46号任务
2017-09-06 00:05:27:0933运行26号任务
2017-09-06 00:05:27:0931运行30号任务
2017-09-06 00:05:27:0933运行131号任务
2017-09-06 00:05:27:0933运行90号任务
2017-09-06 00:05:27:0931运行23号任务
2017-09-06 00:05:27:0933运行121号任务
2017-09-06 00:05:27:0933运行77号任务
2017-09-06 00:05:27:0933运行124号任务
2017-09-06 00:05:27:0934运行56号任务
2017-09-06 00:05:27:0934运行18号任务
2017-09-06 00:05:27:0934运行39号任务
2017-09-06 00:05:27:0933运行79号任务
2017-09-06 00:05:27:0934运行120号任务
2017-09-06 00:05:27:0934运行129号任务
2017-09-06 00:05:27:0934运行126号任务
2017-09-06 00:05:27:0932运行123号任务
2017-09-06 00:05:27:0929运行97号任务
2017-09-06 00:05:27:0935运行1号任务
2017-09-06 00:05:27:0935运行150号任务
2017-09-06 00:05:27:0935运行28号任务
2017-09-06 00:05:27:0932运行153号任务
2017-09-06 00:05:27:0935运行107号任务
2017-09-06 00:05:27:0932运行165号任务
2017-09-06 00:05:27:0928运行48号任务
2017-09-06 00:05:27:0935运行13号任务
2017-09-06 00:05:27:0935运行76号任务
2017-09-06 00:05:27:0935运行86号任务
2017-09-06 00:05:27:0928运行12号任务
2017-09-06 00:05:27:0936运行102号任务
2017-09-06 00:05:27:0936运行68号任务
2017-09-06 00:05:27:0936运行158号任务
2017-09-06 00:05:27:0936运行8号任务
2017-09-06 00:05:27:0936运行80号任务
2017-09-06 00:05:27:0935运行74号任务
2017-09-06 00:05:27:0936运行108号任务
2017-09-06 00:05:27:0936运行25号任务
2017-09-06 00:05:27:0935运行143号任务
2017-09-06 00:05:27:0936运行139号任务
2017-09-06 00:05:27:0936运行144号任务
2017-09-06 00:05:27:0935运行15号任务
2017-09-06 00:05:27:0936运行29号任务
2017-09-06 00:05:27:0935运行21号任务
2017-09-06 00:05:27:0935运行135号任务
2017-09-06 00:05:27:0935运行59号任务
2017-09-06 00:05:27:0937运行88号任务
2017-09-06 00:05:27:0937运行40号任务
2017-09-06 00:05:27:0935运行52号任务
2017-09-06 00:05:27:0937运行82号任务
2017-09-06 00:05:27:0937运行170号任务
2017-09-06 00:05:27:0935运行17号任务
2017-09-06 00:05:27:0937运行84号任务
2017-09-06 00:05:27:0937运行117号任务
2017-09-06 00:05:27:0934运行133号任务
2017-09-06 00:05:27:0937运行53号任务
2017-09-06 00:05:27:0934运行163号任务
2017-09-06 00:05:27:0934运行142号任务
2017-09-06 00:05:27:0938运行99号任务
2017-09-06 00:05:27:0934运行87号任务
2017-09-06 00:05:27:0934运行85号任务
2017-09-06 00:05:27:0934运行78号任务
2017-09-06 00:05:27:0938运行141号任务
2017-09-06 00:05:27:0934运行71号任务
2017-09-06 00:05:27:0938运行110号任务
2017-09-06 00:05:27:0934运行94号任务
2017-09-06 00:05:27:0939运行98号任务
2017-09-06 00:05:27:0939运行136号任务
2017-09-06 00:05:27:0938运行0号任务

可以看到，4号是第一个执行的，但是他的执行时间，并不是最早的

请问这是什么情况？还是我这么写是不对的。谢谢

Answer 1

for中创建的线程，优先级是相同的
线程的调度执行是无序
执行DateFormat mDateFormat = new SimpleDateFormat()之后，时间已经被初始化完成
但执行到输出语句时，其他的线程又开始执行

Answer 2

线程调用的随机性

Answer 3

那是输出时间不是执行时间