LanX has asked for the wisdom of the Perl Monks concerning the following question:

Something weird is happening when I'm starting a Perl script under powershell and redirecting STDOUT to a logfile

PS D:\tmp> perl -E"$|=1;print $]" >.\tmp.log # writ +es log immediately PS D:\tmp> cat .\tmp.log 5.032001 PS D:\tmp> perl -E"$|=1;print $];sleep 100" >.\tmp.log # does +n't write log Terminating on signal SIGINT(2) PS D:\tmp> cat .\tmp.log # empt +y PS D:\tmp> exit d:\tmp>perl -E"$|=1;print $];sleep 100" >.\tmp.log # writ +es log immediately Terminating on signal SIGINT(2) d:\tmp> type .\tmp.log 5.032001

What am I missing? Is this a bug in Perl or Powershell?

Cheers Rolf
(addicted to the Perl Programming Language :)
Wikisyntax for the Monastery

update

Couldn't reproduce the even after finishing sleep part anymore

update

OK to make sure that it's not a side effect from -E I created a (very) short script.pl

PS D:\tmp> echo '$|=1;print $];sleep 10' > tst.pl PS D:\tmp> cat .\tst.pl $|=1;print $];sleep 10 PS D:\tmp> perl tst.pl # prints immediately 5.032001 PS D:\tmp> perl tst.pl >tmp.log Terminating on signal SIGINT(2) PS D:\tmp> cat .\tmp.log PS D:\tmp> PS D:\tmp> perl tst.pl >tmp.log # don't CTRL-c, just wait PS D:\tmp> cat .\tmp.log 5.032001

