I trying to write a programm which benchmarks pipes (linux - IPC). Here is what i've got so far.
#include <unistd.h>
#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>
#include <err.h>
#include <errno.h>
#include <limits.h>
#include <stdint.h>
#include <string.h>
#include <sys/types.h>
#ifndef MEASUREMENTS
# define MEASUREMENTS (100*1000)
#endif
#define ERROR(s,e) do { \
fprintf (stderr, "ERROR: %s (strerror of %d:%s)\n", \
(s), (e), strerror((e))); \
exit (e); \
} while(0)
#if defined(__cplusplus)
extern "C" {
#endif
inline static unsigned long long int getrdtsc(void) __attribute__((always_inline));
inline static unsigned long long int getrdtsc(void)
{
uint64_t x;
#if defined (__i386__)
__asm__ volatile ("rdtsc\n" : "=A" (x));
#else
uint32_t hi, lo;
__asm__ volatile ("rdtsc\n" : "=a" (lo), "=d" (hi));
x = ((uint64_t)hi << 32 | lo);
#endif
return x;
}
#if defined(__cplusplus)
} /* extern "C" */
#endif
int main(int argc, char *argv[])
{
int pipefd[2] = {0};
int *ticks;
const int sizes[] = {128, 256, 512, 1024, 2048, 4096, 8192, 16384, 32768, 65536, 131072, 262144, 524288};
const int sizes_num = sizeof(sizes) / sizeof(sizes[0]);
#define MAX_SIZE sizes[sizes_num - 1]
#define SLEEP_TIME 1
pid_t pid;
pid_t pid_child;
char *buff;
int ret;
ret = pipe(pipefd);
if (ret == -1)
{
ERROR("pipe", errno);
}
pid = getpid();
ret = pid_child = fork();
if( -1 == ret)
{
ERROR("fork", errno);
}
if (0 == ret)
{
// **CHILD**
buff = malloc(MAX_SIZE);
if (buff == NULL)
{
ERROR("malloc", ENOMEM);
}
ret = read(pipefd[0], buff, MAX_SIZE);
exit(EXIT_SUCCESS);
}
else
{
buff = malloc(MAX_SIZE);
if (buff == NULL)
{
ERROR("malloc", errno);
}
ticks = malloc(MEASUREMENTS * sizeof(int));
if (ticks == NULL)
{
ERROR("malloc", errno);
}
memset(ticks, 0, MEASUREMENTS * sizeof(int));
for (int i = 0; i < sizes_num; i++)
{
int current_size = sizes[i];
int j;
int min_ticks;
int max_ticks;
long long ticks_all;
struct timeval tv_start;
struct timeval tv_stop;
double time_delta_sec;
sleep(SLEEP_TIME);
gettimeofday(&tv_start, NULL);
for (j = 0; j < MEASUREMENTS; j++)
{
unsigned long long start;
unsigned long long stop;
start = getrdtsc();
ret = write(pipefd[1], buff, current_size);
stop = getrdtsc();
if (ret != current_size)
{
ERROR("write", errno);
}
ticks[j] = stop - start;
}
gettimeofday(&tv_stop, NULL);
min_ticks = INT_MAX;
max_ticks = INT_MIN;
ticks_all = 0;
for (j = 0; j < MEASUREMENTS; j++)
{
if (min_ticks > ticks[j])
min_ticks = ticks[j];
if (max_ticks < ticks[j])
max_ticks = ticks[j];
ticks_all += ticks[j];
}
ticks_all -= min_ticks;
ticks_all -= max_ticks;
time_delta_sec = ((tv_stop.tv_sec - tv_start.tv_sec) + ((tv_stop.tv_usec - tv_start.tv_usec) / (1000.0 * 1000.0)));
printf("PID:%d time: min:%d max:%d Ticks Avg without min/max:%f Ticks (for %d measurements) for %d Bytes (%.2f MB/s)\n\n",
pid, min_ticks, max_ticks,
(double)ticks_all / (MEASUREMENTS - 2.0), MEASUREMENTS, current_size,
((double)current_size * MEASUREMENTS) / (1024.0 * 1024.0 * time_delta_sec));
}
}
}
compiled with gcc -std=gnu99 -Wall -O2 -DMEASUREMENTS=5 -o bench_pipe bench_pipe.c
Depending on MEASUREMENTS it get's stuck at different positions for example with MEASURMENTS=5 I get the following output.
PID:51601 time: min:85680 max:268201 Ticks Avg without min/max:87360.000000 Ticks (for 5 measurements) for 128 Bytes (2.46 MB/s)
PID:51601 time: min:39600 max:93960 Ticks Avg without min/max:43080.333333 Ticks (for 5 measurements) for 256 Bytes (9.92 MB/s)
PID:51601 time: min:39960 max:53281 Ticks Avg without min/max:40200.000000 Ticks (for 5 measurements) for 512 Bytes (27.43 MB/s)
PID:51601 time: min:45360 max:86041 Ticks Avg without min/max:47760.000000 Ticks (for 5 measurements) for 1024 Bytes (44.39 MB/s)
PID:51601 time: min:50040 max:75960 Ticks Avg without min/max:57720.000000 Ticks (for 5 measurements) for 2048 Bytes (79.40 MB/s)
PID:51601 time: min:41400 max:87120 Ticks Avg without min/max:43200.000000 Ticks (for 5 measurements) for 4096 Bytes (193.38 MB/s)
^C
At the end I have to abort it with CTRL+C.
With strace this is what I get
...
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fff0073e140) = 0
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096
write(1, "PID:51808 time: min:608402 max:1"..., 135PID:51808 time: min:608402 max:1023483 Ticks Avg without min/max:670201.666667 Ticks (for 5 measurements) for 4096 Bytes (18.69 MB/s)
) = 135
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=1, tv_nsec=0}, 0x7fff0073e140) = 0
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192) = 8192
write(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 8192^C) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
strace: Process 51808 detached
I am probably making a major mistake. Unfortunately I am still too unexperienced in this topic to find out where the error is. Please be patient if the error is obvious.
OK, this should go as a comment, BUT the code has some more flaws.
This answer: What happens if a child process won't close the pipe from writing, while reading?, gives an explanation why you see a hang.
Some more notes follow. You call read only once, but you do much writes. The read syscall may have coalesce some data, but it will return and, reading process will finish. Your writing loop could be executed no more than several times.
Note that a write to a pipe has system limit, in bytes. The code suggests that all data will be written in one piece. For the large buffers, > 4096, you need to do more writes. Same goes for read.
Your program logic is wrong. The title goes with "IPC", but you measure some time spent to copy data to the kernel(or maybe even user space) memory, that will be read later, at some point in time. Typically, you measure time spent by write function.