Repository: pytorch
Issue: [Caffe2 Bug] Windows timer is not accurate
Labels: caffe2

## Issue description

Caffe2 fails the timer related test on Windows:
* parallel_net_test.exe - This one always fail.
* timer_test.exe - Not always but...good luck...

```
PS <...erase for privacy...>\pytorch\build> .\bin\RelWithDebInfo\parallel_net_test.exe
Running main() from gtest_main.cc
[==========] Running 10 tests from 2 test cases.
[----------] Global test environment set-up.
[----------] 5 tests from DAGNetTest
[ RUN      ] DAGNetTest.TestDAGNetTiming
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0502 10:15:30.237299 27072 net_dag_utils.cc:102] Operator graph pruning prior to chain compute took: 2.8225e-05 secs
I0502 10:15:30.237299 27072 net_dag.cc:46] Number of parallel execution chains 2 Number of operators = 3
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(108): error: The difference between ms and 200 is 21, which exceeds kTimeThreshold, where
ms evaluates to 221,
200 evaluates to 200, and
kTimeThreshold evaluates to 20.
[  FAILED  ] DAGNetTest.TestDAGNetTiming (227 ms)
[ RUN      ] DAGNetTest.TestDAGNetTimingReadAfterRead
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
I0502 10:15:30.475047 27072 net_dag_utils.cc:102] Operator graph pruning prior to chain compute took: 2.9936e-05 secs
I0502 10:15:30.475047 27072 net_dag.cc:46] Number of parallel execution chains 3 Number of operators = 3
[       OK ] DAGNetTest.TestDAGNetTimingReadAfterRead (267 ms)
[ RUN      ] DAGNetTest.TestDAGNetTimingWriteAfterWrite
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
I0502 10:15:30.736847 27072 net_dag_utils.cc:102] Operator graph pruning prior to chain compute took: 2.1098e-05 secs
I0502 10:15:30.736847 27072 net_dag.cc:46] Number of parallel execution chains 1 Number of operators = 3
[       OK ] DAGNetTest.TestDAGNetTimingWriteAfterWrite (368 ms)
[ RUN      ] DAGNetTest.TestDAGNetTimingWriteAfterRead
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
I0502 10:15:31.104876 27072 net_dag_utils.cc:102] Operator graph pruning prior to chain compute took: 2.1953e-05 secs
I0502 10:15:31.104876 27072 net_dag.cc:46] Number of parallel execution chains 1 Number of operators = 3
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(254): error: The difference between ms and 350 is 43, which exceeds kTimeThreshold, where
ms evaluates to 393,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] DAGNetTest.TestDAGNetTimingWriteAfterRead (400 ms)
[ RUN      ] DAGNetTest.TestDAGNetTimingControlDependency
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 5:3: text format contains deprecated field "num_workers"
I0502 10:15:31.504611 27072 net_dag_utils.cc:102] Operator graph pruning prior to chain compute took: 2.2238e-05 secs
I0502 10:15:31.504611 27072 net_dag.cc:46] Number of parallel execution chains 1 Number of operators = 3
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(304): error: The difference between ms and 350 is 42, which exceeds kTimeThreshold, where
ms evaluates to 392,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] DAGNetTest.TestDAGNetTimingControlDependency (398 ms)
[----------] 5 tests from DAGNetTest (1666 ms total)

[----------] 5 tests from SimpleNetTest
[ RUN      ] SimpleNetTest.TestSimpleNetTiming
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(115): error: The difference between ms and 350 is 42, which exceeds kTimeThreshold, where
ms evaluates to 392,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] SimpleNetTest.TestSimpleNetTiming (398 ms)
[ RUN      ] SimpleNetTest.TestSimpleNetTimingReadAfterRead
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(164): error: The difference between ms and 350 is 42, which exceeds kTimeThreshold, where
ms evaluates to 392,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingReadAfterRead (398 ms)
[ RUN      ] SimpleNetTest.TestSimpleNetTimingWriteAfterWrite
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(212): error: The difference between ms and 350 is 21, which exceeds kTimeThreshold, where
ms evaluates to 371,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingWriteAfterWrite (376 ms)
[ RUN      ] SimpleNetTest.TestSimpleNetTimingWriteAfterRead
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 1:50: text format contains deprecated field "num_workers"
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(260): error: The difference between ms and 350 is 28, which exceeds kTimeThreshold, where
ms evaluates to 378,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingWriteAfterRead (383 ms)
[ RUN      ] SimpleNetTest.TestSimpleNetTimingControlDependency
[libprotobuf WARNING C:\Users\tolia\AppData\Local\Temp\protobuf\src\google\protobuf\text_format.cc:305] Warning parsing text-format caffe2.NetDef: 5:3: text format contains deprecated field "num_workers"
<...erase for privacy...>\pytorch\caffe2\core\parallel_net_test.cc(310): error: The difference between ms and 350 is 43, which exceeds kTimeThreshold, where
ms evaluates to 393,
350 evaluates to 350, and
kTimeThreshold evaluates to 20.
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingControlDependency (398 ms)
[----------] 5 tests from SimpleNetTest (1962 ms total)

[----------] Global test environment tear-down
[==========] 10 tests from 2 test cases ran. (3629 ms total)
[  PASSED  ] 2 tests.
[  FAILED  ] 8 tests, listed below:
[  FAILED  ] DAGNetTest.TestDAGNetTiming
[  FAILED  ] DAGNetTest.TestDAGNetTimingWriteAfterRead
[  FAILED  ] DAGNetTest.TestDAGNetTimingControlDependency
[  FAILED  ] SimpleNetTest.TestSimpleNetTiming
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingReadAfterRead
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingWriteAfterWrite
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingWriteAfterRead
[  FAILED  ] SimpleNetTest.TestSimpleNetTimingControlDependency

 8 FAILED TESTS
```

