serval-dna/performance_timing.c

/*
 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.
 */

#include "fdqueue.h"
#include "conf.h"

struct profile_total *stats_head=NULL;
struct call_stats *current_call=NULL;

void fd_clearstat(struct profile_total *s){
  s->max_time = 0;
  s->total_time = 0;
  s->child_time = 0;
  s->calls = 0;
}

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

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
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
  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
  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()
{
  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};
  
  stats_head = sort(stats_head);
  
  struct profile_total *stats = stats_head;
  while(stats!=NULL){
    /* Get total time spent doing everything */
    fd_tallystats(&total,stats);
    stats = stats->_next;
  }

  // Show periodic rhizome transfer information, but only
  // if there are some active rhizome transfers.
  if (rhizome_active_fetch_count()!=0)
    INFOF("Rhizome transfer progress: %"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64" (remaining %"PRIu64")",
	  rhizome_active_fetch_bytes_received(0),
	  rhizome_active_fetch_bytes_received(1),
	  rhizome_active_fetch_bytes_received(2),
	  rhizome_active_fetch_bytes_received(3),
	  rhizome_active_fetch_bytes_received(4),
	  rhizome_active_fetch_bytes_received(5),
          rhizome_fetch_queue_bytes());

  // 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
	    &&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;
  }
}

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");
  
  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;
}