serval-dna/performance_timing.c

292 lines
8.2 KiB
C
Raw Normal View History

/*
Serval Distributed Numbering Architecture (DNA)
Copyright (C) 2012 Serval Project Inc.
This program is free software; you can redistribute it and/or
modify it under the terms of the GNU General Public License
as published by the Free Software Foundation; either version 2
of the License, or (at your option) any later version.
This program is distributed in the hope that it will be useful,
but WITHOUT ANY WARRANTY; without even the implied warranty of
MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
GNU General Public License for more details.
You should have received a copy of the GNU General Public License
along with this program; if not, write to the Free Software
Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
/*
Portions Copyright (C) 2013 Petter Reinholdtsen
Some rights reserved
Redistribution and use in source and binary forms, with or without
modification, are permitted provided that the following conditions are met:
1. Redistributions of source code must retain the above copyright
notice, this list of conditions and the following disclaimer.
2. Redistributions in binary form must reproduce the above copyright
notice, this list of conditions and the following disclaimer in
the documentation and/or other materials provided with the
distribution.
THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
"AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS
FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE
COPYRIGHT HOLDER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT,
INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING,
BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES;
LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER
CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN
ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
POSSIBILITY OF SUCH DAMAGE.
*/
#include "fdqueue.h"
#include "conf.h"
2012-07-02 06:34:00 +00:00
struct profile_total *stats_head=NULL;
struct call_stats *current_call=NULL;
2012-07-02 06:34:00 +00:00
void fd_clearstat(struct profile_total *s){
s->max_time = 0;
s->total_time = 0;
s->child_time = 0;
s->calls = 0;
}
2012-07-02 06:34:00 +00:00
int fd_tallystats(struct profile_total *total,struct profile_total *a)
{
total->total_time+=a->total_time;
total->calls+=a->calls;
if (a->max_time>total->max_time) total->max_time=a->max_time;
return 0;
}
2012-07-02 06:34:00 +00:00
int fd_showstat(struct profile_total *total, struct profile_total *a)
{
INFOF("%"PRId64"ms (%2.1f%%) in %d calls (max %"PRId64"ms, avg %.1fms, +child avg %.1fms) : %s",
(int64_t) a->total_time,
a->total_time*100.0/total->total_time,
a->calls,
(int64_t) a->max_time,
a->total_time*1.00/a->calls,
(a->total_time+a->child_time)*1.00/a->calls,
a->name);
return 0;
}
// sort the list of call times
2012-07-02 06:34:00 +00:00
struct profile_total *sort(struct profile_total *list){
struct profile_total *first = list;
// the left hand list will contain all items that took longer than the first item
2012-07-02 06:34:00 +00:00
struct profile_total *left_head = NULL;
struct profile_total *left_tail = NULL;
// the right hand list will contain all items that took less time than the first item
2012-07-02 06:34:00 +00:00
struct profile_total *right_head = NULL;
struct profile_total *right_tail = NULL;
// most of the cpu time is likely to be the same offenders
// don't sort a list that's already sorted
int left_already_sorted = 1;
int right_already_sorted = 1;
if (!list)
return NULL;
list = list->_next;
first->_next = NULL;
// split the list into two sub-lists based on the time of the first entry
while(list){
if (list->total_time > first->total_time){
if (left_tail){
left_tail->_next = list;
if (list->total_time > left_tail->total_time)
left_already_sorted = 0;
}else
left_head=list;
left_tail=list;
}else{
if (right_tail){
right_tail->_next = list;
if (list->total_time > right_tail->total_time)
right_already_sorted = 0;
}else
right_head=list;
right_tail=list;
}
list = list->_next;
}
// sort the left sub-list
if (left_tail){
left_tail->_next=NULL;
if (!left_already_sorted){
left_head = sort(left_head);
// find the tail again
left_tail = left_head;
while(left_tail->_next)
left_tail = left_tail->_next;
}
// add the first item after the left list
left_tail->_next = first;
}else
left_head = first;
left_tail = first;
// sort the right sub-list
if (right_tail){
right_tail->_next=NULL;
if (!right_already_sorted)
right_head = sort(right_head);
left_tail->_next = right_head;
}
return left_head;
}
int fd_clearstats()
{
2012-07-02 06:34:00 +00:00
struct profile_total *stats = stats_head;
while(stats!=NULL){
fd_clearstat(stats);
stats = stats->_next;
}
return 0;
}
int fd_showstats()
{
struct profile_total total={NULL, 0, "Total", 0,0,0,0};
stats_head = sort(stats_head);
2012-07-02 06:34:00 +00:00
struct profile_total *stats = stats_head;
while(stats!=NULL){
/* Get total time spent doing everything */
fd_tallystats(&total,stats);
stats = stats->_next;
}
2013-11-04 03:45:08 +00:00
// Show periodic rhizome transfer information
rhizome_fetch_log_short_status();
// Report any functions that take too much time
if (!config.debug.timing)
{
stats = stats_head;
while(stats!=NULL){
/* If a function spends more than 1 second in any
notionally 3 second period, then dob on it */
if ((stats->total_time>1000 || stats->calls > 10000)
&& strcmp(stats->name,"Idle (in poll)"))
fd_showstat(&total,stats);
stats = stats->_next;
}
}
else {
INFOF("servald time usage stats:");
stats = stats_head;
while(stats!=NULL){
/* Get total time spent doing everything */
if (stats->calls)
fd_showstat(&total,stats);
stats = stats->_next;
}
fd_showstat(&total,&total);
}
return 0;
}
void fd_periodicstats(struct sched_ent *alarm)
{
fd_showstats();
fd_clearstats();
alarm->alarm = gettime_ms()+3000;
alarm->deadline = alarm->alarm+1000;
schedule(alarm);
}
void dump_stack(int log_level)
{
struct call_stats *call = current_call;
while(call){
if (call->totals)
LOGF(log_level, "%s",call->totals->name);
call=call->prev;
}
}
2013-11-25 02:22:43 +00:00
unsigned fd_depth()
{
unsigned depth = 0;
struct call_stats *call;
for (call = current_call; call; call = call->prev)
++depth;
return depth;
}
int fd_func_enter(struct __sourceloc __whence, struct call_stats *this_call)
{
if (config.debug.profiling)
DEBUGF("%s called from %s() %s:%d",
__FUNCTION__,__whence.function,__whence.file,__whence.line);
this_call->enter_time=gettime_ms();
this_call->child_time=0;
this_call->prev = current_call;
current_call = this_call;
return 0;
}
int fd_func_exit(struct __sourceloc __whence, struct call_stats *this_call)
{
// If current_call does not match this_call, then all bets are off as to where it points. It
// probably points to somewhere on the stack (see the IN() macro) that has since been overwritten,
// so no sense in trying to print its contents in a diagnostic message; that would just cause
// a SEGV.
if (config.debug.profiling)
DEBUGF("%s called from %s() %s:%d",
__FUNCTION__,__whence.function,__whence.file,__whence.line);
if (current_call != this_call)
FATAL("performance timing stack trace corrupted");
2012-08-09 02:44:32 +00:00
time_ms_t now = gettime_ms();
time_ms_t elapsed = now - this_call->enter_time;
current_call = this_call->prev;
if (this_call->totals && !this_call->totals->_initialised){
this_call->totals->_initialised=1;
this_call->totals->_next = stats_head;
fd_clearstat(this_call->totals);
stats_head = this_call->totals;
}
if (current_call)
current_call->child_time+=elapsed;
elapsed-=this_call->child_time;
if (this_call->totals){
this_call->totals->total_time+=elapsed;
this_call->totals->child_time+=this_call->child_time;
this_call->totals->calls++;
if (elapsed>this_call->totals->max_time) this_call->totals->max_time=elapsed;
}
return 0;
}