From 9f01e50d7efc5c625614e4e055790ca4a92a52a8 Mon Sep 17 00:00:00 2001 From: Jeremy Harris Date: Sat, 12 Oct 2019 12:39:49 +0100 Subject: [PATCH] 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 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(×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 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(×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 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(×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 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 + #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(×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 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 -- 2.30.2