sundayhut's Blog

在上一篇blktrace测试中，我们的测试函数通过getpid函数得到运行程序的进程号。而blktrace的捕捉结果的第五列为进程号。可以通过分析第五列为对应进程号的所有行从而得到该进程在执行过程中的所有动作。测试结果分析程序的代码如下。

该代码输入两个参数：参数一：代分析结果文件的文件名；参数二：进程号

#include"stdio.h"
#include"string.h"
#include"stdlib.h"

void main(int argc,char *argv[])
{
	FILE *src=NULL;
	FILE *des=NULL;
	long COUNT=0;
	int des_pid;
	char inputfile[200]="",outputfile[200]="", temp[1000];
	sprintf(inputfile,"/home/share/6-13/fread_first/%s",argv[1]);
	sprintf(outputfile,"/home/share/6-13/fread_first/interval-%s",argv[1]);
	des_pid=atoi(argv[2]);
	printf("%s\t%s\n",inputfile,outputfile);
	if((src = fopen(inputfile,"r"))<=0)
	{
		printf("open error1!\n");
	}	
	if((des = fopen(outputfile,"w"))<=0)
	{
		printf("open error2!\n");
	}
	char major_minor[10],cpu_id[30],sequence_number[20],time[20],process_id[20],action[10],RWBS[10],detail[200];
	char last_major_minor[10],last_cpu_id[30],last_sequence_number[20],last_time[20],last_process_id[20],last_action[10],last_RWBS[10],last_detail[200];
	
	double t,lasttime,interval,TIME[30],total_time=0.0;
	int last_pid,i;
	for(i=0;i<30;i++)TIME[i]=0.0;
	fgets(temp,200,src);
	//sscanf最后一个输入所有没有读入的
	sscanf(temp,"%s%s%s%s%s%s%s%[^\n]",last_major_minor,last_cpu_id,last_sequence_number,last_time,last_process_id,last_action,last_RWBS,last_detail);
	t=lasttime=atof(time);
	last_pid=atoi(last_process_id);
    //统计pid为对应程序运行pid的动作，并统计不同动作的时间
	while(fgets(temp,1000,src)!=NULL)
	{
		sscanf(temp,"%s%s%s%s%s%s%s%[^\n]",major_minor,cpu_id,sequence_number,time,process_id,action,RWBS,detail);
	    printf("%s %s %s %s %s %s %s %s\n",major_minor,cpu_id,sequence_number,time,process_id,action,RWBS,detail);
		t=atof(time);
		if(last_pid==des_pid)
		{		
		interval=t-lasttime;
		fprintf(des,"%s %s %s %.10lf %s %s %s %s\n",last_major_minor,last_cpu_id,last_sequence_number,interval,last_process_id,last_action,last_RWBS,last_detail);
	    if(!strcmp("A",last_action))TIME['A'-'A'] = TIME['A'-'A']+interval;
		else if(!strcmp("Q",last_action))TIME['Q'-'A'] = TIME['Q'-'A']+interval;
		else if(!strcmp("D",last_action))TIME['D'-'A'] = TIME['D'-'A']+interval;
		else if(!strcmp("G",last_action))TIME['G'-'A'] = TIME['G'-'A']+interval;
		else if(!strcmp("P",last_action))TIME['P'-'A'] = TIME['P'-'A']+interval;
		else if(!strcmp("I",last_action))TIME['I'-'A'] = TIME['I'-'A']+interval;
		else if(!strcmp("M",last_action))TIME['M'-'A'] = TIME['M'-'A']+interval;
		else if(!strcmp("C",last_action))TIME['C'-'A'] = TIME['C'-'A']+interval;
		else if(!strcmp("B",last_action))TIME['B'-'A'] = TIME['B'-'A']+interval;
		else if(!strcmp("F",last_action))TIME['F'-'A'] = TIME['F'-'A']+interval;
		else if(!strcmp("S",last_action))TIME['S'-'A'] = TIME['S'-'A']+interval;
		else if(!strcmp("U",last_action))TIME['U'-'A'] = TIME['U'-'A']+interval;
		else if(!strcmp("T",last_action))TIME['T'-'A'] = TIME['T'-'A']+interval;
		else if(!strcmp("X",last_action))TIME['X'-'A'] = TIME['X'-'A']+interval;
		else if(!strcmp("m",last_action))TIME[26] = TIME[26]+interval;
		else if(!strcmp("UT",last_action))TIME[27] = TIME[27]+interval;
		else printf("A state we do not expect: %s !!!!!!!!!!!\n",last_action);
		COUNT++;
		}
		last_pid=atoi(process_id);		
		
		strcpy(last_major_minor,major_minor);
		strcpy(last_cpu_id,cpu_id);
		strcpy(last_sequence_number,sequence_number);
		strcpy(last_process_id,process_id);
		strcpy(last_action,action);
		strcpy(last_RWBS,RWBS);
		strcpy(last_detail,detail);	
		lasttime=t;
	}
	//输出每个动作的时间
	for(i=0;i<26;i++){
		if(TIME[i]!=0)
		{fprintf(des,"%c = %.10lf\n",'A'+i,TIME[i]);
		total_time=total_time+TIME[i];}
	}
	if(TIME[26]!=0){fprintf(des,"m = %.10lf\n",TIME[26]);total_time=total_time+TIME[i];}
	if(TIME[27]!=0){fprintf(des,"UT = %.10lf\n",TIME[27]);total_time=total_time+TIME[i];}
	fprintf(des,"total_time=%10lf",total_time);
	printf("%ld\n",COUNT);
	fclose(src);
	fclose(des);
}

