https://bugs.exim.org/show_bug.cgi?id=2819
Bug ID: 2819
Summary: /usr/sbin/sendmail interface inefficient at reading
mail
Product: Exim
Version: 4.95
Hardware: x86
URL: https://bugs.debian.org/996282
OS: Linux
Status: NEW
Severity: bug
Priority: medium
Component: Delivery in general
Assignee: unallocated@???
Reporter: eximusers@???
CC: exim-dev@???
Hello,
this was reported by Samuel Thibault in the Debian BTS:
TL;DR:
Sending a large mail through /usr/sbin/sendmail takes a *very* long
time. Setting receive_timeout to 10m makes the send immediate.
Stracing sendmail gives:
select(1, [0], NULL, NULL, {tv_sec=1692, tv_usec=0}) = 1 (in [0], left
{tv_sec=1691, tv_usec=999977})
gettimeofday({tv_sec=1634067536, tv_usec=599153}, NULL) = 0
select(1, [0], NULL, NULL, {tv_sec=1692, tv_usec=0}) = 1 (in [0], left
{tv_sec=1691, tv_usec=999983})
gettimeofday({tv_sec=1634067536, tv_usec=599463}, NULL) = 0
select(1, [0], NULL, NULL, {tv_sec=1692, tv_usec=0}) = 1 (in [0], left
{tv_sec=1691, tv_usec=999977})
gettimeofday({tv_sec=1634067536, tv_usec=599768}, NULL) = 0
select(1, [0], NULL, NULL, {tv_sec=1692, tv_usec=0}) = 1 (in [0], left
{tv_sec=1691, tv_usec=999977})
gettimeofday({tv_sec=1634067536, tv_usec=600085}, NULL) = 0
[...]
i.e. sendmail keeps calling gettimeofday/select ad nauseam. Filtering
them out gives (yes my test mail is just composed of 'a' letters):
22:19:32 write(3, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
22:19:32 read(0, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
22:19:34 write(3, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
22:19:34 read(0, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
22:19:35 write(3, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
22:19:35 read(0, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 4096) = 4096
I.e. a speed of only a few kilobytes per second. I had a look at gdb,
and saw the following backtrace:
(gdb) bt
#0 __GI___select (nfds=nfds@entry=1, readfds=readfds@entry=0x7fffeb849230,
writefds=writefds@entry=0x0, exceptfds=exceptfds@entry=0x0,
timeout=timeout@entry=0x7fffeb849220) at
../sysdeps/unix/sysv/linux/select.c:39
#1 0x000055f49ce40c4d in log_close_chk () at receive.c:602
#2 0x000055f49ce43f15 in log_close_chk () at receive.c:699
#3 read_message_data (fout=<optimized out>) at receive.c:663
#4 receive_msg (extract_recip=extract_recip@entry=0) at receive.c:3167
#5 0x000055f49cde5061 in main (argc=7, cargv=<optimized out>) at exim.c:5706
log_close_chk indeed calls gettimeofday and select(), and it happens
that read_message_data() is like this:
for ( ;
log_close_chk(), (ch = (receive_getc)(GETC_BUFFER_UNLIMITED)) != EOF;
last_ch = ch)
{ [...] }
i.e. gettimeofday + select get called at each receive_getc() call, i.e.
for each and every character of the mail...
Fortunately, log_close_chk does not have this behavior when
receive_timeout is defined, so by setting it to 10m, the
gettimeofday+select calls are disabled, making sending mails just
immediate as expected, but that's only a workaround.
Samuel
--
You are receiving this mail because:
You are on the CC list for the bug.
