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 |