qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

classic Classic list List threaded Threaded
12 messages Options
Reply | Threaded
Open this post in threaded view
|

qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
I'm still debugging the communication issues I've been struggling with
for months - where there are unexpected delays in (I think) message
passing between a C++ Messaging API application and a C++ broker. I've
now narrowed down the problem to the send() call, I believe. I'm using
the following function(s) to publish data - notice the timing etc.:

namespace Util {
namespace {
inline double clockTime(clockid_t clockId)
{
   {
     struct timespec t;
     if(clock_gettime(clockId, &t)==0) {
       return t.tv_sec+0.000000001*t.tv_nsec;
     }
     return -INFINITY;
   }
}
}

double currentMonotonicTime()
{
   return clockTime(CLOCK_MONOTONIC);
}

double currentProcessTime()
{
   return clockTime(CLOCK_PROCESS_CPUTIME_ID);
}
} // End namespace Util

#define PUBLISH_SENDER_CAPACITY 100

std::string QPid::publishArgs()
{
   std::string exchangeArgs="create: sender, delete: never";

   exchangeArgs+=", node: { type: topic, durable: False }";

   return exchangeArgs;
}

bool QPid::publish(qpid::messaging::Session &session,
                   const qpid::messaging::Message &message)
{
   double t0=Util::currentMonotonicTime(), t1=t0;
   double t0cpu=Util::currentThreadTime(), t1cpu=t0cpu;
   
   std::string exchangeName=publishExchange();
   try {
     session.checkError();
     qpid::messaging::Sender sender;

     try {
       sender=session.getSender(exchangeName);
     } catch(qpid::messaging::KeyError &error) {
       std::string exchangeArgs=publishArgs();
       std::string address=exchangeName + "; { " + exchangeArgs + " }";
       
       sender=session.createSender(address);
#ifdef PUBLISH_SENDER_CAPACITY
       sender.setCapacity(PUBLISH_SENDER_CAPACITY);
#endif
     }
     
#ifdef DEBUG
     std::cerr << "Subject " << message.getSubject() << "\n";
#endif /* DEBUG */
     t1=Util::currentMonotonicTime();
     t1cpu=Util::currentThreadTime();
     
     sender.send(message);
   } catch(const std::exception &error) {
     const char *errorMessage=error.what();
     
     if(errorMessage && *errorMessage) {
       Util::error("\"%s\" when sending message to %s/%s", errorMessage,
                   exchangeName.c_str(), message.getSubject().c_str());
     } else {
       /* Note: Exceptions from Session::checkError() often have no error
                message */
       Util::error("Unspecified failure or pre-existing link problem when "
                   "sending to %s/%s", exchangeName.c_str(),
                   message.getSubject().c_str());
     }
   
     return false;
   }
   double t2=Util::currentMonotonicTime(), t2cpu=Util::currentThreadTime();
   
   Util::debug(2, "%s sent to %s in %.2f ms/CPU time %.2f ms (%.2f/%.2f ms in send())",
              message.getSubject().c_str(), exchangeName.c_str(), (t2-t0)*1000,
              (t2cpu-t0cpu)*1000, (t2-t1)*1000, (t2cpu-t1cpu)*1000);
       
   return true;
}

Util::debug() is a simple function that optionally (subject to a "debug
level") config sends data to the console; it takes printf()-style input.

Now, most of the time, output from the above with QPid "debug+" logging
is something like (some names are changed due to paranoia):

2020-12-09 12:30:00 [Client] debug Sending to exchange Data.exch {MessageProperties: content-length=3; content-type=application/x-protobuf; user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64; application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516990),timestamp_usec:F8:int64(16253),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000; routing-key=cxxx.out.extdata.7; }
Dec  9 12:30:00 cxxx.out.extdata.7 sent to Data.exch in 0.03 ms/CPU time 0.03 ms (0.03/0.03 ms in send())

but I sometimes get

