On 02/20/2013 12:54 PM, Amit Kucheria wrote:
> On Tue, Feb 19, 2013 at 10:11 AM, Sanjay Singh Rawat
> <sanjay.ra...@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.ra...@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 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);
>
> 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
--
<http://www.linaro.org/> Linaro.org │ Open source software for ARM SoCs
Follow Linaro: <http://www.facebook.com/pages/Linaro> Facebook |
<http://twitter.com/#!/linaroorg> Twitter |
<http://www.linaro.org/linaro-blog/> Blog
_______________________________________________
linaro-dev mailing list
linaro-dev@lists.linaro.org
http://lists.linaro.org/mailman/listinfo/linaro-dev
