From patchwork Tue Feb 19 04:41:45 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Sanjay Singh Rawat X-Patchwork-Id: 14977 Return-Path: X-Original-To: patchwork@peony.canonical.com Delivered-To: patchwork@peony.canonical.com Received: from fiordland.canonical.com (fiordland.canonical.com [91.189.94.145]) by peony.canonical.com (Postfix) with ESMTP id E76E423E1A for ; Tue, 19 Feb 2013 04:42:08 +0000 (UTC) Received: from mail-ve0-f172.google.com (mail-ve0-f172.google.com [209.85.128.172]) by fiordland.canonical.com (Postfix) with ESMTP id 7A015A184A3 for ; Tue, 19 Feb 2013 04:42:08 +0000 (UTC) Received: by mail-ve0-f172.google.com with SMTP id cz11so5613456veb.3 for ; Mon, 18 Feb 2013 20:42:08 -0800 (PST) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=20120113; h=x-received:x-forwarded-to:x-forwarded-for:delivered-to:x-received :received-spf:x-received:from:to:cc:subject:date:message-id:x-mailer :x-gm-message-state; bh=rJVRKEkbEa7vkzgKBXfI71i4VojMR8Rp6NjYorGMeyk=; b=H0zxdpFNzh6FK+cZ2DLVkzEuaUC5TeEaCssOAJKcVPKdhCutxHcPGmqe48fdxWqI0R 0gE++a2QnTZTxD5tNAkMQrUoFScEJHG2A5jmvjzIuJ1Tv+Z/rieNPzRiI7eAERDLy380 qyNVSZyU2o7rZBt2PjEf5qTQGqa8AYxPw8zSqBEI+ZToZKun7XpjMK+lwTBVjLBdVwpr oRvcvH2tRLBk6USCEb+1q4W+RjyaNdIiglcirwJ8SDvmfeGoUfhFCeH/1CAHLdoHeEph qevdc9pi7Qe+brXplpasyUQe4IFfNFE2UYw11KlcOWM/i40hYXqfrVMl1j/hHmbayG6z wWmA== X-Received: by 10.58.247.132 with SMTP id ye4mr19540195vec.9.1361248927869; Mon, 18 Feb 2013 20:42:07 -0800 (PST) X-Forwarded-To: linaro-patchwork@canonical.com X-Forwarded-For: patch@linaro.org linaro-patchwork@canonical.com Delivered-To: patches@linaro.org Received: by 10.58.145.101 with SMTP id st5csp122900veb; Mon, 18 Feb 2013 20:42:07 -0800 (PST) X-Received: by 10.68.230.225 with SMTP id tb1mr36751393pbc.86.1361248926686; Mon, 18 Feb 2013 20:42:06 -0800 (PST) Received: from mail-pa0-f52.google.com (mail-pa0-f52.google.com [209.85.220.52]) by mx.google.com with ESMTPS id oj4si15118728pbb.143.2013.02.18.20.42.06 (version=TLSv1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Mon, 18 Feb 2013 20:42:06 -0800 (PST) Received-SPF: neutral (google.com: 209.85.220.52 is neither permitted nor denied by best guess record for domain of sanjay.rawat@linaro.org) client-ip=209.85.220.52; Authentication-Results: mx.google.com; spf=neutral (google.com: 209.85.220.52 is neither permitted nor denied by best guess record for domain of sanjay.rawat@linaro.org) smtp.mail=sanjay.rawat@linaro.org Received: by mail-pa0-f52.google.com with SMTP id fb1so3203826pad.39 for ; Mon, 18 Feb 2013 20:42:06 -0800 (PST) X-Received: by 10.68.189.133 with SMTP id gi5mr36350730pbc.129.1361248925884; Mon, 18 Feb 2013 20:42:05 -0800 (PST) Received: from localhost.localdomain ([122.178.193.129]) by mx.google.com with ESMTPS id o5sm106008702pay.5.2013.02.18.20.42.03 (version=TLSv1.1 cipher=ECDHE-RSA-RC4-SHA bits=128/128); Mon, 18 Feb 2013 20:42:05 -0800 (PST) From: Sanjay Singh Rawat To: linaro-dev@lists.linaro.org Cc: Sanjay Singh Rawat Subject: [pmqa,1/1] cpuidle: add function to log cpuidle stats Date: Tue, 19 Feb 2013 10:11:45 +0530 Message-Id: <1361248905-6138-1-git-send-email-sanjay.rawat@linaro.com> X-Mailer: git-send-email 1.7.9.5 X-Gm-Message-State: ALoCoQnEERuOdk++WVNInTSglh4BgpbaCQhBhH7YhNyLmduHxZLnmVut3r2S2QzdSBh9ua7PTwFG Add functionality to record the overall and current runtime cpuidle statistics. Signed-off-by: Sanjay Singh Rawat --- 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 +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#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 ; retnum_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 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 ; cpunum_states = state; + break; + } + } + + cpuidle_stats[cpu]->state = + malloc(cpuidle_stats[cpu]->num_states * sizeof(int *)); + for(state=0 ; statenum_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 /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; +}