Ignite Query Slow

classic Classic list List threaded Threaded
24 messages Options
12
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

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/
Maxim.Pudov Maxim.Pudov
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

Hello

Are u suggesting to have more nodes with REPLICATE OR PARTITIONED settings?

Thanks



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

Can you attach it instead of just posting to the message?

пн, 26 нояб. 2018 г. в 10:12, Skollur <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

In reply to this post by Skollur
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

do you have gc logs from an another node?

вт, 4 дек. 2018 г. в 12:14, Skollur <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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 <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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 <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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 <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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 <[hidden email]>:
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/
Skollur Skollur
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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/
ezhuravlev ezhuravlev
Reply | Threaded
Open this post in threaded view
|

Re: Ignite Query Slow

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 <[hidden email]>:
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/
12