[pmqa,1/1] cpuidle: add function to log cpuidle stats

Message ID 1361248905-6138-1-git-send-email-sanjay.rawat@linaro.com
State New
Headers show

Commit Message

Sanjay Singh Rawat Feb. 19, 2013, 4:41 a.m.
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

Patch

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;
+}