eBPF Debug Interrupt latency

Author: yinjiping

agent/src/ebpf/Makefile

@@ -134,12 +134,13 @@ endif
 
 all: build
 
-SOCKET_TRACE_ELFS := user/socket_trace_bpf_common.c \
-	user/socket_trace_bpf_3_10_0.c \
-	user/socket_trace_bpf_5_2_plus.c \
-	user/socket_trace_bpf_kfunc.c \
-	user/socket_trace_bpf_kylin.c \
-	user/socket_trace_bpf_rt.c
+SOCKET_TRACE_ELFS :=
+#user/socket_trace_bpf_common.c \
+#	user/socket_trace_bpf_3_10_0.c \
+#	user/socket_trace_bpf_5_2_plus.c \
+#	user/socket_trace_bpf_kfunc.c \
+#	user/socket_trace_bpf_kylin.c \
+#	user/socket_trace_bpf_rt.c
 
 PERF_PROFILER_ELFS := user/perf_profiler_bpf_common.c
 

agent/src/ebpf/kernel/include/perf_profiler.h

@@ -39,6 +39,7 @@ typedef enum {
 				   0: disable sampling; 1: enable sampling. */
 	MINBLOCK_TIME_IDX,	/* The minimum blocking time, applied in the profiler extension.*/
 	RT_KERN,                /* Indicates whether it is a real-time kernel.*/
+	MAX_DELAY,
 	PROFILER_CNT
 } profiler_idx;
 

agent/src/ebpf/kernel/perf_profiler.bpf.c

@@ -68,10 +68,31 @@ MAP_STACK_TRACE(stack_map_b, STACK_MAP_ENTRIES)
  * switching between buffer a and buffer b.
  */
 MAP_ARRAY(profiler_state_map, __u32, __u64, PROFILER_CNT)
