Wietse: Sadly I generally don't keep logs at this granular of a level (mail.crit is what I usually store forever) but I can turn logging back on after the queue empties over the weekend and see if the delay is persisting. I know the command itself is completing quickly -- it seems like something in between is causing a delay. Do you have any suggestions for how I could profile the handoff from local to the executable?
Thanks again, Wendy On Thu, Jan 14, 2010 at 4:13 PM, Wietse Venema <wie...@porcupine.org> wrote: > Wendigo Thompson: >> Wietse: >> >> I know who you are -- big fan of yours ever since tcpwrappers :-) > > Hah! > > (As for my claim, of course other people also wrote parts of > Postfix, in particular Victor has been a major contributor). > >> The only reason I wrote in is that this queueing of mail issue >> appeared fairly recently, and other times when I have had to collect >> large volumes of mail from this client my system has been fine. Below >> I have pasted some logs that show long delivery times (sitting in the >> queue for a day) but the last delay (delivery delay?) is in the >> upper-teens. Just trying to reconcile why this is: if it's something >> on my end that is fine and I can work it out, but maybe it is an >> unforeseen issue with Postfix and large volumes of piped mail. The >> system itself is a Nehalem Xserve, so it seems to have plenty of >> horsepower to handle the load. >> >> (anonymized a bit in hostname and email address) >> Jan 14 15:45:43 server001 postfix/local[24570]: 26E371265ED: >> to=<receiver_em...@receiver_ip>, relay=local, delay=81352, >> delays=0.59/81343/0/7.7, dsn=2.0.0, status=sent (delivered to command: >> /usr/bin/db_capture) > > This looks problematic: it took 7.7s from the time that the Postfix > local delivery agent was tasked to deliver the message, to the time > that the db_capture command reported completion. > > Plus, these messages had already been sitting in the queue for > almost 24 hours, so the problem will have started much earlier than > that. > >> delays=0.5/81344/0/8.2, dsn=2.0.0, ... >> delays=0.34/81341/0/13, dsn=2.0.0, ... >> delays=0.41/81344/0/10, dsn=2.0.0, ... >> delays=0/81339/0/19, dsn=2.0.0, ... >> delays=0.42/81342/0/14, dsn=2.0.0, ... >> delays=0.19/81344/0/11, dsn=2.0.0, ... >> delays=0/81341/0/15, dsn=2.0.0, ... >> delays=0/81337/0/21, dsn=2.0.0, ... >> delays=0.57/81343/0/11, dsn=2.0.0, ... >> delays=0.32/81342/0/16, dsn=2.0.0, ... >> delays=0.21/81341/0/18, dsn=2.0.0, ... >> delays=0.35/81348/0/7, dsn=2.0.0, ... >> delays=0.12/81339/0/21, dsn=2.0.0, ... >> delays=0.09/81340/0/20, dsn=2.0.0, ... > > Now the question is why did /usr/bin/db_capture take so long? I am > not sure that my "red" and "green" options are going to solve your > performance problem. > > If you still have the logs, it will be worthwhile to find out when > the delivery delay started climbing through the roof. > > Wietse >
