- introduce log_trace(TRACE_SCHEDULER, ...)

- simplify a tiny tiny bit the scheduler loop
- no functional change (yet)

3 files changed, 66 insertions, 54 deletions

diff --git a/usr.sbin/smtpd/scheduler.c b/usr.sbin/smtpd/scheduler.c
index 7f9b5e33e8c..92cb85ec348 100644
--- a/usr.sbin/smtpd/scheduler.c
+++ b/usr.sbin/smtpd/scheduler.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: scheduler.c,v 1.4 2012/07/09 09:57:53 gilles Exp $	*/
+/*	$OpenBSD: scheduler.c,v 1.5 2012/07/09 17:57:54 gilles Exp $	*/
 
 /*
  * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org>
@@ -56,7 +56,7 @@ static void scheduler_remove_envelope(u_int64_t);
 static int scheduler_process_envelope(u_int64_t);
 static int scheduler_process_batch(enum delivery_type, u_int64_t);
 static int scheduler_check_loop(struct envelope *);
-static int scheduler_message_to_scheduler(u_int32_t);
+static int scheduler_load_message(u_int32_t);
 
 static struct scheduler_backend *backend = NULL;
 
@@ -73,14 +73,17 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 	switch (imsg->hdr.type) {
 	case IMSG_QUEUE_COMMIT_MESSAGE:
 		e = imsg->data;
-		scheduler_message_to_scheduler(evpid_to_msgid(e->id));
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_QUEUE_COMMIT_MESSAGE: %016"PRIx64, e->id);
+		scheduler_load_message(evpid_to_msgid(e->id));
 		scheduler_reset_events();
 		return;
 
 	case IMSG_QUEUE_DELIVERY_OK:
 		stat_decrement(STATS_SCHEDULER);
 		e = imsg->data;
-		log_debug("queue_delivery_ok: %016"PRIx64, e->id);
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_QUEUE_DELIVERY_OK: %016"PRIx64, e->id);
 		backend->remove(e->id);
 		queue_envelope_delete(e);
 		return;
@@ -88,9 +91,10 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 	case IMSG_QUEUE_DELIVERY_TEMPFAIL:
 		stat_decrement(STATS_SCHEDULER);
 		e = imsg->data;
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_QUEUE_DELIVERY_TEMPFAIL: %016"PRIx64, e->id);
 		e->retry++;
 		queue_envelope_update(e);
-		log_debug("queue_delivery_tempfail: %016"PRIx64, e->id);
 		scheduler_info(&si, e);
 		backend->insert(&si);
 		scheduler_reset_events();
@@ -99,10 +103,10 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 	case IMSG_QUEUE_DELIVERY_PERMFAIL:
 		stat_decrement(STATS_SCHEDULER);
 		e = imsg->data;
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_QUEUE_DELIVERY_PERMFAIL: %016"PRIx64, e->id);
 		if (e->type != D_BOUNCE && e->sender.user[0] != '\0') {
 			bounce_record_message(e, &bounce);
-			log_debug("queue_delivery_permfail: %016"PRIx64,
-			    bounce.id);
 			scheduler_info(&si, &bounce);
 			backend->insert(&si);
 			scheduler_reset_events();
@@ -112,6 +116,7 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 		return;
 
 	case IMSG_MDA_SESS_NEW:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_MDA_SESS_NEW");
 		stat_decrement(STATS_MDA_SESSION);
 		if (env->sc_maxconn - stat_get(STATS_MDA_SESSION, STAT_ACTIVE))
 			env->sc_flags &= ~SMTPD_MDA_BUSY;
@@ -119,6 +124,7 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 		return;
 
 	case IMSG_BATCH_DONE:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_BATCH_DONE");
 		stat_decrement(STATS_MTA_SESSION);
 		if (env->sc_maxconn - stat_get(STATS_MTA_SESSION, STAT_ACTIVE))
 			env->sc_flags &= ~SMTPD_MTA_BUSY;
@@ -127,9 +133,10 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 
 	case IMSG_SMTP_ENQUEUE:
 		e = imsg->data;
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_SMTP_ENQUEUE: %016"PRIx64, e->id);
 		if (imsg->fd < 0 || !bounce_session(imsg->fd, e)) {
 			queue_envelope_update(e);
-			log_debug("smtp_enqueue: %016"PRIx64, e->id);
 			scheduler_info(&si, e);
 			backend->insert(&si);
 			scheduler_reset_events();
@@ -138,37 +145,48 @@ scheduler_imsg(struct imsgev *iev, struct imsg *imsg)
 		return;
 
 	case IMSG_QUEUE_PAUSE_MDA:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_QUEUE_PAUSE_MDA");
 		env->sc_flags |= SMTPD_MDA_PAUSED;
 		return;
 
 	case IMSG_QUEUE_RESUME_MDA:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_QUEUE_RESUME_MDA");
 		env->sc_flags &= ~SMTPD_MDA_PAUSED;
 		scheduler_reset_events();
 		return;
 
 	case IMSG_QUEUE_PAUSE_MTA:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_QUEUE_PAUSE_MTA");
 		env->sc_flags |= SMTPD_MTA_PAUSED;
 		return;
 
 	case IMSG_QUEUE_RESUME_MTA:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_QUEUE_RESUME_MTA");
 		env->sc_flags &= ~SMTPD_MTA_PAUSED;
 		scheduler_reset_events();
 		return;
 
 	case IMSG_CTL_VERBOSE:
+		log_trace(TRACE_SCHEDULER, "scheduler: IMSG_CTL_VERBOSE");
 		log_verbose(*(int *)imsg->data);
 		return;
 
 	case IMSG_SCHEDULER_SCHEDULE:
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_SCHEDULER_SCHEDULE: %016"PRIx64,
+		    *(u_int64_t *)imsg->data);
 		backend->force(*(u_int64_t *)imsg->data);
 		scheduler_reset_events();		
 		return;
 
-	case IMSG_SCHEDULER_REMOVE: {
+	case IMSG_SCHEDULER_REMOVE:
+		log_trace(TRACE_SCHEDULER,
+		    "scheduler: IMSG_SCHEDULER_REMOVE: %016"PRIx64,
+		    *(u_int64_t *)imsg->data);
 		scheduler_remove(*(u_int64_t *)imsg->data);
 		scheduler_reset_events();
 		return;
-	}
+
 	}
 
 	errx(1, "scheduler_imsg: unexpected %s imsg", imsg_to_str(imsg->hdr.type));
@@ -297,66 +315,57 @@ scheduler(void)
 void
 scheduler_timeout(int fd, short event, void *p)
 {
-	struct timeval		 tv;
-	static int		 rq_done = 0;
-	time_t			 nsched;
-	time_t			 curtm;
-	u_int64_t		 evpid;
-
-	nsched = 0;
-
+	time_t		nsched;
+	time_t		curtm;
+	int		schedulable;
+	u_int64_t	evpid;
+	static int	setup = 0;
+	struct timeval	tv;
+
+	log_trace(TRACE_SCHEDULER, "scheduler: entering scheduler_timeout");
 again:
-/*
-	if (scheduler->display)
-		scheduler->display();
-*/
+	log_trace(TRACE_SCHEDULER, "scheduler: entering scheduler_timeout loop");
 
