Bug#996282: exim4-daemon-light: sendmail terribly inefficient at reading mail

Tue Oct 12 21:38:59 BST 2021

Package: exim4-daemon-light
Version: 4.95-1
Severity: normal
Tags: upstream

Hello,

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 at entry=1, readfds=readfds at entry=0x7fffeb849230, writefds=writefds at entry=0x0, exceptfds=exceptfds at entry=0x0,
    timeout=timeout at 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 at 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

-- Package-specific info:
Exim version 4.95 #2 built 03-Oct-2021 11:39:56
Copyright (c) University of Cambridge, 1995 - 2018
(c) The Exim Maintainers and contributors in ACKNOWLEDGMENTS file, 2007 - 2020
Berkeley DB: Berkeley DB 5.3.28: (September  9, 2013)
Support for: crypteq iconv() IPv6 GnuTLS TLS_resume move_frozen_messages DANE DKIM DNSSEC Event I18N OCSP PIPE_CONNECT PRDR Experimental_Queue_Ramp SOCKS SRS TCP_Fast_Open
Lookups (built-in): lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmjz dbmnz dnsdb dsearch nis nis0 passwd
Authenticators: cram_md5 plaintext
Routers: accept dnslookup ipliteral manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore autoreply lmtp pipe smtp
Fixed never_users: 0
Configure owner: 0:0
Size of off_t: 8
Configuration file search path is /etc/exim4/exim4.conf:/var/lib/exim4/config.autogenerated
Configuration file is /var/lib/exim4/config.autogenerated
# /etc/exim4/update-exim4.conf.conf
#
# Edit this file and /etc/mailname by hand and execute update-exim4.conf
# yourself or use 'dpkg-reconfigure exim4-config'

dc_eximconfig_configtype='smarthost'
dc_other_hostnames='begin.youpi.perso.aquilenet.fr;begin.ipv6;begin'
dc_local_interfaces='127.0.0.1 ; ::1 '
dc_readhost='youpi.perso.aquilenet.fr'
REMOTE_SMTP_SMARTHOST_HOSTS_REQUIRE_TLS=mail.aquilenet.fr:mail2.aquilenet.fr:sonata.ens-lyon.org:smtp.national.inria.fr:smtpauth.u-bordeaux.fr:smtp.ens-lyon.fr:smtp.hypra.fr
dc_relay_domains=''
dc_minimaldns='false'
dc_relay_nets=''
dc_smarthost='mail.aquilenet.fr::587:mail2.aquilenet.fr::587:sonata.ens-lyon.org::587:smtp.inria.fr::587:smtpauth.u-bordeaux.fr::587:smtp.hypra.fr::587'
CFILEMODE='644'
dc_use_split_config='false'
dc_hide_mailname='true'
dc_mailname_in_oh='true'
dc_localdelivery='mail_spool'
mailname:begin
# /etc/default/exim4
EX4DEF_VERSION=''

# 'combined' -	 one daemon running queue and listening on SMTP port
# 'no'       -	 no daemon running the queue
# 'separate' -	 two separate daemons
# 'ppp'      -   only run queue with /etc/ppp/ip-up.d/exim4.
# 'nodaemon' - no daemon is started at all.
# 'queueonly' - only a queue running daemon is started, no SMTP listener.
# setting this to 'no' will also disable queueruns from /etc/ppp/ip-up.d/exim4
QUEUERUNNER='combined'
# how often should we run the queue
QUEUEINTERVAL='30m'
# options common to quez-runner and listening daemon
COMMONOPTIONS=''
# more options for the daemon/process running the queue (applies to the one
# started in /etc/ppp/ip-up.d/exim4, too.
QUEUERUNNEROPTIONS=''
# special flags given to exim directly after the -q. See exim(8)
QFLAGS=''
# Options for the SMTP listener daemon. By default, it is listening on
# port 25 only. To listen on more ports, it is recommended to use
# -oX 25:587:10025 -oP /run/exim4/exim.pid
SMTPLISTENEROPTIONS=''

-- System Information:
Debian Release: bookworm/sid
  APT prefers testing
  APT policy: (990, 'testing'), (500, 'unstable-debug'), (500, 'testing-debug'), (500, 'stable-security'), (500, 'stable-debug'), (500, 'proposed-updates-debug'), (500, 'proposed-updates'), (500, 'oldstable-proposed-updates-debug'), (500, 'oldstable-proposed-updates'), (500, 'oldoldstable'), (500, 'buildd-unstable'), (500, 'unstable'), (500, 'stable'), (500, 'oldstable'), (1, 'experimental-debug'), (1, 'buildd-experimental'), (1, 'experimental')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 5.14.0 (SMP w/8 CPU threads)
Kernel taint flags: TAINT_OOT_MODULE, TAINT_UNSIGNED_MODULE
Locale: LANG=fr_FR.UTF-8, LC_CTYPE=fr_FR.UTF-8 (charmap=UTF-8), LANGUAGE not set
Shell: /bin/sh linked to /usr/bin/dash
Init: systemd (via /run/systemd/system)
LSM: AppArmor: enabled

Versions of packages exim4-daemon-light depends on:
ii  cdebconf [debconf-2.0]  0.260
ii  debconf [debconf-2.0]   1.5.77
ii  exim4-base              4.95-1
ii  libc6                   2.32-4
ii  libcrypt1               1:4.4.25-2
ii  libdb5.3                5.3.28+dfsg1-0.8
ii  libgnutls-dane0         3.7.2-2
ii  libgnutls30             3.7.2-2
ii  libidn12                1.38-3
ii  libidn2-0               2.3.2-2
ii  libnsl2                 1.3.0-2
ii  libpcre3                2:8.39-13

exim4-daemon-light recommends no packages.

exim4-daemon-light suggests no packages.

-- debconf information excluded