2020-12-09 12:30:07 [Client] debug Sending to exchange Data.exch {MessageProperties: content-length=3; content-type=application/x-protobuf; user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64; application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516991),timestamp_usec:F8:int64(8403),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000; routing-key=cxxx.out.extdata.7; }
Dec  9 12:30:07 cxxx.out.extdata.7 sent to Data.exch in 7195.39 ms/CPU time 2.45 ms (7195.39/2.45 ms in send())

My question is simply, what might cause the send to take several
seconds? I can't see any reason why the communication itself should be
that slow; the software runs on a machine that's connected to the same
network switch as the broker. The systems do have a certain load, but I
didn't think it would be able to cause anything like this. And shouldn't
threading etc. make sure something gets done within a reasonable time in
any case? What am I missing?

Note that the Session object is reused - ideally (if there are no
errors) it's kept throughout the life-time of the application. The same
session is also used to receive data from a number of queues. Is that a
bad idea? Send and receive are done in the same thread.

There is nothing in the broker log to suggest that that a problem is
detected on that end.

I've experimented with "trace+" logging, but it seemed to produce so
much information that it bogged down the system.

So I'm crying for help again... Anyone?

Thanks.

- Toralf

Reply | Threaded
Open this post in threaded view
|

Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Chester
Is it possibly a nagle problem? We always set "tcp_nodelay: true" in our
configs... We also re-use sessions throughout the application lifetime.

On Wed, Dec 9, 2020 at 8:36 AM Toralf Lund <[hidden email]> wrote:

> I'm still debugging the communication issues I've been struggling with
> for months - where there are unexpected delays in (I think) message
> passing between a C++ Messaging API application and a C++ broker. I've
> now narrowed down the problem to the send() call, I believe. I'm using
> the following function(s) to publish data - notice the timing etc.:
>
> namespace Util {
> namespace {
> inline double clockTime(clockid_t clockId)
> {
>    {
>      struct timespec t;
>      if(clock_gettime(clockId, &t)==0) {
>        return t.tv_sec+0.000000001*t.tv_nsec;
>      }
>      return -INFINITY;
>    }
> }
> }
>
> double currentMonotonicTime()
> {
>    return clockTime(CLOCK_MONOTONIC);
> }
>
> double currentProcessTime()
> {
>    return clockTime(CLOCK_PROCESS_CPUTIME_ID);
> }
> } // End namespace Util
>
> #define PUBLISH_SENDER_CAPACITY 100
>
> std::string QPid::publishArgs()
> {
>    std::string exchangeArgs="create: sender, delete: never";
>
>    exchangeArgs+=", node: { type: topic, durable: False }";
>
>    return exchangeArgs;
> }
>
> bool QPid::publish(qpid::messaging::Session &session,
>                    const qpid::messaging::Message &message)
> {
>    double t0=Util::currentMonotonicTime(), t1=t0;
>    double t0cpu=Util::currentThreadTime(), t1cpu=t0cpu;
>
>    std::string exchangeName=publishExchange();
>    try {
>      session.checkError();
>      qpid::messaging::Sender sender;
>
>      try {
>        sender=session.getSender(exchangeName);
>      } catch(qpid::messaging::KeyError &error) {
>        std::string exchangeArgs=publishArgs();
>        std::string address=exchangeName + "; { " + exchangeArgs + " }";
>
>        sender=session.createSender(address);
> #ifdef PUBLISH_SENDER_CAPACITY
>        sender.setCapacity(PUBLISH_SENDER_CAPACITY);
> #endif
>      }
>
> #ifdef DEBUG
>      std::cerr << "Subject " << message.getSubject() << "\n";
> #endif /* DEBUG */
>      t1=Util::currentMonotonicTime();
>      t1cpu=Util::currentThreadTime();
>
>      sender.send(message);
>    } catch(const std::exception &error) {
>      const char *errorMessage=error.what();
>
>      if(errorMessage && *errorMessage) {
>        Util::error("\"%s\" when sending message to %s/%s", errorMessage,
>                    exchangeName.c_str(), message.getSubject().c_str());
>      } else {
>        /* Note: Exceptions from Session::checkError() often have no error
>                 message */
>        Util::error("Unspecified failure or pre-existing link problem when "
>                    "sending to %s/%s", exchangeName.c_str(),
>                    message.getSubject().c_str());
>      }
>
>      return false;
>    }
>    double t2=Util::currentMonotonicTime(), t2cpu=Util::currentThreadTime();
>
>    Util::debug(2, "%s sent to %s in %.2f ms/CPU time %.2f ms (%.2f/%.2f ms
> in send())",
>               message.getSubject().c_str(), exchangeName.c_str(),
> (t2-t0)*1000,
>               (t2cpu-t0cpu)*1000, (t2-t1)*1000, (t2cpu-t1cpu)*1000);
>
>    return true;
> }
>
> Util::debug() is a simple function that optionally (subject to a "debug
> level") config sends data to the console; it takes printf()-style input.
>
> Now, most of the time, output from the above with QPid "debug+" logging
> is something like (some names are changed due to paranoia):
>
> 2020-12-09 12:30:00 [Client] debug Sending to exchange Data.exch
> {MessageProperties: content-length=3; content-type=application/x-protobuf;
> user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64;
> application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516990),timestamp_usec:F8:int64(16253),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram
> 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000;
> routing-key=cxxx.out.extdata.7; }
> Dec  9 12:30:00 cxxx.out.extdata.7 sent to Data.exch in 0.03 ms/CPU time
> 0.03 ms (0.03/0.03 ms in send())
>
> but I sometimes get
>
> 2020-12-09 12:30:07 [Client] debug Sending to exchange Data.exch
> {MessageProperties: content-length=3; content-type=application/x-protobuf;
> user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64;
> application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516991),timestamp_usec:F8:int64(8403),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram
> 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000;
> routing-key=cxxx.out.extdata.7; }
> Dec  9 12:30:07 cxxx.out.extdata.7 sent to Data.exch in 7195.39 ms/CPU
> time 2.45 ms (7195.39/2.45 ms in send())
>
> My question is simply, what might cause the send to take several
> seconds? I can't see any reason why the communication itself should be
> that slow; the software runs on a machine that's connected to the same
> network switch as the broker. The systems do have a certain load, but I
> didn't think it would be able to cause anything like this. And shouldn't
> threading etc. make sure something gets done within a reasonable time in
> any case? What am I missing?
>
> Note that the Session object is reused - ideally (if there are no
> errors) it's kept throughout the life-time of the application. The same
> session is also used to receive data from a number of queues. Is that a
> bad idea? Send and receive are done in the same thread.
>
> There is nothing in the broker log to suggest that that a problem is
> detected on that end.
>
> I've experimented with "trace+" logging, but it seemed to produce so
> much information that it bogged down the system.
>
> So I'm crying for help again... Anyone?
>
> Thanks.
>
> - Toralf
>
>
Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
On 09/12/2020 17:31, Chester wrote:
> Is it possibly a nagle problem? We always set "tcp_nodelay: true" in our
> configs...

That's also done in this application. Or at least it's supposed to be.
Perhaps worth checking if the option actually gets enabled the right way...

>   We also re-use sessions throughout the application lifetime

OK. Good.

- Toralf