-	curtm = time(NULL);
+	/* do we have something to schedule at some point in the future ? */
+	schedulable = 0;
+	if (backend->next(NULL, &nsched))
+		schedulable = 1;
 
-	/* set nsched to the time() of next schedulable envelope */
-	backend->next(NULL, &nsched);
+	/* if we're not done setting up the scheduler, do it some more */
+	curtm = time(NULL);
+	if (! setup)
+		setup = backend->setup(curtm, nsched);
 
-	/* load as many envelopes as possible from disk-queue to
-	 * ram-queue until a schedulable envelope is found.
-	 */
-	if (! rq_done)
-		rq_done = backend->setup(curtm, nsched);
+	/* we have nothing to schedule and we're done setting up the scheduler */
+	if (! schedulable && setup)
+		goto scheduler_sleep;
 
-	if (rq_done) {
-		if (! backend->next(NULL, &nsched))
-			goto scheduler_sleep;
-		if (curtm < nsched)
-			goto scheduler_pause;
-	}
+	/* we have something to schedule, just not now, pause a little */
+	if (nsched > curtm)
+		goto scheduler_pause;
 
-	/* let's do the schedule dance baby ! */
+	/* pop envelopes as long as they are schedulable */
 	while (backend->next(&evpid, &nsched)) {
-		if (curtm < nsched)
+		if (nsched > curtm)
 			goto scheduler_pause;
 
 		scheduler_process_envelope(evpid);
 	}
 
