Assertion failure in find_holes during record

[Keno]

https://buildkite.com/julialang/julia-master/builds/35035#018e807f-e934-4187-a6d1-294631bd1a79

[FATAL src/record_syscall.cc:5763:find_holes() errno: EXDEV]
 (task 808 (rec:808) at time 469522)
 -> Assertion `data > hole' failed to hold. Found data at 4456448 which should be after hole 4456448; file end 7684096, data offset 4456448
[INFO log_pending_events()] SYSCALL: mmap
[INFO log_pending_events()] (none)
[FATAL src/log.cc:444:emergency_debug()] (session doesn't look interactive, aborting emergency debugging)

I'm not sure what the kernel's guarantees on SEEK_HOLE are and whether holes are allowed to be zero size, but that is what the assert seems to be indicating.

[rocallahan]

Is it possible that something else is writing to the file concurrently with the tracee?

[Keno]

Just noting that we saw this again in https://buildkite.com/julialang/julia-master/builds/49666/steps/canvas?sid=01987c83-ea27-470a-8265-bd5de099b92c. I'll try to dig into the trace in the morning to see if I can understand this behavior a bit better.

[Keno]

My suspicion is that the test in question is this one: https://github.com/JuliaLang/julia/blob/master/test/cmdlineargs.jl#L1346-L1354. So the software that's writing this file is lld, and then we're mmaping it in a new process, but lld should definitely be done by the time we do that. I also don't think we detach that second process, so it should all be in the same trace

[Keno]

Also noting that in both of those cases the holes are on 64KiB boundaries and the filesystem is (probably), tempfs (though I will get the login to that node tomorrow to double check).

[Keno]

My suspicion is that the test in question is this one:

Confirmed by downloading the trace:

6637	827	0	/cache/build/tester-amdci4-14/julialang/julia-master/julia-7bfc2ec77f/libexec/julia/lld -flavor gnu  -shared -o /tmp/jl_XrKiUH/sys.so --whole-archive /tmp/jl_XrKiUH/sys.o.a --no-whole-archive -L/cache/build/tester-amdci4-14/julialang/julia-master/julia-7bfc2ec77f/lib/julia -L/cache/build/tester-amdci4-14/julialang/julia-master/julia-7bfc2ec77f/lib -ljulia -ljulia-internal
6639	827	none	/cache/build/tester-amdci4-14/julialang/julia-master/julia-7bfc2ec77f/bin/julia -C native -J/cache/build/tester-amdci4-14/julialang/julia-master/julia-7bfc2ec77f/lib/julia/sys.so --depwarn=error --check-bounds=yes -g1 --startup-file=no -t1,0 -J /tmp/jl_XrKiUH/sys.so -E hasmethod(sort, (Vector{Int},), (:dims,))

lld does use memory mapped I/O for its output, so it's quite possible for it to be creating holes. I will see if I can extract the file from the trace to get more of an idea what's in there.

[Keno]

Sigh, unfortunately the replay diverges before this test starts, so I can't get the file out.

[Keno]

-> Assertion `false' failed to hold. Detected 1505557 ticks, expected no more than 1498385

Unfortunately not stable, which would suggest that our skid window is too small, but that's an extra 7000 ticks. We do know that AMD likes to take its sweet time with these interrupts, but that's getting a bit ridiculous.

[khuey]

If the issue really is the skid window you should be able to make arbitrary increases to that in a one off build to replay this trace.

[Keno]

Yep, working on it. It's a little non-trivial, because this CI machine isn't set up to build rr.

[khuey]

I think you should only need to bump the skid size for replay (which you could do locally, maybe).

[Keno]

Yes, but for lack-of-cpuid-faulting reasons (which I know got fixed recently, but the kernel hasn't been updated), I need to replay this on the CI machine. But anyway, I've got it figured out. Will let you know if that helps.

[khuey]

Yes, but for lack-of-cpuid-faulting reasons (which I know got fixed recently, but the kernel hasn't been updated), I need to replay this on the CI machine

Ah, yeah, that would do it :/

[Keno]

Alright, got a replay running with skid increased to 25000 - will report back.

[Keno]

Replayed fine once at 25000, but broke the second time. I've raised it to 30000. Unfortunately this trace takes a really long time (>1 h) to get to the point, and increasing the skid size makes it slower. I wonder if we can improve the performance of high skid replays, but in the meantime, I'll wait it out again.