> .
>
> On Wed, Dec 9, 2020 at 8:36 AM Toralf Lund <[hidden email]> wrote:
>
>> I'm still debugging the communication issues I've been struggling with
>> for months - where there are unexpected delays in (I think) message
>> passing between a C++ Messaging API application and a C++ broker. I've
>> now narrowed down the problem to the send() call, I believe. I'm using
>> the following function(s) to publish data - notice the timing etc.:
>>
>> namespace Util {
>> namespace {
>> inline double clockTime(clockid_t clockId)
>> {
>>     {
>>       struct timespec t;
>>       if(clock_gettime(clockId, &t)==0) {
>>         return t.tv_sec+0.000000001*t.tv_nsec;
>>       }
>>       return -INFINITY;
>>     }
>> }
>> }
>>
>> double currentMonotonicTime()
>> {
>>     return clockTime(CLOCK_MONOTONIC);
>> }
>>
>> double currentProcessTime()
>> {
>>     return clockTime(CLOCK_PROCESS_CPUTIME_ID);
>> }
>> } // End namespace Util
>>
>> #define PUBLISH_SENDER_CAPACITY 100
>>
>> std::string QPid::publishArgs()
>> {
>>     std::string exchangeArgs="create: sender, delete: never";
>>
>>     exchangeArgs+=", node: { type: topic, durable: False }";
>>
>>     return exchangeArgs;
>> }
>>
>> bool QPid::publish(qpid::messaging::Session &session,
>>                     const qpid::messaging::Message &message)
>> {
>>     double t0=Util::currentMonotonicTime(), t1=t0;
>>     double t0cpu=Util::currentThreadTime(), t1cpu=t0cpu;
>>
>>     std::string exchangeName=publishExchange();
>>     try {
>>       session.checkError();
>>       qpid::messaging::Sender sender;
>>
>>       try {
>>         sender=session.getSender(exchangeName);
>>       } catch(qpid::messaging::KeyError &error) {
>>         std::string exchangeArgs=publishArgs();
>>         std::string address=exchangeName + "; { " + exchangeArgs + " }";
>>
>>         sender=session.createSender(address);
>> #ifdef PUBLISH_SENDER_CAPACITY
>>         sender.setCapacity(PUBLISH_SENDER_CAPACITY);
>> #endif
>>       }
>>
>> #ifdef DEBUG
>>       std::cerr << "Subject " << message.getSubject() << "\n";
>> #endif /* DEBUG */
>>       t1=Util::currentMonotonicTime();
>>       t1cpu=Util::currentThreadTime();
>>
>>       sender.send(message);
>>     } catch(const std::exception &error) {
>>       const char *errorMessage=error.what();
>>
>>       if(errorMessage && *errorMessage) {
>>         Util::error("\"%s\" when sending message to %s/%s", errorMessage,
>>                     exchangeName.c_str(), message.getSubject().c_str());
>>       } else {
>>         /* Note: Exceptions from Session::checkError() often have no error
>>                  message */
>>         Util::error("Unspecified failure or pre-existing link problem when "
>>                     "sending to %s/%s", exchangeName.c_str(),
>>                     message.getSubject().c_str());
>>       }
>>
>>       return false;
>>     }
>>     double t2=Util::currentMonotonicTime(), t2cpu=Util::currentThreadTime();
>>
>>     Util::debug(2, "%s sent to %s in %.2f ms/CPU time %.2f ms (%.2f/%.2f ms
>> in send())",
>>                message.getSubject().c_str(), exchangeName.c_str(),
>> (t2-t0)*1000,
>>                (t2cpu-t0cpu)*1000, (t2-t1)*1000, (t2cpu-t1cpu)*1000);
>>
>>     return true;
>> }
>>
>> Util::debug() is a simple function that optionally (subject to a "debug
>> level") config sends data to the console; it takes printf()-style input.
>>
>> Now, most of the time, output from the above with QPid "debug+" logging
>> is something like (some names are changed due to paranoia):
>>
>> 2020-12-09 12:30:00 [Client] debug Sending to exchange Data.exch
>> {MessageProperties: content-length=3; content-type=application/x-protobuf;
>> user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64;
>> application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516990),timestamp_usec:F8:int64(16253),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram
>> 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000;
>> routing-key=cxxx.out.extdata.7; }
>> Dec  9 12:30:00 cxxx.out.extdata.7 sent to Data.exch in 0.03 ms/CPU time
>> 0.03 ms (0.03/0.03 ms in send())
>>
>> but I sometimes get
>>
>> 2020-12-09 12:30:07 [Client] debug Sending to exchange Data.exch
>> {MessageProperties: content-length=3; content-type=application/x-protobuf;
>> user-id=; app-id=TheProgram 1.0-0.20201207.1.6e9dd21.el7-x86_64;
>> application-headers={message_type:V2:27:vbin16(Cxxx.Out.ExtData),qpid.subject:V2:29:str16(cxxx.out.extdata.7),timestamp:F8:int64(1607516991),timestamp_usec:F8:int64(8403),x-amqp-0-10.app-id:V2:47:vbin16(TheProgram
>> 1.0-0.20201207.1.6e9dd21.el7-x86_64)}; } {DeliveryProperties: ttl=10000;
>> routing-key=cxxx.out.extdata.7; }
>> Dec  9 12:30:07 cxxx.out.extdata.7 sent to Data.exch in 7195.39 ms/CPU
>> time 2.45 ms (7195.39/2.45 ms in send())
>>
>> My question is simply, what might cause the send to take several
>> seconds? I can't see any reason why the communication itself should be
>> that slow; the software runs on a machine that's connected to the same
>> network switch as the broker. The systems do have a certain load, but I
>> didn't think it would be able to cause anything like this. And shouldn't
>> threading etc. make sure something gets done within a reasonable time in
>> any case? What am I missing?
>>
>> Note that the Session object is reused - ideally (if there are no
>> errors) it's kept throughout the life-time of the application. The same
>> session is also used to receive data from a number of queues. Is that a
>> bad idea? Send and receive are done in the same thread.
>>
>> There is nothing in the broker log to suggest that that a problem is
>> detected on that end.
>>
>> I've experimented with "trace+" logging, but it seemed to produce so
>> much information that it bogged down the system.
>>
>> So I'm crying for help again... Anyone?
>>
>> Thanks.
>>
>> - Toralf
>>
>>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Gordon Sim
In reply to this post by Toralf Lund
On 09/12/2020 13:35, Toralf Lund wrote:
> My question is simply, what might cause the send to take several
> seconds? I can't see any reason why the communication itself should be
> that slow; the software runs on a machine that's connected to the same
> network switch as the broker. The systems do have a certain load, but I
> didn't think it would be able to cause anything like this. And shouldn't
> threading etc. make sure something gets done within a reasonable time in
> any case? What am I missing?

