On Mon, May 27, 2013 at 12:45:34AM +0400, Evgeniy Berdnikov wrote:
> On Sun, May 26, 2013 at 06:15:41PM +0200, Mrten wrote:
> > 2013-05-26 05:12:18 [21249] 1UgMol-0004Xa-Lb Completed QT=4h52m15s
...
> so we have about 0.4 proc/sec, and the hangup time value is
> 3784/0.4=9460 sec (or 2.6 hour). Actual value could differ considerably
> because we know nothing about hangup reason (swapping, disk failure, etc),
> but surely time may be several hours, so QT=4h52m15s is not very fantastic.
> It looks not as exim bug, but looks as a problem of your system.
I'd like to add a comment. Maybe it's not a problem (as swapping, etc)
but artifact of the mail submission method with that cron job. If exim
is started in non-smtp mode when job starts, and wait for a long time
until job closes its stdout+stderr, then you get very similar picture
in mainlog. Namely, large gap between pids but close time stamps.
Look:
# wait_time=60
# (echo "From: root\nTo: bd4\n\n"; date ; sleep $wait_time) | exim4 -i bd4
The message is
------------------------------------------------------------------------
Received: from root by ice.mytest.ru with local (Exim 4.80)
(envelope-from <root@???>)
id 1Ugsgq-0006Ej-P1
for bd4@???; Mon, 27 May 2013 12:23:00 +0400
From: root@???
To: bd4@???
Mon May 27 12:22:00 MSK 2013
------------------------------------------------------------------------
and with log_selector=+all I have in mainlog:
2013-05-27 12:22:00 [23977] cwd=/etc/exim4/conf.d/main 3 args: exim4 -i bd4@???
2013-05-27 12:23:00 [23977] 1Ugsgq-0006Ej-P1 <= root@??? U=root P=local S=320 from <root@???> for bd4@???
2013-05-27 12:23:00 [23994] cwd=/var/spool/exim4 3 args: /usr/sbin/exim4 -Mc 1Ugsgq-0006Ej-P1
2013-05-27 12:23:01 [23994] 1Ugsgq-0006Ej-P1 => berd <bd4@???> F=<root@???> P=<root@???> R=procmail T=procmail_pipe S=470 QT=1m1s DT=1s
2013-05-27 12:23:01 [23994] 1Ugsgq-0006Ej-P1 Completed QT=1m1s
The wait period (from 12:22:00 to 12:23:00) can be observed from two first
lines in mainlog. But first line is recorded only if log_selector contains
"arguments" flag, if not then wait time is invisible. It is also invisible
if you grep 1Ugsgq-0006Ej-P1 from mainlog. Nevetheless, QT and pids reflect
the actual value of wait time.
You wrote "This particular cronjob runs at 00:20, so the times do add up",
so probably you have something similar in your setup.
--
Eugene Berdnikov
