Lag in Multi User Chat

Clemens · October 11, 2007, 4:01pm

Greetings!

I would like to know if anybody else experienced this:

I’m participating in a MUC with about 7-10 users. It sometimes occurs that there is a huge lag for (seemingly) all participants. This includes both users that connect from another server as well as local users. Messages geht queued and every (exactly) 20 seconds one message is spit out. During a recent “lag period” it even happened to me that one of my messages only appeared after seven minutes.

It seems to me that this is more or less unrelated to the level of activity, because it does not happen daily and not necessarily when we are engaged into a verbose debate

I wonder if that is some problem with karma/internal traffic shaping which gets applied to the MUC component.

I have not seen any messages related to this in the Warn, Error or Info log.

Running Openfire 3.3.3 on Linux.

Gaston_Dombiak · October 11, 2007, 5:22pm

Hey Clemens,

Openfire does not apply karma or any throttling mechanism to the network traffic. This could be a network problem (e.g. a lazy client not reading quickly incoming traffic thus letting his TCP buffer fill up) or it may be a server problem. For the former you can use the plugin and monitor the MINA queues (i.e. the last 2 columns) and for the latter you can get a few thread dumps of the server’s JVM to see what the server is doing. To get a thread dump in linux just execute kill -3 [process id].

Regards,

– Gato

Clemens · October 11, 2007, 9:28pm

Thanks a lot, Gato!

A very helpful reply indeed; although I have a question regarding the output of loadStats.

I receive output like:

1192137389325,5,15,6,0,17,0,0,493310,21,1493,7325,0,-7311

…

1192137544325,5,15,6,0,17,0,0,493374,21,1495,7336,0,-7322

…

1192137694324,5,15,6,0,17,0,0,493447,21,1508,7350,0,-7336

I wonder why column 14 (Queued NIO writes) does have a negative value that decreases.

Thanks in advance!

Gaston_Dombiak · October 11, 2007, 9:48pm

Hey Clemens,

Today we were discussing this problem in this other thread: Re: 3.3.3 - loadStats broken?.

Regards,

– Gato

Clemens · October 24, 2007, 5:33pm

I just caught an increasing number in Queued NIO events “on tape”. I noticed that there again was a lag, but this time also when sending messages to another server ? receiving messages was just fine.

Log sample, lines with same ‘Queued NIO events’ count removed

1193246244321,5,15,6,0,17,0,0,788074,15,24475,75182,0,-15566

1193246249321,5,15,6,0,17,1,0,788076,15,24476,75184,1,-15568

1193246274321,5,15,6,0,17,1,0,788081,15,24476,75184,3,-15568

1193246279321,5,15,6,0,17,1,0,788082,15,24476,75184,4,-15568

1193246314321,5,15,6,0,17,1,0,788091,15,24477,75187,5,-15571

1193246319321,5,15,6,0,17,1,0,788092,15,24477,75187,5,-15571

1193246329321,5,15,6,0,17,1,0,788093,15,24477,75187,6,-15571

1193246334321,5,15,6,0,17,1,0,788095,15,24477,75188,7,-15572

1193246339321,5,15,6,0,17,1,0,788095,15,24477,75188,8,-15572

1193246344321,5,15,6,0,17,1,0,788095,15,24477,75188,9,-15572

1193246384321,5,15,6,0,17,1,0,788102,15,24477,75188,10,-15572

1193246439320,5,15,6,0,17,1,0,788112,15,24477,75189,11,-15573

1193246444320,5,15,6,0,17,1,0,788113,15,24477,75191,12,-15575

1193246449320,5,15,6,0,17,1,0,788113,15,24477,75192,13,-15576

1193246459324,5,15,6,0,17,1,0,788116,15,24477,75193,14,-15577

1193246464320,5,15,6,0,17,1,0,788116,15,24478,75193,16,-15577

1193246489320,5,15,6,0,17,1,0,788119,15,24478,75193,17,-15577

1193246509320,5,15,6,0,17,1,0,788124,15,24478,75194,18,-15578

1193246519320,5,15,6,0,17,1,0,788126,15,24478,75196,19,-15580

1193246549320,5,15,6,0,17,1,0,788129,15,24478,75196,20,-15580

1193246604320,5,15,6,0,17,1,0,788140,15,24478,75198,21,-15582

1193246659320,5,15,6,0,17,1,0,788150,15,24478,75198,22,-15582

