Re: [lmi] Drastic slowdown related to wine upgrade?

[Vadim Zeitlin]

 Hello,

 Just a quick update about the curious case of slow WINE, mostly to show
that I didn't forget about it, but otherwise very low priority, i.e. you
can safely skip reading all this entirely.


On Thu, 31 Jan 2019 13:33:25 +0000 Greg Chicares <address@hidden> wrote:

GC> On 2019-01-28 23:55, Vadim Zeitlin wrote:
[...]
GC> >  So my minimal reproducible example is that
GC> > 
GC> >   time (wine cmd /c type 'c:\windows\win.ini' >/dev/null)
GC> > 
GC> > takes 0.02s while
GC> > 
GC> >   time (wine cmd /c type 'c:\windows\win.ini' | cat >/dev/null)
GC> > 
GC> > takes 1.2s.
GC> > 
GC> >  If I open the bug with this, which "last good" WINE version should I
GC> > report? I.e. you wrote that you upgraded from wine-3.x, but would you
GC> > remember what was the value of "x"? Was it 3.0.3 from Stretch backports?
GC> 
GC> As of the moment, that version would be exactly this:
GC>   https://packages.debian.org/stretch-backports/wine
GC> | 3.0.3-2~bpo9+1
GC> and what I formerly had is identified above only as:
GC>   3.0.3-2

 So before reporting the bug, I've decided to check if it still exists in
the latest WINE version from Git. It was much simpler to build a 64 bit
version of it for me, rather than 32 bit one, so I've started with this and
am seeing very surprising results: first of all, even the basic command
above, without "cat", is much slower with the version I built, running it
on the same machine yields

( ./wine cmd /c type 'c:\windows\win.ini' > /dev/null; )  0.03s user 0.02s 
system 78% cpu 0.056 total

i.e. 0.05s instead of 0.02s before. Maybe Debian package uses different
(and better) optimization flags or something else, I don't really know.

 Running the command with "cat" is still much slower -- but only the first
first it runs! I.e. if I run it immediately after the simple command above,
I get, as expected by now

( ./wine cmd /c type 'c:\windows\win.ini' | cat > /dev/null; )  0.03s user 
0.03s system 3% cpu 1.721 total

But if I rerun it _immediately_ afterwards I get this instead:

( ./wine cmd /c type 'c:\windows\win.ini' | cat > /dev/null; )  0.02s user 
0.03s system 86% cpu 0.062 total

and the difference between this time and the time without cat is not
significant. The really mysterious part is that it doesn't seem to be a
caching effect because even on a completely idle system if I just wait a
couple of seconds between the commands, the next one is slow again. But as
long as the commands are separated by 2 seconds or less, the second one is
(and all the subsequent ones are) fast.

 I have no explanation about how can this happen but I'll try to poke
around to see if I can find something because I'm afraid that if I report
the bug with just this information to WINE developers they're going to
believe I'm crazy (and I wouldn't blame them). And to make matters even
mysteriousier, Debian 4.0-1 WINE version doesn't show this behaviour while
the version I built directly from the upstream WINE 4.0 sources does.

 The only good news is that I can confirm that the slowdown, even for the
first command with the pipe, didn't exist with WINE 3.0.3, so I should be
able to find the commit which introduced the problem by bisection.
Unfortunately, building WINE takes ~10 minutes on my machine, so doing this
risks taking quite some time, but luckily I probably should have time to do
it (while being unable to do much else) in the near future, so I'll try to
find this out.

 Regards,
VZ