Hi, here is a patch that adds a timer to gather innfeed profiling data. There's a second patch for innreport that creates a table like for innd. The timer is activated by the same parameter as the innd timer in inn.conf. It covers ~99% of the total time on my server. Here is a sample for about one hour and two innfeeds running : INNfeed timer: Code region Time Pct Invoked Min(ms) Avg(ms) Max(ms) article new 00:00:00.682 0.0% 92223 0.005 0.007 0.011 article prepare 00:00:00.390 0.0% 384006 0.001 0.001 0.002 article read 00:09:07.479 6.3% 52049 0.338 10.519 47.055 backlog stats 00:00:03.613 0.0% 1071489 0.000 0.003 0.007 callbacks 00:00:00.001 0.0% 154 0.000 0.006 0.007 data read 00:00:06.841 0.1% 451901 0.000 0.015 0.019 data write 00:01:07.941 0.8% 994719 0.019 0.068 0.121 idle 02:13:01.870 91.7% 1071489 4.258 7.449 1174.270 status file 00:00:02.147 0.0% 852 2.143 2.520 2.806 TOTAL: 02:25:05 02:23:30.964 98.9% - - - - [ Hope listar will not eat the attachments.. ] -- Fabien Tassin -+- fta@sofaraway.org -- Attached file included as plaintext by Listar -- diff -urN innfeed.orig/Makefile innfeed/Makefile --- innfeed.orig/Makefile Tue Aug 1 22:42:53 2000 +++ innfeed/Makefile Wed Jan 17 14:34:07 2001 @@ -8,7 +8,7 @@ SOURCES = article.c buffer.c config_l.c config_y.c \ endpoint.c host.c innlistener.c main.c misc.c \ - startinnfeed.c tape.c version.c + startinnfeed.c tape.c timer.c version.c INCLUDES = article.h buffer.h configfile.h config_y.h connection.h \ endpoint.h host.h innfeed.h innlistener.h misc.h msgs.h \ @@ -17,7 +17,7 @@ # The objects linked into innfeed. All SOURCES except startinnfeed. OBJECTS = article.o buffer.o config_l.o config_y.o \ endpoint.o host.o innlistener.o main.o misc.o tape.o \ - version.o + timer.o version.o INSTALLED = $(D)$(PATHBIN)/innfeed \ $(D)$(PATHBIN)/procbatch \ @@ -115,13 +115,15 @@ ../include/storage.h article.h misc.h buffer.h endpoint.h msgs.h buffer.o: buffer.c innfeed.h buffer.h misc.h ../include/config.h \ ../include/inn/defines.h -config_l.o: config_l.c innfeed.h configfile.h config_y.h +config_l.o: config_l.c innfeed.h configfile.h config_y.h \ + ../include/libinn.h ../include/inn/defines.h ../include/config.h config_y.o: config_y.c innfeed.h ../include/config.h \ - ../include/inn/defines.h ../include/clibrary.h configfile.h msgs.h \ - misc.h + ../include/inn/defines.h ../include/clibrary.h configfile.h \ + ../include/libinn.h msgs.h misc.h endpoint.o: endpoint.c innfeed.h ../include/config.h \ - ../include/inn/defines.h ../include/clibrary.h ../include/libinn.h \ - buffer.h misc.h configfile.h endpoint.h host.h msgs.h + ../include/inn/defines.h ../include/clibrary.h \ + ../include/portable/time.h ../include/libinn.h buffer.h misc.h \ + configfile.h endpoint.h host.h msgs.h host.o: host.c innfeed.h ../include/config.h ../include/inn/defines.h \ ../include/clibrary.h ../include/libinn.h article.h misc.h buffer.h \ configfile.h connection.h endpoint.h host.h innlistener.h msgs.h \ @@ -143,4 +145,6 @@ tape.o: tape.c innfeed.h ../include/config.h ../include/inn/defines.h \ ../include/clibrary.h ../include/libinn.h article.h misc.h \ configfile.h endpoint.h msgs.h tape.h +timer.o: timer.c ../include/clibrary.h ../include/config.h \ + ../include/inn/defines.h innfeed.h version.o: version.c diff -urN innfeed.orig/article.c innfeed/article.c --- innfeed.orig/article.c Thu Dec 28 23:11:00 2000 +++ innfeed/article.c Wed Jan 17 17:58:08 2001 @@ -210,6 +210,7 @@ { Article newArt = NULL ; + TMRstart(TMR_NEWARTICLE); if (hashTable == NULL) { /* first-time through initialization. */ int i ; @@ -265,7 +266,7 @@ newArt->refCount++ ; d_printf (2,"Reusing existing article for %s\nx",msgid) ; } - + TMRstop(TMR_NEWARTICLE); return newArt ; } @@ -550,6 +551,7 @@ ASSERT (article->contents == NULL) ; + TMRstart(TMR_READART); if (maxBytesInUse == 0) maxBytesInUse = SOFT_ARTICLE_BYTE_LIMIT ; @@ -565,6 +567,7 @@ syslog(LOG_ERR, "Could not retrieve %s: %s", article->fname, SMerrorstr); article->articleOk = false; + TMRstop(TMR_READART); return false; } } @@ -577,16 +580,19 @@ if (fstat (fd, &sb) < 0) { article->articleOk = false ; syslog (LOG_ERR,FSTAT_FAILURE,article->fname) ; + TMRstop(TMR_READART); return false; } if (!S_ISREG (sb.st_mode)) { article->articleOk = false ; syslog (LOG_ERR,REGFILE_FAILURE,article->fname) ; + TMRstop(TMR_READART); return false; } if (sb.st_size == 0) { article->articleOk = false ; syslog (LOG_ERR,EMPTY_ARTICLE,article->fname) ; + TMRstop(TMR_READART); return false; } articlesize = sb.st_size; @@ -602,6 +608,7 @@ syslog (LOG_NOTICE,NO_ARTICLE,article->msgid,article->fname) ; article->loggedMissing = true ; } + TMRstop(TMR_READART); return false; } amtToRead = (size_t) articlesize ; @@ -748,7 +755,8 @@ /* If we're not useing storage api, we should close a valid file descriptor */ if (!article->arthandle && (fd >= 0)) close (fd) ; - + + TMRstop(TMR_READART); return (article->contents != NULL ? true : false) ; } @@ -783,13 +791,19 @@ int buffLen = 0 ; int buffIdx = 0 ; char *start, *end ; - Buffer contents = artGetContents (article) ; /* returns a reference */ + Buffer contents ; - if (contents == NULL) + contents = artGetContents (article) ; /* returns a reference */ + + TMRstart(TMR_PREPART); + if (contents == NULL) { + TMRstop(TMR_PREPART); return false ; + } else if (article->nntpBuffers != NULL) { delBuffer (contents) ; + TMRstop(TMR_PREPART); return true ; /* already done */ } @@ -840,7 +854,7 @@ delBuffer (contents) ; /* the article is still holding a reference */ article->nntpBuffers = nntpBuffs ; - + TMRstop(TMR_PREPART); return true ; } diff -urN innfeed.orig/endpoint.c innfeed/endpoint.c --- innfeed.orig/endpoint.c Thu Dec 28 23:11:05 2000 +++ innfeed/endpoint.c Thu Jan 18 16:11:17 2001 @@ -630,6 +630,7 @@ keepSelecting = 1 ; xsignal (SIGPIPE, pipeHandler) ; + TMRinit(); while (keepSelecting) { struct timeval timeout ; @@ -663,11 +664,16 @@ } /* calculate host backlog statistics */ + TMRstart(TMR_BACKLOGSTATS); gCalcHostBlStat (); + TMRstop(TMR_BACKLOGSTATS); + TMRstart(TMR_IDLE); sval = select (highestFd + 1, &rSet, &wSet, &eSet, twait) ; + TMRstop(TMR_IDLE); timePasses () ; + TMRmainloophook(); if (sval == 0 && twait == NULL) die ("No fd's ready and no timeouts") ; @@ -874,7 +880,9 @@ ep->workCbk = NULL ; ep->workData = NULL ; + TMRstart(TMR_CALLBACK); func (ep,data) ; + TMRstop(TMR_CALLBACK); } } @@ -967,6 +975,7 @@ size_t amt = 0 ; IoStatus rval = IoIncomplete ; + TMRstart(TMR_READ); for (i = currIdx ; buffers && buffers [i] != NULL ; i++) bCount++ ; @@ -1075,7 +1084,7 @@ } else rval = IoDone ; - + TMRstop(TMR_READ); return rval ; } @@ -1091,6 +1100,7 @@ u_int currIdx = endp->outBufferIdx ; IoStatus rval = IoIncomplete ; + TMRstart(TMR_WRITE); for (i = currIdx ; buffers && buffers [i] != NULL ; i++) bCount++ ; @@ -1183,6 +1193,7 @@ else rval = IoDone ; + TMRstop(TMR_WRITE); return rval ; } diff -urN innfeed.orig/host.c innfeed/host.c --- innfeed.orig/host.c Thu Dec 28 23:11:05 2000 +++ innfeed/host.c Thu Jan 18 15:49:12 2001 @@ -2935,7 +2935,7 @@ u_int peerNum = 0, actConn = 0, slpConn = 0, maxcon = 0 ; static bool logged = false ; static bool flogged = false ; - + time_t now; if (statusFile == NULL && !logged) { @@ -2961,6 +2961,7 @@ lastStatusLog = theTime() ; + TMRstart(TMR_STATUSFILE); if ((fp = fopen (statusFile,"w")) == NULL) { if ( !flogged ) @@ -3109,6 +3110,7 @@ fclose (fp) ; } + TMRstop(TMR_STATUSFILE); } /* @@ -3291,7 +3293,7 @@ static void hostStatsTimeoutCbk (TimeoutId tid, void *data) { Host host = (Host) data ; - time_t now = theTime () ; + time_t delta, now = theTime () ; (void) tid ; /* keep lint happy */ @@ -3302,7 +3304,6 @@ if (now - lastStatusLog >= statsPeriod) hostLogStatus () ; - host->statsId = prepareSleep (hostStatsTimeoutCbk, statsPeriod, host) ; } diff -urN innfeed.orig/innfeed.h innfeed/innfeed.h --- innfeed.orig/innfeed.h Thu Dec 28 23:11:05 2000 +++ innfeed/innfeed.h Thu Jan 18 16:13:03 2001 @@ -261,4 +261,10 @@ #define DONT_NEED_U_INT 1 #endif +/* some timer constants */ + +typedef enum { TMR_IDLE, TMR_BACKLOGSTATS, TMR_STATUSFILE, TMR_NEWARTICLE, + TMR_READART, TMR_PREPART, TMR_READ, TMR_WRITE, TMR_CALLBACK, TMR_MAX +} TMRTYPE; + #endif /* innfeed_h__ */ diff -urN innfeed.orig/timer.c innfeed/timer.c --- innfeed.orig/timer.c Thu Jan 1 01:00:00 1970 +++ innfeed/timer.c Thu Jan 18 16:13:42 2001 @@ -0,0 +1,97 @@ +/* timer.c */ + +/* A timer for innfeed to gather profiling data. The code is based upon + the original innd timer. See ../innd/timer.c for details. */ +/* Fabien Tassin 2001-01-16 */ + +#include +#include +#include + +#include "clibrary.h" +#include "innfeed.h" +#include "libinn.h" + +unsigned start[TMR_MAX]; +unsigned cumulative[TMR_MAX]; +unsigned count[TMR_MAX]; + +int maxtimer = 0; +unsigned last_summary; + +static unsigned gettime(void) { + static int init = 0; + static struct timeval start_tv; + struct timeval tv; + + if (! init) { + gettimeofday(&start_tv, NULL); + init++; + } + gettimeofday(&tv, NULL); + return((tv.tv_sec - start_tv.tv_sec) * 1000 + + (tv.tv_usec - start_tv.tv_usec) / 1000); +} + +void TMRinit(void) { + int i; + + for (i = 0; i < TMR_MAX; i++) + count[i] = start[i] = cumulative[i] = 0; +} + +void TMRdosummary(unsigned secs) { + char buffer[8192]; + char buf[256]; + char *str; + int i; + + sprintf(buffer, "ME time %d ", secs); + for (i = 0; i < maxtimer; i++) { + str = "???"; + switch (i) { + case TMR_IDLE: str = "idle"; break; + case TMR_BACKLOGSTATS: str = "blstats"; break; + case TMR_STATUSFILE: str = "stsfile"; break; + case TMR_NEWARTICLE: str = "newart"; break; + case TMR_READART: str = "readart"; break; + case TMR_PREPART: str = "prepart"; break; + case TMR_READ: str = "read"; break; + case TMR_WRITE: str = "write"; break; + case TMR_CALLBACK: str = "cb"; break; + } + sprintf(buf, "%s %d(%d) ", str, cumulative[i], count[i]); + cumulative[i] = count[i] = 0; + strcat(buffer, buf); + } + syslog(L_NOTICE, "%s", buffer); +} + +void TMRstart(TMRTYPE t) { + if (!innconf->timer) + return; + if (!maxtimer) + maxtimer = TMR_MAX; + start[t] = gettime(); +} + + +void TMRstop(TMRTYPE t) { + if (!innconf->timer) + return; + cumulative[t] += gettime() - start[t]; + count[t]++; +} + +void TMRmainloophook(void) { + unsigned now; + + if (!innconf->timer) + return; + now = gettime(); + if (now - last_summary > (innconf->timer * 1000)) { + TMRdosummary(now - last_summary); + last_summary = now; + } +} + -- Attached file included as plaintext by Listar -- --- lib/innreport_inn.pm.orig Wed Oct 25 09:07:18 2000 +++ lib/innreport_inn.pm Thu Jan 18 17:06:52 2001 @@ -47,6 +47,18 @@ perl => 'perl filter', python => 'python filter'); +my %innfeed_timer_names = ( + 'idle' => 'idle', + 'blstats' => 'backlog stats', + 'stsfile' => 'status file', + 'newart' => 'article new', + 'prepart' => 'article prepare', + 'readart' => 'article read', + 'read' => 'data read', + 'write' => 'data write', + 'cb' => 'callbacks', +); + # init innd timer foreach (values %timer_names) { $innd_time_min{$_} = $MIN; @@ -56,6 +68,14 @@ } $innd_time_times = 0; # ... +# init innfeed timer +foreach (values %innfeed_timer_names) { + $innfeed_time_min{$_} = $MIN; + $innfeed_time_max{$_} = $MAX; + $innfeed_time_time{$_} = 0; # to avoid a warning... Perl < 5.004 + $innfeed_time_num{$_} = 0; # ... +} +$innfeed_time_times = 0; # ... # collect: Used to collect the data. sub collect { @@ -632,6 +652,28 @@ $innfeed_shrunk{$file} += $s1 - $s2; return 1; } + # profile timer + # ME time X nnnn X(X) [...] + return 1 if $left =~ m/backlogstats/; + if ($left =~ m/^\S+\s+ # ME + time\ (\d+)\s+ # time + ((?:\S+\ \d+\(\d+\)\s*)+) # timer values + $/ox) { + $innfeed_time_times += $1; + my $timers = $2; + + while ($timers =~ /(\S+) (\d+)\((\d+)\)\s*/g) { + my $name = $innfeed_timer_names{$1} || $1; + my $average = $2 / ($3 || 1); + $innfeed_time_time{$name} += $2; + $innfeed_time_num{$name} += $3; + $innfeed_time_min{$name} = $average + if ($3 && $innfeed_time_min{$name} > $average); + $innfeed_time_max{$name} = $average + if ($3 && $innfeed_time_max{$name} < $average); + } + return 1; + } # xxx grabbing external tape file return 1 if $left =~ m/ grabbing external tape file/o; # hostChkCxns - maxConnections was @@ -1689,13 +1731,25 @@ #$innd_time_max{$key} /= 1000; } } - + if (%innfeed_time_min) { + foreach $key (keys (%innfeed_time_min)) { + $innfeed_time_min{$key} = 0 if ($innfeed_time_min{$key} == $MIN); + $innfeed_time_max{$key} = 0 if ($innfeed_time_max{$key} == $MAX); + } + } # remove the innd timer stats if not used. unless ($innd_time_times) { undef %innd_time_min; undef %innd_time_max; undef %innd_time_num; undef %innd_time_time; + } + # same thing for innfeed timer + unless ($innfeed_time_times) { + undef %innfeed_time_min; + undef %innfeed_time_max; + undef %innfeed_time_num; + undef %innfeed_time_time; } # adjust the crosspost stats. diff -u etc/innreport.conf.orig etc/innreport.conf --- etc/innreport.conf.orig Sat Nov 18 01:34:31 2000 +++ etc/innreport.conf Wed Jan 17 17:30:34 2001 @@ -254,6 +270,64 @@ format_name "%10s"; format "%10.3f"; value "$innd_time_max{$key}"; + format_total "%9s-"; + total ""; + }; +}; + +section innfeed_timer { + title "INNfeed timer:"; + data "%innfeed_time_time"; + column { + name "Code region"; + format "%-15.15s"; + value "$key"; + format_total "TOTAL: %-8.8s"; + total "time_ms($innfeed_time_times)"; + }; + column { + name "Time"; + format "%13s"; + value "time_ms($innfeed_time_time{$key})"; + total "time_ms(total(%innfeed_time_time))"; + }; + column { + name "Pct"; + format_name "%6s"; + format "%5.1f%%"; + value "100 * $innfeed_time_time{$key} / $innfeed_time_times"; + total "100 * total(%innfeed_time_time) / + $innfeed_time_times"; + }; + column { + name "Invoked"; + format "%10s"; + value "$innfeed_time_num{$key}"; + format_total "%9s-"; + total ""; + }; + column { + name "Min(ms)"; + format_name "%9s"; + format "%9.3f"; + value "$innfeed_time_min{$key}"; + format_total "%8s-"; + total ""; + }; + column { + name "Avg(ms)"; + format_name "%10s"; + format "%10.3f"; + value "$innfeed_time_time{$key} / + ($innfeed_time_num{$key} ? $innfeed_time_num{$key} : 1)"; + format_total "%9s-"; + total ""; + }; + column { + name "Max(ms)"; + format_name "%10s"; + format "%10.3f"; + value "$innfeed_time_max{$key}"; format_total "%9s-"; total ""; };