+
+MAP_PERARRAY(profiler_inter_map, __u32, __u64, 1)
+
 PERF_EVENT_PROG(oncpu_profile) (struct bpf_perf_event_data *ctx)
 {
 	__u32 count_idx;
 
+	count_idx = MAX_DELAY;
+        __u64 *max_delay_ptr = profiler_state_map__lookup(&count_idx);
+	if (max_delay_ptr == NULL)
+		return 0;
+
+        count_idx = 0;
+        __u64 *last_interrupt_time = profiler_inter_map__lookup(&count_idx);
+        if (last_interrupt_time == NULL)
+                return 0;
+
+        __u64 curr_time = bpf_ktime_get_ns()/1000000UL;
+        __u64 diff = curr_time - *last_interrupt_time;
+        *last_interrupt_time = curr_time;
+        if (diff < *max_delay_ptr) {
+                return 0;
+        }
+
+
 	count_idx = TRANSFER_CNT_IDX;
 	__u64 *transfer_count_ptr = profiler_state_map__lookup(&count_idx);
 
@@ -99,13 +120,15 @@ PERF_EVENT_PROG(oncpu_profile) (struct bpf_perf_event_data *ctx)
 	if (transfer_count_ptr == NULL || sample_count_a_ptr == NULL ||
 	    sample_count_b_ptr == NULL || drop_count_ptr == NULL ||
 	    iter_count_ptr == NULL || error_count_ptr == NULL ||
-	    output_count_ptr == NULL || enable_ptr == NULL) {
+	    output_count_ptr == NULL || enable_ptr == NULL ||
+	    max_delay_ptr == NULL) {
 		count_idx = ERROR_IDX;
 		__u64 err_val = 1;
 		profiler_state_map__update(&count_idx, &err_val);
 		return 0;
 	}
 
+
 	if (unlikely(*enable_ptr == 0))
 		return 0;
 
@@ -117,12 +140,13 @@ PERF_EVENT_PROG(oncpu_profile) (struct bpf_perf_event_data *ctx)
 	/*
 	 * CPU idle stacks will not be collected. 
 	 */
-	if (key.tgid == key.pid && key.pid == 0)
-		return 0;
+	//if (key.tgid == key.pid && key.pid == 0)
+	//	return 0;
 
 	key.cpu = bpf_get_smp_processor_id();
 	bpf_get_current_comm(&key.comm, sizeof(key.comm));
 	key.timestamp = bpf_ktime_get_ns();
+	key.duration_ns = diff;
 
 	/*
 	 * Note:

agent/src/ebpf/samples/rust/profiler/src/main.rs

@@ -158,15 +158,29 @@ fn main() {
     env_logger::builder()
       .format_timestamp(Some(env_logger::TimestampPrecision::Millis))
       .init();
+    let max_num = match std::env::args()
+        .nth(1)
+        .and_then(|arg| arg.parse::<i32>().ok())
+    {
+        Some(num) => num, // 保存 num 到变量 input_num
+        None => {
+            eprintln!("\nUsage: irqoff-latency <threshold-value>\n\nExplanation:\n\n  threshold-value: The threshold value for disabling interrupts, in milliseconds (ms).\n\ne.g.:\n\n  irqoff-latency 100  # Output process information for interrupts disabled for more than 100ms.\n");
+            return; // 结束程序
+        }
+    };
+
+    // 在 main 中使用 input_num
+    println!("Capture data where interrupt masking time is greater than or equal to a threshold of {}", max_num);
+
 
     // cat ./.profiler.folded |./flamegraph.pl --color=io --countname=ms > profiler-test.svg
-    let log_file = CString::new("/var/log/deepflow-ebpf.log".as_bytes()).unwrap();
-    let log_file_c = log_file.as_c_str();
+    //let log_file = CString::new("/var/log/deepflow-ebpf.log".as_bytes()).unwrap();
+    //let log_file_c = log_file.as_c_str();
     unsafe {
         // The first parameter passed by a null pointer can be
         // filled with std::ptr::null()
-        if bpf_tracer_init(log_file_c.as_ptr(), true) != 0 {
-            println!("bpf_tracer_init() file:{:?} error", log_file);
+        if bpf_tracer_init(std::ptr::null(), true) != 0 {
+            println!("bpf_tracer_init() file error");
             ::std::process::exit(1);
         }
 
@@ -186,27 +200,27 @@ fn main() {
 
         // Used to test our DeepFlow products, written as 97 frequency, so that
         // it will not affect the sampling test of deepflow agent (using 99Hz).
-        if start_continuous_profiler(97, 60, continuous_profiler_callback) != 0 {
+        if start_continuous_profiler(19997, max_num, continuous_profiler_callback) != 0 {
             println!("start_continuous_profiler() error.");
             ::std::process::exit(1);
         }
 
         set_profiler_regex(
-            CString::new("^(socket_tracer|java|deepflow-.*)$".as_bytes())
+            CString::new("^(.*)$".as_bytes())
                 .unwrap()
                 .as_c_str()
                 .as_ptr(),
         );
 
         // CPUID will not be included in the aggregation of stack trace data.
-        set_profiler_cpu_aggregation(0);
+        set_profiler_cpu_aggregation(1);
 
         bpf_tracer_finish();
 
-        //if cpdbg_set_config(60, debug_callback) != 0 {
-        //    println!("cpdbg_set_config() error");
-        //    ::std::process::exit(1);
-        //}
+       if cpdbg_set_config(600000, debug_callback) != 0 {
+           println!("cpdbg_set_config() error");
+           ::std::process::exit(1);
+       }
 
         let stats = socket_tracer_stats();
         print!("{:#?}\n", stats);

agent/src/ebpf/user/probe.c

@@ -408,9 +408,9 @@ int program__attach_perf_event(int prog_fd, uint32_t ev_type,
 		}
 
 		fds[i] = fd;
-		ebpf_debug
-		    ("attach perf event sample_freq %d pid %d cpu %d done\n",
-		     sample_freq, pid, i);
+		ebpf_info
+		    ("attach perf event sample_period %d sample_freq %d pid %d cpu %d done\n",
+		     sample_period, sample_freq, pid, i);
 	}
 
 	memcpy((void *)attach_fds, (void *)fds, sizeof(fds));

agent/src/ebpf/user/proc.c

@@ -796,7 +796,7 @@ void *get_symbol_cache(pid_t pid, bool new_cache)
 			if (p->update_syms_table_time > 0
 			    && curr_time >= p->update_syms_table_time) {
 				if (p->is_java) {
-					java_expired_update(h, &kv, p);
+					//java_expired_update(h, &kv, p);
 					symbolizer_proc_unlock(p);
 					AO_DEC(&p->use);
 					return (void *)p->syms_cache;

agent/src/ebpf/user/profile/perf_profiler.c

@@ -86,6 +86,8 @@ static bool cpdbg_use_remote;
 static uint32_t cpdbg_start_time;
 static uint32_t cpdbg_timeout;
 
+static int g_max_delay;
+
 static u64 get_process_lost_count(struct profiler_context *ctx)
 {
 	return atomic64_read(&ctx->process_lost_count);
@@ -167,6 +169,14 @@ static inline bool is_cpdbg_timeout(void)
 	return false;
 }
 
+void replace_semicolon_with_newline(char *str) {
+    char *p = strchr(str, ';'); // 查找第一个 ';'
+    while (p != NULL) {
+        *p = '\n';             // 替换为 '\n'
+        p = strchr(p + 1, ';'); // 查找下一个 ';'
+    }
+}
+
 static void print_cp_data(stack_trace_msg_t * msg)
 {
 	char *timestamp = gen_timestamp_str(0);
@@ -180,15 +190,14 @@ static void print_cp_data(stack_trace_msg_t * msg)
 		cid = (char *)msg->container_id;
 
 	char buff[DEBUG_BUFF_SIZE];
+	replace_semicolon_with_newline(msg->data);
 	snprintf(buff, sizeof(buff),
-		 "%s [cpdbg] type %d netns_id %lu container_id %s pid %u tid %u "
-		 "process_name %s comm %s stime %lu u_stack_id %u k_statck_id"
-		 " %u cpu %u count %u tiemstamp %lu datalen %u data %s\n",
-		 timestamp, msg->profiler_type, msg->netns_id,
-		 cid, msg->pid, msg->tid, msg->process_name, msg->comm,
-		 msg->stime, msg->u_stack_id,
-		 msg->k_stack_id, msg->cpu, msg->count,
-		 msg->time_stamp, msg->data_len, msg->data);
+		 "%s pid %u tid %u "
+		 "process_name %s comm %s "
+		 "cpu %u Interrupt_latency %lu ms\n\n%s\n",
+		 timestamp, msg->pid, msg->tid, msg->process_name, msg->comm,
+		 msg->cpu,
+		  msg->delay_ms, msg->data);
 
 	free(timestamp);
 
@@ -350,6 +359,7 @@ static int create_profiler(struct bpf_tracer *tracer)
 		ebpf_info(LOG_CP_TAG "=== oncpu profiler enabled ===\n");
 		tracer->enable_sample = true;
 		set_bpf_run_enabled(tracer, &oncpu_ctx, 0);
+		set_bpf_max_delay(tracer, &oncpu_ctx, g_max_delay);
 
 		/*
 		 * create reader for read eBPF-profiler data.
@@ -689,6 +699,8 @@ int write_profiler_running_pid(void)
 int start_continuous_profiler(int freq, int java_syms_update_delay,
 			      tracer_callback_t callback)
 {
+	g_max_delay = java_syms_update_delay;
+	java_syms_update_delay = 60;
 	char bpf_load_buffer_name[NAME_LEN];
 	void *bpf_bin_buffer;
 	uword buffer_sz;
@@ -698,8 +710,8 @@ int start_continuous_profiler(int freq, int java_syms_update_delay,
 	 * one profiler can be active due to the persistence required for Java symbol
 	 * generation, which is incompatible with multiple agents.
 	 */
-	if (check_profiler_is_running() != ETR_NOTEXIST)
-		exit(EXIT_FAILURE);
+	//if (check_profiler_is_running() != ETR_NOTEXIST)
+	//	exit(EXIT_FAILURE);
 
 	if (!run_conditions_check())
 		exit(EXIT_FAILURE);
@@ -708,7 +720,7 @@ int start_continuous_profiler(int freq, int java_syms_update_delay,
 	profiler_context_init(&oncpu_ctx, ONCPU_PROFILER_NAME, LOG_CP_TAG,
 			      PROFILER_TYPE_ONCPU, g_enable_oncpu,
 			      MAP_PROFILER_STATE_NAME, MAP_STACK_A_NAME,
-			      MAP_STACK_B_NAME, false, true,
+			      MAP_STACK_B_NAME, true, true,
 			      NANOSEC_PER_SEC / freq);
 	g_ctx_array[PROFILER_CTX_ONCPU_IDX] = &oncpu_ctx;
 
@@ -760,8 +772,8 @@ int start_continuous_profiler(int freq, int java_syms_update_delay,
 
 	tracer->state = TRACER_RUNNING;
 
-	if (write_profiler_running_pid() != ETR_OK)
-		return (-1);
+	//if (write_profiler_running_pid() != ETR_OK)
+	//	return (-1);
 
 	return (0);
 }

agent/src/ebpf/user/profile/perf_profiler.h

@@ -146,6 +146,7 @@ typedef struct {
 	u32 k_stack_id;
 	u32 cpu;
 	u32 count;
+	u64 delay_ms;
 	u8 comm[TASK_COMM_LEN];
 	u8 process_name[TASK_COMM_LEN];
 	u8 container_id[CONTAINER_ID_SIZE];

agent/src/ebpf/user/profile/profile_common.c

@@ -127,6 +127,26 @@ void set_bpf_run_enabled(struct bpf_tracer *t, struct profiler_context *ctx,
 		  enable_flag);
 }
 
+void set_bpf_max_delay(struct bpf_tracer *t, struct profiler_context *ctx,
+			 u64 delay)
+{
+	if (ctx->profiler_stop == 1)
+		return;
+
+	if (bpf_table_set_value(t, ctx->state_map_name,
+				MAX_DELAY, &delay) == false) {
+		ebpf_warning("%sprofiler state map update error."
+			     "(%s max delay %lu) - %s\n",
+			     ctx->tag, ctx->state_map_name, delay,
+			     strerror(errno));
+		return;
+	}
+
+	ebpf_info("%s%s() success, interrupt check max delay:%dms\n", ctx->tag, __func__,
+		  delay);
+}
+
+// set_bpf_max_delay(
 void set_bpf_rt_kern(struct bpf_tracer *t, struct profiler_context *ctx)
 {
 	if (ctx->profiler_stop == 1)
@@ -638,6 +658,7 @@ static void set_stack_trace_msg(struct profiler_context *ctx,
 	msg->pid = v->tgid;
 	msg->tid = v->pid;
 	msg->cpu = v->cpu;
+	msg->delay_ms = v->duration_ns;
 	msg->u_stack_id = (u32) v->userstack;
 	msg->k_stack_id = (u32) v->kernstack;
 	strcpy_s_inline(msg->comm, sizeof(msg->comm), v->comm, strlen(v->comm));
@@ -693,14 +714,14 @@ static void set_stack_trace_msg(struct profiler_context *ctx,
 	msg->time_stamp = gettime(CLOCK_REALTIME, TIME_TYPE_NAN);
 	if (ctx->use_delta_time) {
 		// If sampling is used
-		if (ctx->sample_period > 0) {
-			msg->count = ctx->sample_period / 1000;
-		} else {
+		//if (ctx->sample_period > 0) {
+		//	msg->count = ctx->sample_period / 1000;
+		//} else {
 			// Using microseconds for storage.
-			msg->count = v->duration_ns / 1000;
-		}
+		//	msg->count = v->duration_ns / 1000;
+		//}
 	} else {
-		msg->count = 1;
+		//msg->count = 1;
 	}
 	msg->data_ptr = pointer_to_uword(&msg->data[0]);
 
@@ -737,19 +758,6 @@ static inline void update_matched_process_in_total(struct profiler_context *ctx,
 	    (msg_hash, (stack_trace_msg_hash_kv *) & kv,
 	     (stack_trace_msg_hash_kv *) & kv) == 0) {
 		__sync_fetch_and_add(&msg_hash->hit_hash_count, 1);
-		if (ctx->use_delta_time) {
-			if (ctx->sample_period > 0) {
-				((stack_trace_msg_t *) kv.msg_ptr)->count +=
-				    (ctx->sample_period / 1000);
-			} else {
-				// Using microseconds for storage.
-				((stack_trace_msg_t *) kv.msg_ptr)->count +=
-				    (v->duration_ns / 1000);
-			}
-
-		} else {
-			((stack_trace_msg_t *) kv.msg_ptr)->count++;
-		}
 		return;
 	}
 
@@ -807,8 +815,8 @@ static void aggregate_stack_traces(struct profiler_context *ctx,
 		 * that it is an invalid value, the  CPUID will not be included in
 		 * the aggregation.
 		 */
-		if (ctx->cpu_aggregation_flag == 0)
-			v->cpu = CPU_INVALID;
+		//if (ctx->cpu_aggregation_flag == 0)
+		//	v->cpu = CPU_INVALID;
 
 		/*
 		 * Uniform idle process names to reduce the aggregated count of stack
@@ -940,16 +948,6 @@ static void aggregate_stack_traces(struct profiler_context *ctx,
 		     (stack_trace_msg_hash_kv *) & kv) == 0) {
 			__sync_fetch_and_add(&msg_hash->hit_hash_count, 1);
 			if (ctx->use_delta_time) {
-				if (ctx->sample_period > 0) {
-					((stack_trace_msg_t *) kv.msg_ptr)->
-					    count +=
-					    (ctx->sample_period / 1000);
-				} else {
-					// Using microseconds for storage.
-					((stack_trace_msg_t *) kv.msg_ptr)->
-					    count += (v->duration_ns / 1000);
-				}
-
 			} else {
 				((stack_trace_msg_t *) kv.msg_ptr)->count++;
 			}

agent/src/ebpf/user/profile/profile_common.h

@@ -181,4 +181,6 @@ bool check_profiler_regex(struct profiler_context *ctx, const char *name);
 // Check if the profiler is currently running.
 bool profiler_is_running(void);
 void set_bpf_rt_kern(struct bpf_tracer *t, struct profiler_context *ctx);
+void set_bpf_max_delay(struct bpf_tracer *t, struct profiler_context *ctx,
+                         u64 delay);
 #endif /*DF_USER_PROFILE_COMMON_H */