Gitweb:
https://git.exim.org/exim.git/commitdiff/9f01e50d7efc5c625614e4e055790ca4a92a52a8
Commit: 9f01e50d7efc5c625614e4e055790ca4a92a52a8
Parent: 39e69de6d78795c93d5363f5c70240137194eb5e
Author: Jeremy Harris <jgh146exb@???>
AuthorDate: Sat Oct 12 12:39:49 2019 +0100
Committer: Jeremy Harris <jgh146exb@???>
CommitDate: Sat Oct 12 12:39:49 2019 +0100
Performance timing measurements
---
src/src/EDITME | 4 ++++
src/src/daemon.c | 4 ++++
src/src/deliver.c | 54 +++++++++++--------------------------------
src/src/exim.c | 57 +++++++++++++++++++++++++++++++++++++++++-----
src/src/expand.c | 4 ++--
src/src/functions.h | 58 ++++++++++++++++++++++++++++++++++++++++++++---
src/src/globals.c | 3 +++
src/src/globals.h | 3 +++
src/src/queue.c | 10 +++++++-
src/src/transport.c | 4 ++--
src/src/transports/pipe.c | 2 +-
src/src/transports/smtp.c | 20 ++++++++++++----
12 files changed, 162 insertions(+), 61 deletions(-)
diff --git a/src/src/EDITME b/src/src/EDITME
index 906d50a..45af210 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 1ef28a1..99fa909 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(×tamp_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 7433b5f..e228a0b 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(×tamp_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(×tamp_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 388743f..2b6297b 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(×tamp_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 d2ccddc..8be10c1 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 d99f154..37f6b1b 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 ad6b38e..24281f2 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 533def9..e4725a7 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 f65c652..d8c160a 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(×tamp_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(×tamp_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 13a039d..df7fd16 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 70df872..4386a9a 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 3df06c2..fd550ef 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
