33 ответов в этой теме

[George Kobiashvili]

Hello, last time i reinstalled drweb and problem disappeared, also i managed to run processes by user drweb at 16384 file descriptors, but at rush hour (12:00 to 14:00) it takes too long to send mail, without drweb server works fine, about 1 to 3 sec to send, with drweb ftom 30 sec to 80 sec. How can i make drweb work faster it now users 512/128 (in/out)threads for maild, 128/128 threads for sender and 128 threads for milter. i am going to increse this values, what values do you recommend for each process?

[Anton Ivanov]

I think this values is already very big. In drweb32.ini prefork is set up to no or MaxChildren increase significantly? If disconnect all plugins from MailD speed still very low?

[George Kobiashvili]

prefork is set to yes MaxChildren 64, i disconnected all plugins and then sent test mail here is log output for this mail, it was sendging 36 seconds.

Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: --- 220 mail.grena.ge ESMTP Sendmail 8.13.8/8.13.8; Mon, 6 Oct 2008 11:14:39 +0400
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: Milter: connect to filters
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=connect, continue
Oct 6 11:14:39 mail sendmail[20987]: m967Ed3f020987: Milter (drweb-filter): init success to negotiate
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: --- 250-mail.grena.ge Hello [217.147.227.47], pleased to meet you
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: <-- EHLO ubuntu.local
Oct 6 11:14:44 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=helo, continue
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-8BITMIME
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-DELIVERBY
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-DSN
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-ENHANCEDSTATUSCODES
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-ETRN
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250 HELP
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-PIPELINING
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-SIZE 10485760
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: --- 250-STARTTLS
Oct 6 11:14:45 mail sendmail[20987]: m967Ed3f020987: <-- MAIL FROM: SIZE=345
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.0 ... Sender ok
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=mail, continue
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: Milter: senders:
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: <-- RCPT TO:
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.5 ... Recipient ok
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 354 Enter mail, end with "." on a line by itself
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: <-- DATA
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: from=, size=329, class=0, nrcpts=1, msgid=<200810061114.31017.giokob@grena.ge>, proto=ESMTP, daemon=MTA, rel
ay=[217.147.227.47]
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=rcpt, continue
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: Milter: rcpts:
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO [m967Ed3f020987]: success save mail to /var/drweb/msgs/in/8/000378E8/
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO drweb-maild return pass action for msg 000378E8
Oct 6 11:14:56 mail drweb-milter: [2746125216] milter INFO [m967Ed3f020987]: processing message from is over
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: Milter accept: message
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=body, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=eoh, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:56 mail sendmail[20987]: m967Ed3f020987: milter=drweb-filter, action=header, continue
Oct 6 11:14:57 mail sendmail[20987]: m967Ed3f020987: --- 250 2.0.0 m967Ed3f020987 Message accepted for delivery
Oct 6 11:15:14 mail sendmail[21026]: m967Ed3f020987: SMTP outgoing connect on mail.grena.ge
Oct 6 11:15:16 mail sendmail[21026]: m967Ed3f020987: done; delay=00:00:21, ntries=1
Oct 6 11:15:16 mail sendmail[21026]: m967Ed3f020987: to=, ctladdr= (706/706), delay=00:00:21, xdelay=00:00:19, mailer=esmtp, pri=120329, relay=
gmail-smtp-in.l.google.com. [74.125.79.27], dsn=2.0.0, stat=Sent (OK 1223277307 20si11148126eyk.4)

[Anton Ivanov]

hmm, i don`t see any delay from MailD:
Oct 6 11:14:46 mail sendmail[20987]: m967Ed3f020987: <-- RCPT TO:
Oct 6 11:14:55 mail sendmail[20987]: m967Ed3f020987: --- 250 2.1.5 ... Recipient ok

this delay due to MTA rcpt checking

Oct 6 11:14:57 mail sendmail[20987]: m967Ed3f020987: --- 250 2.0.0 m967Ed3f020987 Message accepted for delivery
Oct 6 11:15:14 mail sendmail[21026]: m967Ed3f020987: SMTP outgoing connect on mail.grena.ge

this delay due to gmail-smtp-in.l.google.com sever delay.

To say more, please, attach some log with Logging/Level = debug for MailD.

[George Kobiashvili]

in attachment is log output for three mails sent to gmail.com, first mail drweb was running without any filter, it took 48 seconds to send, then I turned off drweb and sent second mail it took 6 seconds, i think it's obvious something with drweb. see attachment for log

[Anton Ivanov]

i don`t see any debug logs from MailD (from dweb-milter, for example).

[George Kobiashvili]

i set every loglevel to debug in maild_sendmail.conf, see attachment for logoutput, it took about 5 minutes to send mail to gmail, filters are turned off, in attathment is raw log output please look at it and tell me what to do?

