apache ignite atomicLong.incrementAndGet() is causing starvation in striped pool

classic Classic list List threaded Threaded
3 messages Options
vvasyuk vvasyuk
Reply | Threaded
Open this post in threaded view
|

apache ignite atomicLong.incrementAndGet() is causing starvation in striped pool

Hi All,

I have Ignite cluster which consists of two nodes. Each node after start creates a continuous query which calls atomicLong.incrementAndGet() in "onUpdated" method:

        continuousQuery.setLocalListener(new CacheEntryUpdatedListener<Integer, String>() {
            @Override public void onUpdated(Iterable<CacheEntryEvent<? extends Integer, ? extends String>> evts) {
                for (CacheEntryEvent<? extends Integer, ? extends String> e : evts){
                    System.out.println("Incremented value: " + atomicLong.incrementAndGet());
                }
            }
        });

This continuous query is listening on all events on "test" cache.
I start both nodes and then start a client application which inserts 5 entries into "test" cache. For the first two entries (which client inserts) I see below outputs only on one node:
Incremented value: 1
Incremented value: 2

And after that I get below warn messages in logs on the node where "Incremented value" was printed (on the second node I see no messages) :

2018-07-09 21:56:57.993  WARN 1876 --- [eout-worker-#23] o.apache.ignite.internal.util.typedef.G  : >>> Possible starvation in striped pool.
    Thread name: sys-stripe-0-#1
    Queue: []
    Deadlock: false
    Completed: 1
Thread [name="sys-stripe-0-#1", id=14, state=WAITING, blockCnt=0, waitCnt=5]
        at sun.misc.Unsafe.park(Native Method)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
        at o.a.i.i.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:177)
        at o.a.i.i.util.future.GridFutureAdapter.get(GridFutureAdapter.java:140)
        at o.a.i.i.processors.cache.GridCacheAdapter$25.op(GridCacheAdapter.java:2492)
        at o.a.i.i.processors.cache.GridCacheAdapter$25.op(GridCacheAdapter.java:2478)
        at o.a.i.i.processors.cache.GridCacheAdapter.syncOp(GridCacheAdapter.java:4088)
        at o.a.i.i.processors.cache.GridCacheAdapter.invoke0(GridCacheAdapter.java:2478)
        at o.a.i.i.processors.cache.GridCacheAdapter.invoke(GridCacheAdapter.java:2456)
        at o.a.i.i.processors.cache.GridCacheProxyImpl.invoke(GridCacheProxyImpl.java:588)
        at o.a.i.i.processors.datastructures.GridCacheAtomicLongImpl.incrementAndGet(GridCacheAtomicLongImpl.java:98)
        at com.ignite.config.ServerConfig$2.onUpdated(ServerConfig.java:80)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler.onEntryUpdate(CacheContinuousQueryHandler.java:835)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler.access$700(CacheContinuousQueryHandler.java:82)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler$1$1.apply(CacheContinuousQueryHandler.java:420)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler$1$1.apply(CacheContinuousQueryHandler.java:415)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDone(GridDhtAtomicAbstractUpdateFuture.java:556)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDone(GridDhtAtomicAbstractUpdateFuture.java:61)
        at o.a.i.i.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:440)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.registerResponse(GridDhtAtomicAbstractUpdateFuture.java:367)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDhtResponse(GridDhtAtomicAbstractUpdateFuture.java:522)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateResponse(GridDhtAtomicCache.java:3472)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$700(GridDhtAtomicCache.java:130)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:323)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:318)
        at o.a.i.i.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1060)
        at o.a.i.i.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:579)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:378)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:304)
        at o.a.i.i.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:99)
        at o.a.i.i.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:293)
        at o.a.i.i.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1555)
        at o.a.i.i.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1183)
        at o.a.i.i.managers.communication.GridIoManager.access$4200(GridIoManager.java:126)
        at o.a.i.i.managers.communication.GridIoManager$9.run(GridIoManager.java:1090)
        at o.a.i.i.util.StripedExecutor$Stripe.run(StripedExecutor.java:505)
        at java.lang.Thread.run(Thread.java:748)
After that I see:

