[
https://issues.apache.org/jira/browse/QPIDJMS-505?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17111121#comment-17111121
]
Mario Schlipf edited comment on QPIDJMS-505 at 5/19/20, 12:11 PM:
------------------------------------------------------------------
The {{com.sun.misc.Unsafe.park}} seems to be called very often, so the CPU time
is likely spent on context switching. Digging deeper in the code from the
stacktrace I posted above, we can see how QPID uses this:
{code:java}
at sun.misc.Unsafe.park(Native Method)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at
org.apache.qpid.jms.provider.ProgressiveProviderFuture.sync(ProgressiveProviderFuture.java:143)
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:910)
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:899)
at
org.apache.qpid.jms.JmsMessageConsumer.performPullIfRequired(JmsMessageConsumer.java:726)
at
org.apache.qpid.jms.JmsMessageConsumer.dequeue(JmsMessageConsumer.java:304)
at
org.apache.qpid.jms.JmsMessageConsumer.receive(JmsMessageConsumer.java:213)
at {code}
The {{ProgressiveProviderFuture}} that is used for polling, has this piece of
code in the {{sync}} function:
{code:java}
if (idleCount < SPIN_COUNT) {
idleCount++;
} else if (idleCount < YIELD_COUNT) {
Thread.yield();
idleCount++;
} else if (idleCount < TINY_PARK_COUNT) {
LockSupport.parkNanos(tinyParkNanos);
idleCount++;
} else if (idleCount < SMALL_PARK_COUNT) {
LockSupport.parkNanos(smallParkNanos);
idleCount++;
} else {
synchronized (this) {
if (isComplete()) {
failOnError();
return true;
} waiting++;
try {
wait(-diff / 1000000, (int) (-diff % 1000000));
} finally {
waiting--;
}
}
}{code}
Relevant fields:
{code:java}
private static final int SPIN_COUNT = 10;
private static final int YIELD_COUNT = 100;
private static final int TINY_PARK_COUNT = 1000;
private static final int TINY_PARK_NANOS = 1;
private static final int SMALL_PARK_COUNT = 101_000;
private static final int SMALL_PARK_NANOS = 10_000;{code}
So it calls the {{LockSupport.parkNanos}} thousands of times within 10
seconds.Also, the strategy which provider future (apart from progressive, there
is conservative and balanced) is not configurable:
{code:java}
if (futureTypeKey == null || futureTypeKey.isEmpty()) {
if (Runtime.getRuntime().availableProcessors() < 4) {
return new ConservativeProviderFutureFactory();
} else if (isWindows()) {
return new BalancedProviderFutureFactory();
} else {
return new ProgressiveProviderFutureFactory();
}
}
{code}
({{futureTypeKey}} is always \{{null }}it seems)
We are not running on Windows and the available processors are >= 4.
was (Author: marioschlipf):
The {{com.sun.misc.Unsafe.park}} seems to be called very often, so the CPU time
is spent likely spent on context switching. Digging deeper in the code from the
stacktrace I posted above, we can see how QPID uses this:
{code:java}
at sun.misc.Unsafe.park(Native Method)
at
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at
org.apache.qpid.jms.provider.ProgressiveProviderFuture.sync(ProgressiveProviderFuture.java:143)
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:910)
at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:899)
at
org.apache.qpid.jms.JmsMessageConsumer.performPullIfRequired(JmsMessageConsumer.java:726)
at
org.apache.qpid.jms.JmsMessageConsumer.dequeue(JmsMessageConsumer.java:304)
at
org.apache.qpid.jms.JmsMessageConsumer.receive(JmsMessageConsumer.java:213)
at {code}
The {{ProgressiveProviderFuture}} that is used for polling, has this piece of
code in the {{sync}} function:
{code:java}
if (idleCount < SPIN_COUNT) {
idleCount++;
} else if (idleCount < YIELD_COUNT) {
Thread.yield();
idleCount++;
} else if (idleCount < TINY_PARK_COUNT) {
LockSupport.parkNanos(tinyParkNanos);
idleCount++;
} else if (idleCount < SMALL_PARK_COUNT) {
LockSupport.parkNanos(smallParkNanos);
idleCount++;
} else {
synchronized (this) {
if (isComplete()) {
failOnError();
return true;
} waiting++;
try {
wait(-diff / 1000000, (int) (-diff % 1000000));
} finally {
waiting--;
}
}
}{code}
Relevant fields:
{code:java}
private static final int SPIN_COUNT = 10;
private static final int YIELD_COUNT = 100;
private static final int TINY_PARK_COUNT = 1000;
private static final int TINY_PARK_NANOS = 1;
private static final int SMALL_PARK_COUNT = 101_000;
private static final int SMALL_PARK_NANOS = 10_000;{code}
So it calls the {{LockSupport.parkNanos}} thousands of times within 10
seconds.Also, the strategy which provider future (apart from progressive, there
is conservative and balanced) is not configurable:
{code:java}
if (futureTypeKey == null || futureTypeKey.isEmpty()) {
if (Runtime.getRuntime().availableProcessors() < 4) {
return new ConservativeProviderFutureFactory();
} else if (isWindows()) {
return new BalancedProviderFutureFactory();
} else {
return new ProgressiveProviderFutureFactory();
}
}
{code}
({{futureTypeKey}} is always \{{null }}it seems)
We are not running on Windows and the available processors are >= 4.
> High CPU usage through ProgressiveProviderFuture
> ------------------------------------------------
>
> Key: QPIDJMS-505
> URL: https://issues.apache.org/jira/browse/QPIDJMS-505
> Project: Qpid JMS
> Issue Type: Bug
> Components: qpid-jms-client
> Affects Versions: 0.51.0
> Reporter: Mario Schlipf
> Priority: Major
>
> We are using QPID JMS in combination with Sping Boot to set up JMS listeners
> on queues.
> We are experiencing high CPU loads from the Spring listener threads, about
> 20% CPU usage per thread. We have done some investigations and using a
> profiler, 92% of that CPU time seems to go into `sun.misc.Unsafe.park`, see
> below stacktrace:
> {code:java}
> at sun.misc.Unsafe.park(Native Method)
> at
> java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
> at
> org.apache.qpid.jms.provider.ProgressiveProviderFuture.sync(ProgressiveProviderFuture.java:143)
> at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:910)
> at org.apache.qpid.jms.JmsConnection.pull(JmsConnection.java:899)
> at
> org.apache.qpid.jms.JmsMessageConsumer.performPullIfRequired(JmsMessageConsumer.java:726)
> at
> org.apache.qpid.jms.JmsMessageConsumer.dequeue(JmsMessageConsumer.java:304)
> at
> org.apache.qpid.jms.JmsMessageConsumer.receive(JmsMessageConsumer.java:213)
> at
> org.springframework.jms.support.destination.JmsDestinationAccessor.receiveFromConsumer(JmsDestinationAccessor.java:132)
> at
> org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:418)
> at
> org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:303)
> at
> org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:257)
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1190)
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1180)
> at
> org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:1077)
> at java.lang.Thread.run(Thread.java:747)
> {code}
> We see the high CPU load also reported using a simple `top` command.
> I would expect that the `Unsafe.park` puts the thread into a waiting state,
> i.e. not consuming further resources.
> We have migrated to ActiveMQ JMS for a test and cannot see the same CPU usage.
>
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
