Home » Forums » ejabberd & XMPP » ejabberd Administration

4 times slower performance when sending receipt for close in IBB

Submitted by Tomcat on Fri, 2011-11-04 15:57

Hi all,

I wrote some performance tests that just send dummy messages. I send a message from client1 to client2 giving a length and client2 replies with a message of this length. When the size is over 4096 bytes I use IBB to send the data in chunks. Works all without problems. My problem is, that if I send a receipt with result to the close-IQ at the end of the IBB the performance goes down. If I don't send the receipt everything is fast.

Here is a log file of client1 (I clipped the payload):

2011-11-04 16:22:59.8001 DEBUG: Send : <message to="test@localhost" id="0" xmlns="jabber:client">
  <body>10000</body>
</message>
2011-11-04 16:22:59.8001 DEBUG: Received : <iq from="test@localhost/GU-PC" to="jadmin@localhost/PROTEL-JANTH" type="set" id="2c021b5e" xmlns="jabber:client">
  <open xmlns="http://jabber.org/protocol/ibb" sid="dd88e836" block-size="4096" />
</iq>
2011-11-04 16:22:59.8001 DEBUG: Send : <iq type="result" id="2c021b5e" to="test@localhost/GU-PC" from="jadmin@localhost/PROTEL-JANTH" />
2011-11-04 16:22:59.8001 DEBUG: Received : <message from="test@localhost/GU-PC" to="jadmin@localhost/PROTEL-JANTH" xmlns="jabber:client">
  <data xmlns="http://jabber.org/protocol/ibb" sid="dd88e836" seq="0">*********************...**********</data>
</message>
2011-11-04 16:22:59.8161 DEBUG: Received : <message from="test@localhost/GU-PC" to="jadmin@localhost/PROTEL-JANTH" xmlns="jabber:client">
  <data xmlns="http://jabber.org/protocol/ibb" sid="dd88e836" seq="1">****...**********</data>
</message>
2011-11-04 16:22:59.8161 DEBUG: Received : <message from="test@localhost/GU-PC" to="jadmin@localhost/PROTEL-JANTH" xmlns="jabber:client">
  <data xmlns="http://jabber.org/protocol/ibb" sid="dd88e836" seq="2">********...*****************</data>
</message>
2011-11-04 16:22:59.8161 DEBUG: Received : <iq from="test@localhost/GU-PC" to="jadmin@localhost/PROTEL-JANTH" type="set" id="c2d24839" xmlns="jabber:client">
  <close xmlns="http://jabber.org/protocol/ibb" sid="dd88e836" />
</iq>

The problem is this receipt :

2011-11-04 16:22:59.8161 DEBUG: Send : <iq type="result" id="c2d24839" to="test@localhost/GU-PC" from="jadmin@localhost/PROTEL-JANTH" />

after that the whole thing starts again with :

2011-11-04 16:22:59.8161 DEBUG: Send : <message to="test@localhost" id="1" xmlns="jabber:client">
  <body>10000</body>
</message>

If I do this whole thing 100 times with 10.000 bytes it takes about 4.5 sec with the receipt-IQ and 1.1 without it.

Any idea what can cause this?

Regards

‹ access_from - anonymous registration bug? Shared Roster move bug ›

I did some research with

Submitted by Tomcat on Mon, 2011-11-07 10:32.

I did some research with tcpdump on the server where ejabberd is running. The problem has something to do with an ACK that is send with delay.

Here is the dump corresponding to the sequence above (I can reproduce this any time):

The messages were send from the ejabberd to the client1 and then the <close> is delivered:

09:28:45.387026 IP 192.168.50.51.xmpp-client > 192.168.2.54.26390: Flags [P.], seq 97096:97255, ack 2378, win 262, length 159
E.....@.@.i...23...6.fg....;....P....s..<iq from='test@localhost/GU-PC' to='jadmin@localhost/PROTEL-JANTH' type='set' id='527d7c07'><close xmlns='http://jabber.org/protocol/ibb' sid='7ac8897f'/></iq>

Then the ACKs for the messages from client1 comes in:

09:28:45.387110 IP 192.168.2.54.26390 > 192.168.50.51.xmpp-client: Flags [.], ack 92338, win 16425, length 0
E..(..@...8q...6..23g..f........P.@).4........
09:28:45.387267 IP 192.168.2.54.26390 > 192.168.50.51.xmpp-client: Flags [.], ack 95131, win 16425, length 0
E..(..@...8p...6..23g..f........P.@).K........
09:28:45.387678 IP 192.168.2.54.26390 > 192.168.50.51.xmpp-client: Flags [.], ack 97096, win 16425, length 0
E..(..@...8o...6..23g..f.......;P.@)..........

