Add functionality to record the overall and current runtime cpuidle statistics.
Signed-off-by: Sanjay Singh Rawat sanjay.rawat@linaro.com --- cpuidle/Readme.txt | 9 + cpuidle/cpuidle_03.sh | 9 + cpuidle/cpuidle_stats.c | 443 +++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 461 insertions(+) create mode 100644 cpuidle/Readme.txt create mode 100644 cpuidle/cpuidle_stats.c
diff --git a/cpuidle/Readme.txt b/cpuidle/Readme.txt new file mode 100644 index 0000000..9eacae0 --- /dev/null +++ b/cpuidle/Readme.txt @@ -0,0 +1,9 @@ +# cpuidle_stats execution: + - can compile and run separately. + - can run as part of cpuidle test : "sudo make -C cpuidle check" + +# info: +- Need sudo permission to run. +- saves trace in cpuidle/cpuidle_trace.log. +- Gives complete and current sampling time(in/out and timespent) cpuidle +state information. diff --git a/cpuidle/cpuidle_03.sh b/cpuidle/cpuidle_03.sh index 22bca10..0295555 100755 --- a/cpuidle/cpuidle_03.sh +++ b/cpuidle/cpuidle_03.sh @@ -56,5 +56,14 @@ fi
trap "restore_cpus; sigtrap" SIGHUP SIGINT SIGTERM
+check_cpuidle_trace() { + echo "### cpuidle state transition check:" + echo "## Collect the overall and current runtime cpuidle stats" + check "cpuidle stats execution" "./cpuidle_stats" + return 0 +} + for_each_cpu check_cpuidle_kill restore_cpus + +check_cpuidle_trace diff --git a/cpuidle/cpuidle_stats.c b/cpuidle/cpuidle_stats.c new file mode 100644 index 0000000..8cc5436 --- /dev/null +++ b/cpuidle/cpuidle_stats.c @@ -0,0 +1,443 @@ +#include <stdio.h> +#include <unistd.h> +#include <string.h> +#include <stdlib.h> +#include <sys/types.h> +#include <fcntl.h> +#include <getopt.h> +#include <sched.h> +#include <linux/unistd.h> +#include <signal.h> +#include <time.h> + +#define path "./cpuidle_trace.log" + +unsigned int num_of_cpus; +int signal_handled = 0; +struct timeval start_time, stop_time; +FILE *log_file; +struct cpu_idle_stats { + int num_states, exit,active_state; + struct state_stats{ + char name[25],desc[25],latency[25]; + char power[25],time[25], usage[25]; + int in; + double time_spent, entry_time; + } **state; + double exit_time; +} **cpuidle_stats; + +double traceline_time_stamp(char *line) +{ + char *ptr; + char time_stamp[14]; + + ptr = strchr(line,'.'); + if( ptr == NULL) { + printf("Funtion-%s : error, line format not recognized\n",__func__); + return -1; //todo - proper return value + } + strncpy(time_stamp,(ptr-6),13); //6 digits before and after decimal + time_stamp[14]=0; //set EOS + + return atof(time_stamp); +} + +void print_stat() +{ + int cpu,state; + + fprintf(log_file,"=================== Current cpuidle statistics ================\n"); + + for(cpu=0 ; cpu<4 ; cpu++) { + fprintf(log_file,"cpu-%d : [State] [In-Count] [Time Spent]\n",cpu); + for(state=0 ; state<5 ; state++) { + fprintf(log_file,"\t[states-%d] in-count = %d time-spent = %lf\n", + state, cpuidle_stats[cpu]->state[state]->in, + cpuidle_stats[cpu]->state[state]->time_spent); + } + fprintf(log_file,"\t\t[Out-Count] = %d\n\n",cpuidle_stats[cpu]->exit); + } +} + +/* function: scan the trace file + */ +int scan_trace_file(void) +{ + char line[1024],str[50]; + FILE *fp; + + printf("Scanning trace file ...\n"); + fp = fopen (path, "r"); + if (fp == NULL) { + printf("function-%s: error fopen\n",__func__); + return -1; + } + + while( fgets(line, sizeof(line), fp) != NULL ) { + if(strstr(line,"cpu_idle")) { + int cpu_num; + for(cpu_num=0 ; cpu_num<4 ; cpu_num++) { + int ret; + + sprintf(str,"cpu_id=%d",cpu_num); + if(strstr(line,str) == NULL) + continue; + + for(ret=0 ; ret<cpuidle_stats[cpu_num]->num_states ; ret++) { + sprintf(str,"state=%d",ret); + if(strstr(line,"state=4294967295")) { //todo: do it better + cpuidle_stats[cpu_num]->exit_time = + traceline_time_stamp(line); + if(cpuidle_stats[cpu_num]->state[cpuidle_stats[cpu_num]->active_state]->entry_time) + cpuidle_stats[cpu_num]->state[cpuidle_stats[cpu_num]->active_state]->time_spent += + cpuidle_stats[cpu_num]->exit_time - + cpuidle_stats[cpu_num]->state[cpuidle_stats[cpu_num]->active_state]->entry_time; + + cpuidle_stats[cpu_num]->exit++; + break; + } + if(strstr(line,str) == NULL) + continue; + + cpuidle_stats[cpu_num]->active_state = ret; + cpuidle_stats[cpu_num]->state[ret]->entry_time = + traceline_time_stamp(line); + cpuidle_stats[cpu_num]->state[ret]->in++; + } + + } + } + } + print_stat(); + printf("Logs saved in cpuidle_stats.log\n\n"); +} + +/* function: allocate and setup few structure for you + */ +void print_cpus_states_info(struct cpu_idle_stats **cpuidle_stats) +{ + int cpus, states; + char line_buf[1024],*ptr; + + for(cpus=0 ; cpus<num_of_cpus ; cpus++) + { + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + fprintf(log_file,"=========================================================\n"); + fprintf(log_file,"\nCPU%d - Overall cpuidle state info: [STATE-0 ---> STATE-%d]\n" + ,cpus,(cpuidle_stats[cpus]->num_states-1)); + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->desc); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->desc,str_len); + ptr += (str_len - 1); + *ptr++ = '/'; + *ptr++ = '\t'; + } + fprintf(log_file," desc[0->4] - %s\n",line_buf); + + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->latency); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->latency,str_len); + ptr += (str_len - 1); + *ptr++ = '\t'; + } + fprintf(log_file," latency[0->4] - %s\n",line_buf); + + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->name); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->name,str_len); + ptr += (str_len - 1); + *ptr++ = '\t'; + } + fprintf(log_file," name[0->4] - %s\n",line_buf); + + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->power); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->power,str_len); + ptr += (str_len - 1); + *ptr++ = '\t'; + } + fprintf(log_file," power[0->4] - %s\n",line_buf); + + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->time); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->time,str_len); + ptr += (str_len - 1); + *ptr++ = '\t'; + } + fprintf(log_file," time[0->4] - %s\n",line_buf); + + memset(line_buf,'\0',sizeof(line_buf)); + ptr=line_buf; + for(states=0 ; states< cpuidle_stats[cpus]->num_states ; states++) + { + int str_len= strlen(cpuidle_stats[cpus]->state[states]->usage); + memcpy(ptr,cpuidle_stats[cpus]->state[states]->usage,str_len); + ptr += (str_len - 1); + *ptr++ = '\t'; + } + fprintf(log_file," usage[0->4] - %s\n",line_buf); + } + fprintf(log_file,"=========================================================\n"); +} + +/* function: read sys attribute in char buffer + */ +int read_attribute(char *state_path, char *buf) +{ + int fd, ret; + + fd = open(state_path, O_RDONLY, 0666); + if(fd < 0) { + ret = fd; + goto fail; + } + ret = read(fd, buf, 255); + if(ret < 0) { + close(fd); + goto fail; + } + close(fd); + return 0; +fail: + printf("function-%s: error/fail\n",__func__); + return ret; +} + +/* Function: Read the cpu-state attributes from sysfs + */ +int read_state_stats(struct state_stats *state, char *state_path) +{ + char state_attr_path[256]; + int ret; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"desc"); + ret = read_attribute(state_attr_path,state->desc); + if(ret < 0) + goto fail; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"latency"); + ret = read_attribute(state_attr_path,state->latency); + if(ret < 0) + goto fail; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"name"); + ret = read_attribute(state_attr_path,state->name); + if(ret < 0) + goto fail; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"power"); + ret = read_attribute(state_attr_path,state->power); + if(ret < 0) + goto fail; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"time"); + ret = read_attribute(state_attr_path,state->time); + if(ret < 0) + goto fail; + + snprintf(state_attr_path, sizeof(state_attr_path),"%s/%s", + state_path,"usage"); + ret = read_attribute(state_attr_path,state->usage); + if(ret < 0) + goto fail; + + return 0; +fail: + printf("Function-%s: error\n",__func__); + return ret; +} + +/* function: print complete stats present in sysfs from epoch time + */ +int get_states_info(struct cpu_idle_stats **cpuidle_stats, int num_of_cpus) +{ + char cpu_path[256],state_path[256]; + int cpu,state,ret; + FILE *file; + + for(cpu=0 ; cpu<num_of_cpus ; cpu++) { + snprintf(cpu_path, sizeof(state_path), + "/sys/devices/system/cpu/cpu%d/cpuidle",cpu); + for(state=0 ; state<256 ; state++){ + snprintf(state_path, sizeof(state_path),"%s/state%d", + cpu_path,state); + file = fopen(state_path,"r"); + if(file != NULL) { + fclose(file); + } + else { + fprintf(log_file,"cpu-%d total states = %d\n",cpu,state); + cpuidle_stats[cpu]->num_states = state; + break; + } + } + + cpuidle_stats[cpu]->state = + malloc(cpuidle_stats[cpu]->num_states * sizeof(int *)); + for(state=0 ; state<cpuidle_stats[cpu]->num_states ; state++) { + cpuidle_stats[cpu]->state[state] = + malloc(sizeof(struct state_stats)); + memset(cpuidle_stats[cpu]->state[state],'\0', + sizeof(struct state_stats)); + snprintf(state_path, sizeof(state_path),"%s/state%d", + cpu_path,state); + ret = read_state_stats(cpuidle_stats[cpu]->state[state], + state_path); + } + } + print_cpus_states_info(cpuidle_stats); +} + +/* function: checks cpu and state information and allocate structure accordingly + */ +int setup_cpuidle_info() +{ + int ret,retb; + + num_of_cpus = sysconf(_SC_NPROCESSORS_CONF); + fprintf(log_file,"number of cpus = %d\n",num_of_cpus); + + cpuidle_stats = malloc(num_of_cpus * sizeof(int *)); + for( ret=0 ; ret<num_of_cpus ; ret++) { + int i; + + cpuidle_stats[ret] = (struct cpu_idle_stats*) + malloc(sizeof(struct cpu_idle_stats)); + if(!cpuidle_stats[ret]) { + printf("functioin:%s memory allocation failure\n",__func__); + } + memset(cpuidle_stats[ret],0,sizeof(struct cpu_idle_stats)); + } + ret = get_states_info(cpuidle_stats, num_of_cpus); + if(ret < 0) { + printf("function:%s: error\n",__func__); + } + + return ret; +} + +/* function: Handler to stop tracing + */ +void handle_tracing_stop(int signum) +{ + char buf[256]; + int ret; + double duration; + + snprintf(buf,sizeof(buf), + "echo 0 > /sys/kernel/debug/tracing/events/power/cpu_idle/enable"); + ret = system(buf); + if(ret != 0) + goto fail; + + snprintf(buf,sizeof(buf), + "cat /sys/kernel/debug/tracing/trace > ./cpuidle_trace.log"); + ret = system(buf); + if(ret != 0) + goto fail; + + printf("\nCapturing cpu_idle trace : end, saved in file:" + "cpuidle_trace.log\n"); + signal_handled = 1; + return; +fail: + printf("san-%s: fail/error\n",__func__); +} + +/* function: Generate cpuidle trace and save in file + */ +int capture_trace() +{ + char buf[256]; + char p[]="adkfh"; + int ret; + + printf("\n\nCapturing cpu_idle trace : start\n"); + signal(SIGINT, handle_tracing_stop); + + /* prepare */ + snprintf(buf,sizeof(buf), + "echo 0 > /sys/kernel/debug/tracing/events/power/cpu_idle/enable"); + ret = system(buf); + if(ret != 0) + goto fail; + snprintf(buf,sizeof(buf),"echo > /sys/kernel/debug/tracing/trace"); + ret = system(buf); + if(ret != 0) + goto fail; + /* enable tracing */ + snprintf(buf,sizeof(buf), + "echo nop > /sys/kernel/debug/tracing/current_tracer"); + ret = system(buf); + if(ret != 0) + goto fail; + snprintf(buf,sizeof(buf), + "echo 1 > /sys/kernel/debug/tracing/tracing_enabled"); + ret = system(buf); + if(ret != 0) + goto fail; + snprintf(buf,sizeof(buf),"echo 1 > /sys/kernel/debug/tracing/tracing_on"); + ret = system(buf); + if(ret != 0) + goto fail; + + gettimeofday(&start_time,NULL); + snprintf(buf,sizeof(buf), + "echo 1 > /sys/kernel/debug/tracing/events/power/cpu_idle/enable"); + ret = system(buf); + if(ret != 0) + goto fail; + + printf("\nPress Ctrl + c to Exit\n"); + while(!signal_handled) + sleep(1); + + return 0; +fail: + printf("%s: fail/error\n",__func__); + return ret; +} + +int main() +{ + int ret; + + log_file = fopen("cpuidle_stats.log","w"); + if(log_file == NULL) { + printf("error: can't create log file\n"); + return -1; + } + + ret = setup_cpuidle_info(); + if(ret < 0) { + printf("function: %s: error\n",__func__); + } + + ret = capture_trace(); + if(ret != 0) + return ret; + + scan_trace_file(); + + return 0; +}