why epoll consum sys usage,is normal?
fuyou
fuyou001 at gmail.com
Sun Oct 12 10:02:33 UTC 2014
when I profile java application,find the epoll consum lots of sys usage
step one ：
I use systemtap script find the which thread consum cpu usgae,every second
display one ,find these thread
comm tid %user %kernel (of 15133 ticks)
java 27965 0.00% 7.11%
java 27743 0.00% 4.15%
java 28177 0.00% 3.35%
java 27902 0.00% 3.33%
java 27964 0.00% 3.23%
java 27929 0.00% 2.96%
java 28205 0.00% 2.95%
java 28203 0.00% 2.94%
java 27863 0.00% 2.93%
java 27581 0.00% 1.38%
java 27586 0.00% 1.24%
java 27588 0.00% 0.88%
java 27905 0.00% 0.77%
java 27954 0.00% 0.74%
java 27945 0.00% 0.73%
java 27911 0.00% 0.72%
java 27946 0.00% 0.72%
java 27910 0.00% 0.71%
java 27938 0.00% 0.70%
java 27962 0.00% 0.70%
comm tid %user %kernel (of 457 ticks)
java 27758 0.00% 11.15%
java 27742 0.00% 10.06%
java 27749 0.00% 9.84%
java 27756 0.00% 8.75%
java 27747 0.00% 8.31%
java 27752 0.00% 8.31%
java 27740 0.00% 6.34%
java 27734 0.00% 6.34%
java 27537 0.00% 3.06%
java 27965 0.00% 2.84%
java 27538 0.00% 2.18%
java 27743 0.00% 1.31%
java 27929 0.00% 1.31%
java 28203 0.00% 1.09%
java 27586 0.00% 1.09%
java 27902 0.00% 0.87%
java 27964 0.00% 0.87%
java 28177 0.00% 0.87%
java 28205 0.00% 0.65%
java 27868 0.00% 0.65%
comm tid %user %kernel (of 193 ticks)
java 27863 0.00% 8.80%
java 27965 0.00% 7.77%
java 27964 0.00% 6.21%
java 28177 0.00% 6.21%
java 28203 0.00% 5.18%
java 27929 0.00% 5.18%
java 28205 0.00% 4.14%
java 27902 0.00% 2.59%
java 27615 0.00% 2.59%
java 27590 0.00% 2.59%
java 27743 0.00% 1.55%
java 27762 0.00% 1.55%
java 27775 0.00% 1.55%
java 27776 0.00% 1.55%
java 27767 0.00% 1.55%
java 27794 0.00% 1.55%
java 27731 0.00% 1.55%
java 18362 0.00% 1.03%
java 27828 0.00% 1.03%
java 27747 0.00% 1.03%
step two ：use jstack -l PID go get java stack
step three : change the thread id to hex and find stack in java stack file
the thread:
>>> print(hex(27965))
0x6d3d
>>> print(hex(27758))
0x6c6e
>>> print(hex(27863))
0x6cd7
>>> print(hex(27965))
0x6d3d
the jstacks
[~]$ cat jstack_27523_2.txt |grep --color -A10 --color 0x6c6e
"task-8" prio=10 tid=0x00007f76d7314000 nid=0x6c6e runnable [0x00000000471a0000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000076c5e9980> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:196)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025)
at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:424)
at io.netty.util.concurrent.SingleThreadEventExecutor.takeTask(SingleThreadEventExecutor.java:235)
at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:34)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
at java.lang.Thread.run(Thread.java:662)
[ ~]$ cat jstack_27523_2.txt |grep --color -A10 --color 0x6cd7
"NETTYSERVER-WORKER-14-thread-1" prio=10 tid=0x00007f76d0052000
nid=0x6cd7 runnable [0x000000004da08000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x000000076c436e58> (a
io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000076c2f0990> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000076c417140> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:618)
[~]$ cat jstack_27523_2.txt |grep --color -A10 --color 0x6d3d
"NETTYSERVER-WORKER-14-thread-5" prio=10 tid=0x00007f76d05fa000
nid=0x6d3d runnable [0x000000005204e000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0x000000076c2f5a20> (a
io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000076c3c9688> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000076c035a60> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:618)
I also use systemtap to monitor epoll call every seconds
pid | poll select epoll itimer futex nanosle signal| process
27523 | 0 0 380 0 10543 0 0| java
the os is
Red Hat Enterprise Linux Server release 5.7
2.6.32-el5.x86_64
the java verison
java version "1.6.0_32"
every seonds ,the epoll only 380 ervery seconds ,why epoll method consume
lots sys,is normal?
or
how to check it is normal consum sys cpu usgae?
thanks!
--
=============================================
fuyou001
Best Regards
More information about the core-libs-dev
mailing list