kernel tracepoint hook takes less time to run if the syscall occurred more frequently

Viewed 57

I wrote a kernel module to hook system calls using raw_tracepoint. To measure the time consumption of the tracepoint handler, I wrote a userland program to generate syscalls and use printk() in the kernel module to output the time consumption:

// userland program
#include <stdio.h>
#include <fcntl.h>
#include <errno.h>
extern int errno;
int main()
{
    while (1) {
        int f = open("foo.txt", O_RDONLY | O_CREAT);
        close(f);
        //usleep(1000000);
        //usleep(100000);
        usleep(1);
        //usleep(10);
        //usleep(100);
        //usleep(10000);
        //usleep(1000);
    }
}

Turns out that the time consumption of the tracepoint handler is related to the calling frequency of the corresponding system calls. As the sleep time grows, the tracepoint handler takes more time to run.

The following is the sleep time and corresponding time-consuming of the tracepoint handler (tp90):data graph. Why does this happen?

usleep-time(us) tracepoint-handler-time-consuming(us)
0 0.254
0.1 0.559
1 0.573
10 0.593
50 0.717
100 0.751
300 0.994
500 1.185
1000 1.206
1500 1.211
2000 1.306
3000 1.52
4000 1.656
5000 2.142
6500 2.696
8000 2.546
10000 3.297
1000000 3.625
0 Answers
Related