5 Replies Latest reply: Nov 1, 2013 7:05 AM by df651e24-e5a5-413f-8144-7361aff1f8b3 RSS

    High CPU usage with Coherence 3.5.0 cluster node

    842675
      We're noticing sustained high CPU usage on one of our Coherence nodes - this happens after running a job that pretty intensively interacts with the cache. The jobs complete, however we still see the Coherence process using approximately the equivalent of one core's worth of CPU. I took a couple of thread dumps about fifteen minutes apart, and the only noticeable differences are within the PacketListener1 and PacketListenerN threads - they're holding locks on different DatagramPacket instances, which suggests to be that this may be the piece of code that is looping.

      There are two other cache nodes in this particular cluster - both of them on a different machine - and neither of them are exhibiting the same CPU utilization.

      Environment:

      Coherence 3.5.0
      Java - BEA JRockit(R) (build R27.6.3-40_o-112056-1.6.0_11-20090318-2103-linux-x86_64, compiled mode)

      Has anyone encountered this scenario before?

      Here's a copy of the two thread dumps:

      Thread Dump 1 -

      ===== FULL THREAD DUMP ===============
      Thu Feb 24 21:45:00 2011
      BEA JRockit(R) R27.6.3-40_o-112056-1.6.0_11-20090318-2103-linux-x86_64

      "Main Thread" id=1 idx=0x4 tid=18143 prio=5 alive, in native, waiting
      -- Waiting for notification on: java/lang/Class@0x43587b58[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/net/DefaultCacheServer.main(DefaultCacheServer.java:80)
      ^-- Lock released while waiting: java/lang/Class@0x43587b58[fat lock]
      at com/zzzz/carbon/cacheserver/ZzzzCoherenceServerStartup.doWork(ZzzzCoherenceServerStartup.java:29)
      at com/zzzz/util/runner/ZzzzRunnerBase.run(ZzzzRunnerBase.java:23)
      at com/zzzz/carbon/cacheserver/ZzzzCoherenceServerStartup.main(ZzzzCoherenceServerStartup.java:16)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "(Signal Handler)" id=2 idx=0x8 tid=18144 prio=5 alive, in native, daemon

      "(GC Main Thread)" id=3 idx=0xc tid=18145 prio=5 alive, in native, daemon

      "(GC Worker Thread 1)" id=? idx=0x10 tid=18146 prio=5 alive, in native, daemon

      "(GC Worker Thread 2)" id=? idx=0x14 tid=18147 prio=5 alive, in native, daemon

      "(GC Worker Thread 3)" id=? idx=0x18 tid=18148 prio=5 alive, in native, daemon

      "(GC Worker Thread 4)" id=? idx=0x1c tid=18149 prio=5 alive, in native, daemon

      "(Code Generation Thread 1)" id=4 idx=0x20 tid=18150 prio=5 alive, in native, native_waiting, daemon

      "(Code Optimization Thread 1)" id=5 idx=0x24 tid=18151 prio=5 alive, in native, native_waiting, daemon

      "(VM Periodic Task)" id=6 idx=0x28 tid=18152 prio=10 alive, in native, daemon

      "Finalizer" id=7 idx=0x2c tid=18153 prio=8 alive, in native, native_waiting, daemon
      at jrockit/memory/Finalizer.waitForFinalizees([Ljava/lang/Object;)I(Native Method)
          at jrockit/memory/Finalizer.access$500(Finalizer.java:12)
          at jrockit/memory/Finalizer$4.run(Finalizer.java:159)
          at java/lang/Thread.run(Thread.java:619)
          at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
          -- end of trace

      "Reference Handler" id=8 idx=0x30 tid=18154 prio=10 alive, in native, native_waiting, daemon
          at java/lang/ref/Reference.waitForActivatedQueue()Ljava/lang/ref/Reference;(Native Method)
          at java/lang/ref/Reference.access$100(Reference.java:11)
          at java/lang/ref/Reference$ReferenceHandler.run(Reference.java:79)
          at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
          -- end of trace

      "(Sensor Event Thread)" id=9 idx=0x34 tid=18155 prio=5 alive, in native, daemon

      "Logger@9217551 3.5/459" id=12 idx=0x38 tid=18158 prio=3 alive, in native, waiting, daemon
          -- Waiting for notification on: com/tangosol/coherence/component/application/console/Coherence$Logger$Queue@0x4e1faef8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/application/console/Coherence$Logger$Queue@0x4e1faef8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketListener1" id=14 idx=0x3c tid=18159 prio=8 alive, in native, daemon
      at java/net/PlainDatagramSocketImpl.receive0(Ljava/net/DatagramPacket;)V(Native Method)
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb21360[recursive]
      at java/net/PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)[inlined]
      at java/net/DatagramSocket.receive(DatagramSocket.java:712)[optimized]
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb21360[thin lock]
      ^-- Holding lock: java/net/DatagramPacket@0x73aa4e80[thin lock]
      ^-- Holding lock: java/net/DatagramSocket@0x4cb21338[thin lock]
      at com/tangosol/coherence/component/net/socket/UdpSocket.receive(UdpSocket.CDB:20)[optimized]
      at com/tangosol/coherence/component/net/UdpPacket.receive(UdpPacket.CDB:4)[optimized]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketListener.onNotify(PacketListener.CDB:19)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketReceiver" id=15 idx=0x40 tid=18160 prio=7 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketReceiver$InQueue@0x4cf60d58[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketReceiver.onWait(PacketReceiver.CDB:2)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketReceiver$InQueue@0x4cf60d58[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketPublisher" id=16 idx=0x44 tid=18161 prio=6 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketPublisher.onWait(PacketPublisher.CDB:2)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketSpeaker" id=17 idx=0x48 tid=18162 prio=8 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketSpeaker$BundlingQueue@0x4cabe9d8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/queue/ConcurrentQueue.waitForEntry(ConcurrentQueue.CDB:16)
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketSpeaker$BundlingQueue@0x4cabe9d8[fat lock]
      at com/tangosol/coherence/component/util/queue/ConcurrentQueue.remove(ConcurrentQueue.CDB:7)
      at com/tangosol/coherence/component/util/Queue.remove(Queue.CDB:1)
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketSpeaker.onNotify(PacketSpeaker.CDB:62)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketListenerN" id=18 idx=0x4c tid=18163 prio=8 alive, in native, daemon
      at java/net/PlainDatagramSocketImpl.receive0(Ljava/net/DatagramPacket;)V(Native Method)
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb221b0[recursive]
      at java/net/PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)[inlined]
      at java/net/DatagramSocket.receive(DatagramSocket.java:712)[optimized]
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb221b0[thin lock]
      ^-- Holding lock: java/net/DatagramPacket@0x73e59890[thin lock]
      ^-- Holding lock: java/net/MulticastSocket@0x4cb22178[thin lock]
      at com/tangosol/coherence/component/net/socket/UdpSocket.receive(UdpSocket.CDB:20)[optimized]
      at com/tangosol/coherence/component/net/UdpPacket.receive(UdpPacket.CDB:4)[optimized]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketListener.onNotify(PacketListener.CDB:19)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Cluster|Member(Id=2, Timestamp=2011-02-23 16:25:36.488, Address=10.10.100.77:8095, MachineId=25677, Location=site:emtzzzz.com,machine:njdev04,process:18142,member:cldev201~carboncachelauncher~181)" id=19 idx=0x50 tid=18164 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4cac64d8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4cac64d8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "TcpRingListener" id=20 idx=0x54 tid=18165 prio=6 alive, in native, daemon
      at java/net/PlainSocketImpl.socketAccept(Ljava/net/SocketImpl;)V(Native Method)
      at java/net/PlainSocketImpl.accept(PlainSocketImpl.java:384)
      ^-- Holding lock: java/net/SocksSocketImpl@0x4cb227d8[thin lock]
      at java/net/ServerSocket.implAccept(ServerSocket.java:453)
      at java/net/ServerSocket.accept(ServerSocket.java:421)
      at com/tangosol/coherence/component/net/socket/TcpSocketAccepter.accept(TcpSocketAccepter.CDB:18)
      at com/tangosol/coherence/component/util/daemon/TcpRingListener.acceptConnection(TcpRingListener.CDB:10)
      at com/tangosol/coherence/component/util/daemon/TcpRingListener.onNotify(TcpRingListener.CDB:9)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Invocation:Management:EventDispatcher" id=22 idx=0x58 tid=18166 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher$Queue@0x4ab76140[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher$Queue@0x4ab76140[fat lock]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher.onWait(Service.CDB:7)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Invocation:Management" id=23 idx=0x5c tid=18167 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4ab75508[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4ab75508[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "DistributedCache" id=25 idx=0x60 tid=18168 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4a3869b0[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4a3869b0[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      ===== END OF THREAD DUMP ===============


      Thread Dump 2 -

      ===== FULL THREAD DUMP ===============
      Thu Feb 24 21:27:53 2011
      BEA JRockit(R) R27.6.3-40_o-112056-1.6.0_11-20090318-2103-linux-x86_64

      "Main Thread" id=1 idx=0x4 tid=18143 prio=5 alive, in native, waiting
      -- Waiting for notification on: java/lang/Class@0x43587b58[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/net/DefaultCacheServer.main(DefaultCacheServer.java:80)
      ^-- Lock released while waiting: java/lang/Class@0x43587b58[fat lock]
      at com/zzzz/carbon/cacheserver/ZzzzCoherenceServerStartup.doWork(ZzzzCoherenceServerStartup.java:29)
      at com/zzzz/util/runner/ZzzzRunnerBase.run(ZzzzRunnerBase.java:23)
      at com/zzzz/carbon/cacheserver/ZzzzCoherenceServerStartup.main(ZzzzCoherenceServerStartup.java:16)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "(Signal Handler)" id=2 idx=0x8 tid=18144 prio=5 alive, in native, daemon

      "(GC Main Thread)" id=3 idx=0xc tid=18145 prio=5 alive, in native, native_waiting, daemon

      "(GC Worker Thread 1)" id=? idx=0x10 tid=18146 prio=5 alive, in native, daemon

      "(GC Worker Thread 2)" id=? idx=0x14 tid=18147 prio=5 alive, in native, daemon

      "(GC Worker Thread 3)" id=? idx=0x18 tid=18148 prio=5 alive, in native, daemon

      "(GC Worker Thread 4)" id=? idx=0x1c tid=18149 prio=5 alive, in native, daemon

      "(Code Generation Thread 1)" id=4 idx=0x20 tid=18150 prio=5 alive, in native, native_waiting, daemon

      "(Code Optimization Thread 1)" id=5 idx=0x24 tid=18151 prio=5 alive, in native, native_waiting, daemon

      "(VM Periodic Task)" id=6 idx=0x28 tid=18152 prio=10 alive, in native, daemon

      "Finalizer" id=7 idx=0x2c tid=18153 prio=8 alive, in native, native_waiting, daemon
      at jrockit/memory/Finalizer.waitForFinalizees([Ljava/lang/Object;)I(Native Method)
          at jrockit/memory/Finalizer.access$500(Finalizer.java:12)
          at jrockit/memory/Finalizer$4.run(Finalizer.java:159)
          at java/lang/Thread.run(Thread.java:619)
          at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
          -- end of trace

      "Reference Handler" id=8 idx=0x30 tid=18154 prio=10 alive, in native, native_waiting, daemon
          at java/lang/ref/Reference.waitForActivatedQueue()Ljava/lang/ref/Reference;(Native Method)
          at java/lang/ref/Reference.access$100(Reference.java:11)
          at java/lang/ref/Reference$ReferenceHandler.run(Reference.java:79)
          at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
          -- end of trace

      "(Sensor Event Thread)" id=9 idx=0x34 tid=18155 prio=5 alive, in native, daemon

      "Logger@9217551 3.5/459" id=12 idx=0x38 tid=18158 prio=3 alive, in native, waiting, daemon
          -- Waiting for notification on: com/tangosol/coherence/component/application/console/Coherence$Logger$Queue@0x4e1faef8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/application/console/Coherence$Logger$Queue@0x4e1faef8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketListener1" id=14 idx=0x3c tid=18159 prio=8 alive, in native, daemon
      at java/net/PlainDatagramSocketImpl.receive0(Ljava/net/DatagramPacket;)V(Native Method)
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb21360[recursive]
      at java/net/PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)[inlined]
      at java/net/DatagramSocket.receive(DatagramSocket.java:712)[optimized]
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb21360[thin lock]
      ^-- Holding lock: java/net/DatagramPacket@0x73a80930[thin lock]
      ^-- Holding lock: java/net/DatagramSocket@0x4cb21338[thin lock]
      at com/tangosol/coherence/component/net/socket/UdpSocket.receive(UdpSocket.CDB:20)[optimized]
      at com/tangosol/coherence/component/net/UdpPacket.receive(UdpPacket.CDB:4)[optimized]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketListener.onNotify(PacketListener.CDB:19)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketReceiver" id=15 idx=0x40 tid=18160 prio=7 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketReceiver$InQueue@0x4cf60d58[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketReceiver.onWait(PacketReceiver.CDB:2)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketReceiver$InQueue@0x4cf60d58[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketPublisher" id=16 idx=0x44 tid=18161 prio=6 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketPublisher.onWait(PacketPublisher.CDB:2)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketPublisher$InQueue@0x4ca053a8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketSpeaker" id=17 idx=0x48 tid=18162 prio=8 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/net/Cluster$PacketSpeaker$BundlingQueue@0x4cabe9d8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/queue/ConcurrentQueue.waitForEntry(ConcurrentQueue.CDB:16)
      ^-- Lock released while waiting: com/tangosol/coherence/component/net/Cluster$PacketSpeaker$BundlingQueue@0x4cabe9d8[fat lock]
      at com/tangosol/coherence/component/util/queue/ConcurrentQueue.remove(ConcurrentQueue.CDB:7)
      at com/tangosol/coherence/component/util/Queue.remove(Queue.CDB:1)
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketSpeaker.onNotify(PacketSpeaker.CDB:62)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "PacketListenerN" id=18 idx=0x4c tid=18163 prio=8 alive, in native, daemon
      at java/net/PlainDatagramSocketImpl.receive0(Ljava/net/DatagramPacket;)V(Native Method)
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb221b0[recursive]
      at java/net/PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)[inlined]
      at java/net/DatagramSocket.receive(DatagramSocket.java:712)[optimized]
      ^-- Holding lock: java/net/PlainDatagramSocketImpl@0x4cb221b0[thin lock]
      ^-- Holding lock: java/net/DatagramPacket@0x5e55a240[thin lock]
      ^-- Holding lock: java/net/MulticastSocket@0x4cb22178[thin lock]
      at com/tangosol/coherence/component/net/socket/UdpSocket.receive(UdpSocket.CDB:20)[optimized]
      at com/tangosol/coherence/component/net/UdpPacket.receive(UdpPacket.CDB:4)[optimized]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/packetProcessor/PacketListener.onNotify(PacketListener.CDB:19)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Cluster|Member(Id=2, Timestamp=2011-02-23 16:25:36.488, Address=10.10.100.77:8095, MachineId=25677, Location=site:emtzzzz.com,machine:njdev04,process:18142,member:cldev201~carboncachelauncher~181)" id=19 idx=0x50 tid=18164 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4cac64d8[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4cac64d8[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "TcpRingListener" id=20 idx=0x54 tid=18165 prio=6 alive, in native, daemon
      at java/net/PlainSocketImpl.socketAccept(Ljava/net/SocketImpl;)V(Native Method)
      at java/net/PlainSocketImpl.accept(PlainSocketImpl.java:384)
      ^-- Holding lock: java/net/SocksSocketImpl@0x4cb227d8[thin lock]
      at java/net/ServerSocket.implAccept(ServerSocket.java:453)
      at java/net/ServerSocket.accept(ServerSocket.java:421)
      at com/tangosol/coherence/component/net/socket/TcpSocketAccepter.accept(TcpSocketAccepter.CDB:18)
      at com/tangosol/coherence/component/util/daemon/TcpRingListener.acceptConnection(TcpRingListener.CDB:10)
      at com/tangosol/coherence/component/util/daemon/TcpRingListener.onNotify(TcpRingListener.CDB:9)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:37)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Invocation:Management:EventDispatcher" id=22 idx=0x58 tid=18166 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher$Queue@0x4ab76140[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher$Queue@0x4ab76140[fat lock]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/Service$EventDispatcher.onWait(Service.CDB:7)
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "Invocation:Management" id=23 idx=0x5c tid=18167 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4ab75508[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4ab75508[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      "DistributedCache" id=25 idx=0x60 tid=18168 prio=5 alive, in native, waiting, daemon
      -- Waiting for notification on: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4a3869b0[fat lock]
      at jrockit/vm/Threads.waitForNotifySignal(JLjava/lang/Object;)Z(Native Method)
      at java/lang/Object.wait(J)V(Native Method)[optimized]
      at com/tangosol/coherence/component/util/Daemon.onWait(Daemon.CDB:18)[inlined]
      at com/tangosol/coherence/component/util/daemon/queueProcessor/service/Grid.onWait(Grid.CDB:9)[optimized]
      ^-- Lock released while waiting: com/tangosol/coherence/component/util/queue/concurrentQueue/DualQueue@0x4a3869b0[fat lock]
      at com/tangosol/coherence/component/util/Daemon.run(Daemon.CDB:34)
      at java/lang/Thread.run(Thread.java:619)
      at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
      -- end of trace

      ===== END OF THREAD DUMP ===============
        • 1. Re: High CPU usage with Coherence 3.5.0 cluster node
          Cameron Purdy
          Jason -

          It appears that all of the threads are idle (in various wait states), so it is not clear why a CPU core would be busy. I notice that you're on jRockit, so I'll ask Charlie Helin (our resident jRockit expert) to take a quick look at the thread dumps.

          I'd appreciate if you could verify (e.g. via TOP) that the JVM is chewing up that core, and also try to figure out which thread is actually using it.

          Peace,

          Cameron Purdy | Oracle Coherence
          http://coherence.oracle.com/
          • 2. Re: High CPU usage with Coherence 3.5.0 cluster node
            698451
            Hi Jason

            I would agree with Cameron there is very little indication that the JVM is consuming CPU. But the wait could theoretically result in spinnlocks, which would result in higher cpu usage. If you could take a JRA recording using Mission Control or by invoking it through 'jrcmd'. It should be quite simple to see where the VM is using the CPU.

            Thanks
            /Charlie
            • 3. Re: High CPU usage with Coherence 3.5.0 cluster node
              842675
              Charlie, Cameron,

              Thanks for following up. To answer Cameron's question - yes, running top shows that it is this process using a significant amount of the CPU. I captured a JRA this morning setting nativesamples=true.

              I see the following when I look at the Hot Methods - let me know if there is something else that would shed some more light on this issue.

              Method     Percent(%)     #Samples     Optimized     Native     Method Id.
              libjvm.so#mmDetGcFollowReferencesWorkers     28.575     2,062     0     1     0x2AE6B82EC2C1
              libpthread.so.0#__recvfrom_nocancel     26.012     1,877     0     1     0x3CC1A0D689
              libpthread.so.0#__accept_nocancel     26.012     1,877     0     1     0x3CC1A0D4A9
              libjvm.so#mmBalanceGetReference     4.975     359     0     1     0x2AE6B817A65B
              libjvm.so#objIterStepFieldFromBitmaskWord     4.753     343     0     1     0x2AE6B82A6B34
              libjvm.so#objIterStep     3.88     280     0     1     0x2AE6B82A6F8D
              libjvm.so#objIterInitInner     2.744     198     0     1     0x2AE6B82A71B7
              libjvm.so#mmBalanceStoreReference     1.414     102     0     1     0x2AE6B817A781
              libjvm.so#objIterSetupFields     0.637     46     0     1     0x2AE6B82A6B08
              libjvm.so#nativeInnerLockNotLinked     0.236     17     0     1     0x2AE6B829DE76
              libjvm.so#mmWorkPacketPoolGet     0.125     9     0     1     0x2AE6B817A4F5
              libjvm.so#qBitSetIsBitSetInWord     0.069     5     0     1     0x2AE6B82C8AA6
              libjvm.so#nativeInnerUnlockNotLinked     0.069     5     0     1     0x2AE6B829E028
              libjvm.so#mmWorkPacketPoolAdd     0.042     3     0     1     0x2AE6B817A48E
              libjvm.so#objPoolMarkAllHard     0.042     3     0     1     0x2AE6B82A4923
              libjvm.so#objIterSetupArray     0.028     2     0     1     0x2AE6B82A6BDB
              libjvm.so#markAcquired     0.028     2     0     1     0x2AE6B829DBD3
              libjvm.so#mmPointerMatrixTryInsertAtIndex     0.028     2     0     1     0x2AE6B82BEFEB
              libjvm.so#mmPointerMatrixClear     0.028     2     0     1     0x2AE6B82BF61C
              libjvm.so#objPoolMarkWeakConcurrently     0.028     2     0     1     0x2AE6B82A5358
              libjvm.so#qBitSetFindFirstNonClearedWord     0.014     1     0     1     0x2AE6B82C888E
              libjvm.so#utilCounterToNanos     0.014     1     0     1     0x2AE6B8313B53
              libjvm.so#waitForLockIfNeededAndMarkAcquired     0.014     1     0     1     0x2AE6B829DC30
              libjvm.so#vmtLinkData     0.014     1     0     1     0x2AE6B8325B2E
              libjvm.so#mmBitsIsObjectMarkedGrey     0.014     1     0     1     0x2AE6B82ED7E9
              libjvm.so#qBitSetFindLastSetBitInWord     0.014     1     0     1     0x2AE6B82C8854
              libjvm.so#mark_writebarriers     0.014     1     0     1     0x2AE6B8250EEA
              libjvm.so#signalNextInLockQueueIfNeeded     0.014     1     0     1     0x2AE6B829DF52
              libjvm.so#mmGetUsingMatrixes     0.014     1     0     1     0x2AE6B819F33C
              libjvm.so#ptGetThreadId     0.014     1     0     1     0x2AE6B82BD9ED
              libc.so.6#memset     0.014     1     0     1     0x3CC0A7A000
              libjvm.so#setupNodeForSelf     0.014     1     0     1     0x2AE6B829DD87
              libc.so.6#_int_free     0.014     1     0     1     0x3CC0A714E0
              libjvm.so#mmAddChunkToList     0.014     1     0     1     0x2AE6B830977C
              libjvm.so#vmtiUnlinkData     0.014     1     0     1     0x2AE6B8325B4A
              libjvm.so#nativeLockInSuspendCritical     0.014     1     0     1     0x2AE6B829E0E3
              libjvm.so#mmSweepHeapPart     0.014     1     0     1     0x2AE6B830989A
              libjvm.so#mmBalanceWorkSetSwapPackets     0.014     1     0     1     0x2AE6B817A647
              libc.so.6#_int_malloc     0.014     1     0     1     0x3CC0A71E80
              libjvm.so#charToJlcType     0.014     1     0     1     0x2AE6B8253633
              unknown#unknown functions     0     0     0     1     0x2AE6B8597090

              Running with nativemethods=false, I see the following under hot methods

              Method     Percent(%)     #Samples     Optimized     Native     Method Id.
              jrockit.vm.Locks.monitorExitSecondStage(Object)     50     1     1     0     0x161D30D0
              com.tangosol.coherence.component.util.daemon.queueProcessor.service.grid.ClusterService.onNotify()     50     1     1     0     0x169D2C70
              com.tangosol.coherence.component.util.daemon.queueProcessor.packetProcessor.PacketReceiver.onNotify()     0     0     1     0     0x1551C050
              com.tangosol.coherence.component.util.queue.ConcurrentQueue.checkFlush(int)     0     0     1     0     0x151C2180
              java.lang.Thread.run()     0     0     0     0     0x14E98EB0
              jrockit.vm.RNI.c2java(long, long, long, long, long)     0     0     0     0     0x14C07830
              unknown#unknown functions     0     0     0     1     0x2AE6B8597090
              com.tangosol.coherence.component.util.Daemon.run()     0     0     0     0     0x15CFEBC0
              com.tangosol.coherence.component.util.queue.ConcurrentQueue.add(Object)     0     0     1     0     0x15ED6B00
              com.tangosol.coherence.component.util.queue.ConcurrentQueue.onAddElement()     0     0     1     0     0x151C9C20
              com.tangosol.coherence.component.util.queue.ConcurrentQueue.flush(boolean)     0     0     1     0     0x1618CAD0

              Thanks,

              Jason
              • 4. Re: High CPU usage with Coherence 3.5.0 cluster node
                698451
                Hi Jason

                Given the two samples below it looks like there is two things that the JVM is doing. However it is very hard to say conclusively what is really going on. If you feel comfortable with it you could send me the jra recording charlie(dot)helin(at)oracle(dot)com. The hot spot statistics gives one view that is based on samples, meaning when the VM is running what methods it mostly visits.

                With that in mind we see that what the VM is:
                - In the the native samples that there is Garbage collections.
                - The non-native sample indicates, that there is an unrecursive fat lock being unlocked. More or less meaning that the VM is not doing anything, since the lock is coming from our network stack. If there would be data flowing in the system these methods will become irrelevant.

                Thanks
                /Charlie
                • 5. Re: High CPU usage with Coherence 3.5.0 cluster node
                  df651e24-e5a5-413f-8144-7361aff1f8b3

                  Dear Jason,Charlie, Cameron


                  Did you solve the problem? I am now facing the same problem.

                  My program is to sync data in RDB to Coherence Cluster. I am using Coherence 3.7.1.0.

                   

                  Bests,

                  Tm.