3

I'm working on a library with a test suite that uses Perl open to run it's tests. It looks something like this:

open (MYOUT, "$myprog $arg1 $arg2 $arg3 2>&1 |") die "Bad stuff happened";

What I'd really like to do is to measure the runtime of $myprog. Unfortunately, just grabbing a start time and end time around the open command just grabs roughly how long it takes to start up the process.

Is there some way of either forcing the open command to finish the process (and therefore accurately measure time) or perhaps something else that would accomplish the same thing?

Key constraints are that we need to capture (potentially a lot of) STDOUT and STDERR.

Wesley Bland
  • 8,816
  • 3
  • 44
  • 59

1 Answers1

3

Since you open a pipe, you need to time from before opening to at least after the reading

use warnings;
use strict;
use Time::HiRes qw(gettimeofday tv_interval sleep);

my $t0 = [gettimeofday];

open my $read, '-|', qw(ls -l) or die "Can't open process: $!";

while (<$read>)
{
    sleep 0.1;
    print;
}

print "It took ", tv_interval($t0), " seconds\n";
# close pipe and check

or, to time the whole process, after calling close on the pipe (after all reading is done)

my $t0 = [gettimeofday];
open my $read, '-|', qw(ls -l)  or die "Can't open process: $!";
# ... while ($read) { ... }
close $read  or 
    warn $! ? "Error closing pipe: $!" : "Exit status: $?";
print "It took ", tv_interval($t0), " seconds\n";

The close blocks and waits for the program to finish

Closing a pipe also waits for the process executing on the pipe to exit--in case you wish to look at the output of the pipe afterwards--and implicitly puts the exit status value of that command into $? [...]

For the status check see $? variable in perlvar and system

If the timed program forks and doesn't wait on its children in a blocking way this won't time them correctly. In that case you need to identify resources that they use (files?) and monitor that.

I'd like to add that external commands should be put together carefully, to avoid shell injection trouble. A good module is String::ShellQuote. See for example this answer and this answer

Using a module for capturing streams would free you from the shell and perhaps open other ways to run and time this more reliably. A good one is Capture::Tiny (and there are others as well).

Thanks to HåkonHægland for comments. Thanks to ikegami for setting me straight, to use close (and not waitpid).

zdim
  • 64,580
  • 5
  • 52
  • 81
  • Alternatively, you could probably add another `fork()` as wrapper around the whole thing. Then runtime is found after `waitpid()` for that fork – Håkon Hægland Mar 28 '17 at 23:08
  • 1
    @HåkonHægland Yes, I am contemplating adding a note on doing it manually somehow. But that won't solve problems, I think. – zdim Mar 28 '17 at 23:10
  • Yes I was not thinking clearly.. an extra fork will not help I think..it needs to either read from the handle until EOF (as you show) or use `waitpid()` on the PID returned by `open` – Håkon Hægland Mar 28 '17 at 23:30
  • @HåkonHægland Right, I think now that there is no better way, updated accordingly. – zdim Mar 28 '17 at 23:56
  • Thanks. I had missed the `close(MYOUT)` further down in the script. I'll have some extra time in there because of the overhead of reading the output, but that's probably fine. – Wesley Bland Mar 29 '17 at 13:20
  • @WesleyBland You are welcome. There may be some overhead but I am not sure how much (in comparison to the program's outputting data to, say, files). If you need to time it down to only the necessary work perhaps run the program with redirection of its output to files? Writing data to files is a part of program's operation, so not overhead. Then you wouldn't need to open a pipe but could simply use `system` (or a module). – zdim Mar 29 '17 at 19:47
  • Wouldn't it be possible to create a new class, IO::WithTimer, that would store its start time in the object upon start, and report the time on destruction of the handle? – choroba Apr 03 '17 at 11:08
  • @choroba Right, that would be far nicer! It also provides framework for some conveniencies. With a few addtions it could be a nice module, like `IO::Stats` or some such. – zdim Apr 04 '17 at 19:21