Performance timing measurements

12 files changed, 162 insertions, 61 deletions

diff --git a/src/src/EDITME b/src/src/EDITME
index 906d50ae8..45af21063 100644
--- a/src/src/EDITME
+++ b/src/src/EDITME
@@ -1480,4 +1480,8 @@ EXIM_TMPDIR="/tmp"
 
 # ENABLE_DISABLE_FSYNC=yes
 
+#------------------------------------------------------------------------------
+# For development, add this to include code to time various stages and report.
+# CFLAGS += -DMEASURE_TIMING
+
 # End of EDITME for Exim 4.
diff --git a/src/src/daemon.c b/src/src/daemon.c
index 1ef28a156..99fa909d2 100644
--- a/src/src/daemon.c
+++ b/src/src/daemon.c
@@ -1760,6 +1760,10 @@ DEBUG(D_any) debug_print_ids(US"daemon running with");
 
 smtp_input = TRUE;
 
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"daemon loop start");	/* testcase 0022 */
+#endif
+
 /* Enter the never-ending loop... */
 
 for (;;)
diff --git a/src/src/deliver.c b/src/src/deliver.c
index 7433b5fb2..e228a0bfd 100644
--- a/src/src/deliver.c
+++ b/src/src/deliver.c
@@ -1092,42 +1092,6 @@ return g;
 
 
 
-void
-timesince(struct timeval * diff, struct timeval * then)
-{
-gettimeofday(diff, NULL);
-diff->tv_sec -= then->tv_sec;
-if ((diff->tv_usec -= then->tv_usec) < 0)
-  {
-  diff->tv_sec--;
-  diff->tv_usec += 1000*1000;
-  }
-}
-
-
-
-uschar *
-string_timediff(struct timeval * diff)
-{
-static uschar buf[sizeof("0.000s")];
-
-if (diff->tv_sec >= 5 || !LOGGING(millisec))
-  return readconf_printtime((int)diff->tv_sec);
-
-sprintf(CS buf, "%u.%03us", (uint)diff->tv_sec, (uint)diff->tv_usec/1000);
-return buf;
-}
-
-
-uschar *
-string_timesince(struct timeval * then)
-{
-struct timeval diff;
-
-timesince(&diff, then);
-return string_timediff(&diff);
-}
-
 /******************************************************************************/
 
 
@@ -2579,7 +2543,7 @@ if (!shadowing)
       /* In the test harness, wait just a bit to let the subprocess finish off
       any debug output etc first. */
 
-      if (f.running_in_test_harness) millisleep(300);
+      testharness_pause_ms(300);
 
       DEBUG(D_deliver) debug_printf("journalling %s", big_buffer);
       len = Ustrlen(big_buffer);
@@ -5062,7 +5026,7 @@ all pipes, so I do not see a reason to use non-blocking IO here
   newly created process get going before we create another process. This should
   ensure repeatability in the tests. We only need to wait a tad. */
 
-  else if (f.running_in_test_harness) millisleep(500);
+  else testharness_pause_ms(500);
 
   continue;
 
@@ -5560,8 +5524,13 @@ int process_recipients = RECIP_ACCEPT;
 open_db dbblock;
 open_db *dbm_file;
 extern int acl_where;
+uschar *info;
 
-uschar *info = queue_run_pid == (pid_t)0
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"delivery start");	/* testcase 0022, 2100 */
+#endif
+
+info = queue_run_pid == (pid_t)0
   ? string_sprintf("delivering %s", id)
   : string_sprintf("delivering %s (queue run pid %d)", id, queue_run_pid);
 
@@ -7921,7 +7890,7 @@ wording. */
 
       /* In the test harness, let the child do it's thing first. */
 
