diff --git a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.c b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.c index e5a07aef5..709b29c74 100644 --- a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.c +++ b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.c @@ -480,16 +480,22 @@ static int mq_event(void *ctx, void *data,unsigned long data_sz) time_t now = time(NULL);// 获取当前时间 struct tm *localTime = localtime(&now);// 将时间转换为本地时间结构 printf("\n\nTime: %02d:%02d:%02d\n",localTime->tm_hour, localTime->tm_min, localTime->tm_sec); - printf("-----------------------------------------------------------------------------------------------------------\n"); + printf("-----------------------------------------------------------------------------------------------------------------------\n"); const struct mq_events *e = data; + printf("Mqdes: %-8llu msg_len: %-8llu msg_prio: %-8llu\n",e->mqdes,e->msg_len,e->msg_prio); - printf("SND_PID: %-8lu SND_enter_time: %-16llu\n", - e->send_pid,e->send_enter_time); - printf("-----------------------------------------------------------------------------------------------------------\n"); + printf("SND_PID: %-8lu SND_enter_time: %-16llu SND_exit_time: %-16llu\n", + e->send_pid,e->send_enter_time,e->send_exit_time); printf("RCV_PID: %-8lu RCV_enter_time: %-16llu RCV_exit_time: %-16llu\n", e->rcv_pid,e->rcv_enter_time,e->rcv_exit_time); - printf("RCV_Delay: %-8.2fms\nDelay: %-8.2fms\n\n",(e->rcv_exit_time - e->rcv_enter_time)/1000000.0,e->delay/1000000.0); - + printf("-------------------------------------------------------------------------------\n"); + + printf("SND_Delay/ms: %-8.2f RCV_Delay/ms: %-8.2f Delay/ms: %-8.5f\n", + (e->send_exit_time - e->send_enter_time)/1000000.0, + (e->rcv_exit_time - e->rcv_enter_time)/1000000.0, + (e->rcv_exit_time - e->send_enter_time)/1000000.0); + printf("-----------------------------------------------------------------------------------------------------------------------\n\n"); + return 0; } diff --git a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.h b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.h index 4d09caabf..6812096ce 100644 --- a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.h +++ b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/cpu_watcher.h @@ -156,12 +156,8 @@ struct mq_events { u64 send_enter_time; u64 send_exit_time; - u64 send_delay; - u64 rcv_enter_time; u64 rcv_exit_time; - u64 rcv_delay; - u64 delay; }; struct send_events { int send_pid; diff --git a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/image/image_mq.png b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/image/image_mq.png new file mode 100644 index 000000000..1dae1df8f Binary files /dev/null and b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/image/image_mq.png differ diff --git a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/mq_delay.md b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/mq_delay.md new file mode 100644 index 000000000..cfcc1ba5b --- /dev/null +++ b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/docs/mq_delay.md @@ -0,0 +1,92 @@ +# mq_delay + +为了对进程间通过消息队列通信时，发送消息、接手消息以及处于等待状态所用时间进行监测，cpuwatcher工具增添mq_delay工具。 + +![image_mq](image/image_mq.png) + +以上是发送进程发送，接收进程接收的具体过程。本工具通过跟踪单个的消息块（struct msg_msg结构体）来监测发送时延、接收时延以及等待时延。 + +## 跟踪消息块过程： + +发送过程 + +* 用户程序将要发送的消息通过mq_send()函数或mq_timedsend()函数发送，mq_send/mq_timedsend函数调用mq_timedsend系统调用在内核实现具体的发送实现，此时将指向用户态消息缓冲区的指针u_msg_ptr传入内核态，此处我们第一次追踪到消息块。 +* 在mq_timedsend 系统调用中，会调用do_mq_timedsend()内核函数进行发送消息的操作，此处将u_msg_ptr指针作为传参传入do_mq_timedsend()函数； +* 在do_mq_timedsend()函数中，通过load_msg()函数将消息从用户空间加载到内核中，这里将u_msg_ptr指针作为传参； +* load_msg()函数中，通过copy_from_user()函数将u_msg_ptr指针指向的用户空间信息复制到分配的内核空间msg，并返回一个指向消息块所在内核空间的指针msg_ptr，此时我们便在内核中跟踪到了具体的消息块实体，后续操作都是围绕这个消息块指针展开的，包括接收程序也是对此指针进行copy_to_user操作； + +接受过程 + +* 用户程序通过mq_receive()或mq_timedreceive()函数，从消息队列中接收消息，mq_receive()或mq_timedreceive()函数调用mq_timedreceive系统调用在内核中实现具体的接收实现，此时将指向用户态缓冲区的指针u_msg_ptr传入内核，这里是我们本次跟踪最后一次遇到消息块。 +* mq_timedreceive系统调用通过do_mq_timedreceive()函数找到要接收的消息块，并将其传入u_msg_ptr所指向的用户空间 +* do_mq_timedreceive()函数如果等到要接收的消息块，会通过store_msg()函数将消息块（发送时msg_ptr所指向的消息块）存储至u_msg_ptr所指向的用户空间。所以此时，我们在接收消息的内核处理函数中追踪到了具体的消息块。 + +此处还可拓展一些功能： + +* 对于发送消息块时，是否上等待队列，等待了多久？ +* 对于接收消息块时，是否上等待队列，等待了多久？ +* 对于处于非阻塞状态的进程，是否可以识别到，并及时统计出来？ + +## 挂载点： + +发送过程： + +| 类型 | 名称 | +| --------- | -------------- | +| kprobe | do_mq_timesend | +| kprobe | load_msg | +| kretprobe | load_msg | +| kretprobe | do_mq_timesend | + +接收过程： + +| 类型 | 名称 | +| --------- | ----------------- | +| kprobe | do_mq_timereceive | +| kprobe | store_msg | +| kretprobe | store_msg | +| kretprobe | do_mq_timereceive | + +输出效果 + +```c +Time: 22:12:39 +----------------------------------------------------------------------------------------------------------------------- +Mqdes: 3 msg_len: 1152 msg_prio: 50 +SND_PID: 20945 SND_enter_time: 131725037824711 SND_exit_time: 131725037867085 +RCV_PID: 20984 RCV_enter_time: 131726555726321 RCV_exit_time: 131726555872719 +------------------------------------------------------------------------------- +SND_Delay/ms: 0.04 RCV_Delay/ms: 0.15 Delay/ms: 1518.04801 +----------------------------------------------------------------------------------------------------------------------- + + + +Time: 22:12:44 +----------------------------------------------------------------------------------------------------------------------- +Mqdes: 3 msg_len: 1152 msg_prio: 50 +SND_PID: 21007 SND_enter_time: 131730008219660 SND_exit_time: 131730008614901 +RCV_PID: 21035 RCV_enter_time: 131731465676396 RCV_exit_time: 131731465758821 +------------------------------------------------------------------------------- +SND_Delay/ms: 0.40 RCV_Delay/ms: 0.08 Delay/ms: 1457.53916 +----------------------------------------------------------------------------------------------------------------------- + + + +Time: 22:12:48 +----------------------------------------------------------------------------------------------------------------------- +Mqdes: 3 msg_len: 1152 msg_prio: 50 +SND_PID: 21069 SND_enter_time: 131733828139276 SND_exit_time: 131733828195905 +RCV_PID: 21098 RCV_enter_time: 131735705540405 RCV_exit_time: 131735705924036 +------------------------------------------------------------------------------- +SND_Delay/ms: 0.06 RCV_Delay/ms: 0.38 Delay/ms: 1877.78476 +----------------------------------------------------------------------------------------------------------------------- +``` + + + + + + + + + diff --git a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/mq_delay.bpf.c b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/mq_delay.bpf.c index 0284b1768..92589afd6 100644 --- a/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/mq_delay.bpf.c +++ b/eBPF_Supermarket/CPU_Subsystem/cpu_watcher/mq_delay.bpf.c @@ -14,7 +14,6 @@ // // author: albert_xuu@163.com - #include "vmlinux.h" #include //包含了BPF 辅助函数 #include @@ -116,9 +115,30 @@ int BPF_KRETPROBE(load_msg_exit,void *ret){ } /*已经获得key*/ bpf_map_update_elem(&send_msg2, &Key_msg_ptr, mq_send_info, BPF_ANY);//key_messege->mq_send_info; - bpf_map_delete_elem(&send_msg1,&pid); return 0; } + +SEC("kretprobe/do_mq_timedsend") +int BPF_KRETPROBE(do_mq_timedsend_exit,void *ret) +{ + bpf_printk("do_mq_timedsend_exit----------------------------------------------------------------\n"); + u64 send_exit_time = bpf_ktime_get_ns();//开始发送信息时间； + int pid = bpf_get_current_pid_tgid();//发送端pid + u64 Key; + + struct send_events *mq_send_info1 = bpf_map_lookup_elem(&send_msg1, &pid); + if(!mq_send_info1){ + return 0; + } + Key = mq_send_info1->Key_msg_ptr; + struct send_events *mq_send_info2 = bpf_map_lookup_elem(&send_msg2, &Key); + if(!mq_send_info2){ + return 0; + } + mq_send_info2->send_exit_time = send_exit_time; + bpf_map_delete_elem(&send_msg1,&pid); + return 0; +} /*-----------------------------------------------------------------------------发送端--------------------------------------------------------------------------------------------------------*/ /* 分界 */ /*-----------------------------------------------------------------------------接收端--------------------------------------------------------------------------------------------------------*/ @@ -188,9 +208,6 @@ int BPF_KRETPROBE(do_mq_timedreceive_exit,void *ret){ return 0; } - send_enter_time = mq_send_info->send_enter_time; - delay = rcv_exit_time - send_enter_time; - /*ringbuffer传值*/ struct mq_events *e; e = bpf_ringbuf_reserve(&rb, sizeof(*e), 0); @@ -202,10 +219,9 @@ int BPF_KRETPROBE(do_mq_timedreceive_exit,void *ret){ e->msg_prio = mq_send_info->msg_prio; e->send_enter_time = mq_send_info->send_enter_time; - + e->send_exit_time = mq_send_info->send_exit_time; e->rcv_enter_time = mq_rcv_info->rcv_enter_time; e->rcv_exit_time = rcv_exit_time; - e->delay = delay; bpf_ringbuf_submit(e, 0); bpf_map_delete_elem(&send_msg2, &Key);//暂时性删除 bpf_map_delete_elem(&rcv_msg1,&pid);//删除rcv_msg1 map;