From 0e45e3a774f41a63cbf48adc06de766bae4b3d3b Mon Sep 17 00:00:00 2001 From: Jiping Yin Date: Tue, 17 Oct 2023 11:06:58 +0800 Subject: [PATCH] [eBPF] Add profiler debugging function (#4497) (#4500) Debug eBPF on-cpu profiler, when the debug function is enabled, the profiler data is sent to the agent log. ``` Continuous profiler debug: profiler data output to agent log Usage: deepflow-ebpfctl cpdbg {on|off} [OPTIONS] Options: '-t, --timeout': set profiler debug timout. Unit: second For example: deepflow-ebpfctl cpdbg on --timeout 60 deepflow-ebpfctl cpdbg off ``` --- agent/src/ebpf/user/ctrl.h | 5 + agent/src/ebpf/user/ctrl_tracer.c | 100 ++++++++++++++-- agent/src/ebpf/user/profile/perf_profiler.c | 122 ++++++++++++++++++-- agent/src/ebpf/user/tracer.h | 9 +- 4 files changed, 211 insertions(+), 25 deletions(-) diff --git a/agent/src/ebpf/user/ctrl.h b/agent/src/ebpf/user/ctrl.h index f40955d5e89..d764022851a 100644 --- a/agent/src/ebpf/user/ctrl.h +++ b/agent/src/ebpf/user/ctrl.h @@ -85,6 +85,11 @@ struct datadump_msg { char comm[16]; }; +struct cpdbg_msg { + bool enable; // Whether to enable the datadump ? + int timeout; +}; + int sockopt_ctl(void *arg); int ctrl_init(void); int sockopt_register(struct tracer_sockopts *sockopts); diff --git a/agent/src/ebpf/user/ctrl_tracer.c b/agent/src/ebpf/user/ctrl_tracer.c index 8bb7a43c9a1..e52eab9a881 100644 --- a/agent/src/ebpf/user/ctrl_tracer.c +++ b/agent/src/ebpf/user/ctrl_tracer.c @@ -76,10 +76,27 @@ static void socktrace_help(void) fprintf(stderr, "Usage:\n" " %s tracer show\n", DF_BPF_NAME); } +static void cpdbg_help(void) +{ + fprintf(stderr, + "Continuous profiler debug: profiler data output to agent log\n"); + fprintf(stderr, "Usage:\n" " %s cpdbg {on|off} [OPTIONS]\n", + DF_BPF_NAME); + fprintf(stderr, "Options:\n"); + fprintf(stderr, + " '-t, --timeout': set profiler debug timout. Unit: second\n"); + fprintf(stderr, "For example:\n"); + fprintf(stderr, " %s cpdbg on --timeout 60\n", DF_BPF_NAME); + fprintf(stderr, " %s cpdbg off\n", DF_BPF_NAME); +} + static void datadump_help(void) { - fprintf(stderr, "Usage:\n" " %s datadump {on|off} [OPTIONS]\n", DF_BPF_NAME); - fprintf(stderr, " %s datadump set pid PID comm COMM proto PROTO_NUM\n", DF_BPF_NAME); + fprintf(stderr, "Usage:\n" " %s datadump {on|off} [OPTIONS]\n", + DF_BPF_NAME); + fprintf(stderr, + " %s datadump set pid PID comm COMM proto PROTO_NUM\n", + DF_BPF_NAME); fprintf(stderr, "PROTO_NUM:\n"); fprintf(stderr, " 0: PROTO_ALL\n"); fprintf(stderr, " 1: PROTO_ORTHER\n"); @@ -98,16 +115,20 @@ static void datadump_help(void) fprintf(stderr, "PID:\n"); fprintf(stderr, " 0: all process/thread\n"); fprintf(stderr, "COMM:\n"); - fprintf(stderr, " '': The process name or thread name is not restricted.\n"); + fprintf(stderr, + " '': The process name or thread name is not restricted.\n"); fprintf(stderr, "Options:\n"); fprintf(stderr, " '-O, --only-stdout': dump to stdout only.\n"); - fprintf(stderr, " '-t, --timeout': set datadump timout. Unit: second\n"); + fprintf(stderr, + " '-t, --timeout': set datadump timout. Unit: second\n"); fprintf(stderr, "For example:\n"); fprintf(stderr, " %s datadump set pid 4567 comm curl proto 0\n", DF_BPF_NAME); - fprintf(stderr, " %s datadump set pid 4567 comm '' proto 20\n", DF_BPF_NAME); + fprintf(stderr, " %s datadump set pid 4567 comm '' proto 20\n", + DF_BPF_NAME); fprintf(stderr, " %s datadump on --timeout 60\n", DF_BPF_NAME); - fprintf(stderr, " %s datadump on --only-stdout --timeout 60\n", DF_BPF_NAME); + fprintf(stderr, " %s datadump on --only-stdout --timeout 60\n", + DF_BPF_NAME); fprintf(stderr, " %s datadump off\n", DF_BPF_NAME); } @@ -446,12 +467,10 @@ static int socktrace_do_cmd(struct df_bpf_obj *obj, df_bpf_cmd_t cmd, sk_trace_params->kern_trace_map_used); printf("datadump_enable:\t%s\n", sk_trace_params->datadump_enable ? "true" : "false"); - printf("datadump_pid:\t%d\n", - sk_trace_params->datadump_pid); + printf("datadump_pid:\t%d\n", sk_trace_params->datadump_pid); printf("datadump_proto:\t%d\n", sk_trace_params->datadump_proto); - printf("datadump_comm:\t%s\n", - sk_trace_params->datadump_comm); + printf("datadump_comm:\t%s\n", sk_trace_params->datadump_comm); printf("datadump_file_path:\t%s\n\n", sk_trace_params->datadump_file_path); @@ -496,7 +515,8 @@ static int datadump_do_cmd(struct df_bpf_obj *obj, df_bpf_cmd_t cmd, if (conf->cmd == DF_BPF_CMD_ON) { msg.enable = true; if (msg.timeout == 0) { - printf("Miss --timeout setting.\n"); + printf + ("Miss --timeout setting.\n"); return ETR_NOTSUPP; } printf("Set datadump on, timeout %ds ", @@ -562,6 +582,54 @@ static int datadump_do_cmd(struct df_bpf_obj *obj, df_bpf_cmd_t cmd, return ETR_OK; } +static int cpdbg_do_cmd(struct df_bpf_obj *obj, df_bpf_cmd_t cmd, + struct df_bpf_conf *conf) +{ + switch (conf->cmd) { + case DF_BPF_CMD_ON: + case DF_BPF_CMD_OFF: + { + struct cpdbg_msg msg; + msg.timeout = conf->timeout; + if (conf->cmd == DF_BPF_CMD_ON + || conf->cmd == DF_BPF_CMD_OFF) { + if (conf->argc != 0) { + obj->help(); + return ETR_NOTSUPP; + } + if (conf->cmd == DF_BPF_CMD_ON) { + msg.enable = true; + if (msg.timeout == 0) { + printf + ("Miss --timeout setting.\n"); + return ETR_NOTSUPP; + } + printf("Set cpdbg on, timeout %ds ", + msg.timeout); + } else { + msg.enable = false; + printf("Set cpdbg off "); + } + } else { + obj->help(); + return ETR_NOTSUPP; + } + + if (df_bpf_setsockopt(SOCKOPT_SET_CPDBG_ADD, &msg, + sizeof(msg)) == 0) { + printf("Success.\n"); + } else { + printf("Failed.\n"); + } + + break; + } + default: + return ETR_NOTSUPP; + } + return ETR_OK; +} + static int tracer_do_cmd(struct df_bpf_obj *obj, df_bpf_cmd_t cmd, struct df_bpf_conf *conf) { @@ -613,13 +681,19 @@ struct df_bpf_obj datadump_obj = { .do_cmd = datadump_do_cmd, }; +struct df_bpf_obj cpdbg_obj = { + .name = "cpdbg", + .help = cpdbg_help, + .do_cmd = cpdbg_do_cmd, +}; + static void usage(void) { fprintf(stderr, "Usage:\n" " " DF_BPF_NAME " [OPTIONS] OBJECT { COMMAND | help }\n" "Parameters:\n" - " OBJECT := { tracer socktrace datadump }\n" + " OBJECT := { tracer socktrace datadump cpdbg }\n" " COMMAND := { show list set }\n" "Options:\n" " -v, --verbose\n" @@ -634,6 +708,8 @@ static struct df_bpf_obj *df_bpf_obj_get(const char *name) return &socktrace_obj; } else if (strcmp(name, "datadump") == 0) { return &datadump_obj; + } else if (strcmp(name, "cpdbg") == 0) { + return &cpdbg_obj; } return NULL; diff --git a/agent/src/ebpf/user/profile/perf_profiler.c b/agent/src/ebpf/user/profile/perf_profiler.c index d01584edc4d..bd687d3ec61 100644 --- a/agent/src/ebpf/user/profile/perf_profiler.c +++ b/agent/src/ebpf/user/profile/perf_profiler.c @@ -143,6 +143,12 @@ static void print_cp_tracer_status(struct bpf_tracer *t); */ static atomic64_t process_lost_count; +/* Continuous Profiler debug lock */ +static pthread_mutex_t cpdbg_mutex; +static bool cpdbg_enable; +static uint32_t cpdbg_start_time; +static uint32_t cpdbg_timeout; + static u64 get_process_lost_count(void) { return atomic64_read(&process_lost_count); @@ -322,19 +328,60 @@ static int init_stack_trace_msg_hash(stack_trace_msg_hash_t * h, nbuckets, hash_memory_size); } +static inline bool is_cpdbg_timeout(void) +{ + uint32_t passed_sec; + passed_sec = get_sys_uptime() - cpdbg_start_time; + if (passed_sec > cpdbg_timeout) { + cpdbg_start_time = 0; + cpdbg_enable = false; + ebpf_info("\n\ncpdbg is finished, use time: %us.\n\n", + cpdbg_timeout); + cpdbg_timeout = 0; + return true; + } + + return false; +} + +static void print_cp_data(stack_trace_msg_t * msg) +{ + char *cid; + if (strlen((char *)msg->container_id) == 0) + cid = "null"; + else + cid = (char *)msg->container_id; + + ebpf_info + ("netns_id %lu container_id %s process_name %s pid %u stime %lu " + "u_stack_id %lu k_statck_id %lu cpu %u count %u comm %s tiemstamp" + " %lu datalen %u data %s\n", + msg->netns_id, cid, + msg->process_name, msg->pid, msg->stime, msg->u_stack_id, + msg->k_stack_id, msg->cpu, msg->count, msg->comm, msg->time_stamp, + msg->data_len, msg->data); +} + +static void cpdbg_process(stack_trace_msg_t * msg) +{ + pthread_mutex_lock(&cpdbg_mutex); + if (unlikely(cpdbg_enable)) { + if (!is_cpdbg_timeout()) + print_cp_data(msg); + + } + pthread_mutex_unlock(&cpdbg_mutex); +} + static int push_and_free_msg_kvp_cb(stack_trace_msg_hash_kv * kv, void *ctx) { stack_trace_msg_kv_t *msg_kv = (stack_trace_msg_kv_t *) kv; if (msg_kv->msg_ptr != 0) { stack_trace_msg_t *msg = (stack_trace_msg_t *) msg_kv->msg_ptr; -#ifdef CP_DEBUG - ebpf_debug - ("tiemstamp %lu pid %u stime %lu u_stack_id %lu k_statck_id" - "%lu cpu %u count %u comm %s datalen %u data %s\n", - msg->time_stamp, msg->pid, msg->stime, msg->u_stack_id, - msg->k_stack_id, msg->cpu, msg->count, msg->comm, - msg->data_len, msg->data); -#endif + + /* continuous profiler debug */ + cpdbg_process(msg); + tracer_callback_t fun = profiler_tracer->process_fn; /* * Execute callback function to hand over the data to the @@ -523,7 +570,8 @@ static void aggregate_stack_traces(struct bpf_tracer *t, char *trace_str = resolve_and_gen_stack_trace_str(t, v, stack_map_name, - stack_str_hash, matched, info_p); + stack_str_hash, matched, + info_p); if (trace_str) { /* * append process/thread name to stack string @@ -557,8 +605,8 @@ static void aggregate_stack_traces(struct bpf_tracer *t, ("stack_trace_msg_hash_add_del() failed.\n"); clib_mem_free(msg); } else { - __sync_fetch_and_add(&msg_hash-> - hash_elems_count, 1); + __sync_fetch_and_add + (&msg_hash->hash_elems_count, 1); } } @@ -936,6 +984,48 @@ static bool check_kallsyms_addr_is_zero(void) return (count == check_num); } +static int cpdbg_sockopt_get(sockoptid_t opt, const void *conf, size_t size, + void **out, size_t * outsize) +{ + return 0; +} + +static int cpdbg_sockopt_set(sockoptid_t opt, const void *conf, size_t size) +{ + struct cpdbg_msg *msg = (struct cpdbg_msg *)conf; + pthread_mutex_lock(&cpdbg_mutex); + if (msg->enable) { + cpdbg_start_time = get_sys_uptime(); + cpdbg_timeout = msg->timeout; + } + + if (cpdbg_enable && !msg->enable) { + cpdbg_timeout = 0; + cpdbg_start_time = 0; + } + + cpdbg_enable = msg->enable; + if (cpdbg_enable) { + ebpf_info("cpdbg enable timeout %ds\n", cpdbg_timeout); + } else { + ebpf_info("cpdbg disable"); + } + + pthread_mutex_unlock(&cpdbg_mutex); + + return 0; +} + +static struct tracer_sockopts cpdbg_sockopts = { + .version = SOCKOPT_VERSION, + .set_opt_min = SOCKOPT_SET_CPDBG_ADD, + .set_opt_max = SOCKOPT_SET_CPDBG_OFF, + .set = cpdbg_sockopt_set, + .get_opt_min = SOCKOPT_GET_CPDBG_SHOW, + .get_opt_max = SOCKOPT_GET_CPDBG_SHOW, + .get = cpdbg_sockopt_get, +}; + /* * start continuous profiler * @freq sample frequency, Hertz. (e.g. 99 profile stack traces at 99 Hertz) @@ -971,6 +1061,11 @@ int start_continuous_profiler(int freq, tracer_callback_t callback) atomic64_init(&process_lost_count); + /* + * Initialize cpdbg + */ + pthread_mutex_init(&cpdbg_mutex, NULL); + profiler_stop = 0; start_time = gettime(CLOCK_MONOTONIC, TIME_TYPE_SEC); @@ -1049,6 +1144,9 @@ int start_continuous_profiler(int freq, tracer_callback_t callback) if (tracer == NULL) return (-1); + if (sockopt_register(&cpdbg_sockopts) != ETR_OK) + return (-1); + tracer->state = TRACER_RUNNING; return (0); } @@ -1202,7 +1300,7 @@ int stop_continuous_profiler(void) return (0); } -void process_stack_trace_data_for_flame_graph(stack_trace_msg_t *val) +void process_stack_trace_data_for_flame_graph(stack_trace_msg_t * val) { return; } diff --git a/agent/src/ebpf/user/tracer.h b/agent/src/ebpf/user/tracer.h index 846956c95d1..5d49835af45 100644 --- a/agent/src/ebpf/user/tracer.h +++ b/agent/src/ebpf/user/tracer.h @@ -192,7 +192,14 @@ enum { SOCKOPT_SET_DATADUMP_ON, SOCKOPT_SET_DATADUMP_OFF, /* get */ - SOCKOPT_GET_DATADUMP_SHOW + SOCKOPT_GET_DATADUMP_SHOW, + + /* set */ + SOCKOPT_SET_CPDBG_ADD = 700, + SOCKOPT_SET_CPDBG_ON, + SOCKOPT_SET_CPDBG_OFF, + /* get */ + SOCKOPT_GET_CPDBG_SHOW }; struct mem_block_head {