You are viewing a plain text version of this content. The canonical link for it is here.
Posted to proton@qpid.apache.org by Rafael Schloming <rh...@alum.mit.edu> on 2014/05/01 15:29:56 UTC

Re: Messenger.receive(1) causing sluggish behavior

I'm not sure this is a bug per/se as opposed to a combination of
missunderstood and/or ill conceived features.  The ~/ prefix when used in a
reply-to gets substituted with the name of the messenger. That is what is
substituting the container name into the address. The container name when
the messenger was constructed was left unspecified, and so that is why it
ends up being a UUID. That whole part is functioning as expected and that
is why the reply comes back to the same container that the request
originated from. What's going wrong here is the use of the # notation. That
is signalling messenger to create a dynamic link instead of a regular one,
and it was introduced with the expectation that it would be used for remote
subscriptions, e.g.:

  sub = messenger.subscribe("remote-broker/#")
  ...
  msg.reply_to = sub.address

Note that in the above usage, the # notation requests the dynamically
created node, and the "sub.address" expression accesses the value. The #
notation is never used directly on a message. If you were to print
sub.address it would be some random gobbledygook assigned by the remote
peer, and not #. Now messenger treats addresses symmetrically for sending
and receiving so when you send to foo/# it is also going to create a
dynamic node for sending. The problem here is that unlike the subscription
scenario, there is no way to actually access the remote address assigned by
the peer, and each time we send we end up creating a new link.

The reason this slows things down when recv(1) is used instead of recv(-1)
is that the student only has one credit at a time to share amongst all the
spurious links that are created by the use of the # notation. So basically
by the time you get to N messages, you need to wait for the credit
algorithm to poll N links for one message at a time. I'm actually quite
happy to see that it doesn't freeze, because that means the credit
algorithm is actually doing it's job. This is a pretty pathological case
from a flow control perspective, and it is good news that we aren't locking
up entirely. The problem still exists if you use a larger value for credit
or even if you use -1 for credit, but it will take a while longer to become
noticeable because you have a lot more credit to poll with.

I can think of a bunch of options for changing/extending the # feature to
make it a bit more useful for sending, but regardless, the use of # in this
particular scenario makes no sense even if it were extended/improved. Using
it in a reply-to in this way is basically asking the server to ask the
client to dynamically create an address for the reply. It is much less
perverse for the client to simply create the necessary addresses itself
instead of asking the server to ask the client to create the address, e.g.
the client can just use "~/reply1", "~/reply2", ... or whatever other
scheme it might want to use for identifying replies. In fact in your case
(and many others) you don't really even need more than one address. If you
modify your example to just use "~/replies", it will work properly
regardless of what value you pass to recv.

On the overall # issue it's probably worth a JIRA detailing the problem
with using it on send rather than subscribe, however I'd say it's probably
higher priority to document what it actually means since I don't think very
many sensible uses would run into the problem you're seeing. In fact in
general it probably never makes sense to send a literal '#' in an address
appearing in a message like you're doing. You really would only use it to
query for an address from your peer and then send the result of the query.
Unfortunately I don't think we can just make it illegal to use a '#' since
the '#' behaviour is really local to messenger and '#' might be a
meaningful address if you're speaking to a non messenger implementation.

--Rafael

On Wed, Apr 30, 2014 at 3:42 PM, Ken Giusti <kg...@redhat.com> wrote:

> I think this may be a bug in messenger.
>
> From tracing the wire, I see that every time guru sends a reply using the
> reply_to field in the message, a completely new session and link are
> created.  Over time this leads to a large number of sessions and links -
> one for each reply message sent.
>
> The student is setting the reply_to in its request to "~/#", which causes
> a uuid-based address to be substituted in the outgoing request messages'
> reply_to field.  For example, guru might get the following reply-to in each
> received message:  amqp://cd5ec72c-8d99-4d5f-b796-4b2447f35b6a/#
>
> What appears to be happening is messenger on guru.rb fails to re-use an
> existing 'return link' back to student, and creates a new one.   I think
> this is due to the way messenger marks the link as 'dynamic' and never sets
> the terminus address in the new link.  Thus when the next request arrives
> with the same reply-to, the link resolution logic doesn't find a link with
> a matching terminus address, and creates another one.
>
> Sounds wrong to me - though honestly I'm not 100% sure I understand the
> purpose of the "~/#" address semantics.
>
> -K
>
>
> ----- Original Message -----
> > From: "Darryl L. Pierce" <dp...@redhat.com>
> > To: proton@qpid.apache.org
> > Sent: Tuesday, April 29, 2014 11:01:45 AM
> > Subject: Messenger.receive(1) causing sluggish behavior
> >
> > Using the Ruby Chatty example in my examples repo [1] I see painful
> > slow runtime performance. To run the example, first launch the Guru
> > process:
> >
> >  $ ruby guru.rb
> >
> > Then, in another terminal, start a single Student instance:
> >
> >  $ ruby student
> >
> > What you'll see is the student starts off with a 1 or 2 messages,
> > but then immediately gets sluggish. If you start another instance of
> > Student things degrade very quickly.
> >
> > If, however, in student.rb we change:
> >
> >   $msgr.receive(1)
> >
> > to:
> >
> >   $msgr.receive(-1)
> >
> > then there is no apparently sluggishness until several thousand messages
> > have been sent, and multiple instances of Student are able to run
> > without slowing down.
> >
> >
> > [1]
> >
> https://github.com/mcpierce/qpid-ruby-examples/tree/Rafi-slow-server-performance
> > --
> > Darryl L. Pierce, Sr. Software Engineer @ Red Hat, Inc.
> > Delivering value year after year.
> > Red Hat ranks #1 in value among software vendors.
> > http://www.redhat.com/promo/vendor/
> >
> >
>
> --
> -K
>

