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

/*
  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 <inttypes.h> // for PRIu64 on Android
#include "fdqueue.h"
#include "conf.h"
#include "debug.h"

__thread struct profile_total *stats_head=NULL;
__thread 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 || 
      (list->total_time == first->total_time && list->calls > first->calls)){
      if (left_tail){
	left_tail->_next = list;
	if (list->total_time > left_tail->total_time || 
	  (list->total_time == left_tail->total_time && list->calls > left_tail->calls))
	  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 ||
	  (list->total_time == right_tail->total_time && list->calls > right_tail->calls))
	  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,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;
  }

  // Report any functions that take too much time
  if (!IF_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;
}

DEFINE_ALARM(fd_periodicstats);
void fd_periodicstats(struct sched_ent *UNUSED(alarm))
{
  fd_showstats();
  fd_clearstats();
  time_ms_t now = gettime_ms();
  RESCHEDULE(&ALARM_STRUCT(fd_periodicstats), now+3000, TIME_MS_NEVER_WILL, now+3500);
}

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

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)
{
  DEBUGF(profiling, "%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.
  DEBUGF(profiling, "%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;
}