-      if (f.running_in_test_harness) millisleep(500);
+      testharness_pause_ms(500);
 
       /* If the process failed, there was some disaster in setting up the
       error message. Unless the message is very old, ensure that addr_defer
@@ -8497,6 +8466,9 @@ to try delivery. */
 (void)close(deliver_datafile);
 deliver_datafile = -1;
 DEBUG(D_deliver) debug_printf("end delivery of %s\n", id);
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"delivery end"); /* testcase 0005 */
+#endif
 
 /* It is unlikely that there will be any cached resources, since they are
 released after routing, and in the delivery subprocesses. However, it's
@@ -8639,7 +8611,7 @@ if (cutthrough.cctx.sock >= 0 && cutthrough.callout_hold_only)
 
     else if (pid == 0)		/* child: fork again to totally disconnect */
       {
-      if (f.running_in_test_harness) millisleep(100); /* let parent debug out */
+      testharness_pause_ms(100); /* let parent debug out */
       /* does not return */
       smtp_proxy_tls(cutthrough.cctx.tls_ctx, big_buffer, big_buffer_size,
 		      pfd, 5*60);
diff --git a/src/src/exim.c b/src/src/exim.c
index 388743f8d..2b6297bf5 100644
--- a/src/src/exim.c
+++ b/src/src/exim.c
@@ -1593,6 +1593,10 @@ because some OS define it in /usr/include/unistd.h. */
 
 extern char **environ;
 
+#ifdef MEASURE_TIMING
+(void)gettimeofday(&timestamp_startup, NULL);
+#endif
+
 /* If the Exim user and/or group and/or the configuration file owner/group were
 defined by ref:name at build time, we must now find the actual uid/gid values.
 This is a feature to make the lives of binary distributors easier. */
@@ -2665,7 +2669,7 @@ for (i = 1; i < argc; i++)
 	  exim_fail("exim: getsockname() failed after -MC option: %s\n",
 	    strerror(errno));
 
-      if (f.running_in_test_harness) millisleep(500);
+      testharness_pause_ms(500);
       break;
       }
 
@@ -3464,7 +3468,7 @@ if (debug_selector != 0)
   debug_file = stderr;
   debug_fd = fileno(debug_file);
   f.background_daemon = FALSE;
