in reply to Time::HiRes strange behavior

When you write to the pipe, the other program won't get anything until the pipe's buffer (4096 bytes) fills.

Many of your slow, short line inputs will be read into a buffer as a single unit, and will then be timestamped as they are read (as lines) from the buffer. Since reading lines from a buffer is very fast, the timestamps will be very close together for each buffer load of lines.

The effect is that the perl script gets bursts of input all very close together, but then a long gap until the buffer fills again. To demonstrate this, I fed a file with timestamps once a second lke this: 

perl -MTime::HiRes=time -E"$|++;say scalar localtime while sleep 1" 
    | tee junk.log
Fri Feb  5 22:42:58 2010
Fri Feb  5 22:42:59 2010
Fri Feb  5 22:43:00 2010
Fri Feb  5 22:43:01 2010
Fri Feb  5 22:43:02 2010
...

[download]

And then tailed the file and added a second hires timestamp like this: 

tail -f junk.log 
   |perl -MTime::HiRes=gettimeofday -E"$|++;say gettimeofday().' '.$_ 
+while <>"
1265410130.569 Fri Feb  5 22:46:07 2010
1265410130.56927 Fri Feb  5 22:46:08 2010
1265410130.5694 Fri Feb  5 22:46:09 2010
1265410130.5695 Fri Feb  5 22:46:10 2010
1265410130.56959 Fri Feb  5 22:46:11 2010
...
1265410131.50094 Fri Feb  5 22:48:46 2010
1265410131.50917 Fri Feb  5 22:48:47 2010
1265410131.51604 Fri Feb  5 22:48:48 2010
1265410131.52273 Fri Feb  5 22:48:49 2010 * End of first buffer full
1265410294.569 Fri Feb  5 22:48:50 2010 *** Start of second buffer ful
+l 163 seconds later
1265410322.694 Fri Feb  5 22:48:51 2010
1265410322.69411 Fri Feb  5 22:48:52 2010
1265410322.69423 Fri Feb  5 22:48:53 2010
1265410322.69432 Fri Feb  5 22:48:54 2010
1265410322.6944 Fri Feb  5 22:48:55 2010
...
1265410322.97337 Fri Feb  5 22:49:39 2010
1265410322.98039 Fri Feb  5 22:49:40 2010
1265410322.98775 Fri Feb  5 22:49:41 2010
1265410427.993 Fri Feb  5 22:49:42 2010
Terminating on signal SIGINT(2)
1265410427.998 Fri Feb  5 22:49:43 2010

[download]

As you can see, the data written to the file over a period of 3 minutes, actually arrives at the perl script in just a couple of seconds--but delayed by nearly 3 minutes. Then there's another 3 minute delay before another burst arrives in just a couple of seconds. It's all down to the buffering done by the pipe.

Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
"Science is about questioning the status quo. Questioning authority".
In the absence of evidence, opinion is indistinguishable from prejudice.
"I'd rather go naked than blow up my ass"

Replies are listed 'Best First'.
Re^2: Time::HiRes strange behavior
by rubasov (Friar) on Feb 06, 2010 at 15:26 UTC
    One more thought on this thread:
    It's all down to the buffering done by the pipe.
    As far as I know how pipes work this is not entirely correct.

    Consider a stripped down version of your pipeline: 

    perl -MTime::HiRes=gettimeofday -e '$|++; print gettimeofday() . "\n" 
+while sleep 1' |\
perl -MTime::HiRes=gettimeofday -e '$|++; print gettimeofday() . " " .
+ $_ while <>'

    [download]

    Using this stripped pipeline you won't see any serious buffering related delay. Here's the why: If the process at the write end writes any amount (less then the pipe buffer) to the pipe, then the process at the read end will be able to read it irrespectively the state of the pipe buffer. If you omit the commands with possibly buffered output in your pipeline, you won't get the buffer filling delay. I think the result you showed us is caused by your version of tee (or less likely tail), by using buffered output. (I cannot see the same results with the current GNU versions of tee and tail.)

    Of course the pipe buffer can cause delays: if the buffer is empty then the reads will block, if the buffer is full then the writes will block. But reads will not block just because the buffer is not full.

    So in my comprehension your delayed results are all down to output buffering but not to pipe buffering.

[reply]
[d/l]

      Indeed! You are correct. And it does seem to be tee that's doing the buffering.

      Examine what is said, not who speaks -- Silence betokens consent -- Love the truth but pardon error.
      "Science is about questioning the status quo. Questioning authority".
      In the absence of evidence, opinion is indistinguishable from prejudice.
[reply]
[d/l]

In Section Seekers of Perl Wisdom