One possibility might be lack of capacity (e.g. if the previous 100
messages have not yet been acknowledged).

Is there any pattern (in time for example) as to when the long sends
occur v. the more normal send times?


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
On 09/12/2020 19:16, Gordon Sim wrote:

> On 09/12/2020 13:35, Toralf Lund wrote:
>> My question is simply, what might cause the send to take several
>> seconds? I can't see any reason why the communication itself should
>> be that slow; the software runs on a machine that's connected to the
>> same network switch as the broker. The systems do have a certain
>> load, but I didn't think it would be able to cause anything like
>> this. And shouldn't threading etc. make sure something gets done
>> within a reasonable time in any case? What am I missing?
>
> One possibility might be lack of capacity (e.g. if the previous 100
> messages have not yet been acknowledged).

Maybe. But I still don't get why it would take as long as 6 or 7 seconds.

I have a test app that sends messages through a sender with 0 capacity,
with a certain delay between transfers, and send() then generally takes
less than 1 ms.

>
> Is there any pattern (in time for example) as to when the long sends
> occur v. the more normal send times?

I haven't been able to find one yet.

- Toralf

>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Gordon Sim
On 09/12/2020 18:36, Toralf Lund wrote:

> On 09/12/2020 19:16, Gordon Sim wrote:
>> On 09/12/2020 13:35, Toralf Lund wrote:
>>> My question is simply, what might cause the send to take several
>>> seconds? I can't see any reason why the communication itself should
>>> be that slow; the software runs on a machine that's connected to the
>>> same network switch as the broker. The systems do have a certain
>>> load, but I didn't think it would be able to cause anything like
>>> this. And shouldn't threading etc. make sure something gets done
>>> within a reasonable time in any case? What am I missing?
>>
>> One possibility might be lack of capacity (e.g. if the previous 100
>> messages have not yet been acknowledged).
>
> Maybe. But I still don't get why it would take as long as 6 or 7 seconds.
>
> I have a test app that sends messages through a sender with 0 capacity,
> with a certain delay between transfers, and send() then generally takes
> less than 1 ms.

