1665265 - Intermittent and perma mingw debug Assertion failure: mReleasedChunks->Last()->ChunkHeader().mDoneTimeStamp < aChunks->ChunkHeader().mDoneTimeStamp (Chunks must be released in increasing timestamps), at /builds/worker/workspace/obj-build/dist/include/

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=315804609&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/RE-mD_oLQC2e__upjg7iDA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-09-16T05:20:32.572Z] 05:20:32     INFO -  TEST-START | TestSafeThreadLocal.exe
[task 2020-09-16T05:20:32.611Z] 05:20:32     INFO -  mozcrash checking c:\users\task_1600232880\appdata\local\temp\tmpqod5bm for minidumps...
[task 2020-09-16T05:20:32.611Z] 05:20:32     INFO -  TEST-PASS | TestSafeThreadLocal.exe | took 38ms
[task 2020-09-16T05:20:32.611Z] 05:20:32     INFO -  TEST-START | TestBaseProfiler.exe
[task 2020-09-16T05:20:32.651Z] 05:20:32     INFO -  PID 5016 |
[task 2020-09-16T05:20:32.651Z] 05:20:32     INFO -  Assertion failure: mReleasedChunks->Last()->ChunkHeader().mDoneTimeStamp < aChunks->ChunkHeader().mDoneTimeStamp (Chunks must be released in increasing timestamps), at /builds/worker/workspace/obj-build/dist/include/mozilla/ProfileBufferChunkManagerWithLocalLimit.h:156
[task 2020-09-16T05:20:32.651Z] 05:20:32     INFO -  mozcrash checking c:\users\task_1600232880\appdata\local\temp\tmpza3ntk for minidumps...
[task 2020-09-16T05:20:32.651Z] 05:20:32  WARNING -  TEST-UNEXPECTED-FAIL | TestBaseProfiler.exe | test failed with return code 2147483651
[task 2020-09-16T05:20:32.651Z] 05:20:32     INFO -  TEST-INFO took 38ms```

Comment 1

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

It looks rare, but I feel I should look at it ASAP.

Comment 2

[Intermittent Failures Robot]

1 failures in 3760 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665265&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 3

[Intermittent Failures Robot]

20 failures in 4019 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 17
• autoland: 3

Platform breakdown:

• windows10-64-mingwclang: 16
• windows10-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665265&startday=2020-09-21&endday=2020-09-27&tree=all

Comment 4

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

This is a permanent failure for Windows x64 mingw debug cppunit.

Comment 5

[Intermittent Failures Robot]

12 failures in 4195 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 9
• autoland: 3

Platform breakdown:

• windows10-64-mingwclang: 8
• windows10-64: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665265&startday=2020-09-28&endday=2020-10-04&tree=all

Comment 6

[Intermittent Failures Robot]

22 failures in 4130 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 16
• autoland: 6

Platform breakdown:

• windows10-64-mingwclang: 15
• windows10-64: 7

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665265&startday=2020-10-05&endday=2020-10-11&tree=all

Comment 7

[(Away)]

This was starting to annoy me on try runs so I attempted to take a look, but unfortunately I can't reproduce it locally even if I take the binary from a failing push on treeherder.

I then threw some printf at it, and got:

[task 2020-10-13T20:59:49.823Z] 20:59:49     INFO -  mReleasedChunks->Last()->ChunkHeader().mDoneTimeStamp.mValue.mGTC = 2919070870125
[task 2020-10-13T20:59:49.823Z] 20:59:49     INFO -  mReleasedChunks->Last()->ChunkHeader().mDoneTimeStamp.mValue.mQPC = 2919573268000
[task 2020-10-13T20:59:49.823Z] 20:59:49     INFO -  aChunks->ChunkHeader().mDoneTimeStamp.mValue.mGTC = 2919070870125
[task 2020-10-13T20:59:49.823Z] 20:59:49     INFO -  aChunks->ChunkHeader().mDoneTimeStamp.mValue.mQPC = 2919573268000

So the timestamps are equal.

Gerald, does that offer any clues?

Comment 8

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Sorry for the annoyance, I haven't had a chance to look into this yet, but I really want to, hopefully in the next few days...

Thank you :dmajor for the printfs. I did not expect equal timestamps, so that's certainly a good clue! Are timestamps less precise on mingw?

These failures happen in tests, and tests typically use small chunks, so I guess they could theoretically be filled in such a short time that they could have equal "done" timestamps!? If that's correct, a quick fix would be to add some delays during testing.
(In real life, chunks are 1MB, which should take a significant amount of time to fill.)

Comment 9

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

So the problem is not what I initially feared when I wrote comment 1, but it is indeed a timing issue due to tests going unreasonably quickly through chunks, so they end up with the same timestamps.
I will add some delays between chunks MarkDone() calls, which is closer to what really happens in Firefox.

Thank you again :dmajor for pushing me to take a look at it now.

Comment 10

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1665265 - Prevent chunks from being marked done with the same timestamps in quick tests - r?gregtatum

These unit tests were going through chunks very quickly in tight loops, which on some platforms could cause successive chunks to be marked "done" with the same timestamps.
Distinct timestamps are needed to uniquely identify chunks (in each process), and related assertions caught that. In real Firefox code, chunks are much bigger (around 1MB), and fill at a slower rate, so timestamps are always different as expected there.
To fix this artificial issue in our unit tests, delays are introduced before each MarkDone(), to ensure that they'll get a different timestamp every time.

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9150b0886ac9
Prevent chunks from being marked done with the same timestamps in quick tests - r=gregtatum

Comment 12

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/9150b0886ac9

Comment 13

[Intermittent Failures Robot]

14 failures in 3694 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 9
• try: 1
• mozilla-esr78: 1

Platform breakdown:

• windows10-64: 2
• windows10-64-mingwclang: 9
• windows7-32: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1665265&startday=2020-10-12&endday=2020-10-18&tree=all