Merge pull request #740 from albertxu216/develop

Cpuwatcher：分别增加发送和接收过程的时延监测

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;
 }
 

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;

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
+-----------------------------------------------------------------------------------------------------------------------
+```
+
+
+
+
+
+
+
+
+

eBPF_Supermarket/CPU_Subsystem/cpu_watcher/mq_delay.bpf.c

@@ -14,7 +14,6 @@
 //
 // author: [email protected]
 
-
 #include "vmlinux.h"
 #include <bpf/bpf_helpers.h>		//包含了BPF 辅助函数
 #include <bpf/bpf_tracing.h>
@@ -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;