Unable to time command execution within C (popen)?

Question

I've been trying to time how long it takes for an invocation of popen to complete. popen initializes a process which then creates a pipe, forks, and invokes the shell. In my particular case, I'm using the call to read another programs stdout output.

The problem: I'm expecting the call I make to return the correct length of time it took the program to execute (around 15 seconds for a test program). What I get is that the program took no time at all to finish (0.000223s). Despite all the various functions I have tried, I seem unable to time the call correctly.

Here is a reproducible example of my problem. It is composed of the timing program and a child program that the timing program runs (the child takes about 15s to run on my system):

#include <stdio.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>
#ifdef __MACH__
#include <mach/clock.h>
#include <mach/mach.h>
#endif

#define MAXBUF 10

static void gettime (struct timespec *t) {
#ifdef __MACH__
    clock_serv_t cclock;
    mach_timespec_t mts;
    host_get_clock_service(mach_host_self(), REALTIME_CLOCK, &cclock);
    clock_get_time(cclock, &mts);
    mach_port_deallocate(mach_task_self(), cclock);
    t->tv_sec = mts.tv_sec;
    t->tv_nsec = mts.tv_nsec;
#else
    clock_gettime(CLOCK_REALTIME, t);
#endif
}

int main (void) {
    FILE *fp;
    struct timespec tic, toc;
    char *executableName = "./a.out";
    char answer[MAXBUF];

    gettime(&tic);
    if ((fp = popen(executableName, "r")) == NULL) {
        fprintf(stderr, "The file couldn't be opened.\n");
        return 1;
    }
    gettime(&toc);

    fgets(answer, MAXBUF, fp);
    double elapsed = (double)(toc.tv_nsec - tic.tv_nsec) / 1E9;
    fprintf(stdout, "The program says %s, and took %fs to run!\n", answer, elapsed);

    pclose(fp);
    return 0;
}

Here is the child program:

#include <stdio.h>
#include <stdlib.h>

int timeWastingFunction (long long n) {
    if ((n % 2) == 0) {
        return 1;
    }
    for (int i = 1; i < (n / 2); i += 2) {
        if ((n % i) == 0) {
            return 1;
        }
    }
    return 0;
}

int main (void) {
    int start = 687217000;

    while (start--) {
        timeWastingFunction(start);
    }
    fprintf(stdout, "Hello!");
    return 0;
}

This might look a bit overdone, but I had previously tried using clock_t, (a CPU based timing facility) to do the timing, and gotten the same answers from it. I therefore tried this solution which you see above. I picked: CLOCK_REALTIME as it seemed appropriate for the job. I unfortunately don't have the option to specify if this clock is on a per-process or per-thread level though (I'd want it to be process independent).

Note: I haven't tried using gettimeofday yet, but I don't want to since its apparently inappropriate for timing this way, dependent on the date of the system using it, and being phased out in favor of clock_gettime.

Edit: Just to be clear, what happens when I run this is that the program calling popen will actually stall for the 15 seconds the other program takes to run, before printing the 'wrong' time. It doesn't immediately print the time implying it didn't wait for the call to complete.

Your use of `clock_gettime` is correct [and preferred over `gettimeofday`]. Your problem is that `popen` returns [almost] immediately. It does _not_ wait for the target process to complete. Try: `gettime(&tic); popen(); ... ; pclose(); gettime(&toc);` — Craig Estey, Jun 22 '17 at 20:16
@CraigEstey Thanks! If I want to use the file I opened though, does this require I re-open (run in this case) after timing it? Or is there a way to use it without the overhead of re-opening and not poison the timing? — Micrified, Jun 22 '17 at 20:34
Note that macOS Sierra (10.12.x) does in fact support `clock_gettime()` now. However, if you compile code on Sierra to run on older systems, you can't afford to use it still (and it isn't available if you compile on older versions of Mac OS X so porting forward to Sierra can't (easily) use it). — Jonathan Leffler, Jun 22 '17 at 21:19
@JonathanLeffler I'm unfortunately running El-Capitan still, but it seems my improper use of timing with `popen` was the source of this, not the timing method. Thanks for letting me know about Sierra though! — Micrified, Jun 22 '17 at 21:26

score 3 · Accepted Answer · edited Jun 20 '20 at 09:12

popen() only fork and open a pipe. Your test only show the time that take popen() to create the child and the pipe.

A simple way to solve your problem is to get the time after your pclose(), note that will be not perfect because when you read the data return by your child, it could finish before your call to pclose()

Plus your solution to get the result is broken, you only make the difference between nanosecond, I found a solution on git:

void timespec_diff(struct timespec *start, struct timespec *stop,
                   struct timespec *result)
{
    if ((stop->tv_nsec - start->tv_nsec) < 0) {
        result->tv_sec = stop->tv_sec - start->tv_sec - 1;
        result->tv_nsec = stop->tv_nsec - start->tv_nsec + 1000000000;
    } else {
        result->tv_sec = stop->tv_sec - start->tv_sec;
        result->tv_nsec = stop->tv_nsec - start->tv_nsec;
    }

    return;
}

The last thing is that CLOCK_REALTIME should be used if you want the date. Here you just want a duration. So you should use CLOCK_MONOTONIC if it's available on your system because CLOCK_REALTIME can rollback. (REALTIME_CLOCK of host_get_clock_service() seam monotonic too).

CLOCK_MONOTONIC: Clock that cannot be set and represents monotonic time since some unspecified starting point.

REALTIME_CLOCK: A moderate resolution clock service that (typically) tracks time since the system last boot.

So the working code could look like that:

int main (void) {
    FILE *fp;
    struct timespec tic, toc;
    char *executableName = "./a.out";
    char answer[MAXBUF];

    gettime(&tic);
    if ((fp = popen(executableName, "r")) == NULL) {
        fprintf(stderr, "The file couldn't be opened.\n");
        return 1;
    }

    fgets(answer, MAXBUF, fp);

    pclose(fp);
    gettime(&toc);
    struct timespec result;
    timespec_diff(&tic, &toc, &result);
    fprintf(stdout, "The program says %s, and took %lld.%.9lds\n", answer, (long long)result.tv_sec, result.tv_nsec);

    return 0;
}

Credit:

Unable to time command execution within C (popen)?

1 Answers1