Now the receipt on the <close> is send from the client1 to the ejabberd combined with the ACK for the <close>

09:28:45.391483 IP 192.168.2.54.26390 > 192.168.50.51.xmpp-client: Flags [P.], seq 2378:2484, ack 97255, win 16385, length 106
E.....@...7....6..23g..f........P.@..}..<iq type="result" id="527d7c07" to="test@localhost/GU-PC" from="jadmin@localhost/PROTEL-JANTH" xmlns="" />

The ejabberd sends the receipt to the client2. Everything fine, but ...

09:28:45.391820 IP 192.168.50.51.xmpp-client > 192.168.0.125.48403: Flags [P.], seq 2541:2637, ack 96625, win 1678, length 96
E...rc@.@.....23...}.f...       ....G.P....{..<iq from='jadmin@localhost/PROTEL-JANTH' to='test@localhost/GU-PC' type='result' id='527d7c07'/>

.. the ACK for the receipt is send with delay to the client1.

09:28:45.424646 IP 192.168.50.51.xmpp-client > 192.168.2.54.26390: Flags [.], ack 2484, win 262, length 0
E..(..@.@.j...23...6.fg.........P.......

Any idea what happens this 32 MilliSeconds? If you need anything more to help me with this, please let me know.

I suspected the shaper to be the reason, but the problem still exists after disabling the shapers completly.

Kind regards

PS: Here is the ejabberd-log from this message. I can't see anything suspicous here. I think the next message from client1 is send with delay because of the delayed ACK.

=INFO REPORT==== 2011-11-07 09:28:45.412 ===
D(<0.387.0>:ejabberd_receiver:320) : Received XML on stream = "<iq type=\"result\" id=\"527d7c07\" to=\"test@localhost/GU-PC\" from=\"jadmin@localhost/PROTEL-JANTH\" xmlns=\"\" />"

=INFO REPORT==== 2011-11-07 09:28:45.412 ===
D(<0.388.0>:ejabberd_router:313) : route
        from {jid,"jadmin","localhost","PROTEL-JANTH","jadmin","localhost",
                  "PROTEL-JANTH"}
        to {jid,"test","localhost","GU-PC","test","localhost","GU-PC"}
        packet {xmlelement,"iq",
                           [{"type","result"},
                            {"id","527d7c07"},
                            {"to","test@localhost/GU-PC"},
                            {"from","jadmin@localhost/PROTEL-JANTH"}],
                           []}

=INFO REPORT==== 2011-11-07 09:28:45.413 ===
D(<0.388.0>:ejabberd_local:300) : local route
        from {jid,"jadmin","localhost","PROTEL-JANTH","jadmin","localhost",
                  "PROTEL-JANTH"}
        to {jid,"test","localhost","GU-PC","test","localhost","GU-PC"}
        packet {xmlelement,"iq",
                           [{"type","result"},{"id",[...]},{[...],...},{...}],
                           []}

=INFO REPORT==== 2011-11-07 09:28:45.413 ===
D(<0.388.0>:ejabberd_sm:411) : session manager
        from {jid,"jadmin","localhost","PROTEL-JANTH","jadmin","localhost",
                  "PROTEL-JANTH"}
        to {jid,"test","localhost","GU-PC","test","localhost","GU-PC"}
        packet {xmlelement,"iq",
                           [{"type","result"},{"id",[...]},{[...],...},{...}],
                           []}

=INFO REPORT==== 2011-11-07 09:28:45.414 ===
D(<0.388.0>:ejabberd_sm:510) : sending to process <0.391.0>

=INFO REPORT==== 2011-11-07 09:28:45.414 ===
D(<0.391.0>:ejabberd_c2s:1558) : Send XML on stream = <<"<iq from='jadmin@localhost/PROTEL-JANTH' to='test@localhost/GU-PC' type='result' id='527d7c07'/>">>

=INFO REPORT==== 2011-11-07 09:28:45.425 ===
D(<0.387.0>:ejabberd_receiver:320) : Received XML on stream = "<message to=\"test@localhost\" id=\"9\"><body>10000</body></message>"

»

No one? I'm stucked with this

Submitted by Tomcat on Thu, 2011-11-17 11:18.

No one? I'm stucked with this one.

»
Syndicate content

User login