Improve performance timing diagnostics

Add __whence args to fd_func_enter() and fd_func_exit() so that their log
messages get reported from the location of the IN() or OUT() macro, not a line
in performance_timing.c.

Removed diagnostic information from the FATAL() message in fd_func_exit(), and
a comment explaining why (causes SEGV).
This commit is contained in:
Andrew Bettison 2012-11-12 14:34:30 +10:30
parent 3c69a45d42
commit cbc91d11e0
3 changed files with 18 additions and 19 deletions

View File

@ -204,13 +204,13 @@ static void call_alarm(struct sched_ent *alarm, int revents)
call_stats.totals = alarm->stats;
if (call_stats.totals)
fd_func_enter(&call_stats);
fd_func_enter(__HERE__, &call_stats);
alarm->poll.revents = revents;
alarm->function(alarm);
if (call_stats.totals)
fd_func_exit(&call_stats);
fd_func_exit(__HERE__, &call_stats);
}
int fd_poll()
@ -240,7 +240,7 @@ int fd_poll()
{
struct call_stats call_stats;
call_stats.totals=&poll_stats;
fd_func_enter(&call_stats);
fd_func_enter(__HERE__, &call_stats);
r = poll(fds, fdcount, ms);
if (debug & DEBUG_IO) {
strbuf b = strbuf_alloca(1024);
@ -255,7 +255,7 @@ int fd_poll()
}
DEBUGF("poll(fds=(%s), fdcount=%d, ms=%d) = %d", strbuf_str(b), fdcount, ms, r);
}
fd_func_exit(&call_stats);
fd_func_exit(__HERE__, &call_stats);
now=gettime_ms();
}

View File

@ -1,6 +1,6 @@
/*
Serval Distributed Numbering Architecture (DNA)
Copyright (C) 2012 Paul Gardner-Stephen
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
@ -171,7 +171,8 @@ void fd_periodicstats(struct sched_ent *alarm)
schedule(alarm);
}
void dump_stack(){
void dump_stack()
{
struct call_stats *call = current_call;
while(call){
if (call->totals)
@ -180,7 +181,7 @@ void dump_stack(){
}
}
int fd_func_enter(struct call_stats *this_call)
int fd_func_enter(struct __sourceloc __whence, struct call_stats *this_call)
{
this_call->enter_time=gettime_ms();
this_call->child_time=0;
@ -189,14 +190,14 @@ int fd_func_enter(struct call_stats *this_call)
return 0;
}
int fd_func_exit(struct call_stats *this_call)
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 (current_call != this_call)
FATALF("stack-trace corrupted: %s%s%s exited through %s()",
current_call?" entered through ":"no entry information, but",
current_call?current_call->totals->name:"",
current_call?"(), but":"",
this_call->totals->name);
FATAL("performance timing stack trace corrupted");
time_ms_t now = gettime_ms();
time_ms_t elapsed = now - this_call->enter_time;

View File

@ -776,21 +776,19 @@ void rhizome_server_poll(struct sched_ent *alarm);
int fd_clearstats();
int fd_showstats();
int fd_checkalarms();
int fd_func_exit(struct call_stats *this_call);
int fd_func_enter(struct call_stats *this_call);
int fd_func_enter(struct __sourceloc __whence, struct call_stats *this_call);
int fd_func_exit(struct __sourceloc __whence, struct call_stats *this_call);
void dump_stack();
#define IN() static struct profile_total _aggregate_stats={NULL,0,__FUNCTION__,0,0,0}; \
struct call_stats _this_call; \
_this_call.totals=&_aggregate_stats; \
fd_func_enter(&_this_call);
fd_func_enter(__HERE__, &_this_call);
#define OUT() fd_func_exit(&_this_call)
#define OUT() fd_func_exit(__HERE__, &_this_call)
#define RETURN(X) do { OUT(); return (X); } while (0);
#define RETURNNULL do { OUT(); return (NULL); } while (0);
int olsr_init_socket(void);
int olsr_send(struct overlay_frame *frame);