Re: [exim] 4.87 -> 4.88 readconf performance
On Sat, Mar 18, 2017 at 05:49:42PM -0700, Rical Jasan wrote: > On 03/17/2017 10:46 AM, Wayne wrote: > >> Is there a reason to scan within comment blocks? > >> > > I assume based on the lack of responses that it's not expected that > > comment content be scanned at all? > > The developers would have to tell you if it is intentional, but as a > user/administrator, I fully expect comments to be /ignored/ (when parsed > by the application, haha). > > Rical Ignoring comments is clearly intended in the code as well. I'll work on a patch and hopefully they'll accept it. -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On 03/17/2017 10:46 AM, Wayne wrote: >> Is there a reason to scan within comment blocks? >> > I assume based on the lack of responses that it's not expected that > comment content be scanned at all? The developers would have to tell you if it is intentional, but as a user/administrator, I fully expect comments to be /ignored/ (when parsed by the application, haha). Rical -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Tue, Mar 14, 2017 at 12:03:22PM -0400, Wayne wrote:
> On Tue, Mar 14, 2017 at 02:15:56PM +0200, Lena--- via Exim-users wrote:
> > > >> It triggers when a macro name contains the sequence /_[ODH]/.
> > > >
> > > > Does it include $header_Date: ?
> > > > A workaround: $header_date:
> > >
> > > Macro, not header.
> >
> > Even comment lines are searched for /_[ODH]/
> > As far as I undrestand, every config line is searched before parsing.
> > So, such line triggers creation of builtin macros:
> >
> > condition = ${if match{$rheader_Date:}{\N \+0[56]00\N}}
> >
>
> The additional 'if ((p == t) ...' block below corrects the initial
> problem.
>
> if (!macros_builtin_created)
> {
> const uschar * t, * p;
> uschar c;
> for (t = s; (p = CUstrchr(t, '_')); t = p+1) {
> if (c = p[1], c == 'O' || c == 'D' || c == 'H')
> {
> /* Don't trigger builtins on substrings. */
> if ((p == t) || (isspace(p[-1]) || (p[-1] == '=') )) {
>// fprintf(stderr, "%s: builtins create triggered by '%s'\n",
> __FUNCTION__, s);
>macros_create_builtin();
>break;
> }
> }
> }
> }
>
> Unfortunately it still triggers if an assignment that should trigger
> builtins is commented.
>
> Ex.
>
> NAME = CFG_DIR
> will NOT trigger (good)
>
> NAME = _DIR
> will trigger (good)
>
>
> # NAME = _DIR
> will trigger (bad)
>
> Is there a reason to scan within comment blocks?
>
I assume based on the lack of responses that it's not expected that
comment content be scanned at all? It certainly looks that way based
on the code. I'll look into preventing that as well.
I can supply a patch for both if it makes sense.
Am I the only one that cares about this? Seems strange that no one
else has run into it.
Wayne
--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Tue, Mar 14, 2017 at 02:15:56PM +0200, Lena--- via Exim-users wrote:
> > >> It triggers when a macro name contains the sequence /_[ODH]/.
> > >
> > > Does it include $header_Date: ?
> > > A workaround: $header_date:
> >
> > Macro, not header.
>
> Even comment lines are searched for /_[ODH]/
> As far as I undrestand, every config line is searched before parsing.
> So, such line triggers creation of builtin macros:
>
> condition = ${if match{$rheader_Date:}{\N \+0[56]00\N}}
>
The additional 'if ((p == t) ...' block below corrects the initial
problem.
if (!macros_builtin_created)
{
const uschar * t, * p;
uschar c;
for (t = s; (p = CUstrchr(t, '_')); t = p+1) {
if (c = p[1], c == 'O' || c == 'D' || c == 'H')
{
/* Don't trigger builtins on substrings. */
if ((p == t) || (isspace(p[-1]) || (p[-1] == '=') )) {
// fprintf(stderr, "%s: builtins create triggered by '%s'\n",
__FUNCTION__, s);
macros_create_builtin();
break;
}
}
}
}
Unfortunately it still triggers if an assignment that should trigger
builtins is commented.
Ex.
NAME = CFG_DIR
will NOT trigger (good)
NAME = _DIR
will trigger (good)
# NAME = _DIR
will trigger (bad)
Is there a reason to scan within comment blocks?
Wayne
--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
> >> It triggers when a macro name contains the sequence /_[ODH]/.
> >
> > Does it include $header_Date: ?
> > A workaround: $header_date:
>
> Macro, not header.
Even comment lines are searched for /_[ODH]/
As far as I undrestand, every config line is searched before parsing.
So, such line triggers creation of builtin macros:
condition = ${if match{$rheader_Date:}{\N \+0[56]00\N}}
--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On 13/03/17 14:33, Lena--- via Exim-users wrote: >> It triggers when a macro name contains the sequence /_[ODH]/. > > Does it include $header_Date: ? > A workaround: $header_date: Macro, not header. -- J -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
> This loop appears to be the problem. > It triggers when a macro name contains the sequence /_[ODH]/. Does it include $header_Date: ? A workaround: $header_date: > You are also correct in that when macros_create_builtin() is not > called the startup time is greatly reduced. -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Sun, Mar 12, 2017 at 11:24:45AM +, Jeremy Harris wrote:
> With the 555 calls of macro_create() it does seem that the
> builtin macros are being activated. The place that happens
> is probably the call to macros_create_builtin() in
> get_config_line() - about line 1029 of readconf.c in
> master HEAD. There's a commented-out printf on the line
> before; please uncomment that and run that build
> (normal debug facilities don't work this early in Exim's
> startup, unfortunately).
>
> We should discover what the trigger is.
> --
> Cheers,
> Jeremy
This loop appears to be the problem.
if (!macros_builtin_created)
{
const uschar * t, * p;
uschar c;
for (t = s; (p = CUstrchr(t, '_')); t = p+1)
if (c = p[1], c == 'O' || c == 'D' || c == 'H')
{
fprintf(stderr, "%s: builtins create triggered by '%s'\n", __FUNCTION__, s);
macros_create_builtin();
break;
}
}
It triggers when a macro name contains the sequence /_[ODH]/.
Example from my exim.conf file:
EXIM_ROOT = /opt/exim
CFG_DIR = EXIM_ROOT/etc
ALIASES = CFG_DIR/db/aliases.dbmnz
RELAY_TO_DOMAINS = CFG_DIR/db/relay_to_domains.dbmnz
ROUTE_DATA = CFG_DIR/db/route_data.dbmnz
RELAY_4_HOSTS = CFG_DIR/relay_4_hosts
...
...
get_config_line: builtins create triggered by '= CFG_DIR/db/aliases.dbmnz
'
Additionally the loop is executing inside comments though I wouldn't
expect that.
When I removed the '_' from the definitions above and reran I get the
following:
get_config_line: builtins create triggered by '# LOCAL_DOMAINS,
+relay_to_domains, and +relay_from_hosts, respectively. They
'
This is found in a comment block:
# The next three settings create two lists of domains and one list of hosts.
# These lists are referred to later in this configuration using the syntax
# LOCAL_DOMAINS, +relay_to_domains, and +relay_from_hosts, respectively. They
# are all colon-separated lists:
You are also correct in that when macros_create_builtin() is not
called the startup time is greatly reduced.
Wayne
--
## List details at https://lists.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
With the 555 calls of macro_create() it does seem that the builtin macros are being activated. The place that happens is probably the call to macros_create_builtin() in get_config_line() - about line 1029 of readconf.c in master HEAD. There's a commented-out printf on the line before; please uncomment that and run that build (normal debug facilities don't work this early in Exim's startup, unfortunately). We should discover what the trigger is. -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Thu, Mar 09, 2017 at 11:15:57AM -0600, René Berber via Exim-users wrote: > On 3/9/2017 10:46 AM, Jeremy Harris wrote: > > > On 09/03/17 16:20, lists-e...@useunix.net wrote: > >> Unfortunately this is stuck running this on HPUX 11.2 at the moment. > >> I don't have much installed aside from GCC/GDB but if you can make > >> some suggestions I'll be happy to do some research as time permits. > >> > >> I also plan to take this config and test it on Linux 4.87 vs 4.88 as > >> well. The message originator runs on HPUX and distributes the email to 3 > >> MX hosts in the DMZ all running EXIM 4.80 on Debian. > > > > Linux has a suite of tools called "perf". I'd expect HPUX to have > > something similar; Solaris certainly did when I worked with that. > > > > Learning what to look for is the worst thing with these sorts of > > tools, I find; they have too many options. I'd like a time-by-function > > list, as a start. > > GCC can also do profiling. > > Build with: CFLAGS="-g -pg", LDFLAGS="-g -pg". > > Then run with: gprof -Isrc exim-4.88 gmon.out > gprof-exim.txt > (where "src" is a list of search directories in which to find source > files; exim-4.88 is the executable; gmon.out is a product of the build > -- dynamic call graph and profile) > > Hope this helps. > -- > R.Berber > Thank you, I'd actually found the gprof tool while researching prof after reading Jeremy's email. Following is output from gprof: granularity: each sample hit covers 2 byte(s) in module /mnt/devl3/homedirs/wcuddy/src/exim/exim-4.88/build-HP-UX-ia64/exim for 12.50% of 0.08 seconds granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libm.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libxnet.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libelf.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /usr/local/lib/hpux64/libgcc_s.so.0 no time accumulated granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libunwind.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libgprof.so no time accumulated granularity: each sample hit covers 2 byte(s) in module /lib/hpux64/libc.so.1 for 0.69% of 1.44 seconds granularity: each sample hit covers 2 byte(s) in module /usr/lib/hpux64/libxti.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /usr/lib/hpux64/libuca.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /usr/lib/hpux64/libdl.so.1 no time accumulated granularity: each sample hit covers 2 byte(s) in module /usr/lib/hpux64/libnss_files.so.1 no time accumulated %time cumsecs seconds calls msec/call module_index name 89.51.361.36 7 _strstr 5.31.440.08 7 _getdents 5.31.520.08 0 compile_branch 0.01.520.001814 0.000 store_get_3 0.01.520.001193 0.000 string_copy 0.01.520.00 556 0.000 string_vformat 0.01.520.00 555 0.000 macro_create 0.01.520.00 538 0.000 string_sprintf 0.01.520.00 163 0.000 find_option 0.01.520.00 159 0.000 strncmpic 0.01.520.00 154 0.000 get_config_line 0.01.520.00 140 0.000 readconf_handle_option 0.01.520.00 136 0.000 readconf_readname 0.01.520.00 62 0.000 read_string 0.01.520.00 43 0.000 strcmpic 0.01.520.00 29 0.000 store_malloc_3 0.01.520.00 19 0.000 acl_callback 0.01.520.00 18 0.000 acl_checkcondition 0.01.520.00 18 0.000 acl_checkname 0.01.520.00 17 0.000 readconf_options_from_list 0.01.520.00 16 0.000 string_format 0.01.520.00 13 0.000 init_driver 0.01.520.00 11 0.000 get_set_flag 0.01.520.00 10 0.000 function_store_malloc 0.01.520.00 10 0.000 regex_must_compile 0.01.520.00 10 0.000 store_reset_3 0.01.520.00 9 0.000 add_lookup_to_list 0.01.520.00 8 0.000 host_build_hostlist 0.01.520.00 7 0.000 read_macro_assignment 0.01.520.00 7 0.000 string_nextinlist 0.01.520.00 6
Re: [exim] 4.87 -> 4.88 readconf performance
On 3/9/2017 10:46 AM, Jeremy Harris wrote: > On 09/03/17 16:20, lists-e...@useunix.net wrote: >> Unfortunately this is stuck running this on HPUX 11.2 at the moment. >> I don't have much installed aside from GCC/GDB but if you can make >> some suggestions I'll be happy to do some research as time permits. >> >> I also plan to take this config and test it on Linux 4.87 vs 4.88 as >> well. The message originator runs on HPUX and distributes the email to 3 >> MX hosts in the DMZ all running EXIM 4.80 on Debian. > > Linux has a suite of tools called "perf". I'd expect HPUX to have > something similar; Solaris certainly did when I worked with that. > > Learning what to look for is the worst thing with these sorts of > tools, I find; they have too many options. I'd like a time-by-function > list, as a start. GCC can also do profiling. Build with: CFLAGS="-g -pg", LDFLAGS="-g -pg". Then run with: gprof -Isrc exim-4.88 gmon.out > gprof-exim.txt (where "src" is a list of search directories in which to find source files; exim-4.88 is the executable; gmon.out is a product of the build -- dynamic call graph and profile) Hope this helps. -- R.Berber -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On 09/03/17 16:20, lists-e...@useunix.net wrote: > Unfortunately this is stuck running this on HPUX 11.2 at the moment. > I don't have much installed aside from GCC/GDB but if you can make > some suggestions I'll be happy to do some research as time permits. > > I also plan to take this config and test it on Linux 4.87 vs 4.88 as > well. The message originator runs on HPUX and distributes the email to 3 > MX hosts in the DMZ all running EXIM 4.80 on Debian. Linux has a suite of tools called "perf". I'd expect HPUX to have something similar; Solaris certainly did when I worked with that. Learning what to look for is the worst thing with these sorts of tools, I find; they have too many options. I'd like a time-by-function list, as a start. -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Thu, Mar 09, 2017 at 09:10:13AM +, Jeremy Harris wrote: > On 09/03/17 02:16, lists-e...@useunix.net wrote: > > Most of the time is spent in the while loop in readconf_main around > > line 3424. All other portions of the function are negligible. > > That tells us it's reading the config... > Can you dig deeper? What tools do you have? > -- > Cheers, > Jeremy Unfortunately this is stuck running this on HPUX 11.2 at the moment. I don't have much installed aside from GCC/GDB but if you can make some suggestions I'll be happy to do some research as time permits. I also plan to take this config and test it on Linux 4.87 vs 4.88 as well. The message originator runs on HPUX and distributes the email to 3 MX hosts in the DMZ all running EXIM 4.80 on Debian. Again, thank you for your assistance. Wayne -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On 09/03/17 02:16, lists-e...@useunix.net wrote: > Most of the time is spent in the while loop in readconf_main around > line 3424. All other portions of the function are negligible. That tells us it's reading the config... Can you dig deeper? What tools do you have? -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Mon, Mar 06, 2017 at 11:49:02AM -0500, lists-e...@useunix.net wrote: > On Sun, Mar 05, 2017 at 07:56:12PM +, Jeremy Harris wrote: > > On 04/03/17 22:27, Wayne Cuddy wrote: > > > Instrumenting the code with rudimentary timing metrics I found that on > > > average in versions 4.66-4.87 readconf_main takes < 9000 > > > microseconds. > > > > > > On 4.88 it takes on average 63000 microseconds. > > > > 4.88 added builtin macros (for assorted features) and a startup > > cost is associated with these. They are however only created > > in a lazy fashion, when a macro name is seen in the config input > > which starts underbar, letter. If you do not have any use of > > a macro matching that you should not see a longer startup cost > > for that specific reason. > > > > Please check that and say whether it provides a fix for you. I verified that I'm not using macros that begin with an underbar. I also expanded all of the simple macros in my config file and retested. This had no effect on performance. Most of the time is spent in the while loop in readconf_main around line 3424. All other portions of the function are negligible. > > I am using macros but none that start with an underbar '_'. I have one > that defines the configuration directory. > > CFG_DIR = /etc/exim > > I then use that throughout the configuration file. > > Aside from adding the "keep_environment =" line to exim.conf no other > changes were made to my configuration between 4.66 and 4.88. > > I can try expanding the simple macro above manually in my > configuration just to see if that causes the problem to go away. > > I can also sanitize the configuration and post it here if you think > that would help. > > > > > > If I changed from piping the message to EXIM to connecting to > > > localhost:25 and sending the message via SMTP would that remove calls to > > > readconf_main. > > > > It would remove the per-message reception startup configuration read. > > The delivery cost would still be there. > > > > -- > > Cheers, > > Jeremy > > > > Thank you for the reply. > Wayne > > -- > ## List details at https://lists.exim.org/mailman/listinfo/exim-users > ## Exim details at http://www.exim.org/ > ## Please use the Wiki with this list - http://wiki.exim.org/ > -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On Sun, Mar 05, 2017 at 07:56:12PM +, Jeremy Harris wrote: > On 04/03/17 22:27, Wayne Cuddy wrote: > > Instrumenting the code with rudimentary timing metrics I found that on > > average in versions 4.66-4.87 readconf_main takes < 9000 > > microseconds. > > > > On 4.88 it takes on average 63000 microseconds. > > 4.88 added builtin macros (for assorted features) and a startup > cost is associated with these. They are however only created > in a lazy fashion, when a macro name is seen in the config input > which starts underbar, letter. If you do not have any use of > a macro matching that you should not see a longer startup cost > for that specific reason. > > Please check that and say whether it provides a fix for you. I am using macros but none that start with an underbar '_'. I have one that defines the configuration directory. CFG_DIR = /etc/exim I then use that throughout the configuration file. Aside from adding the "keep_environment =" line to exim.conf no other changes were made to my configuration between 4.66 and 4.88. I can try expanding the simple macro above manually in my configuration just to see if that causes the problem to go away. I can also sanitize the configuration and post it here if you think that would help. > > > If I changed from piping the message to EXIM to connecting to > > localhost:25 and sending the message via SMTP would that remove calls to > > readconf_main. > > It would remove the per-message reception startup configuration read. > The delivery cost would still be there. > > -- > Cheers, > Jeremy > Thank you for the reply. Wayne -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
Re: [exim] 4.87 -> 4.88 readconf performance
On 04/03/17 22:27, Wayne Cuddy wrote: > Instrumenting the code with rudimentary timing metrics I found that on > average in versions 4.66-4.87 readconf_main takes < 9000 > microseconds. > > On 4.88 it takes on average 63000 microseconds. 4.88 added builtin macros (for assorted features) and a startup cost is associated with these. They are however only created in a lazy fashion, when a macro name is seen in the config input which starts underbar, letter. If you do not have any use of a macro matching that you should not see a longer startup cost for that specific reason. Please check that and say whether it provides a fix for you. > If I changed from piping the message to EXIM to connecting to > localhost:25 and sending the message via SMTP would that remove calls to > readconf_main. It would remove the per-message reception startup configuration read. The delivery cost would still be there. -- Cheers, Jeremy -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
[exim] 4.87 -> 4.88 readconf performance
I've been running 4.66 on an internal HP-UX host for quite a long time. We've recently upgraded the hardware and the OS so I figure now is also a good time to upgrade EXIM to the latest. This is a relatively high volume host, 100+ msgs per day that relays mail to DMZ MX relays for internet destined email. Nominally the load on the host is about .3. When I upgraded to 4.88 the load on the host went upwards of 7 and the process that feeds EXIM started to queue up msgs in it's database and backup. I tried version 4.87 and it's performance is on par with 4.66. The feeding application forks EXIM directly and pipes the message to EXIM via standard input. I tracked the 4.88 performance degradation to calls to readconf_main in exim.c. It does appear to have undergone extensive additions/changes from 4.87->4.88. Instrumenting the code with rudimentary timing metrics I found that on average in versions 4.66-4.87 readconf_main takes < 9000 microseconds. On 4.88 it takes on average 63000 microseconds. This is a substantial increase and intolerable for our current configuration and workload. Looking at the code I doubt this is HP-UX specific. Has anyone else experienced this issue? I've not had the time to test other configurations or operating systems. If I changed from piping the message to EXIM to connecting to localhost:25 and sending the message via SMTP would that remove calls to readconf_main. I assume not since it appears EXIM re-invokes itself for delivery using the "-Mc " parameters. I appreciate any assistance you guys can provide, Wayne -- ## List details at https://lists.exim.org/mailman/listinfo/exim-users ## Exim details at http://www.exim.org/ ## Please use the Wiki with this list - http://wiki.exim.org/