Does that test app publish to the same queue(s)? Does the queue depth on
the queue(s) that the slow sends occur on ever get large? (Is there some
limit set on the queue depth?)

The only other thing I can think of that would cause the invocation of
send() to take a long time would be some sort of locking issue. Are the
multiple threads possibly sending concurrently?

How long does the slow sending usually last?


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
On 09/12/2020 22:55, Gordon Sim wrote:

> On 09/12/2020 18:36, Toralf Lund wrote:
>> On 09/12/2020 19:16, Gordon Sim wrote:
>>> On 09/12/2020 13:35, Toralf Lund wrote:
>>>> My question is simply, what might cause the send to take several
>>>> seconds? I can't see any reason why the communication itself should
>>>> be that slow; the software runs on a machine that's connected to
>>>> the same network switch as the broker. The systems do have a
>>>> certain load, but I didn't think it would be able to cause anything
>>>> like this. And shouldn't threading etc. make sure something gets
>>>> done within a reasonable time in any case? What am I missing?
>>>
>>> One possibility might be lack of capacity (e.g. if the previous 100
>>> messages have not yet been acknowledged).
>>
>> Maybe. But I still don't get why it would take as long as 6 or 7
>> seconds.
>>
>> I have a test app that sends messages through a sender with 0
>> capacity, with a certain delay between transfers, and send() then
>> generally takes less than 1 ms.
>
> Does that test app publish to the same queue(s)?

I've run some quick tests that way, and didn't see any delays. This is
something that's kind of hard to do do, though, as I'm seeing the
problem on a system used "in production" at a remote location. I'm
struggling to reproduce on a test installation.

> Does the queue depth on the queue(s) that the slow sends occur on ever
> get large? (Is there some limit set on the queue depth?)

The queues are last-value queues sorted on the "subject" values. They
don't grow large, but obviously, some house-keeping is involved when
storing messages.

This leads to another question: When exactly does the broker acknowledge
message reception? Will it actually update queues first? I mean, it
might conceivably read the message, buffer it, acknowledge, then do the
routing.

>
> The only other thing I can think of that would cause the invocation of
> send() to take a long time would be some sort of locking issue. Are
> the multiple threads possibly sending concurrently?

There is another thread linked to QPid, but it takes care of
"request-response" messaging triggered by user actions. I can't see how
it would be active in all cases where I see delays.

But obviously, it seems quite likely that this is the case of a thread
waiting for *something*. Is there anything else that may somehow cause a
block? Note that my application has extra threads that do unrelated
work. Also, I expect other threads started by the QPid library will be
active, as there is a receiver with a somewhat large capacity linked to
the same session. And my request-response thread will probably be
listening for incoming messages, too.

I should perhaps have mentioned that there is another problem that I
think may be related: It looks like heartbeat messages are also
sometimes delayed in a similar manner, unless they are lost completely.
Every few hours, I get a reconnect attempt during send or receive, even
though there is probably nothing wrong with the connection. That leads
to a "session busy" exception.

>
> How long does the slow sending usually last?

What's shown in the traces sent earlier is fairly typical. I think it's
in the 5-10 s range in nearly all cases.

- Toralf

>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Gordon Sim
On 10/12/2020 09:36, Toralf Lund wrote:

> On 09/12/2020 22:55, Gordon Sim wrote:
>> Does the queue depth on the queue(s) that the slow sends occur on ever
>> get large? (Is there some limit set on the queue depth?)
>
> The queues are last-value queues sorted on the "subject" values. They
> don't grow large, but obviously, some house-keeping is involved when
> storing messages.
>
> This leads to another question: When exactly does the broker acknowledge
> message reception? Will it actually update queues first? I mean, it
> might conceivably read the message, buffer it, acknowledge, then do the
> routing.

The broker will only acknowledge the message once it has been
successfully enqueued on all relevant queues. If persistence is in use
then this will be once the journal has been updated on disk.

A last-value queue update involves dequeuing the old message that
matches the key then enqueuing the updated one.

Is the client on which you observe this the only one to publish to a
particular queue? (If not then it seems less likely that the queue is
the issue, if other clients never see such delays).

>> The only other thing I can think of that would cause the invocation of
>> send() to take a long time would be some sort of locking issue. Are
>> the multiple threads possibly sending concurrently?
>
> There is another thread linked to QPid, but it takes care of
> "request-response" messaging triggered by user actions. I can't see how
> it would be active in all cases where I see delays.
>
> But obviously, it seems quite likely that this is the case of a thread
> waiting for *something*. Is there anything else that may somehow cause a
> block?

The two things I can think of are waiting for a lock or waiting for
capacity. Waiting for capacity on 0-10 involves a session sync request.
If the session is in use by other threads that could include those other
operations as well.

> Note that my application has extra threads that do unrelated
> work. Also, I expect other threads started by the QPid library will be
> active, as there is a receiver with a somewhat large capacity linked to
> the same session. And my request-response thread will probably be
> listening for incoming messages, too.
>
> I should perhaps have mentioned that there is another problem that I
> think may be related: It looks like heartbeat messages are also
> sometimes delayed in a similar manner, unless they are lost completely.
> Every few hours, I get a reconnect attempt during send or receive, even
> though there is probably nothing wrong with the connection. That leads
> to a "session busy" exception.

Is there anything different about the case where you see this? (I'm
assuming that not all clients have the same issue and that those that do
are the same ones i.e. on the same machines and with the same context).

If heartbeats are also delayed it seems to me less likely to be related
to the queue or the acknowledgements being delayed.

Again I wonder whether there is anything different about the
installation where this occurs?


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
On 10/12/2020 11:24, Gordon Sim wrote:

> On 10/12/2020 09:36, Toralf Lund wrote:
>> On 09/12/2020 22:55, Gordon Sim wrote:
>>> Does the queue depth on the queue(s) that the slow sends occur on
>>> ever get large? (Is there some limit set on the queue depth?)
>>
>> The queues are last-value queues sorted on the "subject" values. They
>> don't grow large, but obviously, some house-keeping is involved when
>> storing messages.
>>
>> This leads to another question: When exactly does the broker
>> acknowledge message reception? Will it actually update queues first?
>> I mean, it might conceivably read the message, buffer it,
>> acknowledge, then do the routing.
>
> The broker will only acknowledge the message once it has been
> successfully enqueued on all relevant queues. If persistence is in use
> then this will be once the journal has been updated on disk.
OK
>
> A last-value queue update involves dequeuing the old message that
> matches the key then enqueuing the updated one.
>
> Is the client on which you observe this the only one to publish to a
> particular queue? (If not then it seems less likely that the queue is
> the issue, if other clients never see such delays).
It should be the only one. I see this for two different queues with a
similar configuration. They are generally written by one application,
and could be read in browse mode by multiple ones.

>
>>> The only other thing I can think of that would cause the invocation
>>> of send() to take a long time would be some sort of locking issue.
>>> Are the multiple threads possibly sending concurrently?
>>
>> There is another thread linked to QPid, but it takes care of
>> "request-response" messaging triggered by user actions. I can't see
>> how it would be active in all cases where I see delays.
>>
>> But obviously, it seems quite likely that this is the case of a
>> thread waiting for *something*. Is there anything else that may
>> somehow cause a block?
>
> The two things I can think of are waiting for a lock or waiting for
> capacity. Waiting for capacity on 0-10 involves a session sync
> request. If the session is in use by other threads that could include
> those other operations as well.

