According to Russ Allbery: > > Fabien Tassin writes: > > According to Russ Allbery: > > >> That was part of my mental design for the caching layer on the new > >> history API anyway, since I'd like to handle both pre-commit and > >> hopefully WIP that way. > > > Hmm. How deep is it in your own todo list ? ;) > > It's high, but it's a really large project. I would expect it to be at > least a couple of months, possibly much longer. It's hard for me to > predict how much time I'll have to work on it. I understand.. most of us have the same problem. BTW, here is a patch I've made in order to bench the history code of innd before trying touch the precommit cache. It adds a new ctlinnd command and an inn.conf parameters. I don't know if it should be committed or not but I think it should not break anything. Basically, this patch is a profiler for all HISxxx() functions. It creates a log file (which can grows very quickly, so be careful) that can be processed and analysed later. Note that I've also slightly changed the innd timer code to close some "unclosed" calls and track some uncounted calls. I'm still looking for the 10-20 missing percents but they are not related to history. Here is how I'm using the profiler.. news $ ctlinnd stathist /news/log/stathist.log Ok news $ sleep 1800 news $ ctlinnd stathist off Ok news $ stathist.pl /news/log/stathist.log Function Invoked Total(s) Min(ms) Avg(ms) Max(ms) HIShavearticle 283084 275.632036 0.028 0.974 816.508 HIScacheadd 50205 0.763823 0.007 0.015 1.881 HIScachelookup 283084 2.630648 0.007 0.009 1.164 HISlogstats 15 0.001470 0.064 0.098 0.260 HISremember 153 1.375373 1.201 8.989 38.009 HIScacheadd 153 0.003848 0.010 0.025 0.279 HISsync 3 0.000447 0.045 0.149 0.351 HISsync 6 0.006889 0.052 1.148 6.561 HISwrite 23013 240.367942 0.062 10.445 3397.019 HIScacheadd 23013 0.534562 0.008 0.023 0.940 HISsync 458 0.091440 0.035 0.200 8.751 Used that way, it will not count initialization and closing HIS calls. To include them, you have to use the inn.conf "stathist" parameter (the value is a file name), start innd, wait for a while and stop innd. Now, I have to understand these abnormaly high numbers that produce half of the working time of my innd (!!!). INND timer: Code region Time Pct Invoked Min(ms) Avg(ms) Max(ms) history grep 00:00:00.000 0.0% 0 0.000 0.000 0.000 history lookup 02:23:07.830 10.0% 14028834 0.021 0.612 2.011 history sync 00:00:11.936 0.0% 23274 0.000 0.513 108.227 history write 03:09:02.872 13.3% 1156492 4.623 9.808 14.027 idle 11:31:11.564 48.5% 102312046 0.265 0.405 0.666 TOTAL: 23:45:12 21:43:19.640 91.4% - - - - I wonder if someone has the same problem or if it is only me.. -- Fabien Tassin -+- fta@sofaraway.org -- Attached file included as plaintext by Listar -- diff -ur inn.orig/frontends/ctlinnd.c inn/frontends/ctlinnd.c --- inn.orig/frontends/ctlinnd.c Thu Dec 28 23:10:53 2000 +++ inn/frontends/ctlinnd.c Thu Jan 25 18:11:04 2001 @@ -93,6 +93,8 @@ 2, SC_SEND, TRUE }, { "shutdown", "reason...\t\tShut down server", 1, SC_SHUTDOWN, TRUE }, + { "stathist", "filename|off\t\tLog into filename some history stats", + 1, SC_STATHIST, FALSE }, { "status", "interval|off\t\tTurn innd status generation on or off", 1, SC_STATUS, FALSE }, { "kill", "signal site\t\tSend signal to site's process", diff -ur inn.orig/include/innconf.h inn/include/innconf.h --- inn.orig/include/innconf.h Thu Dec 28 23:10:55 2000 +++ inn/include/innconf.h Sun Jan 28 20:14:00 2001 @@ -335,6 +335,9 @@ { _CONF_DONTREJECTFILTERED, "", 2, 1 }, #define _CONF_KEEPMMAPPEDTHRESHOLD "keepmmappedthreshold" #define CONF_VAR_KEEPMMAPPEDTHRESHOLD 105 - { _CONF_KEEPMMAPPEDTHRESHOLD, "", 2, 1 } + { _CONF_KEEPMMAPPEDTHRESHOLD, "", 2, 1 }, +#define _CONF_STATHIST "stathist" +#define CONF_VAR_STATHIST 106 + { _CONF_STATHIST, "", 1, 0 } }; -#define MAX_CONF_VAR 106 +#define MAX_CONF_VAR 107 diff -ur inn.orig/include/inndcomm.h inn/include/inndcomm.h --- inn.orig/include/inndcomm.h Thu Dec 28 23:10:55 2000 +++ inn/include/inndcomm.h Thu Jan 25 18:13:16 2001 @@ -54,6 +54,7 @@ #define SC_RMGROUP 'p' #define SC_SEND 'A' #define SC_SHUTDOWN 'q' +#define SC_STATHIST 'H' #define SC_STATUS 'S' #define SC_SIGNAL 'B' #define SC_THROTTLE 'r' diff -ur inn.orig/include/libinn.h inn/include/libinn.h --- inn.orig/include/libinn.h Thu Dec 28 23:10:55 2000 +++ inn/include/libinn.h Sun Jan 28 20:05:38 2001 @@ -287,6 +287,7 @@ int nntplinklog; /* Put storage token into the log? */ int status; /* Status file update interval */ int timer; /* Performance monitoring interval */ + char *stathist; /* Filename for history profiler outputs */ /* System Tuning */ int badiocount; /* Failure count before dropping channel */ diff -ur inn.orig/innd/cc.c inn/innd/cc.c --- inn.orig/innd/cc.c Tue Jan 16 22:33:06 2001 +++ inn/innd/cc.c Thu Jan 25 18:24:50 2001 @@ -59,6 +59,7 @@ static const char * CCsend(char *av[]); static const char * CCshutdown(char *av[]); static const char * CCsignal(char *av[]); +static const char * CCstathist(char *av[]); static const char * CCstatus(char *av[]); static const char * CCthrottle(char *av[]); static const char * CCtimer(char *av[]); @@ -126,6 +127,7 @@ { SC_SEND, 2, CCsend }, { SC_SHUTDOWN, 1, CCshutdown }, { SC_SIGNAL, 2, CCsignal }, + { SC_STATHIST, 1, CCstathist }, { SC_STATUS, 1, CCstatus }, { SC_THROTTLE, 1, CCthrottle }, { SC_TIMER, 1, CCtimer }, @@ -1623,6 +1625,19 @@ value = atoi(av[0]); } innconf->timer = value; + return NULL; +} + +/* +** Log into filename some history stats +*/ +static const char * +CCstathist(char *av[]) +{ + if (EQ(av[0], "off")) + HISlogclose(); + else + HISlogto(av[0]); return NULL; } diff -ur inn.orig/innd/his.c inn/innd/his.c --- inn.orig/innd/his.c Thu Dec 28 23:10:56 2000 +++ inn/innd/his.c Thu Jan 25 19:48:46 2001 @@ -17,6 +17,14 @@ typedef enum {HIScachehit, HIScachemiss, HIScachedne} HISresult; +enum { S_HIScacheadd, S_HIScachelookup, S_HISsetup, S_HISsync, + S_HISlogstats, S_HISclose, S_HISfilesfor, S_HIShavearticle, + S_HISwrite, S_HISremember, S_HIS_MAX }; + +static struct timeval HISstat_start[S_HIS_MAX]; +static struct timeval HISstat_total[S_HIS_MAX]; +static unsigned long HISstat_count[S_HIS_MAX]; + static char *HIShistpath = NULL; static FILE *HISwritefp; static int HISreadfd; @@ -28,6 +36,66 @@ static int HISmisses; /* Not in cache, in history */ static int HISdne; /* Not in cache or history */ static time_t HISlastlog; /* Last time that we logged stats */ +static FILE *HISfdlog = NULL; /* filehandle for history logging purpose */ + +void HISlogclose() { + if (HISfdlog != NULL) + fclose(HISfdlog); + HISfdlog = NULL; +} + +void HISlogto(char *s) { + int i; + + HISlogclose(); + if ((HISfdlog = fopen(s, "a")) == NULL) + syslog(L_FATAL, "%s cant open %s %m", LogName, s); + /* initialize our counters */ + for (i = 0; i < S_HIS_MAX; i++) { + HISstat_start[i].tv_sec = 0; + HISstat_start[i].tv_usec = 0; + HISstat_total[i].tv_sec = 0; + HISstat_total[i].tv_usec = 0; + HISstat_count[i] = 0; + } +} + +static void HISlogger(char *s, int code) { + struct timeval tv; + struct tm *tm; + + if (HISfdlog == NULL) /* do nothing unless HISlogto() has been called */ + return; + + gettimeofday(&tv, NULL); + tm = localtime(&(tv.tv_sec)); + if (HISstat_start[code].tv_sec != 0) { + fprintf(HISfdlog, "%d/%d/%d %02d:%02d:%02d.%06d: [%d] %s (%.6f)\n", + tm->tm_year + 1900, tm->tm_mon + 1, tm->tm_mday, tm->tm_hour, + tm->tm_min, tm->tm_sec, tv.tv_usec, code, s, (float) tv.tv_sec + + (float) tv.tv_usec / 1000000 - (float) HISstat_start[code].tv_sec - + (float) HISstat_start[code].tv_usec / 1000000); + if (tv.tv_usec < HISstat_start[code].tv_usec) { + HISstat_total[code].tv_sec++; + HISstat_total[code].tv_usec += + tv.tv_usec - HISstat_start[code].tv_usec + 1000000; + } + else + HISstat_total[code].tv_usec += + tv.tv_usec - HISstat_start[code].tv_usec; + HISstat_total[code].tv_sec += tv.tv_sec - HISstat_start[code].tv_sec; + HISstat_count[code]++; + HISstat_start[code].tv_sec = 0; + HISstat_start[code].tv_usec = 0; + } + else { + fprintf(HISfdlog, "%d/%d/%d %02d:%02d:%02d.%06d: [%d] %s\n", + tm->tm_year + 1900, tm->tm_mon + 1, tm->tm_mday, tm->tm_hour, + tm->tm_min, tm->tm_sec, tv.tv_usec, code, s); + HISstat_start[code].tv_sec = tv.tv_sec; + HISstat_start[code].tv_usec = tv.tv_usec; + } +} /* ** Put an entry into the history cache @@ -36,12 +104,16 @@ HIScacheadd(HASH MessageID, bool Found) { unsigned int i, loc; - if (HIScache == NULL) + HISlogger("HIScacheadd begin", S_HIScacheadd); + if (HIScache == NULL) { + HISlogger("HIScacheadd end", S_HIScacheadd); return; + } memcpy(&loc, ((char *)&MessageID) + (sizeof(HASH) - sizeof(loc)), sizeof(loc)); i = loc % HIScachesize; memcpy((char *)&HIScache[i].Hash, (char *)&MessageID, sizeof(HASH)); HIScache[i].Found = Found; + HISlogger("HIScacheadd end", S_HIScacheadd); } /* @@ -53,17 +125,21 @@ if (HIScache == NULL) return HIScachedne; + HISlogger("HIScachelookup begin", S_HIScachelookup); memcpy(&loc, ((char *)&MessageID) + (sizeof(HASH) - sizeof(loc)), sizeof(loc)); i = loc % HIScachesize; if (memcmp((char *)&HIScache[i].Hash, (char *)&MessageID, sizeof(HASH)) == 0) { if (HIScache[i].Found) { HIShitpos++; + HISlogger("HIScachelookup end", S_HIScachelookup); return HIScachehit; } else { HIShitneg++; + HISlogger("HIScachelookup end", S_HIScachelookup); return HIScachemiss; } } else { + HISlogger("HIScachelookup end", S_HIScachelookup); return HIScachedne; } } @@ -76,6 +152,7 @@ { dbzoptions opt; + HISlogger("HISsetup begin", S_HISsetup); if (HISwritefp == NULL) { if (HIShistpath == NULL) HIShistpath = COPY(cpcatpath(innconf->pathdb, _PATH_HISTORY)); @@ -130,6 +207,7 @@ memset((void *)HIScache, '\0', HIScachesize * sizeof(_HIScache)); } HIShitpos = HIShitneg = HISmisses = HISdne = 0; + HISlogger("HISsetup end", S_HISsetup); } /* @@ -138,6 +216,7 @@ void HISsync(void) { + HISlogger("HISsync begin", S_HISsync); TMRstart(TMR_HISSYNC); if (HISdirty) { if (!dbzsync()) { @@ -147,14 +226,17 @@ HISdirty = 0; } TMRstop(TMR_HISSYNC); + HISlogger("HISsync end", S_HISsync); } static void HISlogstats(void) { + HISlogger("HISlogstats begin", S_HISlogstats); syslog(L_NOTICE, "ME HISstats %d hitpos %d hitneg %d missed %d dne", HIShitpos, HIShitneg, HISmisses, HISdne); HIShitpos = HIShitneg = HISmisses = HISdne = 0; + HISlogger("HISlogstats end", S_HISlogstats); } @@ -164,6 +246,7 @@ void HISclose(void) { + HISlogger("HISclose begin", S_HISclose); if (HISwritefp != NULL) { HISsync(); if (!dbzclose()) @@ -183,6 +266,7 @@ HIScachesize = 0; } TMRstop(TMR_HISSYNC); + HISlogger("HISclose end", S_HISclose); } @@ -198,17 +282,21 @@ int i; static TOKEN token; + HISlogger("HISfilesfor begin", S_HISfilesfor); TMRstart(TMR_HISGREP); - if (HISwritefp == NULL) + if (HISwritefp == NULL) { + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; + } /* Get the seek value into the history file. */ if (!dbzfetch(MessageID, &offset)) { TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; } - TMRstop(TMR_HISGREP); /* Get space. */ if (Files.Data == NULL) { @@ -217,8 +305,11 @@ } /* Seek to the specified location. */ - if (lseek(HISreadfd, offset, SEEK_SET) == -1) + if (lseek(HISreadfd, offset, SEEK_SET) == -1) { + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; + } /* Read the text until \n or EOF. */ for (Files.Used = 0; ; ) { @@ -241,14 +332,24 @@ } /* Move past the first two fields -- Message-ID and date info. */ - if ((p = strchr(Files.Data, HIS_FIELDSEP)) == NULL) + if ((p = strchr(Files.Data, HIS_FIELDSEP)) == NULL) { + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; - if ((p = strchr(p + 1, HIS_FIELDSEP)) == NULL) + } + if ((p = strchr(p + 1, HIS_FIELDSEP)) == NULL) { + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; + } if (!IsToken(++p)) { + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return NULL; } token = TextToToken(p); + TMRstop(TMR_HISGREP); + HISlogger("HISfilesfor end", S_HISfilesfor); return &token; } @@ -261,20 +362,26 @@ { bool val; - if ((Now.time - HISlastlog) > 3600) { + HISlogger("HIShavearticle begin", S_HIShavearticle); + if ((Now.time - HISlastlog) > 120) { /* was 3600 */ HISlogstats(); HISlastlog = Now.time; } TMRstart(TMR_HISHAVE); - if (HISwritefp == NULL) + if (HISwritefp == NULL) { + TMRstop(TMR_HISHAVE); + HISlogger("HIShavearticle end", S_HIShavearticle); return FALSE; + } switch (HIScachelookup(MessageID)) { case HIScachehit: TMRstop(TMR_HISHAVE); + HISlogger("HIShavearticle end", S_HIShavearticle); return TRUE; case HIScachemiss: TMRstop(TMR_HISHAVE); + HISlogger("HIShavearticle end", S_HIShavearticle); return FALSE; case HIScachedne: val = dbzexists(MessageID); @@ -284,9 +391,11 @@ else HISdne++; TMRstop(TMR_HISHAVE); + HISlogger("HIShavearticle end", S_HIShavearticle); return val; } TMRstop(TMR_HISHAVE); + HISlogger("HIShavearticle end", S_HIShavearticle); return FALSE; } @@ -301,10 +410,13 @@ off_t offset; int i; - if (HISwritefp == NULL) - return FALSE; - TMRstart(TMR_HISWRITE); + HISlogger("HISwrite begin", S_HISwrite); + if (HISwritefp == NULL) { + TMRstop(TMR_HISWRITE); + HISlogger("HISwrite end", S_HISwrite); + return FALSE; + } if (paths != NULL && paths[0] != '\0') { /* if (!innconf->storageapi) HISslashify(paths); */ } else @@ -330,6 +442,7 @@ syslog(L_ERROR, "%s cant write history %m", LogName); IOError("history", i); TMRstop(TMR_HISWRITE); + HISlogger("HISwrite end", S_HISwrite); return FALSE; } @@ -340,13 +453,15 @@ HashToText(hash), (double)offset); IOError("history database", i); TMRstop(TMR_HISWRITE); + HISlogger("HISwrite end", S_HISwrite); return FALSE; } HIScacheadd(hash, TRUE); - TMRstop(TMR_HISWRITE); + TMRstop(TMR_HISWRITE); /* not later as HISsync() has its own timer */ if (++HISdirty >= innconf->icdsynccount) HISsync(); + HISlogger("HISwrite end", S_HISwrite); return TRUE; } @@ -359,10 +474,14 @@ off_t offset; int i; + HISlogger("HISremember begin", S_HISremember); TMRstart(TMR_HISWRITE); - if (HISwritefp == NULL) + if (HISwritefp == NULL) { + TMRstop(TMR_HISWRITE); + HISlogger("HISremember end", S_HISremember); return FALSE; + } offset = ftello(HISwritefp); /* Convert the hash to hex */ @@ -377,6 +496,7 @@ syslog(L_ERROR, "%s cant write history %m", LogName); IOError("history", i); TMRstop(TMR_HISWRITE); + HISlogger("HISremember end", S_HISremember); return FALSE; } @@ -387,6 +507,7 @@ HashToText(hash), (double)offset); IOError("history database", i); TMRstop(TMR_HISWRITE); + HISlogger("HISremember end", S_HISremember); return FALSE; } HIScacheadd(hash, TRUE); @@ -394,5 +515,6 @@ if (++HISdirty >= innconf->icdsynccount) HISsync(); + HISlogger("HISremember end", S_HISremember); return TRUE; } diff -ur inn.orig/innd/innd.c inn/innd/innd.c --- inn.orig/innd/innd.c Thu Dec 28 23:10:56 2000 +++ inn/innd/innd.c Sun Jan 28 20:41:07 2001 @@ -385,6 +385,11 @@ Pathalias.Data = NEW(char, Pathalias.Used + 1); sprintf(Pathalias.Data, "%s!", innconf->pathalias); } + /* Trace history ? */ + if (innconf->stathist != NULL) { + syslog(L_NOTICE, "logging hist stats to %s", innconf->stathist); + HISlogto(innconf->stathist); + } i = dbzneedfilecount(); if (!fdreserve(2 + i)) { /* TEMPORARYOPEN, INND_HISTORY and i */ -- Attached file included as plaintext by Listar -- #!/usr/bin/perl -w # Parse log files created by innd history profiler # 2001/01/29 - Fabien Tassin use strict; use FileHandle; my $file = shift || "stathist.log"; if ($file eq '-h' || $file eq '--help') { print "Usage: stathist [logfile]\n"; exit 0; } sub parse { my $file = shift; my $f = new FileHandle $file; unless (defined $f) { print STDERR "Can't open file: $!\n"; return {}; } my $data = {}; my $begin = 1; my @stack = (); while (defined (my $line = <$f>)) { next if $begin && $line !~ / HIS(havearticle|write|setup) begin/; $begin = 0; chomp $line; my @c = split /[\[\]\(\) ]+/, $line; ($c[4] eq 'begin') && do { push @stack, $c[3]; my $d = $data; for my $l (@stack) { unless (defined $$d{$l}) { $$d{$l}{'min'} = 1E10; $$d{$l}{'total'} = $$d{$l}{'count'} = $$d{$l}{'max'} = 0; } $d = $$d{$l} } } || ($c[4] eq 'end') && do { my $d = $data; for my $l (@stack) { $d = $$d{$l}; } $$d{'count'}++; $$d{'total'} += $c[5]; $$d{'min'} = $c[5] if $$d{'min'} > $c[5]; $$d{'max'} = $c[5] if $$d{'max'} < $c[5]; pop @stack; }; } $f->close; $data; } sub report { my $data = shift; my $inc = shift; unless (defined $inc) { printf "%-16s %10s %14s %10s %10s %10s\n\n", "Function", "Invoked", "Total(s)", "Min(ms)", "Avg(ms)", "Max(ms)"; $inc = 0; } for my $key (sort keys %$data) { next unless $key =~ m/^HIS/; printf "%-16s %10d %14.6f %10.3f %10.3f %10.3f\n", (' ' x $inc) . $key, $$data{$key}{'count'}, $$data{$key}{'total'}, $$data{$key}{'min'} * 1000, $$data{$key}{'total'} / $$data{$key}{'count'} * 1000, $$data{$key}{'max'} * 1000; &report($$data{$key}, $inc + 1) } } my $data = &parse($file); &report($data);