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

Re: Connection Speed

Expand Messages
  • Wietse Venema
    ... You *could* start with the time stamps in the Postfix maillog file. For example: Sep 12 00:10:57 spike postfix/smtpd[69741]: connect from
    Message 1 of 10 , Sep 12, 2013
      Roman Gelfand:
      > 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.
      >
      > How can I determine the client connection speed?

      You *could* start with the time stamps in the Postfix maillog file.

      For example:

      Sep 12 00:10:57 spike postfix/smtpd[69741]: connect from some.example.com[1.2.3.4]
      Sep 12 00:10:58 spike postfix/smtpd[69741]: 3cb63Q2c6Zzjymk: client=some.example.com[1.2.3.4]
      Sep 12 00:10:58 spike postfix/cleanup[69745]: 3cb63Q2c6Zzjymk: message-id=<gibberish@...>

      The first time stamp is logged after Postfix has looked up the
      client hostname, after it has verified that the hostname resolves
      to the client IP address, and before it logs the "220" server
      greeting.

      If your Postfix is mis-configured then this first line will be
      logged 5-10 seconds after the client makes the TCP connection.

      You can determine if this is a problem by making a telnet connection
      (telnet server 25) from the system that runs chilkat. You should
      see the "220" server greeting immediately.

      The second time stamp is logged when Postfix accepts the first
      recipient address.

      The third time stamp is logged after the DATA command.

      Wietse
    • Viktor Dukhovni
      ... Don t guess measure. The mail logs record four delay measurements for each message: postfix/smtp[ ]: : to= , ... delays=a/b/c/d, ...
      Message 2 of 10 , Sep 12, 2013
        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.
      • 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 3 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 4 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 5 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 6 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 7 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 8 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 9 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.