通过上述代码，我们可以得到不同动作的时间TIME[i]，以及该进程所有动作的总时间total_time。上述代码通过fprint函数把所有的进程号为测试程序进程号对应行的动作输出到文件中。下面看测试结果。

测试环境：

虚拟机 Linux2.6.34.14 ，i686

测试结果1：fopen-fgets-fclose测试

fgets对象的大小为61M，运行函数得到测试函数（上篇所属）的测试进程号，通过测试结果分析函数分析，得到统计结果，一下是不同动作的运行总时间：

由上述测试结果我们可以看出，在fgets这个动作中，耗时最大的是D,接下来是U A Q G。通过官方文档我们可以看到这几个动作代表的具体含义：

D- issud A request that previously resided on the block layer queue or in the io scheduler has been sent to the driver.一个原本属于通用块层或者io调度层的请求下发到设备驱动层。

A- remap For stacked devices,incoming io is remapped to device below it in the io stack.The remap action details what exactly being remapped to what.地址进行重新映射，找到请求的具体地址

Q- queued This notes intent to queue io at the given location.No real requests exist yet.将io请求在一个指定的地方排队，目前没有真实的io请求。

U- unplug Some request data already queued in the device ,start sending requests to the driver.This may happen automatically if a timeout period has passed or if a number of requests has been added to the queue.

G- get request To send any type of request to a block device, a struct request container must be allocate first. 用request结构来包装请求。

P- plug When io is queued to a previously empty block device queue,Linux will plug the queue in anticipation of future ios being added before this data is needed.当io在一个之前为空的设备上排队，linux会阻塞这个队列

C- complete A previously issued request has been completed.The output will detail the sector and size of that request,as well as the success or failure of it. 上一个请求的完成。输出结果详细说明了请求的扇区和大小，以及该请求成功或者是失败。

测试结果2：fopen-fread-fclose

fread文件的大小为61M，通过以上相同的方法得到分析结果，下面给出不同操作的时间：

以上不同动作的延时由大到小分别是D U G Q A.这几项的含义见上

测试结果3：fopen-fprintf-fclose

fprintf(des,"test\n");输出10000000次。统计输出结果