-  if (f.running_in_test_harness) millisleep(100);   /* lets caller finish */
+  testharness_pause_ms(100);   /* lets caller finish */
   if (debug_selector != D_v)    /* -v only doesn't show this */
     {
     debug_printf("Exim version %s uid=%ld gid=%ld pid=%d D=%x\n",
@@ -3686,7 +3690,18 @@ If any of these options is set, we suppress warnings about configuration
 issues (currently about tls_advertise_hosts and keep_environment not being
 defined) */
 
-readconf_main(checking || list_options);
+  {
+#ifdef MEASURE_TIMING
+  struct timeval t0, diff;
+  (void)gettimeofday(&t0, NULL);
+#endif
+
+  readconf_main(checking || list_options);
+
+#ifdef MEASURE_TIMING
+  report_time_since(&t0, US"readconf_main (delta)");
+#endif
+  }
 
 
 /* Now in directory "/" */
@@ -4294,7 +4309,18 @@ if (msg_action_arg > 0 && msg_action != MSG_DELIVER && msg_action != MSG_LOAD)
 Now, since the intro of the ${acl } expansion, ACL definitions may be
 needed in transports so we lost the optimisation. */
 
-readconf_rest();
+  {
+#ifdef MEASURE_TIMING
+  struct timeval t0, diff;
+  (void)gettimeofday(&t0, NULL);
+#endif
+
+  readconf_rest();
+
+#ifdef MEASURE_TIMING
+  report_time_since(&t0, US"readconf_rest (delta)");
+#endif
+  }
 
 /* Handle the -brt option. This is for checking out retry configurations.
 The next three arguments are a domain name or a complete address, and
@@ -4456,9 +4482,28 @@ if (list_config)
 
 /* Initialise subsystems as required */
 #ifndef DISABLE_DKIM
-dkim_exim_init();
+  {
+# ifdef MEASURE_TIMING
+  struct timeval t0;
+  gettimeofday(&t0, NULL);
+# endif
+  dkim_exim_init();
+# ifdef MEASURE_TIMING
+  report_time_since(&t0, US"dkim_exim_init (delta)");
+# endif
+  }
 #endif
-deliver_init();
+
+  {
+#ifdef MEASURE_TIMING
+  struct timeval t0;
+  gettimeofday(&t0, NULL);
+#endif
+  deliver_init();
+#ifdef MEASURE_TIMING
+  report_time_since(&t0, US"deliver_init (delta)");
+#endif
+  }
 
 
 /* Handle a request to deliver one or more messages that are already on the
diff --git a/src/src/expand.c b/src/src/expand.c
index d2ccddc73..8be10c14f 100644
--- a/src/src/expand.c
+++ b/src/src/expand.c
@@ -5200,7 +5200,7 @@ while (*s != 0)
 #endif
 
 	/* Allow sequencing of test actions */
-	if (f.running_in_test_harness) millisleep(100);
+	testharness_pause_ms(100);
 
         /* Write the request string, if not empty or already done */
 
@@ -5228,7 +5228,7 @@ while (*s != 0)
 	if (!do_tls && do_shutdown) shutdown(cctx.sock, SHUT_WR);
 #endif
 
-	if (f.running_in_test_harness) millisleep(100);
+	testharness_pause_ms(100);
 
         /* Now we need to read from the socket, under a timeout. The function
         that reads a file can be used. */
diff --git a/src/src/functions.h b/src/src/functions.h
index d99f15465..37f6b1b6f 100644
--- a/src/src/functions.h
+++ b/src/src/functions.h
@@ -13,6 +13,8 @@ are in in fact in separate headers. */
 #ifndef _FUNCTIONS_H_
 #define _FUNCTIONS_H_
 
+#include <sys/time.h>
+
 
 #ifdef EXIM_PERL
 extern gstring *call_perl_cat(gstring *, uschar **, uschar *,
@@ -507,8 +509,6 @@ extern BOOL    string_is_utf8(const uschar *);
 extern uschar *string_nextinlist(const uschar **, int *, uschar *, int);
 extern const uschar *string_printing2(const uschar *, BOOL);
 extern uschar *string_split_message(uschar *);
-extern uschar *string_timediff(struct timeval *);
-extern uschar *string_timesince(struct timeval *);
 extern uschar *string_unprinting(uschar *);
 #ifdef SUPPORT_I18N
 extern uschar *string_address_utf8_to_alabel(const uschar *, uschar **);
@@ -541,7 +541,6 @@ extern uschar *strstric(uschar *, uschar *, BOOL);
 #ifdef EXIM_TFO_PROBE
 extern void    tfo_probe(void);
 #endif
-extern void    timesince(struct timeval * diff, struct timeval * then);
 extern void    tls_modify_variables(tls_support *);
 extern uschar *tod_stamp(int);
 
@@ -903,6 +902,59 @@ subdir_str[1] = '\0';
 }
 
 /******************************************************************************/
+static inline void
+timesince(struct timeval * diff, struct timeval * then)
+{
+gettimeofday(diff, NULL);
+diff->tv_sec -= then->tv_sec;
+if ((diff->tv_usec -= then->tv_usec) < 0)
+  {
+  diff->tv_sec--;
+  diff->tv_usec += 1000*1000;
+  }
+}
+
+static inline uschar *
+string_timediff(struct timeval * diff)
+{
+static uschar buf[sizeof("0.000s")];
+
+if (diff->tv_sec >= 5 || !LOGGING(millisec))
+  return readconf_printtime((int)diff->tv_sec);
+
+sprintf(CS buf, "%u.%03us", (uint)diff->tv_sec, (uint)diff->tv_usec/1000);
+return buf;
+}
+
+
+static inline uschar *
+string_timesince(struct timeval * then)
+{
+struct timeval diff;
+timesince(&diff, then);
+return string_timediff(&diff);
+}
+
+static inline void
+report_time_since(struct timeval * t0, uschar * where)
+{
+# ifdef MEASURE_TIMING
+struct timeval diff;
+timesince(&diff, t0);
+fprintf(stderr, "%d %s:\t%ld.%06ld\n",
+       (uint)getpid(), where, (long)diff.tv_sec, (long)diff.tv_usec);
+# endif
+}
+
+
+static inline void
+testharness_pause_ms(int millisec)
+{
+#ifndef MEASURE_TIMING
+if (f.running_in_test_harness) millisleep(millisec);
+#endif
+}
+
 #endif	/* !MACRO_PREDEF */
 
 #endif  /* _FUNCTIONS_H_ */
diff --git a/src/src/globals.c b/src/src/globals.c
index ad6b38ec5..24281f239 100644
--- a/src/src/globals.c
+++ b/src/src/globals.c
@@ -1522,6 +1522,9 @@ uschar *tcp_wrappers_daemon_name = US TCP_WRAPPERS_DAEMON_NAME;
 int     test_harness_load_avg  = 0;
 int     thismessage_size_limit = 0;
 int     timeout_frozen_after   = 0;
+#ifdef MEASURE_TIMING
+struct timeval timestamp_startup;
+#endif
 
 transport_instance  *transports = NULL;
 
diff --git a/src/src/globals.h b/src/src/globals.h
index 533def981..e4725a719 100644
--- a/src/src/globals.h
+++ b/src/src/globals.h
@@ -1019,6 +1019,9 @@ extern uschar *tcp_wrappers_daemon_name; /* tcpwrappers daemon lookup name */
 extern int     test_harness_load_avg;  /* For use when testing */
 extern int     thismessage_size_limit; /* Limit for this message */
 extern int     timeout_frozen_after;   /* Max time to keep frozen messages */
+#ifdef MEASURE_TIMING
+extern struct timeval timestamp_startup; /* For development measurements */
+#endif
 
 extern uschar *transport_name;         /* Name of transport last started */
 extern int     transport_count;        /* Count of bytes transported */
diff --git a/src/src/queue.c b/src/src/queue.c
index f65c65262..d8c160a3a 100644
--- a/src/src/queue.c
+++ b/src/src/queue.c
@@ -347,6 +347,10 @@ uschar *log_detail = NULL;
 int subcount = 0;
 uschar subdirs[64];
 
+#ifdef MEASURE_TIMING
+report_time_since(&timestamp_startup, US"queue_run start");
+#endif
+
 /* Cancel any specific queue domains. Turn off the flag that causes SMTP
 deliveries not to happen, unless doing a 2-stage queue run, when the SMTP flag
 gets set. Save the queue_runner's pid and the flag that indicates any
@@ -608,10 +612,14 @@ for (int i = queue_run_in_order ? -1 : 0;
 
     set_process_info("running queue: %s", fq->text);
     fq->text[SPOOL_NAME_LENGTH-2] = 0;
+#ifdef MEASURE_TIMING
+    report_time_since(&timestamp_startup, US"queue msg selected");
+#endif
+
     if ((pid = fork()) == 0)
       {
       int rc;
-      if (f.running_in_test_harness) millisleep(100);
+      testharness_pause_ms(100);
       (void)close(pfd[pipe_read]);
       rc = deliver_message(fq->text, force_delivery, FALSE);
       exim_underbar_exit(rc == DELIVER_NOT_ATTEMPTED);
diff --git a/src/src/transport.c b/src/src/transport.c
index 13a039d8c..df7fd1628 100644
--- a/src/src/transport.c
+++ b/src/src/transport.c
@@ -1275,7 +1275,7 @@ if (write_pid < 0)
 
 /* When testing, let the subprocess get going */
 
-if (f.running_in_test_harness) millisleep(250);
+testharness_pause_ms(250);
 
 DEBUG(D_transport)
   debug_printf("process %d writing to transport filter\n", (int)write_pid);
@@ -1944,7 +1944,7 @@ if ((pid = fork()) == 0)
     DEBUG(D_transport) debug_printf("transport_pass_socket succeeded (final-pid %d)\n", pid);
     _exit(EXIT_SUCCESS);
     }
-  if (f.running_in_test_harness) sleep(1);
+  testharness_pause_ms(1000);
 
   transport_do_pass_socket(transport_name, hostname, hostaddress,
     id, socket_fd);
diff --git a/src/src/transports/pipe.c b/src/src/transports/pipe.c
index 70df8729d..4386a9ae6 100644
--- a/src/src/transports/pipe.c
+++ b/src/src/transports/pipe.c
@@ -813,7 +813,7 @@ bit here to let the sub-process get going, but it may still not complete. So we
 ignore all writing errors. (When in the test harness, we do do a short sleep so
 any debugging output is likely to be in the same order.) */
 
-if (f.running_in_test_harness) millisleep(500);
+testharness_pause_ms(500);
 
 DEBUG(D_transport) debug_printf("Writing message to pipe\n");
 
diff --git a/src/src/transports/smtp.c b/src/src/transports/smtp.c
index 3df06c202..fd550efff 100644
--- a/src/src/transports/smtp.c
+++ b/src/src/transports/smtp.c
@@ -3340,7 +3340,7 @@ if ((rc = fork()))
   _exit(rc < 0 ? EXIT_FAILURE : EXIT_SUCCESS);
   }
 
