Loading ...
Sorry, an error occurred while loading the content.
 

Re: Connection Speed

Expand Messages
  • Roman Gelfand
    Based on comments made by Wietse, it looks like my server is in good shape as the connections are not even taking a second and the whole process is taking
    Message 1 of 10 , Sep 12, 2013
      Based on comments made by Wietse, it looks like my server is in good
      shape as the connections are not even taking a second and the whole
      process is taking roughly a second.

      Based on what Viktor is saying, this line could be a problem Sep 12
      09:39:56 pmx1 postfix/smtpd[30058]: connect from unknown[192.168.0.86]
      as it could to take some to time to attempt resolve this dns. Is this
      correct?

      On Thu, Sep 12, 2013 at 9:47 AM, Viktor Dukhovni
      <postfix-users@...> wrote:
      > On Thu, Sep 12, 2013 at 09:12:59AM -0400, Roman Gelfand wrote:
      >
      >> We have a program which every so often sends a request, using chilkat,
      >> to postfix to send out email with attachment. With every send it has
      >> to connect to postfix using sasl authentication. Each send appears to
      >> take a long time. In the absence of more detailed information, I am
      >> guessing the connection is taking most of the time.
      >
      > Don't guess measure. The mail logs record four delay measurements for
      > each message:
      >
      > postfix/smtp[<pid>]: <queue_id>: to=<rcpt>, ... delays=a/b/c/d, ...
      >
      > The components of the "delays" field are:
      >
      > a. Time elapsed between message creation and the message entering
      > the active queue. With SMTP the clock starts at the first
      > accepted "RCPT TO:" command. This does not include the time
      > from the client's TCP SYN to initiate the connection until
      > the server responds with "250" to "MAIL FROM:".
      >
      > The start time is that of the log entry of the form:
      >
      > postfix/smtpd[<pid>]: <queue-id>: client=...
      >
      > If your client's IP address triggers slow (failing) PTR
      > lookups, or slow forward lookups of the resulting name
      > that time is not seen in the Postfix logs as the
      > first log message
      >
      > postfix/smtpd[<pid>]: connect from ...
      >
      > is logged after attempting to reverse resolve the client's
      > IP address.
      >
      > b. Time spent in the active queue, large delays here show a congested
      > destination or an overall congested queue.
      >
      > c. Time taken to connect to the remote destination, from the delivery
      > agent receiving the request to deliver the message to the beginning
      > of the mail transaction (with SMTP, sending MAIL FROM:)
      >
      > d. Time taken to complete the mail transaction.
      >
      > Report all logging for your "slow" deliveries, from the "connect from ..."
      > message with the same process id as the "smtpd: <queue_id>: client=" message
      > including all messages with that queue-id, until the "disconnect from".
      >
      > You may find the Perl script in:
      >
      > http://www.mail-archive.com/postfix-devel@.../msg00292.html
      >
      > useful.
      >
      > --
      > Viktor.
    • Viktor Dukhovni
      ... Whether that is slow or not depends on what throughput (messages sent per second) you re trying to achieve and what concurrency (number of parallel
      Message 2 of 10 , Sep 12, 2013
        On Thu, Sep 12, 2013 at 10:03:58AM -0400, Roman Gelfand wrote:

        > Based on comments made by Wietse, it looks like my server is in good
        > shape as the connections are not even taking a second and the whole
        > process is taking roughly a second.

        Whether that is slow or not depends on what throughput (messages
        sent per second) you're trying to achieve and what concurrency
        (number of parallel submission processes or threads) you're using
        to submit mail. Mail delivery is "congested" when the output rate
        is below the input rate, otherwise mail is inevitably delayed in
        transit by a short time, but that is rarely a concern.

        > Based on what Viktor is saying, this line could be a problem
        >
        > Sep 12 09:39:56 pmx1 postfix/smtpd[30058]: connect from unknown[192.168.0.86]
        >
        > as it could to take some to time to attempt resolve this dns. Is this
        > correct?

        A single log message with a single timestamp in isolation is NOT
        evidence of delay. All we see is that reverse resolution of
        [192.168.0.86] failed, whether this took any appreciable time is
        not evident from this log entry alone. There are often prior log
        entries warning about the resolution failure of DNS lookups timed
        out, ...

        To determine whether there is a delay, use "telnet" to connect from
        192.168.0.86 to port 25 on the MTA, and see how long you have to wait
        until the MTA responds with a "220 ..." banner.

        You can also capture with "tcpdump" and see timestamps to the
        microsecond showing how long it takes from TCP SYN to "220 ..."
        (and what DNS lookups are taking time in between).

        --
        Viktor.
      • Wietse Venema
        ... Sending mail into Postfix takes roughly a second? ... Sending mail into Postfix takes a long time? Wietse
        Message 3 of 10 , Sep 12, 2013
          Roman Gelfand:
          > Based on comments made by Wietse, it looks like my server is in good
          > shape as the connections are not even taking a second and the whole
          > process is taking roughly a second.

          Sending mail into Postfix takes roughly a second?

          > We have a program which every so often sends a request, using chilkat,
          > to postfix to send out email with attachment. With every send it has
          > to connect to postfix using sasl authentication. Each send appears to
          > take a long time.

          Sending mail into Postfix takes a long time?

          Wietse
        • Roman Gelfand
          Please, see below... The whole turnaround was roughly a second. What I meant by Sending mail into Postfix is chilkat application takes 13 seconds to send
          Message 4 of 10 , Sep 12, 2013
            Please, see below... The whole turnaround was roughly a second. What
            I meant by "Sending mail into Postfix" is chilkat application takes 13
            seconds to send it.

            Sep 12 10:38:49 mail1 postfix/smtpd[30657]: connect from unknown[192.168.0.147]
            Sep 12 10:38:50 mail1 postfix/smtpd[30657]: 0208544124:
            client=unknown[192.168.0.147], sasl_method=LOGIN,
            sasl_username=user@...
            Sep 12 10:38:50 mail1 postfix/cleanup[30661]: 0208544124: info: header
            Subject: Order from domain Inc. ORDER # 2254400 from
            unknown[192.168.0.147]; from=<user@...>
            to=<6kdpkhxr3t6r6p5@...> proto=ESMTP
            helo=<User29-ws.domain.local>
            Sep 12 10:38:50 mail1 postfix/cleanup[30661]: 0208544124:
            message-id=<CHILKAT-MID-3baab4e7-8ade-db94-236d-92d797ce8be2@...>
            Sep 12 10:38:50 mail1 postfix/qmgr[3632]: 0208544124:
            from=<user@...>, size=2404, nrcpt=1 (queue active)
            Sep 12 10:38:50 mail1 postfix/smtpd[30657]: disconnect from
            unknown[192.168.0.147]
            Sep 12 10:38:50 mail1 postfix/smtp[30325]: 0208544124:
            to=<dkfsdklfdafd@...>,
            relay=retail-smtp-in.amazon.com[176.32.98.133]:25, delay=0.26,
            delays=0/0/0.1/0.15, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
            52D9D9EC1AE)
            Sep 12 10:38:50 mail1 postfix/qmgr[3632]: 0208544124: removed

            On Thu, Sep 12, 2013 at 10:15 AM, Wietse Venema <wietse@...> wrote:
            > Roman Gelfand:
            >> Based on comments made by Wietse, it looks like my server is in good
            >> shape as the connections are not even taking a second and the whole
            >> process is taking roughly a second.
            >
            > Sending mail into Postfix takes roughly a second?
            >
            >> We have a program which every so often sends a request, using chilkat,
            >> to postfix to send out email with attachment. With every send it has
            >> to connect to postfix using sasl authentication. Each send appears to
            >> take a long time.
            >
            > Sending mail into Postfix takes a long time?
            >
            > Wietse
            >
          • Roman Gelfand
            you are right. The telnet connection from that machine was instantaneous. On Thu, Sep 12, 2013 at 10:14 AM, Viktor Dukhovni
            Message 5 of 10 , Sep 12, 2013
              you are right. The telnet connection from that machine was instantaneous.

              On Thu, Sep 12, 2013 at 10:14 AM, Viktor Dukhovni
              <postfix-users@...> wrote:
              > On Thu, Sep 12, 2013 at 10:03:58AM -0400, Roman Gelfand wrote:
              >
              >> Based on comments made by Wietse, it looks like my server is in good
              >> shape as the connections are not even taking a second and the whole
              >> process is taking roughly a second.
              >
              > Whether that is slow or not depends on what throughput (messages
              > sent per second) you're trying to achieve and what concurrency
              > (number of parallel submission processes or threads) you're using
              > to submit mail. Mail delivery is "congested" when the output rate
              > is below the input rate, otherwise mail is inevitably delayed in
              > transit by a short time, but that is rarely a concern.
              >
              >> Based on what Viktor is saying, this line could be a problem
              >>
              >> Sep 12 09:39:56 pmx1 postfix/smtpd[30058]: connect from unknown[192.168.0.86]
              >>
              >> as it could to take some to time to attempt resolve this dns. Is this
              >> correct?
              >
              > A single log message with a single timestamp in isolation is NOT
              > evidence of delay. All we see is that reverse resolution of
              > [192.168.0.86] failed, whether this took any appreciable time is
              > not evident from this log entry alone. There are often prior log
              > entries warning about the resolution failure of DNS lookups timed
              > out, ...
              >
              > To determine whether there is a delay, use "telnet" to connect from
              > 192.168.0.86 to port 25 on the MTA, and see how long you have to wait
              > until the MTA responds with a "220 ..." banner.
              >
              > You can also capture with "tcpdump" and see timestamps to the
              > microsecond showing how long it takes from TCP SYN to "220 ..."
              > (and what DNS lookups are taking time in between).
              >
              > --
              > Viktor.
            • Viktor Dukhovni
              ... In fact delivery takes only 0.25 seconds. So chilkat is not reporting the time spent talking to Postfix. Debug chilkat , not Postfix. Tcpdump is your
              Message 6 of 10 , Sep 12, 2013
                On Thu, Sep 12, 2013 at 10:47:24AM -0400, Roman Gelfand wrote:

                > Sep 12 10:38:50 mail1 postfix/smtp[30325]: 0208544124:
                > to=<dkfsdklfdafd@...>,
                > relay=retail-smtp-in.amazon.com[176.32.98.133]:25, delay=0.26,
                > delays=0/0/0.1/0.15, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
                > 52D9D9EC1AE)
                >
                > Please, see below... The whole turnaround was roughly a second. What
                > I meant by "Sending mail into Postfix" is chilkat application takes 13
                > seconds to send it.

                In fact delivery takes only 0.25 seconds. So "chilkat" is not
                reporting the time spent talking to Postfix. Debug "chilkat", not
                Postfix. Tcpdump is your friend.

                On Thu, Sep 12, 2013 at 10:52:46AM -0400, Roman Gelfand wrote:

                > > To determine whether there is a delay, use "telnet" to connect from
                > > 192.168.0.86 to port 25 on the MTA, and see how long you have to wait
                > > until the MTA responds with a "220 ..." banner.
                >
                > you are right. The telnet connection from that machine was instantaneous.

                In that case the "before banner" time to add to the "0.25s" seconds
                above is essentially zero. Postfix is not the source of the 13s time
                reported by the application.

                Without further evidence of something slow in Postfix, this thread
                is done.

                If you want to pursue this further, use "tcpdump" and also the Perl
                script I posted to postfix-devel.

                --
                Viktor.
              • Wietse Venema
                ... A this point it would be worthwhile for you to look at the chilkat side of things. I am not familar with chilkat, but I would expect that it can produce
                Message 7 of 10 , Sep 12, 2013
                  Roman Gelfand:
                  > Please, see below... The whole turnaround was roughly a second. What
                  > I meant by "Sending mail into Postfix" is chilkat application takes 13
                  > seconds to send it.
                  >
                  > Sep 12 10:38:49 mail1 postfix/smtpd[30657]: connect from unknown[192.168.0.147]
                  ...
                  > Sep 12 10:38:50 mail1 postfix/smtp[30325]: 0208544124:
                  > to=<dkfsdklfdafd@...>,
                  > relay=retail-smtp-in.amazon.com[176.32.98.133]:25, delay=0.26,
                  > delays=0/0/0.1/0.15, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as
                  > 52D9D9EC1AE)
                  > Sep 12 10:38:50 mail1 postfix/qmgr[3632]: 0208544124: removed

                  A this point it would be worthwhile for you to look at the chilkat
                  side of things. I am not familar with chilkat, but I would expect
                  that it can produce logging that shows where it is spending its
                  time.

                  As long as you aren't overloading Postfix, i.e. you don't have
                  logging like this:

                  Oct 3 20:39:27 spike postfix/master[28905]: warning: service "smtp"
                  (25) has reached its process limit "30": new clients may experience
                  noticeable delays

                  Then there is nothing that could be fixed on the Postfix side.

                  Wietse
                Your message has been successfully submitted and would be delivered to recipients shortly.