linux 函数 执行时间间隔,linux 函数执行时间统计

#ifndef __TIME_TRACE_UTILS__

#define __TIME_TRACE_UTILS__

#include

#include

#include

#include

#include

#include

#include

#include

#define NS_TT_START namespace tt {

#define NS_TT_END }

#ifdef __TIME_TRACE_DEBUG__

# define TIME_TRACE tt::record Tt_ReCoRd_AvOiD_ReDeF(new tt::func_time_info(__func__));

# define TIME_TRACE_RESET tt::ctrl::inst()->reset();

# define TIME_TRACE_FORCE_PRINT tt::ctrl::inst()->ctrl_print();

# ifdef __TIME_TRACE_INER_DEBUG__

#define TT_DEBUG printf("", __func__, __LINE__),printf

# else

#define TT_DEBUG

# endif //__TIME_TRACE_INER_DEBUG__

#else // __TIME_TRACE_DEBUG__

# define TIME_TRACE_RESET

# define TIME_TRACE

# define TIME_TRACE_FORCE_PRINT

# define TT_DEBUG

#endif // __TIME_TRACE_DEBUG__

NS_TT_START

/* when a data is newly created

* it should contained by a record

* created in a stack

*/

struct func_time_info

{

func_time_info(std::string _id)

{

id = _id;

}

std::string id;

time_t start_time, end_time, costs;

int layer;

};

struct sum_unit : public func_time_info

{

sum_unit():func_time_info("")

{

start_time = 0;

end_time = 0;

costs = 0;

layer = 0;

cn = 0;

}

int cn;

};

struct process_time_info

{

pid_t id;

time_t start_time, end_time, costs;

process_time_info(pid_t pt):id(pt)

{

}

};

class ctrl

{

public:

/* log may not print after _exit or exit

* as no calling of the record's destructor

* so this may called before a exit call

* to print log and avoid a repeat print

* auto_print status will set to false

* */

void ctrl_print()

{

TT_DEBUG("ctrl::ctrl_print begin \n");

auto_print = false;

//if (ss.size() ==

//pop_back();

print();

}

/* add a new element to CC and SS like

* "[xx:xx:xx ~ xx:xx:xx] func XXs"

* this will clear all the data saved

* and should be called after sys fork

* */

void fork(const char *fn = "")

{

pid();

func_time_info *fti = ss.back();

if (fti) {

fti->id += "";

TT_DEBUG("new fork: %s\n",fti->id.c_str() );

}

TT_DEBUG("new fork\n");

time(&pp.start_time);

}

void reset()

{

pid();

time(&pp.start_time);

}

pid_t pid()

{

return pp.id = getpid();

}

void set_auto_print(bool f)

{

auto_print = f;

}

void push_back(func_time_info* fti)

{

ss.push_back(fti);

fti->layer = ss.size();

cc.push_back(fti);

time(&fti->start_time);

}

void pop_back()

{

func_time_info *fti = ss.back();

if (fti) {

time(&fti->end_time);

fti->costs = fti->end_time - fti->start_time;

}

ss.pop_back();

if (0 == ss.size() && auto_print) {

print();

}

}

void print()

{

pid();

time(&pp.end_time);

pp.costs = pp.end_time - pp.start_time;

char logname[1024] = {0};

sprintf(logname, "TT_%s_%d_%d.log",

time_format(&pp.start_time).c_str(),

(int)pp.start_time ,(int)pp.id);

TT_DEBUG("print start pid:%d, logname:%s\n",pp.id, logname);

std::fstream fs(logname, std::ios_base::out);

if (!fs.good()) {

fs.close();

TT_DEBUG("!!can't create log %s\n",logname);

return ;

}

fs << "------------------time performance--------------\n"

<< "1. detail\n"

<< "2. summary\n"

<< "\n"

<

std::map<:string sum_unit> sum;

std::map<:string sum_unit>::iterator itr_sum;

func_time_info *fti = 0;

std::list::iterator itr;

for (itr = cc.begin(); itr != cc.end(); ++itr) {

/* [start_time ~ end_time] name XXs */

fti = *itr;

fs << "[" << time_format(&fti->start_time)

<< " ~ " << time_format(&fti->end_time) << "] ";

for (int i = 0; i < fti->layer; ++i) {

fs << " " ;

} fs << fti->id << " " << fti->costs << "s\n";

/* summarize */

sum_unit &ref_sum_unit = sum[fti->id];

++ref_sum_unit.cn;

/* newly created */

if ( 1 == ref_sum_unit.cn ) {

ref_sum_unit.start_time = fti->start_time;

ref_sum_unit.end_time = fti->end_time;

} else {

ref_sum_unit.start_time = fti->start_time

< ref_sum_unit.start_time ?

fti->start_time : ref_sum_unit.start_time;

ref_sum_unit.end_time = fti->end_time

> ref_sum_unit.end_time ?

fti->start_time : ref_sum_unit.start_time;

}

ref_sum_unit.costs += fti->costs;

}

/* [start_time ~ end_time] process:id XXs */

/* [---------------------] func:id XXs XX times*/

/* [start_time ~ end_time] func:id XXs XX times*/

fs << "\n";

fs << "---------------------summary-------------------\n"

<< "[" << time_format(&pp.start_time) << " ~ "

<< time_format(&pp.end_time) << "] process:" << pp.id << " "

<< pp.costs << "s\n";

itr_sum = sum.begin();

for(;itr_sum != sum.end();++itr_sum) {

fs << "[" << time_format(&itr_sum->second.start_time) << " ~ "

<< time_format(&itr_sum->second.end_time) << "] "

<< itr_sum->first << " " << itr_sum->second.costs << "s "

<< itr_sum->second.cn << "times\n";

}

fs.close();

}

std::string time_format(time_t *t)

{ /* "Wed Jun 30 21:49:08 1993\n"

* convert to "21:49:08"

*/

char buff[50] = {0};

char *p = ctime_r(t, buff);

p[19] = 0;

p += 11;

return p;

}

void clear()

{

std::list::iterator litr;

std::vector::iterator vitr;

for (litr = cc.begin(); litr != cc.end(); ++litr)

delete *litr;

cc.clear();

for (vitr = ss.begin(); vitr != ss.end(); ++vitr)

delete *vitr;

ss.clear();

}

std::list cc;

std::vector ss;

process_time_info pp;

int auto_print; // 1:true 0:false default:true

public:

static ctrl* inst()

{

if (!s_ctrl) {

s_ctrl = new ctrl;

}

return s_ctrl;

}

~ctrl()

{

TT_DEBUG("~~~CTRL");

// clear();

}

private:

ctrl() : pp(pid()), auto_print(true)

{

TT_DEBUG("CCC CTRL");

clear();

time(&pp.start_time);

}

ctrl(const ctrl& o) : pp(o.pp.id){}

static ctrl *s_ctrl;

};

/* one record hold a time info data

* when a record is created/destroyed

* send a message to ctrler

* via constructor/destructor

*/

class record

{

public:

record(func_time_info *_data)

{

TT_DEBUG("new record: %s\n", _data->id.c_str());

dat = _data;

ctrl::inst()->push_back(dat);

}

~record()

{

TT_DEBUG("delete record: %s\n",ctrl::inst()->ss.back()->id.c_str());

ctrl::inst()->pop_back();

}

private:

func_time_info *dat;

};

NS_TT_END // namespace tt

#endif //__TIME_TRACE_UTILS__