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; +}
On Tue, Feb 19, 2013 at 10:11 AM, Sanjay Singh Rawat sanjay.rawat@linaro.org wrote:
Add functionality to record the overall and current runtime cpuidle statistics.
I'd like the output to be something list this:
[state1]: [number of times entered]: [average residency]: [std. deviation(residency)]: [variance] [state2]: [number of times entered]: [average residency]: [std. deviation(residency)]: [variance] . . [Total transitions (sum of all states entered)]
This could then be compared with results from previous runs (scripted) to flag any major changes. Of course, the environment in which this test is run will have to be rigidly controlled for the results to be comparable.
I'm not sure if capturing the 'to' and 'from' states is required here. It should reflect in the number of times a particular state is entered above.
Is it possible to come up with a single 'idleness' number that tells us at a glance if idleness has decreased or increased on that SoC due to changes in the environment (kernel, userspace)? This calculation would presumably give much higher weight to a C3 compared to a C1. The weight could even be the power draw of the SoC at that state. That way, if we suddenly start staying in shallower states, our idleness number should go down.
Daniel?
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"
What environment does this test run in? We probably want to run this on a stock ubuntu devel root filesystem and android after allowing it to idle for 30 seconds or so. It is probably worth discarding several seconds on data and the beginning and end of the capture too.
It would also be useful to pass a command-line parameter to control how long to run this measurement.
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 decimaltime_stamp[14]=0; //set EOSreturn 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 bettercpuidle_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);
a bit ugly... perhaps replace with a function that opens the file and writes a value into it?
if(ret != 0)goto fail;snprintf(buf,sizeof(buf),"cat /sys/kernel/debug/tracing/trace > ./cpuidle_trace.log");ret = system(buf);
ditto
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);
ditto
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;+}
1.7.9.5
linaro-dev mailing list linaro-dev@lists.linaro.org http://lists.linaro.org/mailman/listinfo/linaro-dev
On 02/20/2013 12:54 PM, Amit Kucheria wrote:
On Tue, Feb 19, 2013 at 10:11 AM, Sanjay Singh Rawat sanjay.rawat@linaro.org wrote:
Add functionality to record the overall and current runtime cpuidle statistics.
I'd like the output to be something list this:
[state1]: [number of times entered]: [average residency]: [std. deviation(residency)]: [variance] [state2]: [number of times entered]: [average residency]: [std. deviation(residency)]: [variance] . . [Total transitions (sum of all states entered)]
This could then be compared with results from previous runs (scripted) to flag any major changes. Of course, the environment in which this test is run will have to be rigidly controlled for the results to be comparable.
I'm not sure if capturing the 'to' and 'from' states is required here. It should reflect in the number of times a particular state is entered above.
Is it possible to come up with a single 'idleness' number that tells us at a glance if idleness has decreased or increased on that SoC due to changes in the environment (kernel, userspace)? This calculation would presumably give much higher weight to a C3 compared to a C1. The weight could even be the power draw of the SoC at that state. That way, if we suddenly start staying in shallower states, our idleness number should go down.
Daniel?
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"What environment does this test run in? We probably want to run this on a stock ubuntu devel root filesystem and android after allowing it to idle for 30 seconds or so. It is probably worth discarding several seconds on data and the beginning and end of the capture too.
It would also be useful to pass a command-line parameter to control how long to run this measurement.
I don't remember if I already mentioned it, but it is worth to have the pm-qa to be a standalone test suite, that is init + minimal configuration (no daemons) + pm-qa. eg: a custom busybox system.
Why ? we don't have the guarantee the userspace programs behave the same across the different versions. We may see improvements because of a new version of an application using a mainloop instead of polling or because a service is no longer set, or irqbalance is there, etc ...
I already saw some cpufreq tests failing because the standard deviation was too high due to a daemon running a job or a flush to disk.
That would be nice to boot the board on the pm-qa tests and then exits with a summary of the results.
I don't know if that could be compatible with Lava, but with this approach, we are sure we are testing the kernel only.
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 decimaltime_stamp[14]=0; //set EOSreturn 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 bettercpuidle_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);a bit ugly... perhaps replace with a function that opens the file and writes a value into it?
if(ret != 0)goto fail;snprintf(buf,sizeof(buf),"cat /sys/kernel/debug/tracing/trace > ./cpuidle_trace.log");ret = system(buf);ditto
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);ditto
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;+}
1.7.9.5
linaro-dev mailing list linaro-dev@lists.linaro.org http://lists.linaro.org/mailman/listinfo/linaro-dev
-
Amit Kucheria -
Daniel Lezcano -
Sanjay Singh Rawat