On Fri, 2010-11-05 at 15:08 +0100, Ralf Hildebrandt wrote:
> > > I'm wondering if the problem has to do with the way processes now do
> > > IPC
> >
> > That could very well be. Lots of time is spent in the kernel
>
> What exactly has changed - and what kind of data are the processes
> exchanging via IPCs?
> And which processes are talking to each other?
There's a lot more of IPC going on now. Each process at startup connects
to config process to read configuration (vs. reading it from environment
variables). State tracking is done in anvil process (vs. master process
internally). Logging is via pipes to log process instead of sockets to
master process (this should improve performance). Maybe other things I
can't think of now.
Anyway, I'd think the used system time is owned by some process(es).
Would be interesting to know what kind of logs you get with the attached
patch (e.g. run dovecot for an hour..day, stop it, gather all logs,
count the used system times per process type and see which ones used the
most).
diff -r 5a10aaf6f510 src/lib-master/master-service.c
--- a/src/lib-master/master-service.c Thu Nov 04 18:56:47 2010 +0000
+++ b/src/lib-master/master-service.c Fri Nov 05 15:22:51 2010 +0000
@@ -5,6 +5,7 @@
#include "ioloop.h"
#include "array.h"
#include "env-util.h"
+#include "time-util.h"
#include "home-expand.h"
#include "process-title.h"
#include "restrict-access.h"
@@ -19,6 +20,8 @@
#include <unistd.h>
#include <sys/stat.h>
#include <syslog.h>
+#include <sys/time.h>
+#include <sys/resource.h>
#define DEFAULT_CONFIG_FILE_PATH SYSCONFDIR"/dovecot.conf"
@@ -38,6 +41,7 @@
#define MASTER_SERVICE_DIE_TIMEOUT_MSECS (30*1000)
struct master_service *master_service;
+static struct timeval startup_timeval;
static void master_service_io_listeners_close(struct master_service *service);
static void master_service_refresh_login_state(struct master_service *service);
@@ -179,6 +183,7 @@
i_set_failure_prefix(t_strdup_printf("%s: ", name));
}
+ gettimeofday(&startup_timeval, NULL);
master_service_verify_version_string(service);
return service;
}
@@ -637,9 +642,26 @@
void master_service_deinit(struct master_service **_service)
{
struct master_service *service = *_service;
+ struct rusage ru;
*_service = NULL;
+ if (getrusage(RUSAGE_SELF, &ru) < 0)
+ i_error("getrusage() failed: %m");
+ else {
+ int diff = timeval_diff_msecs(&ioloop_timeval, &startup_timeval);
+
+ i_debug("rusage: real=%d.%d user=%lu.%lu sys=%lu.%lu reclaims=%lu "
+ "faults=%lu swaps=%lu bin=%lu bout=%lu signals=%lu "
+ "volcs=%lu involcs=%lu",
+ diff/1000, diff%1000,
+ (long)ru.ru_utime.tv_sec, (long)ru.ru_utime.tv_usec,
+ (long)ru.ru_stime.tv_sec, (long)ru.ru_stime.tv_usec,
+ ru.ru_minflt, ru.ru_majflt, ru.ru_nswap,
+ ru.ru_inblock, ru.ru_oublock, ru.ru_nsignals,
+ ru.ru_nvcsw, ru.ru_nivcsw);
+ }
+
master_service_io_listeners_remove(service);
master_service_close_config_fd(service);