again,

  • if I run the script without redirection I see the output immediately
  • if I redirect, the log isn't written while sleeping
  • if I terminate with CTRL c the log isn't written either
  • only if I wait 10 sec I'll see the log written
  • Replies are listed 'Best First'.
    Re: (WIN) Autoflush, Perl, Sleep and Powershell
    by vinoth.ree (Monsignor) on May 14, 2021 at 16:27 UTC
      Hi LanX,

      I am using perl 5.28, but I get the log getting written after sleep completes, I tried different timegap

      PS C:\Users\VinothG> perl -E"$|=1;print $];sleep 10" >.\tmp.log PS C:\Users\VinothG> cat .\tmp.log 5.028001 PS C:\Users\VinothG> perl -E"$|=1;print $];sleep 20" >.\tmp.log PS C:\Users\VinothG> cat .\tmp.log 5.028001 PS C:\Users\VinothG> perl -E"$|=1;print $];sleep 30" >.\tmp.log PS C:\Users\VinothG> cat .\tmp.log 5.028001 PS C:\Users\VinothG> perl -E"$|=1;print $];sleep 40" >.\tmp.log PS C:\Users\VinothG> cat .\tmp.log 5.028001 PS C:\Users\VinothG> perl -E"$|=1;print $];sleep 100" >.\tmp.log PS C:\Users\VinothG> cat .\tmp.log 5.028001

      My PowerShell Version

      PS C:\Users\VinothG> Get-Host | Select-Object Version Version ------- 5.1.18362.1474

      All is well. I learn by answering your questions...
        > but I get the log getting written after sleep completes

        yes sorry, I couldn't reproduce that part anymore.

        But $|=1 aka autoflush should guaranty that it's written immediately, please try CTRL-c while sleeping and see if there is any output.

        My interest is in reading the output of long running scripts in realtime.

        FWIW I tried both quotes " and ' for the -E part.

        Cheers Rolf
        (addicted to the Perl Programming Language :)
        Wikisyntax for the Monastery

          «My interest is in reading the output of long running scripts in realtime.»

          What about Get-Content with the flags -Tail and -Wait?

          «The Crux of the Biscuit is the Apostrophe»

    Re: (WIN) Autoflush, Perl, Sleep and Powershell
    by LanX (Cardinal) on May 14, 2021 at 16:58 UTC
      OK, this seems to be a problem with some powershell buffering.

      If I print with a newline at the end the output shows directly.

      PS D:\tmp> perl -E'$|=1;print qq($]\n);sleep 10' > tmp.log Terminating on signal SIGINT(2) PS D:\tmp> cat .\tmp.log 5.032001 PS D:\tmp> perl -E'$|=1;print qq($]);sleep 10' > tmp.log Terminating on signal SIGINT(2) PS D:\tmp> cat .\tmp.log PS D:\tmp>

      weird ...

      Cheers Rolf
      (addicted to the Perl Programming Language :)
      Wikisyntax for the Monastery

        Newline characters (and what happens when you don't have them) are a known headache with PowerShell. If your string always ends with a newline it will be written timely.
          > If your string always ends with a newline it will be written timely.

          Okay..

          Do you have a reference, please?

          Cheers Rolf
          (addicted to the Perl Programming Language :)
          Wikisyntax for the Monastery

    Re: (WIN) Autoflush, Perl, Sleep and Powershell
    by Marshall (Canon) on May 17, 2021 at 01:14 UTC
      Post withdrawn for the moment because I found a bug after prematurely posting this. Sorry.

      Ok, back again. I see what happened. I put an extra line in the disk example to make sure that the $| was actually causing a flush on the hard disk write. It wasn't. This caused me to be fooled. To get $| to work on the disk file, a select() is needed.

      OK. I think this is ok now. Perl itself will flush on every print(). Now, I am not sure about the Power Shell connection.

      removed tag <readmore>
      OK. First up flush and the command console:

      use strict; use warnings; $| = (@ARGV > 0); print "this is partial line...."; sleep (20); print "the rest of the story\n";
      When run with no args, what you see on the console is that there is a 20 second delay before you see anything and then the entire line appears on the console at once.

      When run with one or more args, you will see the first print, then a 20 second delay, then the second print. Perl does not have to wait to see the \n before flushing what it has to the console screen. Of course program end causes all data to be written to the disk.

      NOW, second up, writing to a hard disk:

      use strict; use warnings; open FILE, '>', 'test' or die; select FILE; #this is important for $| the hard disk file! $| = (@ARGV > 0); print STDERR "partial line going to disk"; print FILE "this is partial line...."; sleep (20); print FILE "the rest of the story\n"; print STDERR "line is complete\n"; print STDERR "starting another sleep\n"; sleep(20); print STDERR "program ended\n";
      To test this, I just opened another command window and repeatedly ran "type test".
      I found much to my surprise that each print goes to the disk.
      There is no "waiting for the \n" when flush is properly enabled. Extra sleep is there to make sure that the second print worked before program end.

      DISCUSSION:

      When you are writing a text file to disk, at the driver level, the OS is working with a typically 4Kbyte buffer. Nowadays this almost always takes 8 512 byte sectors on the hard disk. Why the industry has settled on these values (4K and 512 is a long story that involves some history). Other choices are certainly plausible and are sometimes used for special applications.

      Without any flushing going on, this 4K buffer is written to the disk when it is full. Any overlap of lines (buffer typically will not end exactly on a new line boundary) spills over into the next "fresh, newly started" 4K buffer.

      When auto flushing is going on, the entire 4K buffer will be re-written to the disk as each new print() is executed. There is no such thing as a "partial" 4K buffer write as far as the hard disk system is concerned. If the first line used say 37 bytes of the 4K, then the rest of the buffer is just garbage. 4K is the increment that the file system uses. When the next line comes along, it gets added to this 4K buffer. Note at the disk drive level, this 4K write could take awhile due to rotational delays and the possibility that that the drive will have to do a seek between one of the eight sectors. Writing 4K block to the disk on every flush is just fundamental to how this works.

      So, watch out! if you enable flush to the hard disk. Every print() will flush. This means that a loop which uses separate prints for each value on a single line is going to cause the performance to "auger into the ground".

      I had thought that there was an optimization for only flush on a \n when writing to the disk, but that is not true. This erroneous belief was caused because my code wasn't properly enabling flush on a hard file handle. If you want to do line by line flushing yourself, it is possible to put in explicit flush() commands. In general, don't flush to hard disk due to the performance penalty discussed above. removed tag </readmore>