bug#37093: wc runs 100% cpu when in pipeline or tee >(wc)

[Bernhard Voelker]

On 8/20/19 6:44 AM, Edward Huff wrote:
> In the demo below, dd uses 0.665s to write 1GiB of zeros.
> sha256sum uses 4.285s to calculate the sha256 of 1GiB of zeros.
> wc uses 32.160s to count 1GiB of zeros.
> 
> Linux localhost 5.2.8-200.fc30.x86_64 #1 SMP Sat Aug 10 13:21:39 UTC 2019
> x86_64 x86_64 x86_64 GNU/Linux
> coreutils-8.31-2.fc30.x86_64
> dd (coreutils) 8.31
> wc (GNU coreutils) 8.31
> sha256sum (GNU coreutils) 8.31
> 
> baseline results:
> $ dd if=/dev/zero count=$((1024*1024)) bs=1024 | tee >(sha256sum>&2) | wc
> 1048576+0 records in
> 1048576+0 records out
> 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 32.5007 s, 33.0 MB/s
> 49bc20df15e412a64472421e13fe86ff1c5165e18b2afccf160d4dc19fe68a14  -
>       0       0 1073741824
> $
> 
> Demo script:
> $ cat wc-at-100pct
> #!/bin/bash
> set -xv
> rm pipe* tee*
> {
>    {
>       time dd if=/dev/zero count=$((1024*1024)) bs=1024
>    } 2>>pipedd
> } | {
>    tee >(
>       {
>          time sha256sum
>       } >teesha256 2>&1
>    )
> } | {
>    {
>       time wc
>    } > pipewc 2>&1
> }
> 
> {
>    {
>       time dd if=/dev/zero count=$((1024*1024)) bs=1024
>    } 2>>pipedd
> } | {
>    tee >(
>       {
>          time wc
>       } >teewc 2>&1
>    )
> } | {
>    {
>       time sha256sum
>    } > pipesha256sum 2>&1
> }
> 
> head pipe* tee*
> $
> 
> Results:
> ./wc-at-100pct
> rm pipe* tee*
> + rm pipedd pipesha256sum pipewc teesha256 teewc
> {
>    {
>       time dd if=/dev/zero count=$((1024*1024)) bs=1024
>    } 2>>pipedd
> } | {
>    tee >(
>       {
>          time sha256sum
>       } >teesha256 2>&1
>    )
> } | {
>    {
>       time wc
>    } > pipewc 2>&1
> }
> + tee /dev/fd/63
> 
> {
>    {
>       time dd if=/dev/zero count=$((1024*1024)) bs=1024
>    } 2>>pipedd
> } | {
>    tee >(
>       {
>          time wc
>       } >teewc 2>&1
>    )
> } | {
>    {
>       time sha256sum
>    } > pipesha256sum 2>&1
> }
> + tee /dev/fd/63
> 
> head pipe* tee*
> + head pipedd pipesha256sum pipewc teesha256 teewc
> ==> pipedd <==
> + dd if=/dev/zero count=1048576 bs=1024
> 1048576+0 records in
> 1048576+0 records out
> 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 32.5495 s, 33.0 MB/s
> 
> real 0m32.550s
> user 0m0.665s
> sys 0m1.503s
> + dd if=/dev/zero count=1048576 bs=1024
> 1048576+0 records in
> 
> ==> pipesha256sum <==
> + sha256sum
> 49bc20df15e412a64472421e13fe86ff1c5165e18b2afccf160d4dc19fe68a14  -
> 
> real 0m31.457s
> user 0m4.285s
> sys 0m0.562s
> 
> ==> pipewc <==
> + wc
>       0       0 1073741824
> 
> real 0m32.555s
> user 0m32.160s
> sys 0m0.247s
> 
> ==> teesha256 <==
> ++ sha256sum
> 49bc20df15e412a64472421e13fe86ff1c5165e18b2afccf160d4dc19fe68a14  -
> 
> real 0m32.553s
> user 0m4.333s
> sys 0m0.704s
> 
> ==> teewc <==
> ++ wc
>       0       0 1073741824
> 
> real 0m31.456s
> user 0m31.121s
> sys 0m0.221s

I'm not sure what your report is trying to demonstrate exactly.

Here, your script just takes ~5-6 seconds for each pass on a ~5 year-old
"Intel(R) Core(TM) i5-4570 CPU @ 3.20GHz".

Furthermore, replacing 'time' by 'env time -v' shows that wc(1) is taking
less CPU than sha256sum - exactly as one would expect:

  $ grep CPU * | column -t
  pipedd:         Percent  of  CPU  this  job  got:  27%
  pipedd:         Percent  of  CPU  this  job  got:  29%
  pipesha256sum:  Percent  of  CPU  this  job  got:  99%
  pipewc:         Percent  of  CPU  this  job  got:  65%
  teesha256:      Percent  of  CPU  this  job  got:  99%
  teewc:          Percent  of  CPU  this  job  got:  66%

> coreutils-8.31-2.fc30.x86_64

It looks like you are using the Fedora package of coreutils ... which
may have some additional patches compared to upstream GNU coreutils.
Did you try the upstream version as well?

Have a nice day,
Berny