Sorry about taking a while (was on vacation). Before I get to the results I
wanted to mention how I am getting into this state. I've set up two machines
with the latest 0.8 code base and am using a replication factor of 2. On
starting the brokers there is no idle CPU activity. Then I run a test that
essential does 10k publish operations followed by immediate consume operations
(I was measuring latency). Once this has run the kafka nodes seem to
consistently be consuming CPU essentially forever.
Now, here is the hprof output:
THREAD START (obj=500003ad, id = 200004, name="RMI TCP Accept-0",
group="system")
THREAD START (obj=500003ad, id = 200005, name="RMI TCP Accept-9999",
group="system")
THREAD START (obj=500003ad, id = 200006, name="RMI TCP Accept-0",
group="system")
THREAD START (obj=500003ad, id = 200001, name="main", group="main")
THREAD START (obj=500003ad, id = 200007, name="Thread-2", group="main")
THREAD START (obj=500003ad, id = 200008, name="Thread-3", group="main")
THREAD START (obj=500003ad, id = 200009, name="kafka-processor-9092-0",
group="main")
THREAD START (obj=500003ad, id = 200010, name="kafka-processor-9092-1",
group="main")
THREAD START (obj=500003ad, id = 200011, name="kafka-acceptor", group="main")
THREAD START (obj=5000074b, id = 200012,
name="ZkClient-EventThread-20-localhost:2181", group="main")
THREAD START (obj=5000076d, id = 200013, name="main-SendThread()", group="main")
THREAD START (obj=5000076e, id = 200014, name="main-EventThread", group="main")
THREAD START (obj=500003ad, id = 200015, name="metrics-meter-tick-thread-1",
group="main")
THREAD START (obj=500003ad, id = 200016, name="metrics-meter-tick-thread-2",
group="main")
THREAD START (obj=500003ad, id = 200017, name="request-expiration-task",
group="main")
THREAD START (obj=500003ad, id = 200018, name="request-expiration-task",
group="main")
THREAD START (obj=500003ad, id = 200019, name="kafka-request-handler-0",
group="main")
THREAD START (obj=500003ad, id = 200020, name="kafka-request-handler-1",
group="main")
THREAD START (obj=500003ad, id = 200021, name="Thread-6", group="main")
THREAD START (obj=500003ad, id = 200022, name="Thread-7", group="main")
THREAD START (obj=50000899, id = 200023, name="ReplicaFetcherThread-0-2 on
broker 1, ", group="main")
THREAD START (obj=50000899, id = 200024, name="ReplicaFetcherThread-0-3 on
broker 1, ", group="main")
THREAD START (obj=50000899, id = 200025, name="ReplicaFetcherThread-0-0 on
broker 1, ", group="main")
THREAD START (obj=50000899, id = 200026, name="ReplicaFetcherThread-0-1 on
broker 1, ", group="main")
THREAD START (obj=500003ad, id = 200028, name="SIGINT handler", group="system")
THREAD START (obj=5000074b, id = 200029, name="Thread-0", group="main")
THREAD START (obj=5000074b, id = 200030, name="Thread-1", group="main")
THREAD START (obj=500003ad, id = 200031, name="Thread-5", group="main")
THREAD END (id = 200029)
THREAD END (id = 200031)
THREAD END (id = 200020)
THREAD END (id = 200019)
THREAD END (id = 200008)
THREAD END (id = 200022)
THREAD END (id = 200007)
THREAD END (id = 200021)
THREAD END (id = 200018)
THREAD END (id = 200017)
THREAD END (id = 200012)
THREAD END (id = 200014)
THREAD END (id = 200013)
THREAD END (id = 200025)
THREAD END (id = 200023)
THREAD END (id = 200026)
THREAD END (id = 200024)
THREAD END (id = 200011)
THREAD END (id = 200009)
THREAD END (id = 200010)
THREAD END (id = 200030)
THREAD END (id = 200028)
THREAD END (id = 200002)
TRACE 300680:
sun.nio.ch.EPollArrayWrapper.epollWait(EPollArrayWrapper.java:Unknown
line)
sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:228)
sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:81)
sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)
TRACE 300425:
java.net.PlainSocketImpl.socketAccept(PlainSocketImpl.java:Unknown line)
java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)
java.net.ServerSocket.implAccept(ServerSocket.java:522)
java.net.ServerSocket.accept(ServerSocket.java:490)
TRACE 300886:
sun.misc.Unsafe.park(Unsafe.java:Unknown line)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
java.util.concurrent.DelayQueue.take(DelayQueue.java:220)
CPU SAMPLES BEGIN (total = 882945) Wed Aug 29 23:37:30 2012
rank self accum count trace method
1 72.49% 72.49% 640059 300680 sun.nio.ch.EPollArrayWrapper.epollWait
2 27.25% 99.74% 240621 300425 java.net.PlainSocketImpl.socketAccept
3 0.09% 99.83% 762 300886 sun.misc.Unsafe.park
CPU SAMPLES END
Let me know if you need anything else. Certainly happy to share my config files
and the test program if you need them.
/Sam
On Aug 20, 2012, at 2:30 PM, Sam Meder wrote:
> I've been playing with the 0.8 branch of Kafka and noticed that idle CPU
> usage is fairly high (13% of a core). Is that to be expected? I did look at
> the stack, but didn't see anything obvious. A background task?
>
> /Sam
