It doesn't measure wall clock time, only on-CPU time and some off-CPU time

[akneni]

When profiling the following program,

// Compiled with `gcc -g -O0 -o main main.c`
#include <stdio.h>
#include <stdint.h>
#include <stdlib.h>
#include <time.h>
#include <assert.h>

int main() {
    time_t s = clock();

    uint64_t size_buf = 1000000000;
    uint8_t* buf = malloc(size_buf);
    FILE* fp = fopen("target.bin", "r");

    uint64_t bytes_read = fread(buf, 1, size_buf, fp);
    assert(bytes_read == 1000000000);
    fclose(fp);

    time_t e = clock();
    printf("Time Elapsed %f\n", (double)(e-s) / CLOCKS_PER_SEC);

    return 0;
}

I get the following output,

./wallClockProfiler 99 ./main && cat wcOut.txt

Forked GDB child on PID=3970965
Logging GDB commands and responses to wcGDBLog.txt


Starting gdb program with 'run  > wcOut.txt', redirecting program output to wcOut.txt
Debugging program './main'
PID of debugged process = 3970970
Sampling stack while program runs...
Sampling 99.00 times per second, for 10101 usec between samples
Program exited normally
2 stack samples taken
2 unique stacks sampled



Report:




Functions with more than one sample:

150.000% ===================================== (3 samples)
         ??





Full stacks with at least one sample:

 50.000% ===================================== (1 samples)
         1: __GI__dl_debug_state   (at dl-debug.c:73)
         2: dl_main   (at rtld.c:2540)
         3: _dl_sysdep_start   (at ../elf/dl-sysdep.c:256)
         4: _dl_start_final   (at rtld.c:490)
         5: _dl_start   (at rtld.c:583)
         6: _start   (at :-1)
         7: ??   (at :-1)
         8: ??   (at :-1)
         9: ??   (at :-1)


 50.000% ===================================== (1 samples)
         1: read   (at :-1)
         2: __GI__IO_file_xsgetn   (at :-1)
         3: fread   (at :-1)
         4: main   (at main.c:14)


Time Elapsed 0.901001

I am sampling every 99 seconds while reading a 1 GB file (which takes 900 ms to complete). So, there should be about 90 samples collected, and read() should the current top of the callstack for the vast majority of these samples. However, we only got two samples, and read() is only the top of the callstack for 50% of them. This tells me that it isn't sampling while your docs say that the profiler works while the process is blocked for (some) I/O, it does not work while the process is in an uninterruptible blocked state (this is consistent with the fact that GDB cannot pause a program thats in an uninterruptible blocked state, and your profiler seems to rely on GDB).

I believe network I/O, opening and closing sockets, pipes, and files (and also fseek I assume after seeing the results of your test in the readme) all put a process into a interruptible blocked state for which your profiler still works. However, reading and writing to disk put it into an uninterruptible blocked state, for which your profiler will not work.