Project

General

Profile

chat messages are taking too long to get processed.

jonee jonee
Added over 5 years ago

NOTE continuation of post at old forum http://www.tigase.org/content/chat-messages-are-taking-too-long-get-processed

Here are some of the details about our system.

  • Client app write each chat message on socket and flush it immediately. Then it logs message id with timestamp.

  • We are running tigase on Amazon EC2 its m1.large instance.

OS details

we use amazon ami http://aws.amazon.com/amazon-linux-ami/2013.03-release-notes/

which has linux kernel 3.4.43

Java details

java version "1.7.0_21"

Java(TM) SE Runtime Environment (build 1.7.0_21-b11)

Java HotSpot(TM) 64-Bit Server VM (build 23.21-b01, mixed mode)

I was looking at code in SocketThread.java run() method, and found that it has workaround for selector issue(non blocking bug) in jdk 1.6 with these comments

// Set<SelectionKey> selected_keys = clientsSel.selectedKeys();

// for (SelectionKey sk : selected_keys) {

// Handling a bug or not a bug described in the

// last comment to this issue:

// http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4850373

// and

// http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6403933

but at http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6403933 now shows that it is fixed for version 7.

Is there any possibility that this can occur because of switching from jdk 1.6 to jdk 1.7 ?

FYI: Before switching to jdk 1.7 we were using

java version "1.6.0_24"

OpenJDK Runtime Environment (IcedTea6 1.11.11) (amazon-61.1.11.11.53.amzn1-x86_64)

OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

A sample delayed message

message_id : "m_57"

sent from client : 09:07:43

appeared at xmpp server: 09:12:14

logs:

2013-07-10 09:12:14  IOService.isConnected()             FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Connected: true, id: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  SocketThread$ResultsListener.run()  FINEST:   COMPLETED: xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  SocketThread.addSocketServicePriv()  FINEST:  Adding to waiting: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, type: accept, Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443]
2013-07-10 09:12:14  SocketThread.run()                  FINEST:   Selector AWAKE: sun.nio.ch.EPollSelectorImpl@61d10846
2013-07-10 09:12:14  SocketThread.addAllWaiting()        FINEST:   waiting.size(): 1
2013-07-10 09:12:14  SocketThread.addAllWaiting()        FINEST:   ADDED OP_READ: xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  SocketThread.run()                  FINEST:   Selector AWAKE: sun.nio.ch.EPollSelectorImpl@61d10846
2013-07-10 09:12:14  SocketThread.run()                  FINEST:   AWAKEN: xx.xx.166.201_443_xx.xx.167.98_52220, ready for READING, readyOps() = 1
2013-07-10 09:12:14  SocketThread.addAllWaiting()        FINEST:   waiting.size(): 0
2013-07-10 09:12:14  IOService.isConnected()             FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Connected: true, id: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  SocketIO.read()                     FINER:    Read from channel 421 bytes, c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443]
2013-07-10 09:12:14  TLSIO.read()                        FINER:    Read bytes: 421, TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443]
2013-07-10 09:12:14  TLSWrapper.unwrap()                 FINEST:   TLS: nullSocket[addr=/xx.xx.167.98,port=52220,localport=443], unwrap() tlsEngineRsult.getStatus() = OK, tlsEngineRsult.getHandshakeStatus() = NOT_HANDSHAKING
2013-07-10 09:12:14  TLSWrapper.unwrap()                 FINEST:   TLS: nullSocket[addr=/xx.xx.167.98,port=52220,localport=443], unwrap() tlsEngineRsult.getStatus() = BUFFER_UNDERFLOW, tlsEngineRsult.getHandshakeStatus() = NOT_HANDSHAKING
2013-07-10 09:12:14  IOService.readData()                FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Reading network binary data: 421
2013-07-10 09:12:14  IOService.readData()                FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Decoded character data: <message type="chat" id="m_57" from="jack1234@abc.com/xiff" to="chris123@abc.com"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>
2013-07-10 09:12:14  IOService.isConnected()             FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Connected: true, id: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  SocketIO.read()                     FINER:    Read from channel 0 bytes, c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443]
2013-07-10 09:12:14  IOService.isConnected()             FINEST:   Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220 Socket[addr=/xx.xx.167.98,port=52220,localport=443], Connected: true, id: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  ClientConnectionManager.processSocketData()  FINEST: Processing socket data: from=null, to=null, DATA=<message to="chris123@abc.com" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=618, XMLNS=null, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat from connection: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  ClientConnectionManager.processSocketData()  FINEST: XMLNS set for packet: from=null, to=null, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat from connection: c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   Processing packet: from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   1. Packet will be processed by: sess-man@amazon-host-ip.internal, from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   Received packet: from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   processing packet: from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, connection: user_jid=jack1234@abc.com/xiff, packets=376, connectioId=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, domain=abc.com, authState=AUTHORIZED, isAnon=false
2013-07-10 09:12:14  PacketDefaultHandler.preprocess()   FINEST:   Skipping setting correct from attribute: jack1234@abc.com/xiff, is already correct.
2013-07-10 09:12:14  SessionManager.walk()               FINEST:   XMPPProcessorIfc: Message (message)
 Request: from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat, conn: user_jid=jack1234@abc.com/xiff, packets=377, connectioId=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, domain=abc.com, authState=AUTHORIZED, isAnon=false
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   Packet processed by: [message]
2013-07-10 09:12:14  Message.process()                   FINEST:   Processing packet: from=c2s@amazon-host-ip.internal/xx.xx.166.201_443_xx.xx.167.98_52220, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=NONE, TYPE=chat
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   Processing packet: from=sess-man@amazon-host-ip.internal, to=null, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   2. Packet will be processed by: sess-man@amazon-host-ip.internal, from=sess-man@amazon-host-ip.internal, to=null, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   Received packet: from=sess-man@amazon-host-ip.internal, to=null, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  SessionManager.getXMPPResourceConnection()  FINEST: Searching for resource connection for: chris123@abc.com
2013-07-10 09:12:14  SessionManager.getResourceConnection()  FINEST: Session not null, getting resource for jid: chris123@abc.com
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   processing packet: from=sess-man@amazon-host-ip.internal, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, connection: user_jid=chris123@abc.com/xiff, packets=356, connectioId=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, domain=abc.com, authState=AUTHORIZED, isAnon=false
2013-07-10 09:12:14  SessionManager.walk()               FINEST:   XMPPProcessorIfc: Message (message)
 Request: from=sess-man@amazon-host-ip.internal, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat, conn: user_jid=chris123@abc.com/xiff, packets=357, connectioId=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, domain=abc.com, authState=AUTHORIZED, isAnon=false
