[lmi] Drastic slowdown related to wine upgrade?

[Greg Chicares]

Since I upgraded from wine-3.x to wine-4.x the other day, the time it takes to
run this command:
  time make $coefficiency check_concinnity
  make $coefficiency check_concinnity  3.50s user 0.98s system 8% cpu 52.817 
total
has grown remarkably, from a few seconds to nearly a minute. Suppressing the
xmllint command in that makefile target reduces the time to about four seconds,
so that (pipelined) command is the culprit.

Here's how long it takes in another chroot with wine-1.x:

/opt/lmi/src/lmi[0]$wine --version 
wine-1.8.7 (Debian 1.8.7-2)
/opt/lmi/src/lmi[0]$time make $coefficiency check_concinnity >/dev/null
make $coefficiency check_concinnity > /dev/null  3.55s user 0.99s system 86% 
cpu 5.219 total

That's artificially slow because the old chroot's lmi source files are old,
resulting in hundreds of warnings about copyright dates (hence the redirection),
and also because the old chroot contains XSL files that must be tested with
xmllint. Otherwise, it performs just about the same work, because this
makefile didn't change between its date in the old chroot:

  $git log -1 GNUmakefile
  commit 1b4310455f4d10f0694b2a407d50c6a3e411f095
  Author: Gregory W. Chicares <address@hidden>
  Date:   2018-01-28T15:53:10+00:00
    Update copyright notices

and the beginning of this month's changes in the new chroot:

  commit 1b4310455f4d10f0694b2a407d50c6a3e411f095
  Author: Gregory W. Chicares <address@hidden>
  Date:   2018-01-28T15:53:10+00:00
    Update copyright notices

At first, I thought that perhaps 'wine xmllint' had somehow become much
slower, but running just that part of the command pipeline in both
chroots (and comparing it to native xmllint) shows little difference:

/opt/lmi/src/lmi[0]$wine --version
wine-1.8.7 (Debian 1.8.7-2)
/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; do /usr/bin/xmllint 
--encode ASCII $z >/dev/null ; done)
( for z in *.cns *.ill *.xrc *.xsd; do; /usr/bin/xmllint --encode ASCII $z > )  
0.08s user 0.04s system 76% cpu 0.167 total
/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; do wine 
/opt/lmi/local/bin/xmllint --encode ASCII $z >/dev/null ; done) 
( for z in *.cns *.ill *.xrc *.xsd; do; wine /opt/lmi/local/bin/xmllint  ASCI)  
0.47s user 0.64s system 74% cpu 1.495 total

/opt/lmi/src/lmi[0]$wine --version
wine-4.0-rc6 (Debian 4.0~rc6-1)
/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; do /usr/bin/xmllint 
--encode ASCII $z >/dev/null ; done)
( for z in *.cns *.ill *.xrc *.xsd; do; /usr/bin/xmllint --encode ASCII $z > )  
0.10s user 0.05s system 72% cpu 0.198 total
/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; do wine 
/opt/lmi/local/bin/xmllint --encode ASCII $z >/dev/null ; done)
( for z in *.cns *.ill *.xrc *.xsd; do; wine /opt/lmi/local/bin/xmllint  ASCI)  
0.56s user 0.80s system 72% cpu 1.875 total

Even though I used the same filespec in both chroots (to eliminate the
old XSL files), the files aren't entirely identical:
  $wc -l *.cns *.ill *.xrc *.xsd |grep total
    22854 total [new chroot]
    20646 total [old chroot]
so it is to be expected that the command takes slightly longer in the
new chroot. It is also obvious that the native xmllint is much faster.

However, the full command pipeline is much slower. The demonstration
below compares the wine vs. native timings, summarized here:
  46.509 total [wine /path/to/lmi/xmllint]
   0.197 total [/usr/bin/xmllint]
which suggests that using wine in a pipeline is the problem:

/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; \               
  do \
    wine /opt/lmi/local/bin/xmllint --encode ASCII $z \
    | tr --delete '\r' \
    | diff \
      --ignore-blank-lines \
      --ignore-matching-lines='<\?xml' \
      --unified=0 \
      $z - \
      || echo "... in file $z"; \
  done;)

( for z in *.cns *.ill *.xrc *.xsd; do; wine /opt/lmi/local/bin/xmllint  ASCI)  
0.60s user 0.82s system 3% cpu 46.509 total
/opt/lmi/src/lmi[0]$time (for z in *.cns *.ill *.xrc *.xsd; \
  do \
    /usr/bin/xmllint --encode ASCII $z \ 
    | tr --delete '\r' \
    | diff \
      --ignore-blank-lines \
      --ignore-matching-lines='<\?xml' \
      --unified=0 \
      $z - \
      || echo "... in file $z"; \
  done;)

( for z in *.cns *.ill *.xrc *.xsd; do; /usr/bin/xmllint --encode ASCII $z | )  
0.09s user 0.07s system 83% cpu 0.197 total

I copied and pasted those exact command lines into the older chroot;
here's a tabulation of the results:

  * wine-4.x
( for [...]; wine /opt/lmi/local/bin/xmllint  ASCI)  0.60s user 0.82s system 3% 
cpu 46.509 total
( for [...]; /usr/bin/xmllint --encode ASCII $z | )  0.09s user 0.07s system 
83% cpu 0.197 total
  * wine-1.x
( for [...]; wine /opt/lmi/local/bin/xmllint  ASCI)  0.48s user 0.65s system 
75% cpu 1.486 total
( for [...]; /usr/bin/xmllint --encode ASCII $z | )  0.10s user 0.06s system 
85% cpu 0.179 total

which clearly seems to establish that there's a wine regression here.

Vadim--Can you reproduce this in your 32-bit chroot? A web search for
  winehq pipeline slow
finds nothing clearly relevant, while
  wine pipeline slow
finds articles about petroleum pipelines near vineyards. But if you
see the same problem I see, then it's probably worthwhile to devise
a simple test case that the winehq or debian people can reproduce,
because this may expose a serious problem that they don't know about.

Obviously I'll use native /usr/bin/xmllint here for the time being.