Tee and file redirections are very slow to write anything.

Tee and file redirections are very slow to write anything.

[Hamish McIntyre-Bhatty]

[-- Attachment #1.1.1: Type: text/plain, Size: 883 bytes --]

Hi there,

I found recently when trying to save output from a script for later 
inspection that "tee" and file redirections seem to have massive delays 
when run in Cygwin - usually nothing is written to file or stdout until 
after the command has finished - not very helpful.

I'm running a bash script with the following cmdlines:

"bash ./path/to/script.sh > stdout.log"

and:

"bash ./path/to/script.sh | tee stdout.log"

Both of them result in no writes to the file (or stdout in the second 
case) until the command is finished, and as this script takes minutes to 
run, it's not very helpful. I'm running these commands from bash in Mintty.

Is there any configuration I need to do, or have I potentially 
discovered a bug? IIRC there have been some changes in the dev version 
of Cygwin relating to file I/O so perhaps this is already fixed?

Hamish


[-- Attachment #1.1.2: OpenPGP_0x18F1759B3457223F.asc --]
[-- Type: application/pgp-keys, Size: 3175 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]

Re: Tee and file redirections are very slow to write anything.

[ASSI]

Hamish McIntyre-Bhatty via Cygwin writes:
> I found recently when trying to save output from a script for later
> inspection that "tee" and file redirections seem to have massive
> delays when run in Cygwin - usually nothing is written to file or
> stdout until after the command has finished - not very helpful.

You will want to switch from fully buffered to line-buffered or even
unbuffered output.


Regards,
Achim.
-- 
+<[Q+ Matrix-12 WAVE#46+305 Neuron microQkb Andromeda XTk Blofeld]>+

SD adaptation for Waldorf Blofeld V1.15B11:
http://Synth.Stromeko.net/Downloads.html#WaldorfSDada

Re: Tee and file redirections are very slow to write anything.

[Hamish McIntyre-Bhatty]

[-- Attachment #1.1.1: Type: text/plain, Size: 774 bytes --]

On 24/02/2021 20:48, ASSI wrote:
> Hamish McIntyre-Bhatty via Cygwin writes:
>> I found recently when trying to save output from a script for later
>> inspection that "tee" and file redirections seem to have massive
>> delays when run in Cygwin - usually nothing is written to file or
>> stdout until after the command has finished - not very helpful.
> You will want to switch from fully buffered to line-buffered or even
> unbuffered output.
>
>
> Regards,
> Achim.

Thanks for the prompt response.

How do I do that? Also, considering that I've never had this issue on 
anything except Cygwin (various Linux distros over the years, and macOS, 
with a variety of different shells), is there a reason line or no 
buffering isn't the default?

Hamish


[-- Attachment #1.1.2: OpenPGP_0x18F1759B3457223F.asc --]
[-- Type: application/pgp-keys, Size: 3175 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]

Re: Tee and file redirections are very slow to write anything.

[Eliot Moss]

On 2/24/2021 3:48 PM, ASSI wrote:
> Hamish McIntyre-Bhatty via Cygwin writes:
>> I found recently when trying to save output from a script for later
>> inspection that "tee" and file redirections seem to have massive
>> delays when run in Cygwin - usually nothing is written to file or
>> stdout until after the command has finished - not very helpful.
> 
> You will want to switch from fully buffered to line-buffered or even
> unbuffered output.

And this does not have to do with Cygwin.  The same happens on Linux.
The default is that terminal I/O is unbuffered while other stream are
buffered.  Pipes come under "other streams".  One can make programmatic
changes to get around this, but most programs won't override the
default behavior on their own ...

Best -- Eliot Moss

Re: Tee and file redirections are very slow to write anything.

[Duncan Roe]

On Wed, Feb 24, 2021 at 04:58:24PM -0500, Eliot Moss wrote:
> On 2/24/2021 3:48 PM, ASSI wrote:
> > Hamish McIntyre-Bhatty via Cygwin writes:
> > > I found recently when trying to save output from a script for later
> > > inspection that "tee" and file redirections seem to have massive
> > > delays when run in Cygwin - usually nothing is written to file or
> > > stdout until after the command has finished - not very helpful.
> >
> > You will want to switch from fully buffered to line-buffered or even
> > unbuffered output.
>
> And this does not have to do with Cygwin.  The same happens on Linux.
> The default is that terminal I/O is unbuffered while other stream are
> buffered.  Pipes come under "other streams".  One can make programmatic
> changes to get around this, but most programs won't override the
> default behavior on their own ...
>
> Best -- Eliot Moss

The (Linux) default is that terminal I/O is *line* buffered

The man page for tee doesn't show an option to change buffering, while that for
grep does.

Cheers ... Duncan.

Re: Tee and file redirections are very slow to write anything.

[Takashi Yano]

On Thu, 25 Feb 2021 09:41:49 +1100
Duncan Roe wrote:
> On Wed, Feb 24, 2021 at 04:58:24PM -0500, Eliot Moss wrote:
> > On 2/24/2021 3:48 PM, ASSI wrote:
> > > Hamish McIntyre-Bhatty via Cygwin writes:
> > > > I found recently when trying to save output from a script for later
> > > > inspection that "tee" and file redirections seem to have massive
> > > > delays when run in Cygwin - usually nothing is written to file or
> > > > stdout until after the command has finished - not very helpful.
> > >
> > > You will want to switch from fully buffered to line-buffered or even
> > > unbuffered output.
> >
> > And this does not have to do with Cygwin.  The same happens on Linux.
> > The default is that terminal I/O is unbuffered while other stream are
> > buffered.  Pipes come under "other streams".  One can make programmatic
> > changes to get around this, but most programs won't override the
> > default behavior on their own ...
> >
> > Best -- Eliot Moss
> 
> The (Linux) default is that terminal I/O is *line* buffered
> 
> The man page for tee doesn't show an option to change buffering, while that for
> grep does.

However, in this case, output is not a 'terminal I/O' because it is
redirected to a file or a pipe.

Do these help?

"stdbuf -o L bash ./path/to/script.sh > stdout.log"
"stdbuf -o L bash ./path/to/script.sh | tee stdout.log"

-- 
Takashi Yano <takashi.yano@nifty.ne.jp>

Re: Tee and file redirections are very slow to write anything.

[Brian Inglis]

On 2021-02-24 15:41, Duncan Roe wrote:
> On Wed, Feb 24, 2021 at 04:58:24PM -0500, Eliot Moss wrote:
>> On 2/24/2021 3:48 PM, ASSI wrote:
>>> Hamish McIntyre-Bhatty via Cygwin writes:
>>>> I found recently when trying to save output from a script for later
>>>> inspection that "tee" and file redirections seem to have massive
>>>> delays when run in Cygwin - usually nothing is written to file or
>>>> stdout until after the command has finished - not very helpful.
>>>
>>> You will want to switch from fully buffered to line-buffered or even
>>> unbuffered output.

>> And this does not have to do with Cygwin.  The same happens on Linux.
>> The default is that terminal I/O is unbuffered while other stream are
>> buffered.  Pipes come under "other streams".  One can make programmatic
>> changes to get around this, but most programs won't override the
>> default behavior on their own ...

> The (Linux) default is that terminal I/O is *line* buffered
> 
> The man page for tee doesn't show an option to change buffering, while that for
> grep does.

I believe the default for both Cygwin and Linux is 64KB pipe buffer, so if you 
want to see smaller chunks as they are generated, you need to add some utility 
that may allow you to change that e.g.

	$ tail -f access.log | stdbuf -oL cut -d ' ' -f1 | uniq

but read the disclaimers on the stdbuf and grep man pages, which is why it is 
not done more, especially under Cygwin where Windows adds its own performance 
penalties.
Some utilities may use read(2/3p), write(2/3p), or mmap(3) if they can and don't 
care about text or lines, for more efficient access to disk files, rather than 
buffered stream I/O functions.

-- 
Take care. Thanks, Brian Inglis, Calgary, Alberta, Canada

This email may be disturbing to some readers as it contains
too much technical detail. Reader discretion is advised.
[Data in binary units and prefixes, physical quantities in SI.]

Re: Tee and file redirections are very slow to write anything.

[Eliot Moss]

On 2/24/2021 6:26 PM, Takashi Yano via Cygwin wrote:

 > "stdbuf -o L bash ./path/to/script.sh > stdout.log"
 > "stdbuf -o L bash ./path/to/script.sh | tee stdout.log"

Great stuff - thanks guys!  And thanks for the correction about line buffering.

Best - Eliot Moss

Re: Tee and file redirections are very slow to write anything.

[Brian Inglis]

On 2021-02-24 16:50, Brian Inglis wrote:
> On 2021-02-24 15:41, Duncan Roe wrote:
>> On Wed, Feb 24, 2021 at 04:58:24PM -0500, Eliot Moss wrote:
>>> On 2/24/2021 3:48 PM, ASSI wrote:
>>>> Hamish McIntyre-Bhatty via Cygwin writes:
>>>>> I found recently when trying to save output from a script for later
>>>>> inspection that "tee" and file redirections seem to have massive
>>>>> delays when run in Cygwin - usually nothing is written to file or
>>>>> stdout until after the command has finished - not very helpful.
>>>>
>>>> You will want to switch from fully buffered to line-buffered or even
>>>> unbuffered output.
> 
>>> And this does not have to do with Cygwin.  The same happens on Linux.
>>> The default is that terminal I/O is unbuffered while other stream are
>>> buffered.  Pipes come under "other streams".  One can make programmatic
>>> changes to get around this, but most programs won't override the
>>> default behavior on their own ...
> 
>> The (Linux) default is that terminal I/O is *line* buffered
>>
>> The man page for tee doesn't show an option to change buffering, while that for
>> grep does.
> 
> I believe the default for both Cygwin and Linux is 64KB pipe buffer, so if you 
> want to see smaller chunks as they are generated, you need to add some utility 
> that may allow you to change that e.g.
> 
>      $ tail -f access.log | stdbuf -oL cut -d ' ' -f1 | uniq
> 
> but read the disclaimers on the stdbuf and grep man pages, which is why it is 
> not done more, especially under Cygwin where Windows adds its own performance 
> penalties.
> Some utilities may use read(2/3p), write(2/3p), or mmap(3) if they can and don't 
> care about text or lines, for more efficient access to disk files, rather than 
> buffered stream I/O functions.

 From what I have been able to find, Cygwin <stdio.h> BUFSIZ is only 1K, 
compared to Linux 8K, and Cygwin internal 64K, and that is used in many places 
in coreutils like tee, which will slow everything down by a factor of at least 8 
plus increased overhead.

Suggest <stdio.h> BUFSIZ be bumped to at least Linux value of 8K, if not 64K.

-- 
Take care. Thanks, Brian Inglis, Calgary, Alberta, Canada

This email may be disturbing to some readers as it contains
too much technical detail. Reader discretion is advised.
[Data in binary units and prefixes, physical quantities in SI.]

Re: Tee and file redirections are very slow to write anything.

[Hamish McIntyre-Bhatty]

[-- Attachment #1.1.1: Type: text/plain, Size: 2767 bytes --]

On 25/02/2021 07:50, Brian Inglis wrote:
> On 2021-02-24 16:50, Brian Inglis wrote:
>> On 2021-02-24 15:41, Duncan Roe wrote:
>>> On Wed, Feb 24, 2021 at 04:58:24PM -0500, Eliot Moss wrote:
>>>> On 2/24/2021 3:48 PM, ASSI wrote:
>>>>> Hamish McIntyre-Bhatty via Cygwin writes:
>>>>>> I found recently when trying to save output from a script for later
>>>>>> inspection that "tee" and file redirections seem to have massive
>>>>>> delays when run in Cygwin - usually nothing is written to file or
>>>>>> stdout until after the command has finished - not very helpful.
>>>>>
>>>>> You will want to switch from fully buffered to line-buffered or even
>>>>> unbuffered output.
>>
>>>> And this does not have to do with Cygwin.  The same happens on Linux.
>>>> The default is that terminal I/O is unbuffered while other stream are
>>>> buffered.  Pipes come under "other streams".  One can make 
>>>> programmatic
>>>> changes to get around this, but most programs won't override the
>>>> default behavior on their own ...
>>
>>> The (Linux) default is that terminal I/O is *line* buffered
>>>
>>> The man page for tee doesn't show an option to change buffering, 
>>> while that for
>>> grep does.
>>
>> I believe the default for both Cygwin and Linux is 64KB pipe buffer, 
>> so if you want to see smaller chunks as they are generated, you need 
>> to add some utility that may allow you to change that e.g.
>>
>>      $ tail -f access.log | stdbuf -oL cut -d ' ' -f1 | uniq
>>
>> but read the disclaimers on the stdbuf and grep man pages, which is 
>> why it is not done more, especially under Cygwin where Windows adds 
>> its own performance penalties.
>> Some utilities may use read(2/3p), write(2/3p), or mmap(3) if they 
>> can and don't care about text or lines, for more efficient access to 
>> disk files, rather than buffered stream I/O functions.
>
> From what I have been able to find, Cygwin <stdio.h> BUFSIZ is only 
> 1K, compared to Linux 8K, and Cygwin internal 64K, and that is used in 
> many places in coreutils like tee, which will slow everything down by 
> a factor of at least 8 plus increased overhead.
>
> Suggest <stdio.h> BUFSIZ be bumped to at least Linux value of 8K, if 
> not 64K.

So from the discussion above, I've not sure I fully understand why the 
behaviour is different on Cygwin to Linux for me, especially if Linux's 
buffer size is sometimes bigger.

Perhaps:

#1: It depends on the program being run and how it sets its buffers up?

#2: stdbuf -o L enables line buffering and should fix my problem?

I'm now thinking it may have been a Python script that was behaving this 
way - I might go and double check in case this isn't what I think it is.

Hamish


[-- Attachment #1.1.2: OpenPGP_0x18F1759B3457223F.asc --]
[-- Type: application/pgp-keys, Size: 3175 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]

Re: Tee and file redirections are very slow to write anything.

[Henry S. Thompson]

Hamish McIntyre-Bhatty via Cygwin writes:

> I'm now thinking it may have been a Python script that was behaving this
> way - I might go and double check in case this isn't what I think it is.

I have noticed recently (on a Linux box) that Python3.8 logging exhibits
the problem you report, that is, no output until end of job.

ht
-- 
       Henry S. Thompson, School of Informatics, University of Edinburgh
      10 Crichton Street, Edinburgh EH8 9AB, SCOTLAND -- (44) 131 650-4440
                Fax: (44) 131 650-4587, e-mail: ht@inf.ed.ac.uk
                       URL: http://www.ltg.ed.ac.uk/~ht/
 [mail from me _always_ has a .sig like this -- mail without it is forged spam]

The University of Edinburgh is a charitable body, registered in
Scotland, with registration number SC005336.

Re: Tee and file redirections are very slow to write anything.

[Takashi Yano]

On Thu, 25 Feb 2021 09:51:48 +0000
"Henry S. Thompson wrote:
> Hamish McIntyre-Bhatty via Cygwin writes:
> 
> > I'm now thinking it may have been a Python script that was behaving this
> > way - I might go and double check in case this isn't what I think it is.
> 
> I have noticed recently (on a Linux box) that Python3.8 logging exhibits
> the problem you report, that is, no output until end of job.

stdbuf does not take effect for python, however, you can use
-u option or setting environment PYTHONUNBUFFERED=1.

-- 
Takashi Yano <takashi.yano@nifty.ne.jp>

Re: Tee and file redirections are very slow to write anything.

[Hamish McIntyre-Bhatty]

[-- Attachment #1.1.1: Type: text/plain, Size: 648 bytes --]

Excellent, I shall give that a try. Thanks.

Hamish

On 25/02/2021 10:27, Takashi Yano via Cygwin wrote:
> On Thu, 25 Feb 2021 09:51:48 +0000
> "Henry S. Thompson wrote:
>> Hamish McIntyre-Bhatty via Cygwin writes:
>>
>>> I'm now thinking it may have been a Python script that was behaving this
>>> way - I might go and double check in case this isn't what I think it is.
>> I have noticed recently (on a Linux box) that Python3.8 logging exhibits
>> the problem you report, that is, no output until end of job.
> stdbuf does not take effect for python, however, you can use
> -u option or setting environment PYTHONUNBUFFERED=1.
>

[-- Attachment #1.1.2: OpenPGP_0x18F1759B3457223F.asc --]
[-- Type: application/pgp-keys, Size: 3175 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 840 bytes --]