Re: Messenger.receive(1) causing sluggish behavior

Posted by Ken Giusti <kg...@redhat.com>.

----- Original Message -----
> From: "Rafael Schloming" <rh...@alum.mit.edu>
> To: proton@qpid.apache.org
> Sent: Thursday, May 1, 2014 9:29:56 AM
> Subject: Re: Messenger.receive(1) causing sluggish behavior
> 
> I'm not sure this is a bug per/se as opposed to a combination of
> missunderstood and/or ill conceived features.  The ~/ prefix when used in a
> reply-to gets substituted with the name of the messenger. That is what is
> substituting the container name into the address. The container name when
> the messenger was constructed was left unspecified, and so that is why it
> ends up being a UUID. That whole part is functioning as expected and that
> is why the reply comes back to the same container that the request
> originated from. What's going wrong here is the use of the # notation. That
> is signalling messenger to create a dynamic link instead of a regular one,
> and it was introduced with the expectation that it would be used for remote
> subscriptions, e.g.:
> 
>   sub = messenger.subscribe("remote-broker/#")
>   ...
>   msg.reply_to = sub.address
> 
> Note that in the above usage, the # notation requests the dynamically
> created node, and the "sub.address" expression accesses the value. The #
> notation is never used directly on a message. If you were to print
> sub.address it would be some random gobbledygook assigned by the remote
> peer, and not #. Now messenger treats addresses symmetrically for sending
> and receiving so when you send to foo/# it is also going to create a
> dynamic node for sending. The problem here is that unlike the subscription
> scenario, there is no way to actually access the remote address assigned by
> the peer, and each time we send we end up creating a new link.
> 
> The reason this slows things down when recv(1) is used instead of recv(-1)
> is that the student only has one credit at a time to share amongst all the
> spurious links that are created by the use of the # notation. So basically
> by the time you get to N messages, you need to wait for the credit
> algorithm to poll N links for one message at a time. I'm actually quite
> happy to see that it doesn't freeze, because that means the credit
> algorithm is actually doing it's job. This is a pretty pathological case
> from a flow control perspective, and it is good news that we aren't locking
> up entirely. The problem still exists if you use a larger value for credit
> or even if you use -1 for credit, but it will take a while longer to become
> noticeable because you have a lot more credit to poll with.
> 
> I can think of a bunch of options for changing/extending the # feature to
> make it a bit more useful for sending, but regardless, the use of # in this
> particular scenario makes no sense even if it were extended/improved. Using
> it in a reply-to in this way is basically asking the server to ask the
> client to dynamically create an address for the reply. It is much less
> perverse for the client to simply create the necessary addresses itself
> instead of asking the server to ask the client to create the address, e.g.
> the client can just use "~/reply1", "~/reply2", ... or whatever other
> scheme it might want to use for identifying replies. In fact in your case
> (and many others) you don't really even need more than one address. If you
> modify your example to just use "~/replies", it will work properly
> regardless of what value you pass to recv.
> 
> On the overall # issue it's probably worth a JIRA detailing the problem
> with using it on send rather than subscribe, however I'd say it's probably
> higher priority to document what it actually means since I don't think very
> many sensible uses would run into the problem you're seeing. In fact in
> general it probably never makes sense to send a literal '#' in an address
> appearing in a message like you're doing. You really would only use it to
> query for an address from your peer and then send the result of the query.
> Unfortunately I don't think we can just make it illegal to use a '#' since
> the '#' behaviour is really local to messenger and '#' might be a
> meaningful address if you're speaking to a non messenger implementation.
> 


Thanks for the detailed explanation.  Given that, I'd agree this isn't JIRA worthy, but I would love to see the description you've given added to the messenger documentation (hint-hint)!




