11 Replies Latest reply on Aug 31, 2010 2:31 AM by kevin.lohmann

    PingTimerTask broken pipe

    bob_walker99

      I just upgraded to 4.2.0/1.3.0GA and left the server running overnight, wth a couple of relatively heavy clients sending messages (approx 10,000 messages per client), and one receiver with a listener registered on my queue.

      When I looked this morning, my client has nearly 300 "Timer-nnn" threads running, and the JBoss server.log is full of these:

      2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4936 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4937 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4938 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4939 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4940 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4941 2007-07-03 00:29:32,971 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4942 2007-07-03 00:29:33,032 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4943 2007-07-03 00:29:33,032 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4944 2007-07-03 00:29:33,032 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
      4945 2007-07-03 00:29:33,032 WARN [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: shutting down PingTimerTask
      4946 java.net.SocketException: Write failed: Broken pipe
      4947 at jrockit.net.SocketNativeIO.writeBytesPinned(Native Method)
      4948 at jrockit.net.SocketNativeIO.socketWrite(Unknown Source)
      4949 at java.net.SocketOutputStream.socketWrite0(SocketOutputStream.java)
      4950 at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
      4951 at java.net.SocketOutputStream.write(SocketOutputStream.java:115)
      4952 at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:497)
      4953 at java.util.TimerThread.mainLoop(Timer.java:512)
      4954 at java.util.TimerThread.run(Timer.java:462)

      Presumably the server is using the ping to test the health of the registered client - but if this ping fails, it shouldn't leave an open thread in my client?

      It looks like I'm going to have to roll back to 1.0.1 again, which is what I had to do when I tried 1.2.0 (for a different reason). This is really disappointing for me. I'm not using clustering at this stage - should I just be happy sticking with 1.0.1? I was of the impression that the newer releases offered efficiencies and performance gains, but if this is negligible, I'm happy to stick with what works for me.

      I'm on an x86_64 box with 4Gb RAM running Suse SLES 9, with JBoss running on JRockit 6.0 - R27.2.0-131-78843-1.6.0-20070320-1507-linux-x86_64.

      Any help greatly appreciated.

        • 1. Re: PingTimerTask broken pipe
          bob_walker99

          Update:

          I've just tried restarting the server and resubmitting one of my client jobs - whilst it is running , the client has many, many threads created seemingly in pairs like this:

          Timer-7 (main), 5, alive, daemon
          control: Socket[addr=/10.0.x.xx,port=3089,localport=37979] (main), 5, alive, daemon


          Each pair has an incremented [Timer-nnn] number, and a different value for ["localport"].

          Regards,

          Bob

          • 2. Re: PingTimerTask broken pipe
            timfox

            Bob - Are you sure you are closing your connections after you get an exception?

            I remember you had a similar issue some time back (too many open files) which would make me think the same.

            If not, can you post a small test program that replicates the problem?

            • 3. Re: PingTimerTask broken pipe
              timfox

              If you are attempting an upgrade now, personally I'd wait a bit, since 1.4.0 is out very soon.

              • 4. Re: PingTimerTask broken pipe
                ron_sigal

                1. Each JBossMessaging connection has a "control:" thread associated with it on the client side. I've tried to reproduce the phenomenon of control threads outliving the messaging connection, but so far I haven't been able to.

                2. I noticed that a new Timer is being created on the client side for each messaging connection. That wasn't my intention, and I'll fix it, but these Timers have daemon threads. Looking at the code, I don't see how the only TimerTask scheduled on each would not be canceled when the messaging connection is closed.

                I'm not saying there isn't a problem somewhere in the bisocket transport that is causing these threads to remain alive, but I haven't found one yet.

                • 5. Re: PingTimerTask broken pipe
                  bob_walker99

                  Hi - I' checked my code and did find some instances in my sending client that wasn't closing connections properly in the event of exceptions, which I've fixed, but I've had the same problem overnight again.

                  I've isolated my sending and receiving jobs - this morning I've successfully sent around 10,000 messages to a single queue with no apparent resource hit to either my client or the JBM server, so I have to conclude that the problem is in the receiver.

                  I have an ExceptionListener in place that notifies the thread that starts the listener when an exception occurs, this disposes all the JMS environment objects and re-initialises them, correctly as far as I can see.

                  However, all this is kind of academic, because I'm not actually getting exceptions in my listener code - the threads and open file handles are just mounting and mounting, but until the server runs out of resources, it does actually work. I'm at a bit of a loss as to where to look next...?

                  If it helps, these are fairly large text messages, often up to 1Mb, so I've set the queue's FullSize param to 100, and the PageSize and DownCacheSize to 20 apiece - are these reasonable values?

                  Any advice gratefully received.

                  Best regards,
                  Bob

                  • 6. Re: PingTimerTask broken pipe
                    timfox

                    If you can post (or send to me direct) your test program with instructions to replicate - we'll make sure we investigate.

                    • 7. Re: PingTimerTask broken pipe
                      bob_walker99

                      Hi Tim,

                      I think I've nailed it.

                      I built a test case, and of course it worked just fine, which obviously pointed to my application code as the culprit. I've made a few changes but there /seems/ to have been 2 main points of failure:

                      1) In one of my listeners, I was holding on to a reference to the message received in onMessage unnecessarily, and even though this was going out of scope it seems that it wasn't getting garbage collected. I've processed the text much earlier and aggressively nulled out the reference now and it seems to hold up - it processed 20,000 messages yesterday without a resource hit to either the client or server.

                      2) it seems a NPE in my client code was breaking the connection - because I had no RuntimeException handling code and this was not happening "out-of-band" for my ExceptionListener to handle, there was nowhere for me to close my connection.

                      So, it was my fault, my apologies.

                      However, are these 2 situations reasonable behaviour? I'm guessing that because I've set the FullSize/PageSize/DownCacheSize on the queue quite low, that these messsages are being backed by files - when the onMessage completes and the message goes out of scope - are these files always getting closed/cleaned up? Although my code was holding onto the reference longer than it should, it did /eventually/ going out of scope.

                      Also, obviously NPEs should either not happen at all or be handled/anticipated in my client code - but should the server be able to dispose a connection if it happens?

                      I'm not saying this is how it should work, just my thoughts; feel free to shoot me down.

                      Thanks for your time and effort on this,

                      Best regards,

                      Bob

                      • 8. Re: PingTimerTask broken pipe
                        btsibr

                        I'm having a similar issue after using an EJB3 timer to send a status request message to a topic from a stateless session bean. There is an MDB that receives the responses and writes them to the DB.

                        In the EJB that sends the message, I'm absolutely closing all connections in a finally block.. however after a while the server stops accepting connections (and even refuses to gracefully shut down).

                        So it seem as if something in the timer implementation or remoting is causing the server to run out of resources. We do see lots of 'hung' control threads.

                        • 9. Re: PingTimerTask broken pipe
                          timfox

                          Yes, there is a whole stack of JBoss remoting issues in the version in AS 4.2.0 which will be fixed for the next release.

                          BTW in your timer ejb, are you using the managed connection factory (i.e. the one at /JmsXA), or are you manually creating a connection each time to send to the topic using a standard connection factory?

                          If you use JmsXA, this will actually cache connections under the bonnet, so you won't need to create a new one each time - this will help your resource usage, and performance true.

                          In general, there are few reasons *not* to use JmsXA from EJBs.

                          • 10. Re: PingTimerTask broken pipe
                            bob_walker99

                            I'm still seeing this after the upgrade to 1.4.0-CR2:

                            2007-09-10 11:26:03,237 WARN [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: shutting down PingTimerTask
                             java.net.SocketException: Write failed: Broken pipe
                             at jrockit.net.SocketNativeIO.writeBytesPinned(Native Method)
                             at jrockit.net.SocketNativeIO.socketWrite(SocketNativeIO.java:45)
                             at java.net.SocketOutputStream.socketWrite0(SocketOutputStream.java)
                             at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
                             at java.net.SocketOutputStream.write(SocketOutputStream.java:115)
                             at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:612)
                             at java.util.TimerThread.mainLoop(Timer.java:512)
                             at java.util.TimerThread.run(Timer.java:462)
                            2007-09-10 11:26:03,308 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,327 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,327 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,327 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: trying again
                            2007-09-10 11:26:03,370 WARN [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] Unable to send ping: shutting down PingTimerTask
                             java.net.SocketException: Write failed: Broken pipe
                             at jrockit.net.SocketNativeIO.writeBytesPinned(Native Method)
                             at jrockit.net.SocketNativeIO.socketWrite(SocketNativeIO.java:45)
                             at java.net.SocketOutputStream.socketWrite0(SocketOutputStream.java)
                             at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
                             at java.net.SocketOutputStream.write(SocketOutputStream.java:115)
                             at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:612)
                             at java.util.TimerThread.mainLoop(Timer.java:512)
                             at java.util.TimerThread.run(Timer.java:462)
                            2007-09-10 11:26:06,064 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[14071c5, bisocket://10.0.2.15:1698313622] replacing control socket: Socket[addr=/10.0.2.15,port=24004,localport=3692]
                            2007-09-10 11:26:06,064 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[14071c5, bisocket://10.0.2.15:1698313622] control socket replaced by: Socket[addr=/10.0.2.15,port=24109,localport=3692]
                            2007-09-10 11:26:06,334 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[14e5a8d, bisocket://10.0.2.15:1699615737] replacing control socket: Socket[addr=/10.0.2.15,port=24003,localport=3692]
                            2007-09-10 11:26:06,420 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[14e5a8d, bisocket://10.0.2.15:1699615737] control socket replaced by: Socket[addr=/10.0.2.15,port=24111,localport=3692]
                            2007-09-10 11:26:06,457 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[1409e1c, bisocket://10.0.2.15:1699584984] replacing control socket: Socket[addr=/10.0.2.15,port=24034,localport=3692]
                            2007-09-10 11:26:06,522 DEBUG [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] SocketClientInvoker[1409e1c, bisocket://10.0.2.15:1699584984] control socket replaced by: Socket[addr=/10.0.2.15,port=24110,localport=3692]
                            


                            Do I need to worry about this? It looks like perhaps is it just indicating that the Bisocket control is working, detecting a connection error, and re-initiliasing itself with that client, but I want to make sure everything is as it should be?

                            • 11. Re: PingTimerTask broken pipe
                              kevin.lohmann

                              Hi there,

                               

                              sorry for coming up with this old thread, but actually we are seeing these warnings (and one NPE) again and again in JBoss AS 5.0.1.GA and within its client:

                               

                               

                              2010-08-30 18:38:11,886 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
                              java.lang.NullPointerException
                                  at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
                                  at java.util.TimerThread.mainLoop(Unknown Source)
                                  at java.util.TimerThread.run(Unknown Source)
                              

                               

                               

                              2010-08-30 22:44:48,043 WARN  [org.jboss.remoting.transport.bisocket.BisocketClientInvoker] (Timer-4) Unable to send ping: shutting down PingTimerTask
                              java.net.SocketException: Socket closed
                                  at java.net.SocketOutputStream.socketWrite(Unknown Source)
                                  at java.net.SocketOutputStream.write(Unknown Source)
                                  at org.jboss.remoting.transport.bisocket.BisocketClientInvoker$PingTimerTask.run(BisocketClientInvoker.java:723)
                                  at java.util.TimerThread.mainLoop(Unknown Source)
                                  at java.util.TimerThread.run(Unknown Source)
                              

                               

                              Unfortunately we can't find out, if we can ignore these warnings or what we can do. AS and client are running on the same machine.

                               

                              Have you any hints what we should think about it?

                               

                              Thanks,

                                 Kevin