1193246664320,5,15,6,0,17,1,0,788151,15,24479,75201,21,-15585

1193246669319,5,15,6,0,17,1,0,788152,15,24479,75201,22,-15585

1193246684327,5,15,6,0,17,1,0,788158,15,24480,75205,21,-15589

1193246704319,5,15,6,0,17,1,0,788162,15,24486,75208,2,-15592

1193246709323,5,15,6,0,17,1,0,788163,15,24486,75209,4,-15593

1193246714323,5,15,6,0,17,1,0,788165,15,24486,75209,4,-15593

1193246719323,5,15,6,0,17,0,0,788170,14,24486,75213,5,-15597

1193246724323,5,15,6,0,17,0,0,788171,14,24486,75214,0,-15598

Not sure if that is helpful in any way, but maybe some evidence is better than none

Gernot_Pansy · December 7, 2007, 2:50pm

i see the same problem (especially under 3.4.x) - running with connection manager:

i have attached an extra log of each of my 5 connection manager sessions to the server. only one is hanging. there a no read messages, but read bytes and queued nio events…

perhaps some developer can explain, where these messages are queued? (ProtocolDecoderOutput ?)

i really would like to find issue, but i need some help.

sometimes the queue is cleaned after some time, but also sometimes it never gets cleaned … i always have to restart the server & connection manager -> that’s bad…

please help,

thanks

Gernot_Pansy · December 8, 2007, 2:01pm

that what seeing from a jstack dump if the error occured the last time. seems to be a dead lock:

“connectionManager-9” daemon prio=10 tid=0x0865c000 nid=0x340d runnable http://0x700c7000…0x700c8020

java.lang.Thread.State: RUNNABLE

at java.lang.Throwable.fillInStackTrace(Native Method)

locked (UserNotFoundException.java:31)

at org.jivesoftware.openfire.roster.Roster.getRosterItem(Roster.java:223)

at org.jivesoftware.openfire.handler.PresenceUpdateHandler.directedPresenceSent(Pr esenceUpdateHandler.java:330)

at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:161)

at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:69)

at org.jivesoftware.openfire.handler.PresenceUpdateHandler.broadcastUnavailableFor DirectedPresences(PresenceUpdateHandler.java:447)

at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:136)

at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:110)

at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateH andler.java:174)

at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:133)

at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:69)

at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:75)

at org.jivesoftware.openfire.SessionPacketRouter.route(SessionPacketRouter.java:11 1)

at org.jivesoftware.openfire.SessionPacketRouter.route(SessionPacketRouter.java:66 )

at org.jivesoftware.openfire.multiplex.MultiplexerPacketHandler.route(MultiplexerP acketHandler.java:164)

at org.jivesoftware.openfire.net.MultiplexerStanzaHandler.processRoute(Multiplexer StanzaHandler.java:89)

at org.jivesoftware.openfire.net.MultiplexerStanzaHandler.processUnknowPacket(Mult iplexerStanzaHandler.java:96)

at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:271)

at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:167)

at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandl er.java:132)

at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived (AbstractIoFilterChain.java:570)

at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)

at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)

at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)

at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimplePr otocolDecoderOutput.java:58)

at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecF ilter.java:173)

at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(Ab stractIoFilterChain.java:299)

at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilt erChain.java:53)

at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceive d(AbstractIoFilterChain.java:648)

at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java :239)

at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(Execut orFilter.java:283)

at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 885)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)

at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)

at java.lang.Thread.run(Thread.java:619)

{/code}

Gernot_Pansy · December 8, 2007, 2:11pm

that’s what i got after another jstack dump:

“connectionManager-9” daemon prio=10 tid=0x0865c000 nid=0x340d runnable http://0x700c7000…0x700c8020

java.lang.Thread.State: RUNNABLE

at java.lang.String.intern(Native Method)

at org.jivesoftware.openfire.muc.spi.MultiUserChatServerImpl.getChatUser(MultiUser ChatServerImpl.java:602)

at org.jivesoftware.openfire.muc.spi.MultiUserChatServerImpl.processPacket(MultiUs erChatServerImpl.java:247)

at org.jivesoftware.openfire.muc.spi.MultiUserChatServerImpl.process(MultiUserChat ServerImpl.java:227)

at org.jivesoftware.openfire.spi.RoutingTableImpl.routePacket(RoutingTableImpl.jav a:234)

at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:163)