[Anton Ivanov]

i see very strange timing in log:
Oct 6 17:19:54 mail sendmail[14812]: AUTH: available mech=ANONYMOUS, allowed mech=LOGIN PLAIN
Oct 6 17:19:53 mail drweb-maild: [615201696] maild DEBUG FileList::insert_file(/var/drweb/msgs/in/5/00037B45/.p2.p1.epi) was called
Oct 6 17:19:28 mail drweb-milter: [1697139616] milter DEBUG end of a SMTP session
Oct 6 17:19:54 mail sendmail[14239]: m96DGt8P014239: milter=drweb-filter, action=header, continue

maybe this is because very big system loading?

[George Kobiashvili]

here is output os sar command:
as you can see load is not big, just iowait is big

[root@mail mail]# sar
Linux 2.6.17-1.2187_FC5smp (mail.grena.ge) 10/06/2008

12:00:01 AM CPU %user %nice %system %iowait %idle
12:10:02 AM all 3.10 0.00 1.94 20.33 74.64
12:20:01 AM all 2.33 0.00 1.27 21.54 74.87
12:30:01 AM all 1.75 0.00 0.90 18.50 78.85
12:40:01 AM all 0.95 0.00 0.45 9.80 88.80
12:50:01 AM all 0.70 0.00 0.42 11.19 87.69
01:00:01 AM all 0.91 0.00 0.49 11.42 87.18
01:10:01 AM all 0.79 0.00 0.41 9.76 89.04
01:20:01 AM all 0.83 0.00 0.42 9.36 89.39
01:30:01 AM all 0.81 0.00 0.42 8.24 90.54
01:40:01 AM all 0.73 0.00 0.45 9.26 89.56
01:50:01 AM all 0.62 0.00 0.39 9.32 89.67
02:00:01 AM all 0.69 0.00 0.41 9.03 89.88
02:10:01 AM all 0.75 0.00 0.48 11.87 86.90
02:20:01 AM all 0.71 0.00 0.42 9.34 89.53
02:30:01 AM all 0.72 0.00 0.49 10.64 88.15
02:40:01 AM all 0.80 0.00 0.50 10.96 87.75
02:50:01 AM all 0.71 0.00 0.46 10.74 88.08
03:00:01 AM all 0.71 0.00 0.41 9.16 89.72
03:10:01 AM all 0.82 0.00 0.52 10.24 88.42
03:20:01 AM all 0.72 0.00 0.47 11.65 87.16
03:30:01 AM all 1.12 0.00 0.55 12.49 85.84
03:40:01 AM all 0.85 0.00 0.58 13.61 84.95
03:50:01 AM all 0.66 0.00 0.41 10.25 88.68
04:00:01 AM all 0.65 0.00 0.49 14.04 84.82
04:10:01 AM all 0.71 0.00 0.46 10.73 88.11
04:20:01 AM all 0.81 0.00 0.53 13.16 85.49
04:30:01 AM all 10.60 0.00 2.25 15.60 71.55
04:40:01 AM all 19.34 0.41 1.12 16.66 62.48
04:50:01 AM all 0.83 0.00 0.58 13.52 85.07
05:00:01 AM all 0.73 0.00 0.55 16.70 82.02
05:10:01 AM all 0.77 0.00 0.58 17.80 80.85
05:20:01 AM all 1.01 0.00 0.73 18.99 79.27
05:30:01 AM all 0.82 0.00 0.60 17.69 80.89
05:40:01 AM all 0.80 0.00 0.54 14.33 84.33
05:50:01 AM all 0.90 0.00 0.66 15.80 82.64
06:00:01 AM all 0.76 0.00 0.48 12.67 86.08
06:10:02 AM all 0.86 0.00 0.58 13.84 84.72
06:20:01 AM all 0.91 0.00 0.61 14.33 84.15
06:30:01 AM all 1.17 0.00 0.69 12.59 85.55
06:40:01 AM all 0.64 0.00 0.44 12.17 86.75
06:50:01 AM all 0.63 0.00 0.39 11.02 87.97
07:00:01 AM all 0.64 0.00 0.41 12.51 86.44
07:10:01 AM all 0.59 0.00 0.48 13.85 85.08
07:20:01 AM all 0.70 0.00 0.51 13.33 85.47
07:30:01 AM all 0.56 0.00 0.38 10.39 88.67
07:40:01 AM all 6.93 0.00 4.57 12.87 75.63
07:50:01 AM all 13.04 0.00 8.58 13.07 65.31
08:00:01 AM all 12.43 0.00 8.16 15.55 63.85
08:10:01 AM all 12.28 0.00 8.18 19.09 60.45
08:20:01 AM all 11.34 0.00 7.30 20.13 61.23
08:30:01 AM all 14.43 0.00 9.64 15.27 60.66
08:40:01 AM all 7.02 0.00 4.70 11.55 76.73
08:50:01 AM all 1.99 0.00 1.01 17.95 79.05
09:00:01 AM all 1.14 0.00 0.62 9.31 88.93
09:10:01 AM all 0.85 0.00 0.36 2.11 96.68
09:20:01 AM all 1.90 0.00 0.96 16.52 80.62
09:30:01 AM all 1.57 0.00 0.88 20.01 77.54