-if (f.running_in_test_harness) millisleep(100); /* let parent debug out */
+testharness_pause_ms(100); /* let parent debug out */
 set_process_info("proxying TLS connection for continued transport");
 FD_ZERO(&rfds);
 FD_SET(tls_out.active.sock, &rfds);
@@ -3414,7 +3414,7 @@ for (int fd_bits = 3; fd_bits; )
   }
 
 done:
-  if (f.running_in_test_harness) millisleep(100);	/* let logging complete */
+  testharness_pause_ms(100);	/* let logging complete */
   exim_exit(0, US"TLS proxy");
 }
 #endif
@@ -3703,6 +3703,11 @@ else
   transport_count = 0;
 
 #ifndef DISABLE_DKIM
+  {
+# ifdef MEASURE_TIMING
+  struct timeval t0;
+  gettimeofday(&t0, NULL);
+# endif
   dkim_exim_sign_init();
 # ifdef EXPERIMENTAL_ARC
     {
@@ -3727,6 +3732,10 @@ else
       }
     }
 # endif
+# ifdef MEASURE_TIMING
+  report_time_since(&t0, US"dkim_exim_sign_init (delta)");
+# endif
+  }
   sx.ok = dkim_transport_write_message(&tctx, &ob->dkim, CUSS &message);
 #else
   sx.ok = transport_write_message(&tctx, 0);