2013-07-10 09:12:14  SessionManager.processPacket()      FINEST:   Packet processed by: [message]
2013-07-10 09:12:14  Message.process()                   FINEST:   Processing packet: from=sess-man@amazon-host-ip.internal, to=sess-man@amazon-host-ip.internal, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   Processing packet: from=sess-man@amazon-host-ip.internal, to=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  MessageRouter.processPacket()       FINEST:   1. Packet will be processed by: c2s@amazon-host-ip.internal, from=sess-man@amazon-host-ip.internal, to=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  ClientConnectionManager.processPacket()  FINEST: Processing packet: from=sess-man@amazon-host-ip.internal, to=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>CData size: 36</thread><body>CData size: 304</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat
2013-07-10 09:12:14  ConnectionManager.writePacketToSocket()  FINEST: c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, type: accept, Socket: TLS: c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062 Socket[addr=/xx.xx.251.110,port=40062,localport=5222], Writing packet: from=sess-man@amazon-host-ip.internal, to=c2s@amazon-host-ip.internal/xx.xx.166.201_5222_xx.xx.251.110_40062, DATA=<message to="chris123@abc.com" xmlns="jabber:client" from="jack1234@abc.com/xiff" id="m_57" type="chat"><thread>p2pchat_1245</thread><body>[body text not displayed here]</body></message>, SIZE=640, XMLNS=jabber:client, PRIORITY=NORMAL, PERMISSION=AUTH, TYPE=chat

Replies (3)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 5 years ago

These logs are from the server as I can see. And as we can see there is no delay or long processing on the server side.

Actually I have run lots of loads tests on the Amazon EC2 cloud on different instances. There are problems with CPU availability under a high load but I have never noticed such a long delays you describe.

Could you please give us more information of the client side? What OS, what client or library do you use?

Added by jonee jonee over 5 years ago

We are using flash library xiff for xmpp communication. The app adobe air based and it run both on windows and mac os x. As i mentioned in my previous post, we have recently switched from jdk 1.6 to jdk 1.7. Before that it was never reported.

I was looking at code in SocketThread.java run() method, and found that it has workaround for selector issue(non blocking bug) in jdk 1.6 with these comments

// Set selected_keys = clientsSel.selectedKeys();

// for (SelectionKey sk : selected_keys) {

// Handling a bug or not a bug described in the

// last comment to this issue:

// http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=4850373

// and

// http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6403933

but at http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6403933 now shows that it is fixed for version 7.

Is there any possibility that this can occur because of switching from jdk 1.6 to jdk 1.7 ?

FYI: Before switching to jdk 1.7 we were using

java version "1.6.0_24"

OpenJDK Runtime Environment (IcedTea6 1.11.11) (amazon-61.1.11.11.53.amzn1-x86_64)

OpenJDK 64-Bit Server VM (build 20.0-b12, mixed mode)

Avatar?id=6023&size=32x32

Added by Artur Hefczyc TigaseTeam over 5 years ago

Although we have not experienced this particular problem with Java7, there are some problems with Java7, such as SSL, JDBC and some others, therefore we still not recommend yet JDK7 to run Tigase for production systems.

Also, we have experienced some performance problems and instability of the JVM for OpenJDK, even for OpenJDK 1.6. Therefore we do not recommend using it as well, especially for a high load installations.

Could you please try Oracle's (SUN's) JDK instead of OpenJDK to see if this problem still happens?

    (1-3/3)