```
PS <...erase for privacy...>\pytorch\build> .\bin\RelWithDebInfo\timer_test.exe
Running main() from gtest_main.cc
[==========] Running 2 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 2 tests from TimerTest
[ RUN      ] TimerTest.Test
[       OK ] TimerTest.Test (115 ms)
[ RUN      ] TimerTest.TestLatency
Average nanosecond latency is: 38.775
Average microsecond latency is: 0.040485
Average millisecond latency is: 4.0208e-05
[       OK ] TimerTest.TestLatency (3 ms)
[----------] 2 tests from TimerTest (119 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test case ran. (119 ms total)
[  PASSED  ] 2 tests.
```

```
PS <...erase for privacy...>\pytorch\build> .\bin\RelWithDebInfo\timer_test.exe
Running main() from gtest_main.cc
[==========] Running 2 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 2 tests from TimerTest
[ RUN      ] TimerTest.Test
<...erase for privacy...>\pytorch\caffe2\core\timer_test.cc(26): error: The difference between ns and 100000000 is 15655312, which exceeds 10000000, where
ns evaluates to 115655312,
100000000 evaluates to 100000000, and
10000000 evaluates to 10000000.
<...erase for privacy...>\pytorch\caffe2\core\timer_test.cc(27): error: The difference between us and 100000 is 15655.3125, which exceeds 10000, where
us evaluates to 115655.3125,
100000 evaluates to 100000, and
10000 evaluates to 10000.
<...erase for privacy...>\pytorch\caffe2\core\timer_test.cc(28): error: The difference between ms and 100 is 15.655593872070313, which exceeds 10, where
ms evaluates to 115.65559387207031,
100 evaluates to 100, and
10 evaluates to 10.
[  FAILED  ] TimerTest.Test (126 ms)
[ RUN      ] TimerTest.TestLatency
Average nanosecond latency is: 37.066
Average microsecond latency is: 0.036486
Average millisecond latency is: 4.0194e-05
[       OK ] TimerTest.TestLatency (4 ms)
[----------] 2 tests from TimerTest (131 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test case ran. (131 ms total)
[  PASSED  ] 1 test.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] TimerTest.Test

 1 FAILED TEST
```

I don't think the problem is due to timer itself.
It's more likely to be caused by Windows scheduler/time slice configuration.

On my machine the timer_test almost always shows 15ms (for ns/us/ms tests) difference when failed.
Sometimes it can also be 21ms or 22ms.

NOTE that I'm testing with 12-thread idle machine, so no system load related issues.

## System Info

- PyTorch or Caffe2: Caffe2
- How you installed PyTorch (conda, pip, source): source
- Build command you used (if compiling from source): cmake
- OS: Win10
- PyTorch version: master
- CUDA/cuDNN version: 9.1/7.1.3
- GPU models and configuration: 1080Ti
- Visual Studio version (if compiling from source): 2017.6 + v140 toolchain
- CMake version: 3.11.1