@@ -4313,7 +4322,7 @@ propagate it from the initial
 	  int pid = fork();
 	  if (pid == 0)		/* child; fork again to disconnect totally */
 	    {
-	    if (f.running_in_test_harness) millisleep(100); /* let parent debug out */
+	    testharness_pause_ms(100); /* let parent debug out */
 	    /* does not return */
 	    smtp_proxy_tls(sx.cctx.tls_ctx, sx.buffer, sizeof(sx.buffer), pfd,
 			    ob->command_timeout);
@@ -4394,7 +4403,8 @@ HDEBUG(D_transport|D_acl|D_v) debug_printf_indent("  SMTP(close)>>\n");
 if (sx.send_quit)
   {
   shutdown(sx.cctx.sock, SHUT_WR);
-  millisleep(f.running_in_test_harness ? 200 : 20);
+  millisleep(20);
+  testharness_pause_ms(200);
   if (fcntl(sx.cctx.sock, F_SETFL, O_NONBLOCK) == 0)
     for (int i = 16; read(sx.cctx.sock, sx.inbuffer, sizeof(sx.inbuffer)) > 0 && i > 0;)
       i--;				/* drain socket */
@@ -5348,7 +5358,7 @@ retry_non_continued:
 	  ob->hosts_max_try_hardlimit);
       }
 
-    if (f.running_in_test_harness) millisleep(500); /* let server debug out */
+    testharness_pause_ms(500); /* let server debug out */
     }   /* End of loop for trying multiple hosts. */
 
   /* If we failed to find a matching host in the list, for an already-open