09:30:01 AM CPU %user %nice %system %iowait %idle
09:40:01 AM all 1.31 0.00 0.80 18.37 79.52
09:50:01 AM all 1.58 0.00 0.85 17.13 80.44
10:00:01 AM all 1.78 0.00 0.83 16.30 81.10
10:10:01 AM all 2.14 0.00 1.01 21.34 75.51
10:20:01 AM all 2.69 0.00 1.05 17.97 78.30
10:30:01 AM all 2.34 0.00 0.94 19.59 77.13
10:40:03 AM all 1.72 0.00 0.91 24.55 72.82
10:50:01 AM all 2.27 0.00 1.15 22.86 73.72
11:00:01 AM all 1.96 0.00 1.08 22.12 74.83
11:10:01 AM all 2.54 0.00 1.24 23.88 72.34
11:20:01 AM all 1.78 0.00 0.78 24.80 72.65
11:30:02 AM all 0.80 0.00 0.65 24.76 73.79
11:40:01 AM all 1.48 0.00 0.83 24.59 73.10
11:50:01 AM all 1.57 0.00 0.91 25.25 72.28
12:00:01 PM all 0.88 0.00 0.74 24.81 73.57
12:10:01 PM all 1.24 0.00 0.79 24.90 73.08
12:20:01 PM all 1.04 0.00 0.73 24.80 73.43
12:30:01 PM all 1.66 0.00 0.70 24.83 72.80
12:40:02 PM all 1.16 0.00 0.65 24.86 73.34
12:50:01 PM all 0.99 0.00 0.76 24.79 73.46
01:00:01 PM all 1.00 0.00 0.62 24.79 73.59
01:10:01 PM all 0.82 0.00 0.58 24.85 73.75
01:20:01 PM all 0.85 0.00 0.65 24.78 73.72
01:30:01 PM all 0.92 0.00 0.78 24.83 73.47
01:40:01 PM all 0.80 0.00 0.75 24.75 73.69
01:50:01 PM all 0.86 0.00 0.67 24.69 73.78
02:00:01 PM all 1.03 0.00 0.59 24.82 73.56
02:10:01 PM all 1.87 0.00 0.75 23.69 73.69
02:20:01 PM all 2.03 0.00 1.14 17.17 79.66
02:30:02 PM all 1.45 0.00 1.01 16.02 81.52
02:40:01 PM all 1.40 0.00 0.89 13.01 84.70
02:50:01 PM all 1.53 0.00 1.10 21.22 76.15
03:00:02 PM all 1.99 0.00 0.98 24.40 72.63
03:10:01 PM all 3.35 0.00 1.07 24.49 71.09
03:20:02 PM all 1.52 0.00 0.96 24.11 73.42
03:30:01 PM all 2.91 0.00 1.22 17.21 78.67
03:40:01 PM all 2.18 0.00 1.11 16.60 80.11
03:50:02 PM all 1.42 0.00 0.98 22.17 75.44
04:00:02 PM all 1.31 0.00 0.84 17.60 80.26
04:10:01 PM all 1.92 0.00 1.05 19.13 77.90
04:20:01 PM all 1.47 0.00 0.90 18.49 79.14
04:30:01 PM all 1.11 0.00 0.80 17.04 81.05
04:40:01 PM all 1.22 0.00 0.82 21.17 76.79
04:50:01 PM all 1.23 0.00 0.89 18.50 79.38
05:00:01 PM all 1.25 0.00 0.96 22.26 75.52
05:10:01 PM all 1.60 0.00 1.01 19.31 78.08
05:20:01 PM all 1.80 0.00 0.96 23.20 74.03
05:30:02 PM all 1.42 0.00 0.97 24.64 72.97
05:40:02 PM all 1.19 0.00 0.88 24.61 73.32
05:50:02 PM all 1.12 0.00 0.88 24.79 73.22
06:00:02 PM all 1.22 0.00 0.88 24.69 73.21
06:10:01 PM all 1.31 0.00 0.89 23.27 74.52
06:20:01 PM all 1.15 0.00 0.81 18.43 79.61
06:30:01 PM all 1.06 0.00 0.78 18.18 79.98
06:40:01 PM all 0.93 0.00 0.77 18.37 79.93
06:50:01 PM all 1.01 0.00 0.91 20.55 77.53
Average: all 2.10 0.00 1.16 17.47 79.26

