From e61482ad725deff2897fe1e4b27a500904caf3b5 Mon Sep 17 00:00:00 2001 From: Bron Gondwana Date: Wed, 24 Dec 2008 23:28:48 +1100 Subject: [PATCH] Command timer We want to be able to track which commands take a long time to run so we can figure out which parts of our interface to optimise or move "problem" users to less loaded servers. This patch tracks how long each command takes to run and puts an entry into the log if it's longer than the time configured by commandmintimer. --- imap/imapd.c | 36 ++++++++++++++++++++++++++++++------ lib/imapoptions | 4 ++++ lib/prot.c | 4 ++++ lib/util.c | 40 ++++++++++++++++++++++++++++++++++++++++ lib/util.h | 8 ++++++++ 5 files changed, 86 insertions(+), 6 deletions(-) diff --git a/imap/imapd.c b/imap/imapd.c index 7d294b5..c3bc97c 100644 --- a/imap/imapd.c +++ b/imap/imapd.c @@ -999,8 +999,10 @@ void cmdloop() int ret; int usinguid, havepartition, havenamespace, recursive; static struct buf tag, cmd, arg1, arg2, arg3, arg4; - char *p, shut[MAX_MAILBOX_PATH+1]; + char *p, shut[MAX_MAILBOX_PATH+1], cmdname[100]; const char *err; + const char * commandmintimer; + double commandmintimerd; prot_printf(imapd_out, "* OK [CAPABILITY "); capa_response(CAPA_PREAUTH); @@ -1025,6 +1027,15 @@ void cmdloop() close(fd); } + /* Get command timer logging paramater. This string + * is a time in seconds. Any command that takes >= + * this time to execute is logged */ + commandmintimer = config_getstring(IMAPOPT_COMMANDMINTIMER); + cmdtime_settimer(commandmintimer ? 1 : 0); + if (commandmintimer) { + commandmintimerd = atof(commandmintimer); + } + for (;;) { /* Flush any buffered output */ prot_flush(imapd_out); @@ -1070,11 +1081,9 @@ void cmdloop() eatline(imapd_in, c); continue; } - if (Uislower(cmd.s[0])) - cmd.s[0] = toupper((unsigned char) cmd.s[0]); - for (p = &cmd.s[1]; *p; p++) { - if (Uisupper(*p)) *p = tolower((unsigned char) *p); - } + lcase(cmd.s); + strncpy(cmdname, cmd.s, 99); + cmd.s[0] = toupper((unsigned char) cmd.s[0]); /* if we need to force a kick, do so */ if (referral_kick) { @@ -1091,6 +1100,9 @@ void cmdloop() /* Only Authenticate/Login/Logout/Noop/Capability/Id/Starttls allowed when not logged in */ if (!imapd_userid && !strchr("ALNCIS", cmd.s[0])) goto nologin; + + /* Start command timer */ + cmdtime_starttimer(); /* note that about half the commands (the common ones that don't hit the mailboxes file) now close the mailboxes file just in @@ -1864,6 +1876,7 @@ void cmdloop() c = getword(imapd_in, &arg1); if (c != ' ') goto missingargs; lcase(arg1.s); + strncpy(cmdname, arg1.s, 99); if (!strcmp(arg1.s, "fetch")) { goto fetch; } @@ -1980,6 +1993,17 @@ void cmdloop() eatline(imapd_in, c); } + /* End command timer - don't log "idle" commands */ + if (commandmintimer && strcmp("idle", cmdname)) { + double cmdtime, nettime; + cmdtime_endtimer(&cmdtime, &nettime); + if (cmdtime >= commandmintimerd) { + syslog(LOG_NOTICE, "cmdtimer: '%s' '%s' '%s' '%f' '%f' '%f'", + imapd_userid ? imapd_userid : "", + cmdname, imapd_mailbox ? imapd_mailbox->name : "", + cmdtime, nettime, cmdtime + nettime); + } + } continue; nologin: diff --git a/lib/imapoptions b/lib/imapoptions index 88f8f0f..f11ab6d 100644 --- a/lib/imapoptions +++ b/lib/imapoptions @@ -203,6 +203,10 @@ are listed with ``''. /* Number of seconds to wait before returning a timeout failure when performing a client connection (e.g., in a murder environment) */ +{ "commandmintimer", NULL, STRING } +/* Time in seconds. Any imap command that takes longer than this + time is logged. */ + { "configdirectory", NULL, STRING } /* The pathname of the IMAP configuration directory. This field is required. */ diff --git a/lib/prot.c b/lib/prot.c index 63a0098..5261f75 100644 --- a/lib/prot.c +++ b/lib/prot.c @@ -611,6 +611,7 @@ int prot_fill(struct protstream *s) s->timeout_mark = time(NULL) + s->read_timeout; do { + cmdtime_netstart(); #ifdef HAVE_SSL /* just do a SSL read instead if we're under a tls layer */ if (s->tls_conn != NULL) { @@ -621,6 +622,7 @@ int prot_fill(struct protstream *s) #else /* HAVE_SSL */ n = read(s->fd, s->buf, PROT_BUFSIZE); #endif /* HAVE_SSL */ + cmdtime_netend(); } while (n == -1 && errno == EINTR && !signals_poll()); if (n <= 0) { @@ -830,6 +832,7 @@ static int prot_flush_writebuffer(struct protstream *s, int n; do { + cmdtime_netstart(); #ifdef HAVE_SSL if (s->tls_conn != NULL) { n = SSL_write(s->tls_conn, (char *)buf, len); @@ -839,6 +842,7 @@ static int prot_flush_writebuffer(struct protstream *s, #else /* HAVE_SSL */ n = write(s->fd, buf, len); #endif /* HAVE_SSL */ + cmdtime_netend(); } while (n == -1 && errno == EINTR && !signals_poll()); return n; diff --git a/lib/util.c b/lib/util.c index d7b55ba..bbe3e3b 100644 --- a/lib/util.c +++ b/lib/util.c @@ -400,3 +400,43 @@ int become_cyrus(void) uid = newuid; return result; } + +static int cmdtime_enabled = 0; +static struct timeval cmdtime_start, cmdtime_end, nettime_start, nettime_end; +static double totaltime, cmdtime, nettime; + +double timesub(struct timeval * start, struct timeval * end) { + return (double)(end->tv_sec - start->tv_sec) + + (double)(end->tv_usec - start->tv_usec)/1000000.0; +} + +void cmdtime_settimer(int enable) { + cmdtime_enabled = enable; +} + +void cmdtime_starttimer() { + if (!cmdtime_enabled) { return; } + gettimeofday(&cmdtime_start, 0); + totaltime = cmdtime = nettime = 0.0; +} + +void cmdtime_endtimer(double * pcmdtime, double * pnettime) { + if (!cmdtime_enabled) { return; } + gettimeofday(&cmdtime_end, 0); + totaltime = timesub(&cmdtime_start, &cmdtime_end); + cmdtime = totaltime - nettime; + *pcmdtime = cmdtime; + *pnettime = nettime; +} + +void cmdtime_netstart() { + if (!cmdtime_enabled) { return; } + gettimeofday(&nettime_start, 0); +} + +void cmdtime_netend() { + if (!cmdtime_enabled) { return; } + gettimeofday(&nettime_end, 0); + nettime += timesub(&nettime_start, &nettime_end); +} + diff --git a/lib/util.h b/lib/util.h index fa537da..783f087 100644 --- a/lib/util.h +++ b/lib/util.h @@ -127,4 +127,12 @@ extern int become_cyrus(void); #define cyrus_isdigit(x) ((x) >= '0' && (x) <= '9') +/* Timing related funcs/vars */ +extern void cmdtime_settimer(int enable); +extern void cmdtime_starttimer(); +extern void cmdtime_endtimer(double * cmdtime, double * nettime); +extern void cmdtime_netstart(); +extern void cmdtime_netend(); + + #endif /* INCLUDED_UTIL_H */ -- 1.5.6.5