Well, none of the application threads should use the same session. Like
I said, there is a 2nd messaging thread, but it has a separate
connection and session. On the other hand, I have multiple senders and
receivers on the same session, so perhaps a different thread set up by
the library might be accessing it?

>> Note that my application has extra threads that do unrelated work.
>> Also, I expect other threads started by the QPid library will be
>> active, as there is a receiver with a somewhat large capacity linked
>> to the same session. And my request-response thread will probably be
>> listening for incoming messages, too.
>>
>> I should perhaps have mentioned that there is another problem that I
>> think may be related: It looks like heartbeat messages are also
>> sometimes delayed in a similar manner, unless they are lost
>> completely. Every few hours, I get a reconnect attempt during send or
>> receive, even though there is probably nothing wrong with the
>> connection. That leads to a "session busy" exception.
>
> Is there anything different about the case where you see this? (I'm
> assuming that not all clients have the same issue and that those that
> do are the same ones i.e. on the same machines and with the same
> context).

I actually see signs of lost heartbeats in at least one other client. It
accesses different queues and exchanges, but connects to the same
broker, and has as similar layout in some other respects.

Maybe this is where I should start looking. Where and when exactly are
the heartbeats sent? What might cause problems to occur?

>
> If heartbeats are also delayed it seems to me less likely to be
> related to the queue or the acknowledgements being delayed.
>
> Again I wonder whether there is anything different about the
> installation where this occurs?
That's the million dollar question, I think...
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Gordon Sim
On 10/12/2020 16:04, Toralf Lund wrote:
> Where and when exactly are the heartbeats sent?

The interval is negotiated at connection time. I believe the default for
the 0-10 qpid::messaging client is 0, i.e. heartbeats disabled, so I
suspect your client has some configuration setting a non-zero value?

Heartbeats only need to be sent if there has been no other traffic in
that negotiated interval. The client or server will consider the
connection failed if nothing arrives for twice the interval.

> What might cause problems to occur?

The only issues I have ever seen have been either genuine networking
issues or cpu starvation (on extremely heavily loaded server).

I'm at a loss to explain what you are seeing I'm afraid.


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Toralf Lund
On 10/12/2020 22:30, Gordon Sim wrote:
> On 10/12/2020 16:04, Toralf Lund wrote:
>> Where and when exactly are the heartbeats sent?
>
> The interval is negotiated at connection time. I believe the default
> for the 0-10 qpid::messaging client is 0, i.e. heartbeats disabled, so
> I suspect your client has some configuration setting a non-zero value?
Yes. It connects with option "heartbeat". I've been experimenting with
different values, but 5 is currently used.
>
> Heartbeats only need to be sent if there has been no other traffic in
> that negotiated interval. The client or server will consider the
> connection failed if nothing arrives for twice the interval.

That's useful info. I was under the impression that heartbearts would
always be sent, and that the system might dumbly consider only those
when deciding if the connection was good or not.

My software gets data from a bunch of other systems that might
theoretically all be switched off or have their data disabled in some
other manner, but it a more normal situation, heartbeats should actually
never be necessary.

>> What might cause problems to occur?
>
> The only issues I have ever seen have been either genuine networking
> issues or cpu starvation (on extremely heavily loaded server).
>
> I'm at a loss to explain what you are seeing I'm afraid.

Right... I guess I'll just have to keep trying various changes etc.
Although I'm a bit out of ideas just now.

- Toralf


>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: [External] Re: qpid::messaging::Sender::send() sometimes takes much longer than expected (in C++)

Gordon Sim
On 11/12/2020 08:55, Toralf Lund wrote:
> I guess I'll just have to keep trying various changes etc. Although I'm
> a bit out of ideas just now.

Would capturing tcp dumps on the host in question by feasible? (You
could output N files and overwrite oldest in a ring).


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]