Recording WINE is slow

[Keno]

Continuing from our IRC conversation, there is significant overhead to recording WINE. E.g.:

$ time wineconsole ./usr/bin/julia.exe -e 'quit()'
real    0m0.976s
user    0m0.006s
sys 0m0.010s

$ time ~/rr-build/bin/rr record wineconsole ./usr/bin/julia.exe -e 'quit()'
real    0m42.874s
user    0m32.998s
sys 0m10.637s

#1777 has helped some, but unfortunately this is after (before it was 2x this). Most of the time is spent in rr. This workload appears notable in that it frequently descheds in read for synchronization purposes (requests made to the wineserver).

A flamegraph of the whole execution tree is available here:
https://gist.github.com/Keno/c1ec0b7f22ccb585d378ddf0e03cd426

[rocallahan]

Simple ping-pong testcase: https://gist.github.com/rocallahan/fec1dcd017d1bb3fcb5e29ba0ed70b15

[roc@glory src]$ time ~/tmp/test
real    0m0.500s
user    0m0.017s
sys 0m0.612s
[roc@glory src]$ time taskset 1 ~/tmp/test
real    0m0.248s
user    0m0.028s
sys 0m0.220s
[roc@glory src]$ time rr record ~/tmp/test
real    0m55.117s
user    0m34.208s
sys 0m15.618s

[rocallahan]

[roc@glory src]$ time rr record -n ~/tmp/test
real    0m29.472s
user    0m20.507s
sys 0m7.613s

I expect this kind of context-switch-dominated test to be bad. But not this bad...

[rocallahan]

Those were with a debug rr build. With an opt build:

[roc@glory src]$ time rr record ~/tmp/test
real    0m20.520s
user    0m8.752s
sys 0m9.723s
[roc@glory src]$ time rr record -n ~/tmp/test
real    0m12.579s
user    0m6.076s
sys 0m6.021s

[Keno]

Yeah, since this spends so much time in rr optimizations make a huge difference. There's some more things we can do to make rr itself faster (not descheduling performance counters, avoiding syscalls if we can, etc.), but seems like the original design was really trying to avoid having to do that ;).

[rocallahan]

Yeah, up until now we've been able to get good performance on workloads we care about just by reducing the number of context switches to rr. But when the tracee itself is dominated by context switches, there's no way to avoid context switching to rr. At least, not without extraordinary changes to the way rr works.

[rocallahan]

I'd accept patches to improve this benchmark, but I don't see any incredibly low-hanging fruit, and to be honest I have other priorities at the moment. Most applications don't context-switch this badly because that's kinda bad for performance in general. I guess Wine is kind of constrained by the need to emulate the Windows kernel.

[Keno]

I'd accept patches to improve this benchmark

I'll do some benchmarking tomorrow and see what I can do.

[rocallahan]

I think avoiding the full perf-counter resets would be good. We never got to the bottom of why that was necessary; hopefully it was an old kernel bug that we can just ignore now.

You could look at Task::resume_execution and the waitpid(WNOHANG) we do there; maybe you can figure out a better way to address the problem described in the comment.

Just running strace on rr will probably show a number of syscalls that can be optimized out with better caching.

[Keno]

I think avoiding the full perf-counter resets would be good. We never got to the bottom of why that was necessary; hopefully it was an old kernel bug that we can just ignore now.

Yes, it's a kernel bug, but IIRC it was only fixed recently, I want to say somewhere around 3.17, certainly after 3.11 but before 4.7 since that's the versions I looked at. Still, we can avoid the reset on on new-enough kernels.

[Keno]

You could look at Task::resume_execution and the waitpid(WNOHANG) we do there; maybe you can figure out a better way to address the problem described in the comment.

Is the primary problem the robust futex handling? If so what is wrong with the following:

• If we detect that this race happened (because the tracee died without us having seen the exit event), wait until we're sure the kernel is done with the process and has applied any necessary OWNER_DIED bits
• During replay, when we get to the exit event, we should now have the futex list (since we decide when to exit), so we should be able to apply the OWNER_DIED bits.

I.e. the suggestion is moving the behavior of record_robust_futex_changes from record-time to replay time and letting the kernel take care of it at record-time. Please poke holes in this design ;)

[rocallahan]

The core issue is that whenever we allow the kernel to apply the robust futex changes itself, we risk an unreplayable race between those changes and the currently recording thread. So we need to keep the current record_robust_futex_change path as the "normal path".

I think you're suggesting adding a backup path that we only use in case of async SIGKILL and removing the waitpid(NOHANG) in resume_execution so that the potential race window opens a little wider, but hopefully not enough to be a significant problem in practice. Right?

Having two different ways that the robust futex changes get applied is annoying extra complexity, but if it doesn't cause problems in practice and it lets us remove that extra waitpid, I'd be happy with that.

[rocallahan]

Hmmm. What if we didn't expose the tracee's robust futex list to the kernel at all, by blocking that syscall, and made rr responsible for applying those changes, synchronously after we've detected task death? That might work!

[rocallahan]

Oh, I remember why that doesn't work. It's because after task death you may have no access to the address space so you can't walk the robust futex list. (And some of them might be in shared memory so might still need to be updated.)

[rocallahan]

Another thing that might work is to start trapping SIGCHLD in rr. That has its own overheads, of course, but probably not very much and it would let us avoid a lot of waitpid(NOHANG) calls in the scheduler and in resume_execution here. One way to do it might be to have a dedicated thread handling SIGCHLD and storing the results in a thread-safe data structure that we can probe efficiently.

[rocallahan]

If you handle SIGCHLD on the main thread then you might have better synchronization properties. For example I think we can guarantee that upon return from a successful waitpid, the corresponding SIGCHLD will already have been delivered.