[Anton Ivanov]

1. Try to set unix-socket in Milter/Address setting and in sendmail configuration
2. Move all plugins from BeforeQueueFilters to AfterQueueFilters - this must remove timeouts between drweb-milter and drweb-maild (but this is does not increase total speed of msgs checking)

[George Kobiashvili]

changed both, but after 10 minutes got this:

Oct 7 10:30:50 mail drweb-maild: [652827552] maild INFO start processing msg 0003A9B7 ...
Oct 7 10:30:50 mail drweb-maild: [652827552] maild INFO put msg 0003A9B7 to queue for processing
Oct 7 10:38:10 mail drweb-maild: [652827552] maild INFO start processing msg 0003AA45 ...
Oct 7 10:39:14 mail drweb-maild: [652827552] maild INFO put msg 0003AA45 to queue for processing
Oct 7 10:40:15 mail drweb-maild: [652827552] maild.ipc ERROR Socket::Send(4) to connection (fd->342, local->local:/var/drweb/ipc/.db, client->local:) failed becasue Broken pipe
Oct 7 10:41:25 mail drweb-maild: [652827552] maild.ipc ERROR Session::Execute - error for address(es) [local:/var/drweb/ipc/.db]: Socket::Send: [32] Broken pipe




Oct 7 10:34:36 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: success save mail to /var/drweb/msgs/in/4/0003AA04/
Oct 7 10:35:31 mail drweb-milter: [2545773472] milter INFO success send msg 0003AA04 to drweb-maild component
Oct 7 10:36:13 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: can not find action for msg after 40 sec; discard it (it may be send by drweb-sender process)
Oct 7 10:36:13 mail drweb-milter: [2545773472] milter INFO [m976XguR020642]: processing message from is over
Oct 7 10:36:42 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: success save mail to /var/drweb/msgs/in/1/0003AA31/
Oct 7 10:38:38 mail drweb-milter: [2545773472] milter INFO success send msg 0003AA31 to drweb-maild component
Oct 7 10:39:19 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: can not find action for msg after 40 sec; discard it (it may be send by drweb-sender process)
Oct 7 10:39:24 mail drweb-milter: [2545773472] milter INFO [m976aIu5021117]: processing message from is over
Oct 7 10:41:30 mail drweb-milter: [2545773472] milter INFO [m976eOVo021842]: success save mail to /var/drweb/msgs/in/D/0003AA6D/
Oct 7 10:43:36 mail drweb-milter: [2545773472] milter.ipc ERROR is timed out (timeout= 1 m 119 s 119741 ms)!
Oct 7 10:44:16 mail drweb-milter: [2545773472] milter.ipc ERROR Session::Execute - error for address(es) [local:/var/drweb/ipc/.db]: a waiting of Socket::IsReady(0x1) for connection (fd->482, local->local:, server->local:/var/drweb/ipc/.db): timed out (timeout= 1 m 119 s 119741 ms)
Oct 7 10:44:17 mail drweb-milter: [2545773472] milter ERROR error in send request to drweb-maild: a waiting of Socket::IsReady(0x1) for connection (fd->482, local->local:, server->local:/var/drweb/ipc/.db): timed out (timeout= 1 m 119 s 119741 ms)

[Anton Ivanov]

i see very strange long processing:

Oct 7 10:38:10 mail drweb-maild: [652827552] maild INFO start processing msg 0003AA45 ...
Oct 7 10:39:14 mail drweb-maild: [652827552] maild INFO put msg 0003AA45 to queue for processing

this is strange because only msg parsing and saving to disk executing during this operatoin. Please, show your hardware configuration and output of commands:
vmstat -s
free

[George Kobiashvili]

[root@mail ~]# vmstat -s
2075192 total memory
1966472 used memory
1090996 active memory
666332 inactive memory
108720 free memory
240372 buffer memory
1331604 swap cache
4209020 total swap
74828 used swap
4134192 free swap
43811576 non-nice user cpu ticks
192011 nice user cpu ticks
19451988 system cpu ticks
2020430801 idle cpu ticks
289394665 IO-wait cpu ticks
178463 IRQ cpu ticks
2075388 softirq cpu ticks
0 stolen cpu ticks
417023574 pages paged in
1360785008 pages paged out
2814869 pages swapped in
3873276 pages swapped out
3211395722 interrupts
3878242764 CPU context switches
1217422738 boot time
13197275 forks


[root@mail ~]# free
total used free shared buffers cached
Mem: 2075192 1971556 103636 0 240412 1331564
-/+ buffers/cache: 399580 1675612
Swap: 4209020 74828 4134192

[Anton Ivanov]

please, contact Dr.Web support with this problem.