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