> I have a Postfix+Amavisd-new+MySQL+ClamAV mail gateway system. > > I'm observing time spent by a messagge in (Amavisd-new) content_filter > of postfix (I trascure deliberately the time spent by a message to be > processed by postfix, because it is neglegible with respect to the > filter). > > I "grep" a maillog line with match "delays=", "127.0.0.1" and > "status=sent (250 2.0.0" (I don't consider rejected messages, and > blocked message by content_filter). > > The aim is to get an average latency of a message of processing. > > Once I get all 4-ple delays="a/b/c/d", I calculate the average time > during a specified time period. > > What I note is that the average of "Time to transmit the message" (the > term pointed as d in 4-ple above) is a little bit to high for what I can > perceive. > > For example, I obtain: > > Every 1.0s: cat /tmp/filter.latencies.txt Fri Jan 30 > 19:54:26 2009 > > 5.844000/0.000000/0.001000/4.049000 > > I can accept that the value "Time Before Queued" is a little bit high, > as it represent the time for the content filter to queue the message > since it has been trasmitted by the sender. But I can't figure out why > the "Time to transmit the message" is high at the same manner, even if > it represent (at least I think) the time employed by the content filter > to transmit the message back to Postfix. > > Sorry for my not completely clear exposition, but I'ld like to have a > better one that possibly explay better the messages timing inside a such > architecture. I appreciate any comment about. >
For example consider the log relative to the relay entries (to the cntent filer and to postfix without conten filter): 1) Jan 30 10:02:17 av5 postfix/smtp[10603]: C0AFB226F23: to=<recei...@domain.tld>, relay=127.0.0.1[127.0.0.1]:10026, delay=8.9, delays=1.3/0/0/7.7, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 95CEE226F30) 2) Jan 30 10:02:17 av5 postfix/smtp[5441]: 95CEE226F30: to=<recei...@domain.tld>, relay=server[xxx.yyy.zzz.uuu]:25, delay=0.11, delays=0.03/0.04/0.01/0.03, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 5C7951098002) - Why "d" in 1) is high? It includes the processing mase by content filter? - How could I tune Postfix to lower this delay? Maybe raising "maxprocs" value for the contet filter? Are there other tunings to apply? - Why d) in 1) and a) in 2) are different values? - How could raise the concurrency in postfix so that the queue manager is faster in managing the messages and deliver it to the delivery processes? - It is possible to lower d) in 2)? Or depends exclusively from other factors (network, receiving MTA and other)? Thanks, rocsca
