> -----Original Message----- > From: [EMAIL PROTECTED] [mailto:amavis-user- > [EMAIL PROTECTED] On Behalf Of Mark Martinec > Sent: Tuesday, June 13, 2006 7:55 AM > To: [email protected] > Subject: Re: [AMaViS-user] Odd Behaviour > > Ed, > > > ...The odd behavior is occasionally the mail will start to stack up in > the > > postfix queue, climbing up to 800. Amavis is processing mail, and the > speed > > per message is normal, but it appears to be picking up the emails from > > postfix very slowly. Eventually it will clear the queue. But lf left > alone > > it will take 20-30 minutes. Stopping and starting postfix does not > affect > > it. Flushing the queue .postqueue .f . does not affect it. CPU is 85-90% > > idle no swapping and I/O is not an issue. > > Restarting amavis is what is required to kick start it. > > After the restart the queue will clear in 5 min or less. > > Tough. > > > The logs do not give me any obvious > > information that I am able to recognize that indicates what the problem > is. > > Does the TIMING log entries (at log level 2) show anything unusual? > The interesting thing to determine is whether time is spent within > processing of mail (which would show as larger values in TIMING report), > or are amavisd child processes idling between tasks. > > amavisd-nanny could also indicate which is which. > > > I have varied the number of postfix and amavis servers between 5 and 10. > > I am currently running 10. > > That's about right. > > > The number of servers does not affect the > > behavior. The mysql server is very fast and runs 90% idle, mytop shows > no > > slow queries and key efficenty off 99% queries per second range between > > 30-150 averaging 50. Any help on how to troubleshoot this issue will be > > appreciated. > > If SQL would be slow it would show in the TIMING report. > > Mark >
Ok I sent some 8 identical test messages during one of the problem times. 4 were processed by this server. Mailq on the server showed between 150 - 250 messages. Top showed amavis servers running between 0-5% on this server with show 2 logical CPU's (Hyper-threading) Over utilization was up and down between 30% and 80 idle with it spending most of its time around 70% idle. Next time I will run vmstat to get more definitive data. I will need to find a utility that will log the per process data on FreeBSD. I did not know how to interpret amavisd-nanny data. Here is the log data and amavisd-nanny data. Here is my summary. Message Sent LMTP Delivered Queued Timing 1 11:16:48 11:19:32 11:19:38 2:44 6433 ms 2 11:17:01 11:19:46 11:19:55 2:45 8733 ms 3 11:17:13 11:19:57 11:20:04 2:44 6574 ms 4 11:17:30 11:20:09 11:20:16 2:39 6405 ms I see that the queued times are pretty consistent. I wonder which parameter effects that number. Ed Message 1 --------- 11:16:48 postfix/cleanup[29430]: 29DC61CD0B: message-id=<[EMAIL PROTECTED]> 11:16:48 postfix/qmgr[29417]: 29DC61CD0B: from=<[EMAIL PROTECTED]>, size=3177, nrcpt=1 (queue active) 11:16:48 postfix/smtpd[29415]: 29DC61CD0B: client=mx4.sandiegort.com[69.43.139.64] 11:19:32 amavis[29465]: (29465-02-29) Cached virus check expired, TTL = 180 s 11:19:32 amavis[29465]: (29465-02-29) Checking: mqT80ffFaL8n [69.43.139.64] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> 11:19:32 amavis[29465]: (29465-02-29) LMTP::10024 /var/amavis/tmp/amavis-20060614T111543-29465: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=3177 from cs3.sandiegort.com ([127.0.0.1]) by localhost (cs3.sandiegort.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 29465-02-29 for <[EMAIL PROTECTED]>; Wed, 14 Jun 2006 11:19:32 -0700 (PDT) 11:19:32 amavis[29465]: (29465-02-29) cached 1d32c29413dd3a6a1061afddfafa541d from <[EMAIL PROTECTED]> (0,1) 11:19:32 amavis[29465]: (29465-02-29) p001 1 Content-Type: text/plain, size: 1944 B, name: 11:19:38 amavis[29465]: (29465-02-29) FWD via SMTP: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=29465-02-29, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 9CB3E1CD63 11:19:38 amavis[29465]: (29465-02-29) Passed CLEAN, [69.43.139.64] [68.230.241.33] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>, mail_id: mqT80ffFaL8n, Hits: 1.919, 6429 ms 11:19:38 amavis[29465]: (29465-02-29) TIMING [total 6433 ms] - lookup_sql: 6 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 92 (1%)2, body_hash: 1 (0%)2, gen_mail_id: 0 (0%)2, mime_decode: 10 (0%)2, get-file-type1: 25 (0%)2, decompose_part: 1 (0%)2, parts_decode: 0 (0%)2, AV-scan-1: 9 (0%)2, lookup_sql: 4 (0%)2, lookup_sql: 2 (0%)2, lookup_sql: 2 (0%)2, spam-wb-list: 2 (0%)2, update_cache: 6145 (96%)98, deal_with_mail_size: 0 (0%)98, fwd-connect: 11 (0%)98, fwd-mail-from: 1 (0%)98, fwd-rcpt-to: 1 (0%)98, write-header: 2 (0%)98, fwd-data: 0 (0%)98, fwd-data-end: 99 (2%)100, fwd-rundown: 1 (0%)100, main_log_entry: 14 (0%)100, update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 1 (0%)100 11:19:38 postfix/cleanup[29707]: 9CB3E1CD63: message-id=<[EMAIL PROTECTED]> 11:19:38 postfix/lmtp[29747]: 29DC61CD0B: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=29, delay=171, delays=0.01/164/0/6.4, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=29465-02-29, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 9CB3E1CD63) 11:19:38 postfix/qmgr[29417]: 29DC61CD0B: removed 11:19:38 postfix/qmgr[29417]: 9CB3E1CD63: from=<[EMAIL PROTECTED]>, size=3225, nrcpt=1 (queue active) 11:19:38 postfix/qmgr[29417]: 9CB3E1CD63: removed 11:19:38 postfix/smtp[29433]: 9CB3E1CD63: to=<[EMAIL PROTECTED]>, relay=69.43.139.233[69.43.139.233]:25, delay=0.13, delays=0.1/0/0/0.02, dsn=2.0.0, status=sent (250 Message queued) 11:19:38 postfix/smtpd[29803]: 9CB3E1CD63: client=localhost.sandiegort.com[127.0.0.1] PID 29465: 29465-02-29 0:00:01 = PID 29465: 29465-02-29 0:00:03 === PID 29465: 29465-02-29 0:00:05 ===== Message 2 --------- 11:17:01 postfix/cleanup[29504]: 51C2F1CDBA: message-id=<[EMAIL PROTECTED]> 11:17:01 postfix/qmgr[29417]: 51C2F1CDBA: from=<[EMAIL PROTECTED]>, size=3177, nrcpt=1 (queue active) 11:17:01 postfix/smtpd[29503]: 51C2F1CDBA: client=mx3.sandiegort.com[69.43.139.63] 11:19:46 amavis[29668]: (29668-01-21) Cached virus check expired, TTL = 180 s 11:19:46 amavis[29668]: (29668-01-21) Checking: 8eTOFvCPzT35 [69.43.139.63] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> 11:19:46 amavis[29668]: (29668-01-21) LMTP::10024 /var/amavis/tmp/amavis-20060614T111724-29668: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=3177 from cs3.sandiegort.com ([127.0.0.1]) by localhost (cs3.sandiegort.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 29668-01-21 for <[EMAIL PROTECTED]>; Wed, 14 Jun 2006 11:19:46 -0700 (PDT) 11:19:46 amavis[29668]: (29668-01-21) cached e99e81caa16d10f7ffbc1db60876eb98 from <[EMAIL PROTECTED]> (0,1) 11:19:46 amavis[29668]: (29668-01-21) p001 1 Content-Type: text/plain, size: 1944 B, name: 11:19:55 amavis[29668]: (29668-01-21) FWD via SMTP: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=29668-01-21, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 721B41CC6C 11:19:55 amavis[29668]: (29668-01-21) Passed CLEAN, [69.43.139.63] [68.230.241.30] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>, mail_id: 8eTOFvCPzT35, Hits: 1.919, 8729 ms 11:19:55 amavis[29668]: (29668-01-21) TIMING [total 8733 ms] - lookup_sql: 6 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 97 (1%)1, body_hash: 3 (0%)1, gen_mail_id: 1 (0%)1, mime_decode: 20 (0%)1, get-file-type1: 143 (2%)3, decompose_part: 1 (0%)3, parts_decode: 0 (0%)3, AV-scan-1: 191 (2%)5, lookup_sql: 4 (0%)5, lookup_sql: 2 (0%)5, lookup_sql: 1 (0%)5, spam-wb-list: 2 (0%)5, update_cache: 8111 (93%)98, deal_with_mail_size: 0 (0%)98, fwd-connect: 18 (0%)98, fwd-mail-from: 1 (0%)99, fwd-rcpt-to: 1 (0%)99, write-header: 2 (0%)99, fwd-data: 0 (0%)99, fwd-data-end: 110 (1%)100, fwd-rundown: 1 (0%)100, main_log_entry: 13 (0%)100, update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100 11:19:55 postfix/cleanup[29707]: 721B41CC6C: message-id=<[EMAIL PROTECTED]> 11:19:55 postfix/lmtp[29751]: 51C2F1CDBA: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=21, delay=174, delays=0/166/0/8.7, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=29668-01-21, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 721B41CC6C) 11:19:55 postfix/qmgr[29417]: 51C2F1CDBA: removed 11:19:55 postfix/qmgr[29417]: 721B41CC6C: from=<[EMAIL PROTECTED]>, size=3225, nrcpt=1 (queue active) 11:19:55 postfix/qmgr[29417]: 721B41CC6C: removed 11:19:55 postfix/smtp[29433]: 721B41CC6C: to=<[EMAIL PROTECTED]>, relay=69.43.139.233[69.43.139.233]:25, delay=0.14, delays=0.11/0/0/0.02, dsn=2.0.0, status=sent (250 Message queued) 11:19:55 postfix/smtpd[29804]: 721B41CC6C: client=localhost.sandiegort.com[127.0.0.1] PID 29668: 29668-01-21 0:00:01 = PID 29668: 29668-01-21 0:00:03 === PID 29668: 29668-01-21 0:00:05 ===== PID 29668: 29668-01-21 0:00:07 ======= PID 29668: 29668-01-21 0:00:09 ========= Message 3 --------- 11:17:13 postfix/cleanup[29430]: D7D2B1CDE9: message-id=<[EMAIL PROTECTED]> 11:17:13 postfix/qmgr[29417]: D7D2B1CDE9: from=<[EMAIL PROTECTED]>, size=3177, nrcpt=1 (queue active) 11:17:13 postfix/smtpd[29415]: D7D2B1CDE9: client=mx3.sandiegort.com[69.43.139.63] 11:19:57 amavis[29484]: (29484-01-33) Checking: ID3o4QJKjW48 [69.43.139.63] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> 11:19:57 amavis[29484]: (29484-01-33) LMTP::10024 /var/amavis/tmp/amavis-20060614T111549-29484: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=3177 from cs3.sandiegort.com ([127.0.0.1]) by localhost (cs3.sandiegort.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 29484-01-33 for <[EMAIL PROTECTED]>; Wed, 14 Jun 2006 11:19:57 -0700 (PDT) 11:19:57 amavis[29484]: (29484-01-33) cached 1d32c29413dd3a6a1061afddfafa541d from <[EMAIL PROTECTED]> (1,1) 11:19:57 amavis[29484]: (29484-01-33) p001 1 Content-Type: text/plain, size: 1944 B, name: 11:20:04 amavis[29484]: (29484-01-33) FWD via SMTP: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=29484-01-33, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 2B91A1CCCD 11:20:04 amavis[29484]: (29484-01-33) Passed CLEAN, [69.43.139.63] [68.230.241.34] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>, mail_id: ID3o4QJKjW48, Hits: 1.919, 6570 ms 11:20:04 amavis[29484]: (29484-01-33) TIMING [total 6574 ms] - lookup_sql: 5 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 96 (1%)2, body_hash: 1 (0%)2, gen_mail_id: 0 (0%)2, mime_decode: 10 (0%)2, get-file-type1: 24 (0%)2, decompose_part: 1 (0%)2, parts_decode: 0 (0%)2, lookup_sql: 176 (3%)5, lookup_sql: 2 (0%)5, lookup_sql: 2 (0%)5, spam-wb-list: 1 (0%)5, update_cache: 6123 (93%)98, deal_with_mail_size: 1 (0%)98, fwd-connect: 8 (0%)98, fwd-mail-from: 2 (0%)98, fwd-rcpt-to: 2 (0%)98, write-header: 4 (0%)98, fwd-data: 0 (0%)98, fwd-data-end: 98 (1%)100, fwd-rundown: 1 (0%)100, main_log_entry: 13 (0%)100, update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100 11:20:04 postfix/cleanup[29706]: 2B91A1CCCD: message-id=<[EMAIL PROTECTED]> 11:20:04 postfix/lmtp[29731]: D7D2B1CDE9: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=33, delay=170, delays=0/164/0/6.6, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=29484-01-33, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 2B91A1CCCD) 11:20:04 postfix/qmgr[29417]: 2B91A1CCCD: from=<[EMAIL PROTECTED]>, size=3225, nrcpt=1 (queue active) 11:20:04 postfix/qmgr[29417]: 2B91A1CCCD: removed 11:20:04 postfix/qmgr[29417]: D7D2B1CDE9: removed 11:20:04 postfix/smtp[29578]: 2B91A1CCCD: to=<[EMAIL PROTECTED]>, relay=69.43.139.233[69.43.139.233]:25, delay=0.13, delays=0.1/0/0/0.02, dsn=2.0.0, status=sent (250 Message queued) 11:20:04 postfix/smtpd[29586]: 2B91A1CCCD: client=localhost.sandiegort.com[127.0.0.1] PID 29484: 29484-01-33 0:00:02 == PID 29484: 29484-01-33 0:00:04 ==== PID 29484: 29484-01-33 0:00:06 ====== Message 4 --------- 11:17:30 postfix/cleanup[29430]: 0B72B1CD2B: message-id=<[EMAIL PROTECTED]> 11:17:30 postfix/qmgr[29417]: 0B72B1CD2B: from=<[EMAIL PROTECTED]>, size=3178, nrcpt=1 (queue active) 11:17:30 postfix/smtpd[29503]: 0B72B1CD2B: client=mx3.sandiegort.com[69.43.139.63] 11:20:09 amavis[29679]: (29679-01-23) LMTP::10024 /var/amavis/tmp/amavis-20060614T111728-29679: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received: SIZE=3178 from cs3.sandiegort.com ([127.0.0.1]) by localhost (cs3.sandiegort.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP id 29679-01-23 for <[EMAIL PROTECTED]>; Wed, 14 Jun 2006 11:20:09 -0700 (PDT) 11:20:10 amavis[29679]: (29679-01-23) Checking: 17Wnq4J2+X5B [69.43.139.63] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> 11:20:10 amavis[29679]: (29679-01-23) cached e99e81caa16d10f7ffbc1db60876eb98 from <[EMAIL PROTECTED]> (1,1) 11:20:10 amavis[29679]: (29679-01-23) p001 1 Content-Type: text/plain, size: 1944 B, name: 11:20:16 amavis[29679]: (29679-01-23) FWD via SMTP: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, 250 2.6.0 Ok, id=29679-01-23, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 31AE71CCD0 11:20:16 amavis[29679]: (29679-01-23) Passed CLEAN, [69.43.139.63] [68.230.241.37] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>, mail_id: 17Wnq4J2+X5B, Hits: 1.919, 6401 ms 11:20:16 amavis[29679]: (29679-01-23) TIMING [total 6405 ms] - lookup_sql: 4 (0%)0, SMTP pre-DATA-flush: 1 (0%)0, SMTP DATA: 95 (1%)2, body_hash: 1 (0%)2, gen_mail_id: 0 (0%)2, mime_decode: 7 (0%)2, get-file-type1: 19 (0%)2, decompose_part: 1 (0%)2, parts_decode: 0 (0%)2, lookup_sql: 6 (0%)2, lookup_sql: 1 (0%)2, lookup_sql: 1 (0%)2, spam-wb-list: 1 (0%)2, update_cache: 6134 (96%)98, deal_with_mail_size: 0 (0%)98, fwd-connect: 14 (0%)98, fwd-mail-from: 0 (0%)98, fwd-rcpt-to: 1 (0%)98, write-header: 2 (0%)98, fwd-data: 0 (0%)98, fwd-data-end: 99 (2%)100, fwd-rundown: 1 (0%)100, main_log_entry: 13 (0%)100, update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100 11:20:16 postfix/cleanup[29805]: 31AE71CCD0: message-id=<[EMAIL PROTECTED]> 11:20:16 postfix/lmtp[29728]: 0B72B1CD2B: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1]:10024, conn_use=23, delay=166, delays=0/160/0.01/6.4, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=29679-01-23, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 31AE71CCD0) 11:20:16 postfix/qmgr[29417]: 0B72B1CD2B: removed 11:20:16 postfix/qmgr[29417]: 31AE71CCD0: from=<[EMAIL PROTECTED]>, size=3226, nrcpt=1 (queue active) 11:20:16 postfix/qmgr[29417]: 31AE71CCD0: removed 11:20:16 postfix/smtp[29578]: 31AE71CCD0: to=<[EMAIL PROTECTED]>, relay=69.43.139.233[69.43.139.233]:25, delay=0.13, delays=0.1/0/0/0.02, dsn=2.0.0, status=sent (250 Message queued) 11:20:16 postfix/smtpd[29803]: 31AE71CCD0: client=localhost.sandiegort.com[127.0.0.1] PID 29679: 29679-01-23 0:00:01 = PID 29679: 29679-01-23 0:00:03 === PID 29679: 29679-01-23 0:00:05 ===== _______________________________________________ AMaViS-user mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