> --Rafael
> 
> On Wed, Apr 30, 2014 at 3:42 PM, Ken Giusti <kg...@redhat.com> wrote:
> 
> > I think this may be a bug in messenger.
> >
> > From tracing the wire, I see that every time guru sends a reply using the
> > reply_to field in the message, a completely new session and link are
> > created.  Over time this leads to a large number of sessions and links -
> > one for each reply message sent.
> >
> > The student is setting the reply_to in its request to "~/#", which causes
> > a uuid-based address to be substituted in the outgoing request messages'
> > reply_to field.  For example, guru might get the following reply-to in each
> > received message:  amqp://cd5ec72c-8d99-4d5f-b796-4b2447f35b6a/#
> >
> > What appears to be happening is messenger on guru.rb fails to re-use an
> > existing 'return link' back to student, and creates a new one.   I think
> > this is due to the way messenger marks the link as 'dynamic' and never sets
> > the terminus address in the new link.  Thus when the next request arrives
> > with the same reply-to, the link resolution logic doesn't find a link with
> > a matching terminus address, and creates another one.
> >
> > Sounds wrong to me - though honestly I'm not 100% sure I understand the
> > purpose of the "~/#" address semantics.
> >
> > -K
> >
> >
> > ----- Original Message -----
> > > From: "Darryl L. Pierce" <dp...@redhat.com>
> > > To: proton@qpid.apache.org
> > > Sent: Tuesday, April 29, 2014 11:01:45 AM
> > > Subject: Messenger.receive(1) causing sluggish behavior
> > >
> > > Using the Ruby Chatty example in my examples repo [1] I see painful
> > > slow runtime performance. To run the example, first launch the Guru
> > > process:
> > >
> > >  $ ruby guru.rb
> > >
> > > Then, in another terminal, start a single Student instance:
> > >
> > >  $ ruby student
> > >
> > > What you'll see is the student starts off with a 1 or 2 messages,
> > > but then immediately gets sluggish. If you start another instance of
> > > Student things degrade very quickly.
> > >
> > > If, however, in student.rb we change:
> > >
> > >   $msgr.receive(1)
> > >
> > > to:
> > >
> > >   $msgr.receive(-1)
> > >
> > > then there is no apparently sluggishness until several thousand messages
> > > have been sent, and multiple instances of Student are able to run
> > > without slowing down.
> > >
> > >
> > > [1]
> > >
> > https://github.com/mcpierce/qpid-ruby-examples/tree/Rafi-slow-server-performance
> > > --
> > > Darryl L. Pierce, Sr. Software Engineer @ Red Hat, Inc.
> > > Delivering value year after year.
> > > Red Hat ranks #1 in value among software vendors.
> > > http://www.redhat.com/promo/vendor/
> > >
> > >
> >
> > --
> > -K
> >
> 

-- 
-K

Re: Messenger.receive(1) causing sluggish behavior

Posted by "Darryl L. Pierce" <dp...@redhat.com>.
On Thu, May 01, 2014 at 04:02:51PM -0400, Darryl L. Pierce wrote:
> On Thu, May 01, 2014 at 09:29:56AM -0400, Rafael Schloming wrote:
> <snip>
> > (and many others) you don't really even need more than one address. If you
> > modify your example to just use "~/replies", it will work properly
> > regardless of what value you pass to recv.
> 
> I did this, set the Messenger back to recv(1) and the speed increased.
> Now it starts around 2300 msg/sec and drops off from there. Though I
> would wager part of that drop off in speed isn't due to communications
> issues but because the student does random guesses and avoids resending
> previous guesses. When I comment out the checks for duplicate guesses it
> stays at around 2300 msg/sec.

Another interesting point: memory usage has dropped off significantly,
which I guess is expected given that there aren't a bunch of links being
used now. Before I would see guru get to about 20% of memory used while
running, this after throwing many different instances of student at it.
Now it sits consistently at 0.1% memory usage.

-- 
Darryl L. Pierce, Sr. Software Engineer @ Red Hat, Inc.
Delivering value year after year.
Red Hat ranks #1 in value among software vendors.
http://www.redhat.com/promo/vendor/


Re: Messenger.receive(1) causing sluggish behavior

Posted by "Darryl L. Pierce" <dp...@redhat.com>.
On Thu, May 01, 2014 at 09:29:56AM -0400, Rafael Schloming wrote:
<snip>
> (and many others) you don't really even need more than one address. If you
> modify your example to just use "~/replies", it will work properly
> regardless of what value you pass to recv.

I did this, set the Messenger back to recv(1) and the speed increased.
Now it starts around 2300 msg/sec and drops off from there. Though I
would wager part of that drop off in speed isn't due to communications
issues but because the student does random guesses and avoids resending
previous guesses. When I comment out the checks for duplicate guesses it
stays at around 2300 msg/sec.

-- 
Darryl L. Pierce, Sr. Software Engineer @ Red Hat, Inc.
Delivering value year after year.
Red Hat ranks #1 in value among software vendors.
http://www.redhat.com/promo/vendor/