-	if (rq_done)
-		goto scheduler_sleep;
-
-	goto again;
-
+	/* nothing left to schedule, but we're not done setting scheduler */
+	if (! setup)
+		goto again;
 
 scheduler_pause:
-	nsched = nsched - curtm;
-
-	log_debug("scheduler: nothing to do for the next %lld seconds, zZzZzZ",
-	    (long long int) nsched);
-
-	tv.tv_sec = nsched;
+	log_info("scheduler: pausing for %lld seconds",
+	    (long long int)nsched - curtm);
+	tv.tv_sec = nsched - curtm;
 	tv.tv_usec = 0;
 	evtimer_add(&env->sc_ev, &tv);
 	return;
 
-
 scheduler_sleep:
-	log_debug("scheduler: nothing to schedule, wake me up. zZzZzZ");
+	log_info("scheduler: sleeping");
 	return;
 }
 
@@ -501,7 +510,7 @@ end:
 }
 
 static int
-scheduler_message_to_scheduler(u_int32_t msgid)
+scheduler_load_message(u_int32_t msgid)
 {
 	struct qwalk	*q;
 	u_int64_t	 evpid;
diff --git a/usr.sbin/smtpd/smtpd.c b/usr.sbin/smtpd/smtpd.c
index 4bf6b203910..8505b5e13f0 100644
--- a/usr.sbin/smtpd/smtpd.c
+++ b/usr.sbin/smtpd/smtpd.c
@@ -1,4 +1,4 @@
-/*	$OpenBSD: smtpd.c,v 1.154 2012/07/09 09:57:53 gilles Exp $	*/
+/*	$OpenBSD: smtpd.c,v 1.155 2012/07/09 17:57:54 gilles Exp $	*/
 
 /*
  * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org>
@@ -484,6 +484,8 @@ main(int argc, char *argv[])
 				verbose |= TRACE_MTA;
 			else if (!strcmp(optarg, "bounce"))
 				verbose |= TRACE_BOUNCE;
+			else if (!strcmp(optarg, "scheduler"))
+				verbose |= TRACE_SCHEDULER;
 			else if (!strcmp(optarg, "all"))
 				verbose |= ~TRACE_VERBOSE;
 			else
diff --git a/usr.sbin/smtpd/smtpd.h b/usr.sbin/smtpd/smtpd.h
index f4379162016..a38f9618e24 100644
--- a/usr.sbin/smtpd/smtpd.h
+++ b/usr.sbin/smtpd/smtpd.h
@@ -1,4 +1,4 @@
-/*	$OpenBSD: smtpd.h,v 1.305 2012/07/09 09:57:53 gilles Exp $	*/
+/*	$OpenBSD: smtpd.h,v 1.306 2012/07/09 17:57:54 gilles Exp $	*/
 
 /*
  * Copyright (c) 2008 Gilles Chehade <gilles@openbsd.org>
@@ -622,6 +622,7 @@ struct smtpd {
 #define	TRACE_SMTP	0x0008
 #define	TRACE_MTA	0x0010
 #define	TRACE_BOUNCE	0x0020
+#define	TRACE_SCHEDULER	0x0040
 
 enum {
 	STATS_SMTP_SESSION = 0,