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