search

DynamoRIO / dynamorio

Dynamic Instrumentation Tool Platform
Other
2.59k stars 552 forks source link

timestamps used by drmemtrace scheduler, analyzer, and schedule_{launcher,stats} are too coarse on Windows #6640

Closed derekbruening closed 5 months ago

derekbruening commented 5 months ago

My schedule randomizer is seeded with the get_micros() scheduler function but on Windows my tests were failing as the seeds were all the same:

https://github.com/DynamoRIO/dynamorio/actions/runs/7820979725/job/21336911370?pr=6639

5: cpu #0 schedule: ..AAA..EEEEEEE..GGGBBBEE.CCC.BBB.GGGGGG._____
5: cpu #1 schedule: ..BBB..CCC..DDDAAACCCDDDAAA...FFFDDD.FFFFFF.

5: cpu #0 schedule: ..AAA..EEEEEEE..GGGBBBEE.CCC.BBB.GGGGGG._____
5: cpu #1 schedule: ..BBB..CCC..DDDAAACCCDDDAAA...FFFDDD.FFFFFF.

5: cpu #0 schedule: ..AAA..EEEEEEE..GGGBBBEE.CCC.BBB.GGGGGG._____
5: cpu #1 schedule: ..BBB..CCC..DDDAAACCCDDDAAA...FFFDDD.FFFFFF.
5: [scheduler] 7 inputs
5: [scheduler] input 4 at eof; 6 live inputs left
5: [scheduler] input 0 at eof; 5 live inputs left
5: [scheduler] input 2 at eof; 4 live inputs left
5: [scheduler] input 1 at eof; 3 live inputs left
5: [scheduler] input 3 at eof; 2 live inputs left
5: [scheduler] input 6 at eof; 1 live inputs left
5: [scheduler] input 5 at eof; 0 live inputs left
5: cpu #0 schedule: ..AAA..EEEEEEE..GGGBBBEE.CCC.BBB.GGGGGG._____
5: cpu #1 schedule: ..BBB..CCC..DDDAAACCCDDDAAA...FFFDDD.FFFFFF.
5: Assertion failed: scheds_by_cpu[i].size() >= ITERS / 2, file D:\a\dynamorio\dynamorio\clients\drcachesim\tests\scheduler_unit_tests.cpp, line 3852
5: abort() has been called
  3/309 Test   #5: tool.scheduler.unit_tests ........................................***Failed    0.06 sec

get_time_micros() is always the same!

5: time is 133518165841993473 int: 2115165953
5: time is 133518165841993473 int: 2115165953
5: time is 133518165841993473 int: 2115165953
5: time is 133518165841993473 int: 2115165953

I tried

    FILETIME file_time;
    GetSystemTimeAsFileTime(&file_time);

instead of GetSystemTime: same behavior.

The various docs and FAQ's seem to imply GetSystemTime should be giving out at least microsecond granularity but that does not seem to be the case.

Then I tried:

    uint64_t res;
    QueryPerformanceCounter((LARGE_INTEGER *)&res);
    return res;

Which works!

5: time is 3353910786292 int: -458671883
5: time is 3353910787556 int: -458670619
5: time is 3353910810719 int: -458647456
5: time is 3353910811957 int: -458646219