You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by Skollur <Sk...@idbny.com> on 2018/11/23 18:57:22 UTC
Ignite Query Slow
Hello
I have ignite server running with 2 nodes. Each node has 30 cache stores
with one table in each with REPLICATE configured. Found query is taking
longer to return when simultaneous 100 requests were sent to ignite. In the
first iteration the query is quick. But as number of hits more, same query
with different parameter takes longer. Note I have INDEX for each of joins
and query is quick for one request and takes about 400 milli seconds and
same query takes longer when multiple simultaneous requests. Is there any
solution?
Thanks
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Discovery is a basic functionality, that is needed for clustering. You can
try to implement your own DiscoverySpi, which will do absolutely nothing,
but do you really want it?
вт, 11 дек. 2018 г. в 13:42, Skollur <Sk...@idbny.com>:
> is there anyway i can run ignite on machine and port without discovery?
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
is there anyway i can run ignite on machine and port without discovery?
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Port 10800 is used by Ignite for thin clients by default, looks like it was
bound earlier on this machine. But why do you want to use 10800 for
discovery?
вт, 11 дек. 2018 г. в 13:09, Skollur <Sk...@idbny.com>:
> It is different machine. Wondering why not able to use same port? I have
> put
> the IP and port for each node in different machine.
>
> Machine 1: node
> discovery.setLocalAddress("192.2.2.1");
> discovery.setLocalPort(new Integer("10800")));
>
> Machine 2: node
> discovery.setLocalAddress("192.2.2.2");
> discovery.setLocalPort(new Integer("10800")));
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
It is different machine. Wondering why not able to use same port? I have put
the IP and port for each node in different machine.
Machine 1: node
discovery.setLocalAddress("192.2.2.1");
discovery.setLocalPort(new Integer("10800")));
Machine 2: node
discovery.setLocalAddress("192.2.2.2");
discovery.setLocalPort(new Integer("10800")));
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
There is also a portRange property, which is set to 100 by default. If the
first address is already occupied, then discovery will try to bind to the
next one.
вт, 11 дек. 2018 г. в 12:14, Skollur <Sk...@idbny.com>:
> I have following code in node1 ->
> TcpDiscoverySpi discovery = new TcpDiscoverySpi();
> discovery.setLocalAddress("192.2.2.1");
> discovery.setLocalPort(new Integer("10800")));
> cfg.setDiscoverySpi(discovery);
>
>
> and node 2 ->
> TcpDiscoverySpi discovery = new TcpDiscoverySpi();
> discovery.setLocalAddress("192.2.2.2");
> discovery.setLocalPort(new Integer("10800")));
> cfg.setDiscoverySpi(discovery);
>
>
> But I see node2 is starting in port 10801 and not 10800. How this is
> possible?
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
I have following code in node1 ->
TcpDiscoverySpi discovery = new TcpDiscoverySpi();
discovery.setLocalAddress("192.2.2.1");
discovery.setLocalPort(new Integer("10800")));
cfg.setDiscoverySpi(discovery);
and node 2 ->
TcpDiscoverySpi discovery = new TcpDiscoverySpi();
discovery.setLocalAddress("192.2.2.2");
discovery.setLocalPort(new Integer("10800")));
cfg.setDiscoverySpi(discovery);
But I see node2 is starting in port 10801 and not 10800. How this is
possible?
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
In case, when you have replicated cache and you connected with thin client
only to one of them, it decides that it can perform query on the one node
only, because all data can be found locally. You can try to connect a
different client to the different node and divide all queries into 2
clients.
Evgenii
пн, 10 дек. 2018 г. в 20:11, Skollur <Sk...@idbny.com>:
> sql-performance.PNG
> <
> http://apache-ignite-users.70518.x6.nabble.com/file/t1867/sql-performance.PNG>
>
> enclosed sql performance time.
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
sql-performance.PNG
<http://apache-ignite-users.70518.x6.nabble.com/file/t1867/sql-performance.PNG>
enclosed sql performance time.
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Ok..Will 2 nodes helps? I saw only one node is busy most of time since I have
configured as REPLICATE and also found that REPLICATE is faster in multi
join queries than PARTITIONED in my case. Is there anyway REPLICATE (with 2
nodes) take loads equally among 2 nodes?
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
It should be better, I'd recommend using the default value - it will be
calculated based on the cores count.
пн, 10 дек. 2018 г. в 10:56, Skollur <Sk...@idbny.com>:
> How about 6 cores. Will that help? In that case what is the thread counts?
>
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
How about 6 cores. Will that help? In that case what is the thread counts?
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
2 cores are just not enough for 100 running simultaneously queries, of
course, you will see a lot of context-switching, which will lead to the
slowness of the part of queries.
пн, 10 дек. 2018 г. в 10:35, Skollur <Sk...@idbny.com>:
> Enclosed CPU/Thread usage. Ignite became super slow after applying
> below. I
> am still not sure how many threads are required to span 100 queries
> simultaneously. I am seeing CPU is hitting almost 100%.
>
> cfg.setQueryThreadPoolSize(16);
> cfg.setSystemThreadPoolSize(16);
> cfg.setPublicThreadPoolSize(16);
> cfg.setServiceThreadPoolSize(16);
> cfg.setRebalanceThreadPoolSize(10);
>
> Will below helps?
> //ccfg.setSqlOnheapCacheEnabled(true); //ccfg.setOnheapCacheEnabled(true);
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Enclosed CPU/Thread usage. Ignite became super slow after applying below. I
am still not sure how many threads are required to span 100 queries
simultaneously. I am seeing CPU is hitting almost 100%.
cfg.setQueryThreadPoolSize(16);
cfg.setSystemThreadPoolSize(16);
cfg.setPublicThreadPoolSize(16);
cfg.setServiceThreadPoolSize(16);
cfg.setRebalanceThreadPoolSize(10);
Will below helps?
//ccfg.setSqlOnheapCacheEnabled(true); //ccfg.setOnheapCacheEnabled(true);
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Thank you for reply. I have 2 core, 20 GB memory space allocated for Ignite
cache. My data size is about 3 to 4 GB. I have batch process(multi
threaded) where simultaneously 100 requests sends to ignite cache (same
query with different parameters for each request).
What is the recommended thread pool size for 100 requests at a time? Is just
setQueryThreadPoolSize(16) is enough or do I need to increase or any other
parameter needs to be considered?
After your reply, I have setup as below and can you please let me know if
anything missing here or to be added? Thanks for your help.
cfg.setQueryThreadPoolSize(16);
cfg.setSystemThreadPoolSize(16);
cfg.setPublicThreadPoolSize(16);
cfg.setServiceThreadPoolSize(16);
cfg.setRebalanceThreadPoolSize(10);
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Hi,
I'd say that it's normal to have bigger latency in the case when you
starting more queries simultaneously than you have threads in query pool(
https://apacheignite.readme.io/docs/thread-pools#section-queries-pool) and
cores) Some of the queries will wait till other will finish.
As for the thing that only one node was busy - you have replicated caches,
so, there is no need to search on a different node, it's enough just to
collect all data on the one. Instead of connecting to the one node only you
can connect drivers to the different nodes, not only to one.
By the way, how do you start 100 requests simultaneously? Do you run them
from one machine? You can have slowdown even on this step, since you
probably have fewer cores than the threads count.
Evgenii
чт, 6 дек. 2018 г. в 11:31, Skollur <Sk...@idbny.com>:
> Currently I have only one node and other node is idle and brought it down.
> I have noticed that only one node is busy and I have code as below.
>
> IgniteConfiguration cfg = new IgniteConfiguration();
> TcpDiscoverySpi discovery = new TcpDiscoverySpi();
> discovery.setLocalAddress("192.0.1.2");
> discovery.setLocalPort(10800);
> cfg.setDiscoverySpi(discovery);
> cfg.setPeerClassLoadingEnabled(true);
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Currently I have only one node and other node is idle and brought it down.
I have noticed that only one node is busy and I have code as below.
IgniteConfiguration cfg = new IgniteConfiguration();
TcpDiscoverySpi discovery = new TcpDiscoverySpi();
discovery.setLocalAddress("192.0.1.2");
discovery.setLocalPort(10800);
cfg.setDiscoverySpi(discovery);
cfg.setPeerClassLoadingEnabled(true);
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
do you have gc logs from an another node?
вт, 4 дек. 2018 г. в 12:14, Skollur <Sk...@idbny.com>:
> Ignite.zip
> <http://apache-ignite-users.70518.x6.nabble.com/file/t1867/Ignite.zip>
> Ignite is using high CPU and enclosed high CPU profile. Let me know if you
> need any further information to help us on this.
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Ignite.zip
<http://apache-ignite-users.70518.x6.nabble.com/file/t1867/Ignite.zip>
Ignite is using high CPU and enclosed high CPU profile. Let me know if you
need any further information to help us on this.
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Attached.
Thanks gclog.zip
<http://apache-ignite-users.70518.x6.nabble.com/file/t1867/gclog.zip>
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Evgenii Zhuravlev <e....@gmail.com>.
Can you attach it instead of just posting to the message?
пн, 26 нояб. 2018 г. в 10:12, Skollur <Sk...@idbny.com>:
> Also attached GC->
>
> 2018-11-26T13:35:23.058-0500: 1172.703: [GC pause (G1 Evacuation Pause)
> (young), 0.0070730 secs]
> [Parallel Time: 6.3 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1172702.9, Avg: 1172703.3, Max:
> 1172703.7,
> Diff: 0.8]
> [Ext Root Scanning (ms): Min: 1.1, Avg: 1.4, Max: 1.7, Diff: 0.7,
> Sum:
> 2.8]
> [Update RS (ms): Min: 0.6, Avg: 0.7, Max: 0.7, Diff: 0.1, Sum: 1.3]
> [Processed Buffers: Min: 5, Avg: 7.0, Max: 9, Diff: 4, Sum: 14]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.4, Avg: 3.4, Max: 3.5, Diff: 0.1, Sum: 6.9]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.4, Avg: 5.8, Max: 6.2, Diff: 0.8, Sum:
> 11.6]
> [GC Worker End (ms): Min: 1172709.1, Avg: 1172709.1, Max: 1172709.1,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 296.0M(296.0M)->0.0B(294.0M) Survivors: 3072.0K->4096.0K Heap:
> 456.9M(512.0M)->161.4M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.00 secs]
> 2018-11-26T13:35:23.305-0500: 1172.950: [GC pause (G1 Evacuation Pause)
> (young), 0.0065406 secs]
> [Parallel Time: 5.8 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1172950.3, Avg: 1172950.3, Max:
> 1172950.3,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.5, Diff: 0.0,
> Sum:
> 2.9]
> [Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.6, Diff: 0.0, Sum: 1.1]
> [Processed Buffers: Min: 3, Avg: 5.0, Max: 7, Diff: 4, Sum: 10]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.3]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.4, Avg: 3.4, Max: 3.4, Diff: 0.0, Sum: 6.8]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.7, Avg: 5.7, Max: 5.7, Diff: 0.0, Sum:
> 11.4]
> [GC Worker End (ms): Min: 1172956.0, Avg: 1172956.0, Max: 1172956.0,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 294.0M(294.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
> 455.4M(512.0M)->161.5M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:23.590-0500: 1173.235: [GC pause (G1 Evacuation Pause)
> (young), 0.0068220 secs]
> [Parallel Time: 6.1 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1173235.1, Avg: 1173235.2, Max:
> 1173235.2,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.5, Max: 1.6, Diff: 0.1,
> Sum:
> 3.0]
> [Update RS (ms): Min: 0.6, Avg: 0.6, Max: 0.7, Diff: 0.1, Sum: 1.3]
> [Processed Buffers: Min: 6, Avg: 7.0, Max: 8, Diff: 2, Sum: 14]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.4, Avg: 3.5, Max: 3.5, Diff: 0.1, Sum: 6.9]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.9, Avg: 5.9, Max: 5.9, Diff: 0.0, Sum:
> 11.8]
> [GC Worker End (ms): Min: 1173241.0, Avg: 1173241.0, Max: 1173241.0,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.1 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.0 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
> 454.5M(512.0M)->161.6M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.00 secs]
> 2018-11-26T13:35:23.922-0500: 1173.567: [GC pause (G1 Evacuation Pause)
> (young), 0.0075437 secs]
> [Parallel Time: 6.6 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1173567.5, Avg: 1173567.5, Max:
> 1173567.5,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.5, Avg: 1.5, Max: 1.6, Diff: 0.1,
> Sum:
> 3.1]
> [Update RS (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 1.3]
> [Processed Buffers: Min: 1, Avg: 4.0, Max: 7, Diff: 6, Sum: 8]
> [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.8, Avg: 3.8, Max: 3.9, Diff: 0.1, Sum: 7.7]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 6.3, Avg: 6.3, Max: 6.3, Diff: 0.0, Sum:
> 12.6]
> [GC Worker End (ms): Min: 1173573.8, Avg: 1173573.8, Max: 1173573.8,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.8 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.3 ms]
> [Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
> 454.6M(512.0M)->161.6M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:24.209-0500: 1173.855: [GC pause (G1 Evacuation Pause)
> (young), 0.0065890 secs]
> [Parallel Time: 5.8 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1173854.8, Avg: 1173854.8, Max:
> 1173854.8,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0,
> Sum:
> 2.8]
> [Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.0]
> [Processed Buffers: Min: 2, Avg: 5.0, Max: 8, Diff: 6, Sum: 10]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.3, Avg: 3.3, Max: 3.3, Diff: 0.0, Sum: 6.7]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.6, Avg: 5.6, Max: 5.6, Diff: 0.0, Sum:
> 11.1]
> [GC Worker End (ms): Min: 1173860.3, Avg: 1173860.3, Max: 1173860.3,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.1 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.1 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
> 454.6M(512.0M)->161.7M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.00 secs]
> 2018-11-26T13:35:24.504-0500: 1174.149: [GC pause (G1 Evacuation Pause)
> (young), 0.0069335 secs]
> [Parallel Time: 6.2 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1174148.9, Avg: 1174148.9, Max:
> 1174148.9,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0,
> Sum:
> 2.8]
> [Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.7, Diff: 0.0, Sum: 1.3]
> [Processed Buffers: Min: 3, Avg: 5.0, Max: 7, Diff: 4, Sum: 10]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.3]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.5, Avg: 3.5, Max: 3.5, Diff: 0.0, Sum: 7.1]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.0]
> [GC Worker Total (ms): Min: 5.9, Avg: 5.9, Max: 5.9, Diff: 0.0, Sum:
> 11.8]
> [GC Worker End (ms): Min: 1174154.8, Avg: 1174154.8, Max: 1174154.8,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.1 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
> 454.7M(512.0M)->162.4M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:24.804-0500: 1174.449: [GC pause (G1 Evacuation Pause)
> (young), 0.0073623 secs]
> [Parallel Time: 6.3 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1174449.1, Avg: 1174449.2, Max:
> 1174449.2,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0,
> Sum:
> 2.8]
> [Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.8, Diff: 0.1, Sum: 1.4]
> [Processed Buffers: Min: 3, Avg: 7.0, Max: 11, Diff: 8, Sum: 14]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.7, Avg: 3.7, Max: 3.7, Diff: 0.0, Sum: 7.4]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 6.1, Avg: 6.1, Max: 6.1, Diff: 0.0, Sum:
> 12.2]
> [GC Worker End (ms): Min: 1174455.3, Avg: 1174455.3, Max: 1174455.3,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.4 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.3 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.0 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 293.0M(293.0M)->0.0B(292.0M) Survivors: 4096.0K->4096.0K Heap:
> 455.4M(512.0M)->162.6M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:25.102-0500: 1174.747: [GC pause (G1 Evacuation Pause)
> (young), 0.0110492 secs]
> [Parallel Time: 10.3 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1174747.0, Avg: 1174750.4, Max:
> 1174753.7,
> Diff: 6.6]
> [Ext Root Scanning (ms): Min: 0.0, Avg: 1.3, Max: 2.7, Diff: 2.6,
> Sum:
> 2.7]
> [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.1, Diff: 2.1, Sum: 2.1]
> [Processed Buffers: Min: 0, Avg: 7.0, Max: 14, Diff: 14, Sum: 14]
> [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.3]
> [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.5, Avg: 4.3, Max: 5.0, Diff: 1.5, Sum: 8.5]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.0]
> [GC Worker Total (ms): Min: 3.6, Avg: 6.9, Max: 10.2, Diff: 6.6, Sum:
> 13.8]
> [GC Worker End (ms): Min: 1174757.3, Avg: 1174757.3, Max: 1174757.3,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 292.0M(292.0M)->0.0B(292.0M) Survivors: 4096.0K->4096.0K Heap:
> 454.6M(512.0M)->163.0M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:25.387-0500: 1175.032: [GC pause (G1 Evacuation Pause)
> (young), 0.0063483 secs]
> [Parallel Time: 5.5 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1175032.0, Avg: 1175032.0, Max:
> 1175032.1,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.3, Avg: 1.4, Max: 1.5, Diff: 0.1,
> Sum:
> 2.8]
> [Update RS (ms): Min: 0.7, Avg: 0.8, Max: 0.8, Diff: 0.0, Sum: 1.5]
> [Processed Buffers: Min: 1, Avg: 5.5, Max: 10, Diff: 9, Sum: 11]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 2.9, Avg: 3.0, Max: 3.0, Diff: 0.1, Sum: 6.0]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.0]
> [GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.4, Diff: 0.0, Sum:
> 10.8]
> [GC Worker End (ms): Min: 1175037.5, Avg: 1175037.5, Max: 1175037.5,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.1 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.1 ms]
> [Humongous Register: 0.1 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 292.0M(292.0M)->0.0B(294.0M) Survivors: 4096.0K->3072.0K Heap:
> 455.0M(512.0M)->162.7M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:25.602-0500: 1175.247: [GC pause (G1 Evacuation Pause)
> (young), 0.0069090 secs]
> [Parallel Time: 6.0 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1175247.3, Avg: 1175247.3, Max:
> 1175247.3,
> Diff: 0.0]
> [Ext Root Scanning (ms): Min: 1.4, Avg: 1.5, Max: 1.6, Diff: 0.2,
> Sum:
> 3.0]
> [Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.7, Diff: 0.0, Sum: 1.4]
> [Processed Buffers: Min: 1, Avg: 7.0, Max: 13, Diff: 12, Sum: 14]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.5]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.2, Avg: 3.3, Max: 3.4, Diff: 0.2, Sum: 6.5]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.8, Avg: 5.8, Max: 5.9, Diff: 0.0, Sum:
> 11.7]
> [GC Worker End (ms): Min: 1175253.1, Avg: 1175253.1, Max: 1175253.1,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.2 ms]
> [Other: 0.7 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.0 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.3 ms]
> [Eden: 294.0M(294.0M)->0.0B(292.0M) Survivors: 3072.0K->4096.0K Heap:
> 456.7M(512.0M)->163.3M(512.0M)]
> [Times: user=0.02 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:25.807-0500: 1175.452: [GC pause (G1 Evacuation Pause)
> (young), 0.0065281 secs]
> [Parallel Time: 5.7 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1175452.1, Avg: 1175452.4, Max:
> 1175452.7,
> Diff: 0.6]
> [Ext Root Scanning (ms): Min: 1.1, Avg: 1.5, Max: 1.8, Diff: 0.7,
> Sum:
> 3.0]
> [Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.5, Diff: 0.1, Sum: 1.0]
> [Processed Buffers: Min: 1, Avg: 5.0, Max: 9, Diff: 8, Sum: 10]
> [Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
> Sum: 0.2]
> [Object Copy (ms): Min: 3.0, Avg: 3.1, Max: 3.1, Diff: 0.1, Sum: 6.1]
> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.1]
> [GC Worker Total (ms): Min: 5.1, Avg: 5.3, Max: 5.6, Diff: 0.6, Sum:
> 10.7]
> [GC Worker End (ms): Min: 1175457.7, Avg: 1175457.7, Max: 1175457.7,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.2 ms]
> [Other: 0.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.0 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 292.0M(292.0M)->0.0B(293.0M) Survivors: 4096.0K->3072.0K Heap:
> 455.3M(512.0M)->163.3M(512.0M)]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
> 2018-11-26T13:35:26.012-0500: 1175.657: [GC pause (G1 Evacuation Pause)
> (young), 0.0124949 secs]
> [Parallel Time: 11.7 ms, GC Workers: 2]
> [GC Worker Start (ms): Min: 1175657.0, Avg: 1175662.3, Max:
> 1175667.7,
> Diff: 10.7]
> [Ext Root Scanning (ms): Min: 0.0, Avg: 1.6, Max: 3.1, Diff: 3.1,
> Sum:
> 3.2]
> [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.0, Diff: 2.0, Sum: 2.0]
> [Processed Buffers: Min: 0, Avg: 6.0, Max: 12, Diff: 12, Sum: 12]
> [Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.4]
> [Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
> Sum: 0.2]
> [Object Copy (ms): Min: 0.5, Avg: 3.2, Max: 6.0, Diff: 5.4, Sum: 6.5]
> [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 0.4]
> [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
> [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
> 0.0]
> [GC Worker Total (ms): Min: 1.0, Avg: 6.3, Max: 11.6, Diff: 10.6,
> Sum:
> 12.6]
> [GC Worker End (ms): Min: 1175668.6, Avg: 1175668.6, Max: 1175668.7,
> Diff: 0.0]
> [Code Root Fixup: 0.0 ms]
> [Code Root Purge: 0.0 ms]
> [Clear CT: 0.2 ms]
> [Other: 0.6 ms]
> [Choose CSet: 0.0 ms]
> [Ref Proc: 0.2 ms]
> [Ref Enq: 0.0 ms]
> [Redirty Cards: 0.0 ms]
> [Humongous Register: 0.0 ms]
> [Humongous Reclaim: 0.0 ms]
> [Free CSet: 0.2 ms]
> [Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 3072.0K->3072.0K Heap:
> 456.3M(512.0M)->163.8M(512.0M)]
> [Times: user=0.01 sys=0.01, real=0.01 secs]
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Also attached GC->
2018-11-26T13:35:23.058-0500: 1172.703: [GC pause (G1 Evacuation Pause)
(young), 0.0070730 secs]
[Parallel Time: 6.3 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1172702.9, Avg: 1172703.3, Max: 1172703.7,
Diff: 0.8]
[Ext Root Scanning (ms): Min: 1.1, Avg: 1.4, Max: 1.7, Diff: 0.7, Sum:
2.8]
[Update RS (ms): Min: 0.6, Avg: 0.7, Max: 0.7, Diff: 0.1, Sum: 1.3]
[Processed Buffers: Min: 5, Avg: 7.0, Max: 9, Diff: 4, Sum: 14]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.4, Avg: 3.4, Max: 3.5, Diff: 0.1, Sum: 6.9]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.4, Avg: 5.8, Max: 6.2, Diff: 0.8, Sum:
11.6]
[GC Worker End (ms): Min: 1172709.1, Avg: 1172709.1, Max: 1172709.1,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 296.0M(296.0M)->0.0B(294.0M) Survivors: 3072.0K->4096.0K Heap:
456.9M(512.0M)->161.4M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2018-11-26T13:35:23.305-0500: 1172.950: [GC pause (G1 Evacuation Pause)
(young), 0.0065406 secs]
[Parallel Time: 5.8 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1172950.3, Avg: 1172950.3, Max: 1172950.3,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.5, Diff: 0.0, Sum:
2.9]
[Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.6, Diff: 0.0, Sum: 1.1]
[Processed Buffers: Min: 3, Avg: 5.0, Max: 7, Diff: 4, Sum: 10]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.4, Avg: 3.4, Max: 3.4, Diff: 0.0, Sum: 6.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.7, Avg: 5.7, Max: 5.7, Diff: 0.0, Sum:
11.4]
[GC Worker End (ms): Min: 1172956.0, Avg: 1172956.0, Max: 1172956.0,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 294.0M(294.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
455.4M(512.0M)->161.5M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:23.590-0500: 1173.235: [GC pause (G1 Evacuation Pause)
(young), 0.0068220 secs]
[Parallel Time: 6.1 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1173235.1, Avg: 1173235.2, Max: 1173235.2,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.5, Max: 1.6, Diff: 0.1, Sum:
3.0]
[Update RS (ms): Min: 0.6, Avg: 0.6, Max: 0.7, Diff: 0.1, Sum: 1.3]
[Processed Buffers: Min: 6, Avg: 7.0, Max: 8, Diff: 2, Sum: 14]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.1, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.4, Avg: 3.5, Max: 3.5, Diff: 0.1, Sum: 6.9]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.9, Avg: 5.9, Max: 5.9, Diff: 0.0, Sum:
11.8]
[GC Worker End (ms): Min: 1173241.0, Avg: 1173241.0, Max: 1173241.0,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
454.5M(512.0M)->161.6M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2018-11-26T13:35:23.922-0500: 1173.567: [GC pause (G1 Evacuation Pause)
(young), 0.0075437 secs]
[Parallel Time: 6.6 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1173567.5, Avg: 1173567.5, Max: 1173567.5,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.5, Avg: 1.5, Max: 1.6, Diff: 0.1, Sum:
3.1]
[Update RS (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 1.3]
[Processed Buffers: Min: 1, Avg: 4.0, Max: 7, Diff: 6, Sum: 8]
[Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.1, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1,
Sum: 0.2]
[Object Copy (ms): Min: 3.8, Avg: 3.8, Max: 3.9, Diff: 0.1, Sum: 7.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 6.3, Avg: 6.3, Max: 6.3, Diff: 0.0, Sum:
12.6]
[GC Worker End (ms): Min: 1173573.8, Avg: 1173573.8, Max: 1173573.8,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
454.6M(512.0M)->161.6M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:24.209-0500: 1173.855: [GC pause (G1 Evacuation Pause)
(young), 0.0065890 secs]
[Parallel Time: 5.8 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1173854.8, Avg: 1173854.8, Max: 1173854.8,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0, Sum:
2.8]
[Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.5, Diff: 0.0, Sum: 1.0]
[Processed Buffers: Min: 2, Avg: 5.0, Max: 8, Diff: 6, Sum: 10]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.3, Avg: 3.3, Max: 3.3, Diff: 0.0, Sum: 6.7]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.6, Avg: 5.6, Max: 5.6, Diff: 0.0, Sum:
11.1]
[GC Worker End (ms): Min: 1173860.3, Avg: 1173860.3, Max: 1173860.3,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
454.6M(512.0M)->161.7M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
2018-11-26T13:35:24.504-0500: 1174.149: [GC pause (G1 Evacuation Pause)
(young), 0.0069335 secs]
[Parallel Time: 6.2 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1174148.9, Avg: 1174148.9, Max: 1174148.9,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0, Sum:
2.8]
[Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.7, Diff: 0.0, Sum: 1.3]
[Processed Buffers: Min: 3, Avg: 5.0, Max: 7, Diff: 4, Sum: 10]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.5, Avg: 3.5, Max: 3.5, Diff: 0.0, Sum: 7.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.0]
[GC Worker Total (ms): Min: 5.9, Avg: 5.9, Max: 5.9, Diff: 0.0, Sum:
11.8]
[GC Worker End (ms): Min: 1174154.8, Avg: 1174154.8, Max: 1174154.8,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.1 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 4096.0K->4096.0K Heap:
454.7M(512.0M)->162.4M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:24.804-0500: 1174.449: [GC pause (G1 Evacuation Pause)
(young), 0.0073623 secs]
[Parallel Time: 6.3 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1174449.1, Avg: 1174449.2, Max: 1174449.2,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.4, Max: 1.4, Diff: 0.0, Sum:
2.8]
[Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.8, Diff: 0.1, Sum: 1.4]
[Processed Buffers: Min: 3, Avg: 7.0, Max: 11, Diff: 8, Sum: 14]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.7, Avg: 3.7, Max: 3.7, Diff: 0.0, Sum: 7.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 6.1, Avg: 6.1, Max: 6.1, Diff: 0.0, Sum:
12.2]
[GC Worker End (ms): Min: 1174455.3, Avg: 1174455.3, Max: 1174455.3,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.4 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 293.0M(293.0M)->0.0B(292.0M) Survivors: 4096.0K->4096.0K Heap:
455.4M(512.0M)->162.6M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:25.102-0500: 1174.747: [GC pause (G1 Evacuation Pause)
(young), 0.0110492 secs]
[Parallel Time: 10.3 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1174747.0, Avg: 1174750.4, Max: 1174753.7,
Diff: 6.6]
[Ext Root Scanning (ms): Min: 0.0, Avg: 1.3, Max: 2.7, Diff: 2.6, Sum:
2.7]
[Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.1, Diff: 2.1, Sum: 2.1]
[Processed Buffers: Min: 0, Avg: 7.0, Max: 14, Diff: 14, Sum: 14]
[Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
Sum: 0.2]
[Object Copy (ms): Min: 3.5, Avg: 4.3, Max: 5.0, Diff: 1.5, Sum: 8.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.0]
[GC Worker Total (ms): Min: 3.6, Avg: 6.9, Max: 10.2, Diff: 6.6, Sum:
13.8]
[GC Worker End (ms): Min: 1174757.3, Avg: 1174757.3, Max: 1174757.3,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 292.0M(292.0M)->0.0B(292.0M) Survivors: 4096.0K->4096.0K Heap:
454.6M(512.0M)->163.0M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:25.387-0500: 1175.032: [GC pause (G1 Evacuation Pause)
(young), 0.0063483 secs]
[Parallel Time: 5.5 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1175032.0, Avg: 1175032.0, Max: 1175032.1,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.3, Avg: 1.4, Max: 1.5, Diff: 0.1, Sum:
2.8]
[Update RS (ms): Min: 0.7, Avg: 0.8, Max: 0.8, Diff: 0.0, Sum: 1.5]
[Processed Buffers: Min: 1, Avg: 5.5, Max: 10, Diff: 9, Sum: 11]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 2.9, Avg: 3.0, Max: 3.0, Diff: 0.1, Sum: 6.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.0]
[GC Worker Total (ms): Min: 5.4, Avg: 5.4, Max: 5.4, Diff: 0.0, Sum:
10.8]
[GC Worker End (ms): Min: 1175037.5, Avg: 1175037.5, Max: 1175037.5,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 292.0M(292.0M)->0.0B(294.0M) Survivors: 4096.0K->3072.0K Heap:
455.0M(512.0M)->162.7M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:25.602-0500: 1175.247: [GC pause (G1 Evacuation Pause)
(young), 0.0069090 secs]
[Parallel Time: 6.0 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1175247.3, Avg: 1175247.3, Max: 1175247.3,
Diff: 0.0]
[Ext Root Scanning (ms): Min: 1.4, Avg: 1.5, Max: 1.6, Diff: 0.2, Sum:
3.0]
[Update RS (ms): Min: 0.7, Avg: 0.7, Max: 0.7, Diff: 0.0, Sum: 1.4]
[Processed Buffers: Min: 1, Avg: 7.0, Max: 13, Diff: 12, Sum: 14]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.5]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.2, Avg: 3.3, Max: 3.4, Diff: 0.2, Sum: 6.5]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.8, Avg: 5.8, Max: 5.9, Diff: 0.0, Sum:
11.7]
[GC Worker End (ms): Min: 1175253.1, Avg: 1175253.1, Max: 1175253.1,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 294.0M(294.0M)->0.0B(292.0M) Survivors: 3072.0K->4096.0K Heap:
456.7M(512.0M)->163.3M(512.0M)]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2018-11-26T13:35:25.807-0500: 1175.452: [GC pause (G1 Evacuation Pause)
(young), 0.0065281 secs]
[Parallel Time: 5.7 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1175452.1, Avg: 1175452.4, Max: 1175452.7,
Diff: 0.6]
[Ext Root Scanning (ms): Min: 1.1, Avg: 1.5, Max: 1.8, Diff: 0.7, Sum:
3.0]
[Update RS (ms): Min: 0.5, Avg: 0.5, Max: 0.5, Diff: 0.1, Sum: 1.0]
[Processed Buffers: Min: 1, Avg: 5.0, Max: 9, Diff: 8, Sum: 10]
[Scan RS (ms): Min: 0.2, Avg: 0.2, Max: 0.2, Diff: 0.0, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0,
Sum: 0.2]
[Object Copy (ms): Min: 3.0, Avg: 3.1, Max: 3.1, Diff: 0.1, Sum: 6.1]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.1]
[GC Worker Total (ms): Min: 5.1, Avg: 5.3, Max: 5.6, Diff: 0.6, Sum:
10.7]
[GC Worker End (ms): Min: 1175457.7, Avg: 1175457.7, Max: 1175457.7,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 292.0M(292.0M)->0.0B(293.0M) Survivors: 4096.0K->3072.0K Heap:
455.3M(512.0M)->163.3M(512.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
2018-11-26T13:35:26.012-0500: 1175.657: [GC pause (G1 Evacuation Pause)
(young), 0.0124949 secs]
[Parallel Time: 11.7 ms, GC Workers: 2]
[GC Worker Start (ms): Min: 1175657.0, Avg: 1175662.3, Max: 1175667.7,
Diff: 10.7]
[Ext Root Scanning (ms): Min: 0.0, Avg: 1.6, Max: 3.1, Diff: 3.1, Sum:
3.2]
[Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.0, Diff: 2.0, Sum: 2.0]
[Processed Buffers: Min: 0, Avg: 6.0, Max: 12, Diff: 12, Sum: 12]
[Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2,
Sum: 0.2]
[Object Copy (ms): Min: 0.5, Avg: 3.2, Max: 6.0, Diff: 5.4, Sum: 6.5]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 0.4]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum:
0.0]
[GC Worker Total (ms): Min: 1.0, Avg: 6.3, Max: 11.6, Diff: 10.6, Sum:
12.6]
[GC Worker End (ms): Min: 1175668.6, Avg: 1175668.6, Max: 1175668.7,
Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 0.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.2 ms]
[Eden: 293.0M(293.0M)->0.0B(293.0M) Survivors: 3072.0K->3072.0K Heap:
456.3M(512.0M)->163.8M(512.0M)]
[Times: user=0.01 sys=0.01, real=0.01 secs]
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by Skollur <Sk...@idbny.com>.
Hello
Are u suggesting to have more nodes with REPLICATE OR PARTITIONED settings?
Thanks
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Re: Ignite Query Slow
Posted by "Maxim.Pudov" <pu...@gmail.com>.
Hello,
It is hard to tell what is the bottleneck in your case, could be anything. I
suggest tracking CPU and memory usage, enable GC logs. Adding more nodes
will definitely help in this case.
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/