2018-07-09 21:56:57.887  WARN 1876 --- [eout-worker-#23] org.apache.ignite.internal.diagnostic    : Found long running transaction
and
2018-07-09 21:57:58.021  WARN 1876 --- [eout-worker-#23] org.apache.ignite.internal.diagnostic    : Found long running cache future

Please help me understand if my way of using atomicLong is incorrect or there is something else?

Thank you in advance for assistence.

--
Sincerely Yours
Vadim Vasyuk
slava.koptilin slava.koptilin
Reply | Threaded
Open this post in threaded view
|

Re: apache ignite atomicLong.incrementAndGet() is causing starvation in striped pool

Hello Vadym,

The root cause of the behavior is that you are trying to use `IgniteAtomicLong` instance within `ContinuousQuery` local listener.
In general, you should avoid using cache operations in that listener ( `IgniteAtomicLong` uses IgniteCache under the hood),
because this callback is invoked from a sensitive part of implementation in a synchronous way and therefore, it may lead to starvation and/or deadlocks.

In order to resolve this issue, you can use @IgniteAsyncCallback annotation, it allows executing callback methods in the AsyncCallback thread pool.
Please try the following approach:

@IgniteAsyncCallback
public class MyLocalListener implements CacheEntryUpdatedListener<Integer, String> {
@Override public void onUpdated(
Iterable<CacheEntryEvent<? extends Integer, ? extends String>> events) throws CacheEntryListenerException {

...
}
}
continuousQuery.setLocalListener(new MyLocalListener());
Thanks,
Slava.


пн, 9 июл. 2018 г. в 22:19, Vadym Vasiuk <[hidden email]>:
Hi All,

I have Ignite cluster which consists of two nodes. Each node after start creates a continuous query which calls atomicLong.incrementAndGet() in "onUpdated" method:

        continuousQuery.setLocalListener(new CacheEntryUpdatedListener<Integer, String>() {
            @Override public void onUpdated(Iterable<CacheEntryEvent<? extends Integer, ? extends String>> evts) {
                for (CacheEntryEvent<? extends Integer, ? extends String> e : evts){
                    System.out.println("Incremented value: " + atomicLong.incrementAndGet());
                }
            }
        });

This continuous query is listening on all events on "test" cache.
I start both nodes and then start a client application which inserts 5 entries into "test" cache. For the first two entries (which client inserts) I see below outputs only on one node:
Incremented value: 1
Incremented value: 2

And after that I get below warn messages in logs on the node where "Incremented value" was printed (on the second node I see no messages) :

2018-07-09 21:56:57.993  WARN 1876 --- [eout-worker-#23] o.apache.ignite.internal.util.typedef.G  : >>> Possible starvation in striped pool.
    Thread name: sys-stripe-0-#1
    Queue: []
    Deadlock: false
    Completed: 1
Thread [name="sys-stripe-0-#1", id=14, state=WAITING, blockCnt=0, waitCnt=5]
        at sun.misc.Unsafe.park(Native Method)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
        at o.a.i.i.util.future.GridFutureAdapter.get0(GridFutureAdapter.java:177)
        at o.a.i.i.util.future.GridFutureAdapter.get(GridFutureAdapter.java:140)
        at o.a.i.i.processors.cache.GridCacheAdapter$25.op(GridCacheAdapter.java:2492)
        at o.a.i.i.processors.cache.GridCacheAdapter$25.op(GridCacheAdapter.java:2478)
        at o.a.i.i.processors.cache.GridCacheAdapter.syncOp(GridCacheAdapter.java:4088)
        at o.a.i.i.processors.cache.GridCacheAdapter.invoke0(GridCacheAdapter.java:2478)
        at o.a.i.i.processors.cache.GridCacheAdapter.invoke(GridCacheAdapter.java:2456)
        at o.a.i.i.processors.cache.GridCacheProxyImpl.invoke(GridCacheProxyImpl.java:588)
        at o.a.i.i.processors.datastructures.GridCacheAtomicLongImpl.incrementAndGet(GridCacheAtomicLongImpl.java:98)
        at com.ignite.config.ServerConfig$2.onUpdated(ServerConfig.java:80)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler.onEntryUpdate(CacheContinuousQueryHandler.java:835)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler.access$700(CacheContinuousQueryHandler.java:82)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler$1$1.apply(CacheContinuousQueryHandler.java:420)
        at o.a.i.i.processors.cache.query.continuous.CacheContinuousQueryHandler$1$1.apply(CacheContinuousQueryHandler.java:415)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDone(GridDhtAtomicAbstractUpdateFuture.java:556)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDone(GridDhtAtomicAbstractUpdateFuture.java:61)
        at o.a.i.i.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:440)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.registerResponse(GridDhtAtomicAbstractUpdateFuture.java:367)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicAbstractUpdateFuture.onDhtResponse(GridDhtAtomicAbstractUpdateFuture.java:522)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.processDhtAtomicUpdateResponse(GridDhtAtomicCache.java:3472)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache.access$700(GridDhtAtomicCache.java:130)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:323)
        at o.a.i.i.processors.cache.distributed.dht.atomic.GridDhtAtomicCache$8.apply(GridDhtAtomicCache.java:318)
        at o.a.i.i.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1060)
        at o.a.i.i.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:579)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:378)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:304)
        at o.a.i.i.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:99)
        at o.a.i.i.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:293)
        at o.a.i.i.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1555)
        at o.a.i.i.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1183)
        at o.a.i.i.managers.communication.GridIoManager.access$4200(GridIoManager.java:126)
        at o.a.i.i.managers.communication.GridIoManager$9.run(GridIoManager.java:1090)
        at o.a.i.i.util.StripedExecutor$Stripe.run(StripedExecutor.java:505)
        at java.lang.Thread.run(Thread.java:748)
After that I see:

2018-07-09 21:56:57.887  WARN 1876 --- [eout-worker-#23] org.apache.ignite.internal.diagnostic    : Found long running transaction
and
2018-07-09 21:57:58.021  WARN 1876 --- [eout-worker-#23] org.apache.ignite.internal.diagnostic    : Found long running cache future

Please help me understand if my way of using atomicLong is incorrect or there is something else?

Thank you in advance for assistence.

--
Sincerely Yours
Vadim Vasyuk
vvasyuk vvasyuk
Reply | Threaded
Open this post in threaded view
|

Re: apache ignite atomicLong.incrementAndGet() is causing starvation in striped pool

Hello Slava,

Thank you for reply. Will try your solution.



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/