diff --git a/source/tools/detect/irqoff/bpf/irqoff.bpf.c b/source/tools/detect/irqoff/bpf/irqoff.bpf.c index 19f4b16c3e6518869620c4cf0d5ba4240206bebb..608ee6117f2b3b5b14fe18f5f06f5dd2e745a087 100644 --- a/source/tools/detect/irqoff/bpf/irqoff.bpf.c +++ b/source/tools/detect/irqoff/bpf/irqoff.bpf.c @@ -79,7 +79,7 @@ int hw_irqoff_event(struct bpf_perf_event_data *ctx) if (delta > thresh) { event.cpu = cpu; event.stamp = now; - event.delay = delta/1000; + event.delay = delta; event.pid = bpf_get_current_pid_tgid(); bpf_get_current_comm(&event.comm, sizeof(event.comm)); event.ret = bpf_get_stackid(ctx, &stackmap, KERN_STACKID_FLAGS); @@ -129,7 +129,7 @@ int sw_irqoff_event2(struct bpf_perf_event_data *ctx) delta = now - stamp; if (delta > thresh) { event.cpu = cpu; - event.delay = delta/1000; + event.delay = delta; event.pid = bpf_get_current_pid_tgid(); bpf_get_current_comm(&event.comm, sizeof(event.comm)); event.ret = bpf_get_stackid(ctx, &stackmap, KERN_STACKID_FLAGS); diff --git a/source/tools/detect/irqoff/irqoff.c b/source/tools/detect/irqoff/irqoff.c index aeb802ddef400ebe3d7572b17c694249962ac268..c1f70f6a447c3603a3968a219f44f3833b3aa409 100644 --- a/source/tools/detect/irqoff/irqoff.c +++ b/source/tools/detect/irqoff/irqoff.c @@ -25,7 +25,7 @@ struct env { __u64 threshold; } env = { .duration = 0, - .threshold = 10, /* 10ms */ + .threshold = 10*1000*1000, /* 10ms */ .summary = false, }; @@ -268,7 +268,7 @@ static void update_summary(struct summary* summary, const struct event *e) idx = summary->num % CPU_ARRY_LEN; summary->total += e->delay; summary->cpus[idx] = e->cpu; - summary->jitter[idx] = e->delay/1000; + summary->jitter[idx] = e->delay; if (get_container(buf, e->pid)) strncpy(summary->container[idx], "000000000000", sizeof(summary->container[idx])); else @@ -294,7 +294,7 @@ static int record_summary(struct summary *summary, long offset, bool total) p = buf; pos = sprintf(p,"%-7s %-5lu %-6llu", total?"irqoff":header, - summary->num, summary->total/1000); + summary->num, summary->total); if (total) { idx = summary->num % CPU_ARRY_LEN; @@ -315,7 +315,7 @@ static int record_summary(struct summary *summary, long offset, bool total) } else { p = p+pos; pos = sprintf(p, " %-4llu %-12llu %-3d %-9d %-15s\n", - summary->max.value/1000, summary->max.stamp/1000, + summary->max.value, summary->max.stamp/1000, summary->max.cpu, summary->max.pid, summary->max.comm); } @@ -330,14 +330,18 @@ static int record_summary(struct summary *summary, long offset, bool total) void handle_event(void *ctx, int cpu, void *data, __u32 data_sz) { - const struct event *e = data; + struct event ev, *e; + const struct event *ep = data; struct tm *tm; char ts[64]; time_t t; + ev = *ep; + e = &ev; time(&t); tm = localtime(&t); strftime(ts, sizeof(ts), "%F_%H:%M:%S", tm); + e->delay = e->delay/(1000*1000); if (env.summary) { struct summary *sumi; diff --git a/source/tools/monitor/mservice/master/modules/mod_cgroup.c b/source/tools/monitor/mservice/master/modules/mod_cgroup.c index 02b6a4aac404181476109213ccf42d69d6774c7f..d9578d1d261837ecd764d89c0b06196913101ca9 100644 --- a/source/tools/monitor/mservice/master/modules/mod_cgroup.c +++ b/source/tools/monitor/mservice/master/modules/mod_cgroup.c @@ -25,8 +25,28 @@ char *cg_usage = " --cg Linux container stats"; /*Todo,user configure ?*/ #define CGROUP_INFO_AGING_TIME 7200 #define NCONF_HW 2 +#define JITITEM 4 +#define CONID_LEN 13 +static int cg_jitter_init = 0; int nr_cpus; +//extern char *cg_jit_mod[]; +char *cg_jit_mod[] = {"rqslow", "noschd", "irqoff"}; +char *log_path[] = { + "/var/log/sysak/mservice/runqslower", + "/var/log/sysak/mservice/nosched", + "/var/log/sysak/mservice/irqoff", +}; +//extern char *log_path[]; +//int init_sysak(void); +//int prepare_jitter_dictory(char *path); +enum jitter_types { + RQSLOW, + NOSCHE, + IRQOFF, + JITTER_NTYPE, +}; + int hwconfigs[] = { PERF_COUNT_HW_CACHE_MISSES, PERF_COUNT_HW_CACHE_REFERENCES}; @@ -100,6 +120,30 @@ struct cg_hwres_info { long long hw_sum[NCONF_HW]; }; +struct sum_jitter_info { + unsigned long num, lastnum; + unsigned long long total; + int lastcpu[JITITEM]; + unsigned long lastjit[JITITEM]; + char container[JITITEM][CONID_LEN]; +}; + +struct sum_jitter_infos { + struct sum_jitter_info sum[JITTER_NTYPE]; +}; + +struct jitter_info { + int idx; + unsigned long num; + unsigned long long time; + int lastcpu[JITITEM]; + char container[JITITEM][CONID_LEN]; +}; + +struct cg_jitter_info { + struct jitter_info info[JITTER_NTYPE]; +}; + struct cgroup_info { char name[LEN_32]; int valid; @@ -108,6 +152,7 @@ struct cgroup_info { struct cg_mem_info mem; struct cg_blkio_info blkio; struct cg_hwres_info hwres; + struct cg_jitter_info jitter; } cgroups[MAX_CGROUPS]; unsigned int n_cgs = 0; /* Number of cgroups */ @@ -188,6 +233,13 @@ static struct mod_info cg_info[] = { {"cahmis", DETAIL_BIT, 0, STATS_NULL}, {"_cahrf", DETAIL_BIT, MERGE_AVG, STATS_NULL}, {"cahref", DETAIL_BIT, 0, STATS_NULL}, + /* jitter info 69-74 */ + {"numrsw", DETAIL_BIT, 0, STATS_NULL}, /* total numbers of runqslow jitter */ + {" tmrsw", DETAIL_BIT, 0, STATS_NULL}, /* the sum-time of runqslow delay */ + {"numnsc", DETAIL_BIT, 0, STATS_NULL}, /* total numbers of nosched jitter */ + {" tmnsc", DETAIL_BIT, 0, STATS_NULL}, /* the sum-time of nosched delay */ + {"numirq", DETAIL_BIT, 0, STATS_NULL}, /* total numbers of irqoff jitter */ + {" tmirq", DETAIL_BIT, 0, STATS_NULL}, /* the sum-time of irqoff delay */ }; #define NR_CGROUP_INFO sizeof(cg_info)/sizeof(struct mod_info) @@ -298,6 +350,52 @@ static int perf_event_init(struct cgroup_info *cgroup) return ret; } +static int cg_prepare_jitter_dictory(char *path) +{ + int ret; + + ret = mkdir(path, 0777); + if (ret < 0 && errno != EEXIST) + return errno; + else + return 0; +} + +static int cg_init_sysak(void) +{ + int ret; + FILE *fp1, *fp2, *fp3; + char *mservice_log_dir = "/var/log/sysak/mservice/"; + + if (cg_jitter_init) + return 0; + + ret = cg_prepare_jitter_dictory(mservice_log_dir); + if (ret) + return ret; + + /* todo: what if command can't be find? */ + /* threshold is 40ms */ + fp1 = popen("sysak runqslower -S -f /var/log/sysak/mservice/runqslower 40 2>/dev/null &", "r"); + if (!fp1) { + perror("popen runqslower"); + return -1; + } + + fp2 = popen("sysak nosched -S -f /var/log/sysak/mservice/nosched -t 10 2>/dev/null &", "r"); + if (!fp2) { + perror("popen nosched"); + return -1; + } + + fp3 = popen("sysak irqoff -S -f /var/log/sysak/mservice/irqoff 10 2>/dev/null &", "r"); + if (!fp3) { + perror("popen irqoff"); + return -1; + } + cg_jitter_init = 1; + return 0; +} static void init_cgroups(void) { int i, ret; @@ -329,6 +427,7 @@ static void init_cgroups(void) n_cgs++; } pclose(result); + cg_init_sysak(); cgroup_init_time = time(NULL); } @@ -738,10 +837,140 @@ static int get_hwres_stats(int cg_idx) return nr_cpus*sizeof(long long); } +static unsigned long jitter_cgroup_matched(int cg_idx, struct sum_jitter_info *sum) +{ + int num, cpu, i; + FILE *file; + char *token, *pbuf; + char filepath[LEN_1024]; + unsigned long long cpusets, mask; + + if (!get_cgroup_path(cgroups[cg_idx].name, "cpuset", filepath)) + return 0; + + strcat(filepath, "/cpuset.cpus"); + file = fopen(filepath, "r"); + if (!file) + return 0; + memset(buffer, 0, sizeof(buffer)); + if (!fgets(buffer, sizeof(buffer), file)) { + fclose(file); + return 0; + } + pbuf = buffer; + cpusets = 0; + while((token = strsep(&pbuf, ",")) != NULL) { + unsigned long long tmp; + int vals[2], val, ret; + char *token1, *pbuf1=token; + + i = 0; + tmp = 0; + while(((token1 = strsep(&pbuf1, "-")) != NULL) && i < 2) { + errno = 0; + val = strtol(token1, NULL, 10); + ret = errno; + if ((ret == ERANGE && (val == LONG_MAX || val == LONG_MIN)) + || (ret != 0 && val == 0)) { + printf("strtol:(val=%d,str=%s)%s fail\n", val, token1,strerror(ret)); + break; + } + vals[i++] = val; + } + if (i == 1) + tmp = tmp | 1 << vals[0]; + else if (i == 2) { + tmp = tmp | ((1 << (vals[1]+1)) - 1); + tmp = tmp & ~((1 << vals[0]) -1); + } + cpusets = cpusets | tmp; + } + mask = 0; + num = sum->num - sum->lastnum; + num = num > 4?4:num; + for (i = 0; i < num; i++) { + cpu = sum->lastcpu[i]; + if ((1 << cpu) & cpusets) + mask |= 1 << i; + } + sum->lastnum = sum->num; + fclose(file); + return mask; +} + +static int get_jitter_stats(int cg_idx, struct sum_jitter_infos *sums) +{ + int i = 0, j, idx; + unsigned long long mask = 0; + struct cg_jitter_info *jits; + + jits = &cgroups[cg_idx].jitter; + for (j = 0; j < JITTER_NTYPE; j++) { + struct jitter_info *jit; + struct sum_jitter_info *sum; + + jit = &jits->info[j]; + sum = &sums->sum[j]; + if (!(mask = jitter_cgroup_matched(cg_idx, sum))) + continue; + while(i < JITITEM) { + if (mask & (1 << i)) { + jit->idx = idx = (jit->idx+1)%JITITEM; + jit->num = jit->num + 1; + jit->time = jit->time + sum->lastjit[i]; + jit->lastcpu[idx] = sum->lastcpu[i]; + strncpy(jit->container[idx], sum->container[i], CONID_LEN - 1); + } + i++; + } + } + return 0; +} + +int get_jitter_summary(struct sum_jitter_infos *sums) +{ + int i, ret = -1; + char line[512]; + FILE *fp; + + for (i = 0; i < JITTER_NTYPE; i++) { + struct sum_jitter_info *sump = &sums->sum[i]; + if((fp = fopen(log_path[i], "r")) == NULL) { + fprintf(stderr, "fopen %s fail\n", log_path[i]); + continue; + } + memset(line, 0, sizeof(line)); + if (fgets(line, 512, fp) != NULL) { + if (strlen(line) < 32) { + memset(sump, 0, sizeof(*sump)); + memset(sump->container, '0', sizeof(sump->container)); + goto retry; + } + sscanf(line+6, "%lu %llu %d %d %d %d %lu %lu %lu %lu %s %s %s %s", + &sump->num, &sump->total, + &sump->lastcpu[0], &sump->lastcpu[1], + &sump->lastcpu[2], &sump->lastcpu[3], + &sump->lastjit[0], &sump->lastjit[1], + &sump->lastjit[2], &sump->lastjit[3], + sump->container[0], sump->container[1], + sump->container[2], sump->container[3]); + ret = 0; + } else { + fprintf(stderr, "fgets %s fail:%s\n", log_path[i], strerror(errno)); + } +retry: + rewind(fp); + fclose(fp); + } + return ret; +} + void get_cgroup_stats(void) { int i, items; + struct sum_jitter_infos sums; + get_jitter_summary(&sums); for (i = 0; i < n_cgs; i++) { items = 0; items += get_load_and_enhanced_cpu_stats(i); @@ -749,6 +978,7 @@ void get_cgroup_stats(void) items += get_memory_stats(i); items += get_blkinfo_stats(i); items += get_hwres_stats(i); + items += get_jitter_stats(i, &sums); cgroups[i].valid = !!items; } } @@ -818,9 +1048,30 @@ static int print_cgroup_hwres(char *buf, int len, struct cg_hwres_info *info) { int i, pos = 0; - for (i = 0; i < NCONF_HW - 1; i++) + for (i = 0; i < NCONF_HW; i++) pos += snprintf(buf + pos, len - pos, "%lld,", info->hw_sum[i]); - pos += snprintf(buf + pos, len - pos, "%lld", info->hw_sum[i]); + return pos; +} + +static int print_cgroup_jitter(char *buf, int len, struct cg_jitter_info *infos) +{ + int i, pos = 0; + struct jitter_info *info; + + for (i = 0; i < JITTER_NTYPE - 1; i++) { + info = &infos->info[i]; + pos += snprintf(buf + pos, len - pos, + "%s,%lu,%llu,%s,%s,%s,%s,", + cg_jit_mod[i], info->num, info->time, + info->container[0], info->container[1], + info->container[2], info->container[3]); + } + info = &infos->info[i]; + pos += snprintf(buf + pos, len - pos, + "%s,%lu,%llu,%s,%s,%s,%s", + cg_jit_mod[i],info->num, info->time, + info->container[0], info->container[1], + info->container[2], info->container[3]); return pos; } @@ -841,6 +1092,7 @@ print_cgroup_stats(struct module *mod) pos += print_cgroup_memory(buf + pos, LEN_1M - pos, &cgroups[i].mem); pos += print_cgroup_blkio(buf + pos, LEN_1M - pos, &cgroups[i].blkio); pos += print_cgroup_hwres(buf + pos, LEN_1M - pos, &cgroups[i].hwres); + pos += print_cgroup_jitter(buf + pos, LEN_1M - pos, &cgroups[i].jitter); pos += snprintf(buf + pos, LEN_1M - pos, ITEM_SPLIT); } set_mod_record(mod, buf); @@ -995,6 +1247,24 @@ set_hwres_record(double st_array[], U_64 pre_array[], U_64 cur_array[]) st_array[3] = cur_array[3]; } +static void +set_cg_jit_record(double st_array[], U_64 pre_array[], U_64 cur_array[]) +{ + /* + * numrqs: numbers of runqueue-slower jitter 69 + * tmrqs: time of runqeueue-slower jitter 70 + * numnsc: numbers of system-delay jitter 71 + * tmnsc: time of system-delay jitter 72 + * numirq: numbers of irqoff of jitter 73 + * tmirq: time of irqoff jitter 74 + * */ + st_array[0] = cur_array[0]; + st_array[1] = cur_array[1]; + st_array[2] = cur_array[2]; + st_array[3] = cur_array[3]; + st_array[4] = cur_array[4]; + st_array[5] = cur_array[5]; +} static void set_cgroup_record(struct module *mod, double st_array[], U_64 pre_array[], U_64 cur_array[], int inter) @@ -1004,6 +1274,7 @@ set_cgroup_record(struct module *mod, double st_array[], set_memory_record(&st_array[16], &pre_array[16], &cur_array[16]); set_blkio_record(&st_array[51], &pre_array[51], &cur_array[51], inter); set_hwres_record(&st_array[65], &pre_array[65], &cur_array[65]); + set_cg_jit_record(&st_array[69], &pre_array[69], &cur_array[69]); } void diff --git a/source/tools/monitor/mservice/master/modules/mod_jitter.c b/source/tools/monitor/mservice/master/modules/mod_jitter.c index 148fcf067d3276cac96ef77588cb763b3bb71981..f7357489dc0a87b570a14972d190158cafd1f147 100644 --- a/source/tools/monitor/mservice/master/modules/mod_jitter.c +++ b/source/tools/monitor/mservice/master/modules/mod_jitter.c @@ -15,9 +15,9 @@ #define NR_MODS 3 #define BUF_SIZE (NR_MODS * 4096) char g_buf[BUF_SIZE]; +char line[512]; static int jitter_init = 0; char *jitter_usage = " --jit Application jitter stats"; -char *mservice_log_dir = "/var/log/sysak/mservice/"; char *jit_mod[] = {"rqslow", "noschd", "irqoff"}; char *log_path[] = { "/var/log/sysak/mservice/runqslower", @@ -28,10 +28,8 @@ char *log_path[] = { struct summary { unsigned long num; unsigned long long total; - unsigned long long max_value; - unsigned long long max_stamp; - int max_cpu, max_pid; int lastcpu0, lastcpu1, lastcpu2, lastcpu3; + unsigned long lastjit0, lastjit1, lastjit2, lastjit3; }; static struct mod_info jitter_info[] = { @@ -41,10 +39,6 @@ static struct mod_info jitter_info[] = { {" lCPU1", DETAIL_BIT, 0, STATS_NULL}, /* last happened cpu[1] */ {" lCPU2", DETAIL_BIT, 0, STATS_NULL}, /* last happened cpu[2] */ {" lCPU3", DETAIL_BIT, 0, STATS_NULL}, /* last happened cpu[3] */ - {"mvalue", DETAIL_BIT, 0, STATS_NULL}, /* max-delay event value */ - {"mstamp", HIDE_BIT, 0, STATS_NULL}, /* max-delay event time-stamp */ - {" mcpu", DETAIL_BIT, 0, STATS_NULL}, /* max-delay event of cpu */ - {" mpid", HIDE_BIT, 0, STATS_NULL}, /* max-delay event of pid */ {"dltnum", SUMMARY_BIT, 0, STATS_NULL}, /* delta numbers of happend */ {" dlttm", SUMMARY_BIT, 0, STATS_NULL}, /* the delta time of delay */ }; @@ -52,7 +46,7 @@ static struct mod_info jitter_info[] = { #define NR_JITTER_INFO sizeof(jitter_info)/sizeof(struct mod_info) struct summary summary; -static int prepare_dictory(char *path) +int prepare_jitter_dictory(char *path) { int ret; @@ -63,15 +57,16 @@ static int prepare_dictory(char *path) return 0; } -static int init_sysak(void) +int init_sysak(void) { - FILE *fp1, *fp2, *fp3; int ret; + FILE *fp1, *fp2, *fp3; + char *mservice_log_dir = "/var/log/sysak/mservice/"; if (jitter_init) return 0; - ret = prepare_dictory(mservice_log_dir); + ret = prepare_jitter_dictory(mservice_log_dir); if (ret) return ret; @@ -101,23 +96,21 @@ static int init_sysak(void) static int get_jitter_info(char *path, struct summary *sump) { int ret = -1; - char line[4096]; FILE *fp; if((fp = fopen(path, "r")) == NULL) { fprintf(stderr, "fopen %s fail\n", path); return ret; } - memset(line, 0, sizeof(line)); - if (fgets(line, 4096, fp) != NULL) { + if (fgets(line, sizeof(line), fp) != NULL) { /* "irqoff", "noschd", "rqslow" has 6 charactors */ - sscanf(line+6, "%lu %llu %d %d %d %d %llu %llu %d %d", + sscanf(line+6, "%lu %llu %d %d %d %d %lu %lu %lu %lu", &sump->num, &sump->total, &sump->lastcpu0, &sump->lastcpu1, &sump->lastcpu2, &sump->lastcpu3, - &sump->max_value, &sump->max_stamp, - &sump->max_cpu, &sump->max_pid); + &sump->lastjit0, &sump->lastjit1, + &sump->lastjit2, &sump->lastjit3); ret = 0; } else { fprintf(stderr, "fgets %s fail:%s\n", path, strerror(errno)); @@ -138,12 +131,12 @@ void print_jitter_stats(struct module *mod) ret = get_jitter_info(log_path[i], &summary); if (ret < 0) continue; - pos += snprintf(g_buf + pos, BUF_SIZE - pos, "%s=%ld,%llu,%d,%d,%d,%d,%llu,%llu,%d,%d,%d" ITEM_SPLIT, + pos += snprintf(g_buf + pos, BUF_SIZE - pos, "%s=%ld,%llu,%d,%d,%d,%d,%lu,%lu,%lu,%lu,%d" ITEM_SPLIT, jit_mod[i], summary.num, summary.total, summary.lastcpu0, summary.lastcpu1, summary.lastcpu2, summary.lastcpu3, - summary.max_value, summary.max_stamp, - summary.max_cpu, summary.max_pid, pos); + summary.lastjit0, summary.lastjit1, + summary.lastjit2, summary.lastjit3, pos); } set_mod_record(mod, g_buf); } @@ -151,7 +144,6 @@ void print_jitter_stats(struct module *mod) void read_jitter_stat(struct module *mod, char *parameter) { int ret; - ret = init_sysak(); if (ret) fprintf(stderr, "init_sysak failed\n");/*todo*/ @@ -169,20 +161,15 @@ set_jitter_record(struct module *mod, double st_array[], st_array[3] = cur_array[3]; st_array[4] = cur_array[4]; st_array[5] = cur_array[5]; - st_array[6] = cur_array[6]; - st_array[7] = cur_array[7]; - - st_array[8] = cur_array[8]; - st_array[9] = cur_array[9]; if (cur_array[0] >= pre_array[0]) - st_array[10] = cur_array[0] - pre_array[0]; + st_array[6] = cur_array[0] - pre_array[0]; else - st_array[10] = -1; + st_array[6] = -1; if (cur_array[1] >= pre_array[1]) - st_array[11] = cur_array[1] - pre_array[1]; + st_array[7] = cur_array[1] - pre_array[1]; else - st_array[11] = -1; + st_array[7] = -1; } void diff --git a/source/tools/monitor/sched/nosched/bpf/nosched.bpf.c b/source/tools/monitor/sched/nosched/bpf/nosched.bpf.c index b879a6d2ee0b477f559b98b923792d62b1ea3c82..86a88572763009ced96f6663367b7b5e583781ad 100644 --- a/source/tools/monitor/sched/nosched/bpf/nosched.bpf.c +++ b/source/tools/monitor/sched/nosched/bpf/nosched.bpf.c @@ -114,7 +114,7 @@ int BPF_KPROBE(account_process_tick, struct task_struct *p, int user_tick) struct event event = {}; event.stamp = now; event.cpu = cpuid; - event.delay = resched_latency/1000; + event.delay = resched_latency; event.pid = bpf_get_current_pid_tgid(); bpf_get_current_comm(&event.comm, sizeof(event.comm)); event.ret = bpf_get_stackid(ctx, &stackmap, KERN_STACKID_FLAGS); diff --git a/source/tools/monitor/sched/nosched/nosched.c b/source/tools/monitor/sched/nosched/nosched.c index c087970a9aa97f745a3ce3b0b4534f5f58e45e15..32b563a31c9cac6b684e7250e83d34f0f6cc6094 100644 --- a/source/tools/monitor/sched/nosched/nosched.c +++ b/source/tools/monitor/sched/nosched/nosched.c @@ -161,8 +161,6 @@ static void print_stack(int fd, __u32 ret) } } -#define SEC_TO_NS (1000*1000*1000) - static int prepare_dictory(char *path) { int ret; @@ -227,7 +225,7 @@ static void update_summary(struct summary* summary, const struct event *e) idx = summary->num % CPU_ARRY_LEN; summary->total += e->delay; summary->cpus[idx] = e->cpu; - summary->jitter[idx] = e->delay/1000; + summary->jitter[idx] = e->delay; if (get_container(buf, e->pid)) strncpy(summary->container[idx], "000000000000", sizeof(summary->container[idx])); else @@ -253,7 +251,7 @@ static int record_summary(struct summary *summary, long offset, bool total) p = buf; pos = sprintf(p,"%-7s %-5lu %-6llu", total?"nosche":header, - summary->num, summary->total/1000); + summary->num, summary->total); if (total) { idx = summary->num % CPU_ARRY_LEN; @@ -274,7 +272,7 @@ static int record_summary(struct summary *summary, long offset, bool total) } else { p = p+pos; pos = sprintf(p, " %-4llu %-12llu %-3d %-9d %-15s\n", - summary->max.value/1000, summary->max.stamp/1000, + summary->max.value, summary->max.stamp, summary->max.cpu, summary->max.pid, summary->max.comm); } @@ -289,14 +287,18 @@ static int record_summary(struct summary *summary, long offset, bool total) void handle_event(void *ctx, int cpu, void *data, __u32 data_sz) { - const struct event *e = data; + struct event tmpe, *e; + const struct event *ep = data; struct tm *tm; char ts[64]; time_t t; + tmpe = *ep; + e = &tmpe; time(&t); tm = localtime(&t); strftime(ts, sizeof(ts), "%F_%H:%M:%S", tm); + e->delay = e->delay/(1000*1000); if (env.summary) { struct summary *sumi; diff --git a/source/tools/monitor/sched/runqslower/bpf/runqslower.bpf.c b/source/tools/monitor/sched/runqslower/bpf/runqslower.bpf.c index d362fd3fc283a98628869699172dca105fce38c8..4d6f18f416b66847d90fbd29d7d07559e4dba65e 100644 --- a/source/tools/monitor/sched/runqslower/bpf/runqslower.bpf.c +++ b/source/tools/monitor/sched/runqslower/bpf/runqslower.bpf.c @@ -94,7 +94,7 @@ int handle_switch(struct trace_event_raw_sched_switch *ctx) u32 pid, prev_pid; long int prev_state; struct event event = {}; - u64 *tsp, delta_us, min_us, now; + u64 *tsp, delta, threshold, now; struct args *argp; prev_pid = ctx->prev_pid; @@ -110,15 +110,15 @@ int handle_switch(struct trace_event_raw_sched_switch *ctx) if (!tsp) return 0; /* missed enqueue */ now = bpf_ktime_get_ns(); - delta_us = (now - *tsp) / 1000; - min_us = GETARG_FROM_ARRYMAP(argmap, argp, u64, min_us); - if (min_us && delta_us <= min_us) + delta = (now - *tsp); + threshold = GETARG_FROM_ARRYMAP(argmap, argp, u64, threshold); + if (threshold && delta <= threshold) return 0; event.cpuid = cpuid; event.pid = pid; event.prev_pid = prev_pid; - event.delta_us = delta_us; + event.delay = delta; event.stamp = now; bpf_probe_read(event.task, sizeof(event.task), &(ctx->next_comm)); bpf_probe_read(event.prev_task, sizeof(event.prev_task), &(ctx->prev_comm)); diff --git a/source/tools/monitor/sched/runqslower/runqslower.c b/source/tools/monitor/sched/runqslower/runqslower.c index 0b948182c12ac0775ba4d2446404289d36d7b07e..09f3b641c4b0e90bd0b7a12a3d23b0916adce503 100644 --- a/source/tools/monitor/sched/runqslower/runqslower.c +++ b/source/tools/monitor/sched/runqslower/runqslower.c @@ -30,13 +30,13 @@ struct env { pid_t pid; pid_t tid; unsigned long span; - __u64 min_us; + __u64 threshold; bool previous; bool verbose; bool summary; } env = { .span = 0, - .min_us = 10000, + .threshold = 10*1000*1000, }; const char *argp_program_version = "runqslower 0.1"; @@ -45,12 +45,12 @@ const char *argp_program_bug_address = const char argp_program_doc[] = "Trace high run queue latency.\n" "\n" -"USAGE: runqslower [--help] [-s SPAN] [-t TID] [-P] [min_us] [-f ./runslow.log]\n" +"USAGE: runqslower [--help] [-s SPAN] [-t TID] [-P] [threshold] [-f ./runslow.log]\n" "\n" "EXAMPLES:\n" -" runqslower # trace latency higher than 10000 us (default)\n" +" runqslower # trace latency higher than 10ms (default)\n" " runqslower -f a.log # trace latency and record result to a.log (default to /var/log/sysak/runqslow/runqslow.log)\n" -" runqslower 1000 # trace latency higher than 1000 us\n" +" runqslower 12 # trace latency higher than 12 ms\n" " runqslower -p 123 # trace pid 123\n" " runqslower -t 123 # trace tid 123 (use for threads only)\n" " schedmoni -s 10 # monitor for 10 seconds\n" @@ -96,7 +96,7 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state) { static int pos_args; int pid; - long long min_us; + long long threshold; unsigned long span; switch (key) { @@ -163,12 +163,12 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state) argp_usage(state); } errno = 0; - min_us = strtoll(arg, NULL, 10); - if (errno || min_us <= 0) { - fprintf(stderr, "Invalid delay (in us): %s\n", arg); + threshold = strtoll(arg, NULL, 10); + if (errno || threshold <= 0) { + fprintf(stderr, "Invalid delay (in ms): %s\n", arg); argp_usage(state); } - env.min_us = min_us; + env.threshold = threshold*1000*1000; break; default: return ARGP_ERR_UNKNOWN; @@ -253,16 +253,16 @@ static void update_summary(struct summary* summary, const struct event *e) summary->num++; idx = summary->num % CPU_ARRY_LEN; - summary->total += e->delta_us; + summary->total += e->delay; summary->cpus[idx] = e->cpuid; - summary->jitter[idx] = e->delta_us/1000; + summary->jitter[idx] = e->delay; if (get_container(buf, e->pid)) strncpy(summary->container[idx], "000000000000", sizeof(summary->container[idx])); else strncpy(summary->container[idx], buf, sizeof(summary->container[idx])); - if (summary->max.value < e->delta_us) { - summary->max.value = e->delta_us; + if (summary->max.value < e->delay) { + summary->max.value = e->delay; summary->max.cpu = e->cpuid; summary->max.pid = e->pid; summary->max.stamp = e->stamp; @@ -281,7 +281,7 @@ static int record_summary(struct summary *summary, long offset, bool total) p = buf; pos = sprintf(p,"%-7s %-5lu %-6llu", total?"rqslow":header, - summary->num, summary->total/1000); + summary->num, summary->total); if (total) { idx = summary->num % CPU_ARRY_LEN; @@ -302,7 +302,7 @@ static int record_summary(struct summary *summary, long offset, bool total) } else { p = p+pos; pos = sprintf(p, " %-4llu %-12llu %-3d %-9d %-15s\n", - summary->max.value/1000, summary->max.stamp/1000, + summary->max.value, summary->max.stamp/1000, summary->max.cpu, summary->max.pid, summary->max.comm); } if (total) @@ -315,19 +315,22 @@ static int record_summary(struct summary *summary, long offset, bool total) void handle_event(void *ctx, int cpu, void *data, __u32 data_sz) { - const struct event *e = data; + struct event tmpe, *e; + const struct event *ep = data; struct tm *tm; char ts[64]; time_t t; + tmpe = *ep; + e = &tmpe; time(&t); tm = localtime(&t); strftime(ts, sizeof(ts), "%F %H:%M:%S", tm); + e->delay = e->delay/(1000*1000); if (env.summary) { struct summary *sumi; if (e->cpuid > nr_cpus - 1) return; - sumi = &percpu_summary[e->cpuid]; update_summary(&summary, e); update_summary(sumi, e); @@ -338,10 +341,10 @@ void handle_event(void *ctx, int cpu, void *data, __u32 data_sz) if (env.previous) fprintf(filep, "%-21s %-6d %-16s %-8d %-10llu %-16s %-6d\n", ts, e->cpuid, e->task, e->pid, - e->delta_us, e->prev_task, e->prev_pid); + e->delay, e->prev_task, e->prev_pid); else fprintf(filep, "%-21s %-6d %-16s %-8d %-10llu\n", - ts, e->cpuid, e->task, e->pid, e->delta_us); + ts, e->cpuid, e->task, e->pid, e->delay); } } @@ -398,15 +401,15 @@ int main(int argc, char **argv) args.targ_tgid = env.pid; args.targ_pid = env.tid; args.filter_pid = getpid(); - args.min_us = env.min_us; + args.threshold = env.threshold; if (!env.summary) { if (env.previous) fprintf(filep, "%-21s %-6s %-16s %-8s %-10s %-16s %-6s\n", - "TIME(runslw)", "CPU", "COMM", "TID", "LAT(us)", "PREV COMM", "PREV TID"); + "TIME(runslw)", "CPU", "COMM", "TID", "LAT(ms)", "PREV COMM", "PREV TID"); else fprintf(filep, "%-21s %-6s %-16s %-8s %-10s\n", - "TIME(runslw)", "CPU", "COMM", "TID", "LAT(us)"); + "TIME(runslw)", "CPU", "COMM", "TID", "LAT(ms)"); } else { int i; char buf[128] = {' '}; diff --git a/source/tools/monitor/sched/runqslower/runqslower.h b/source/tools/monitor/sched/runqslower/runqslower.h index 8f9253a03efa68e51c0b5b1ae14a7c3bc935d1b2..e65d47df6ee2ed1246b9f7fd5a6bb33266e88465 100644 --- a/source/tools/monitor/sched/runqslower/runqslower.h +++ b/source/tools/monitor/sched/runqslower/runqslower.h @@ -10,7 +10,7 @@ struct event { char task[TASK_COMM_LEN]; char prev_task[TASK_COMM_LEN]; - __u64 delta_us; + __u64 delay; __u64 stamp; pid_t pid; pid_t prev_pid; @@ -34,7 +34,7 @@ struct summary { }; struct args { - __u64 min_us; + __u64 threshold; pid_t targ_pid; pid_t targ_tgid; pid_t filter_pid;