Hi,
I am populating three caches running on a single ignite node (version
1.5.27 ) with 4 GB heap (Configure as: JVM_OPTS="-server -Xms4g -Xmx4g)
with less than 100k records in each. I'am performing a join query on them
but the query takes a hell lot of time and I get this log (Or I don't know
It is just ERROR or INFO) as following logs.
[09:47:18,720][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Added new node to topology: TcpDiscoveryNode
[id=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d, addrs=[0:0:0:0:0:0:0:1%lo,
10.178.148.8, 127.0.0.1], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
elssie-gridgain2.internal/10.178.148.8:0], discPort=0, order=8, intOrder=5,
lastExchangeTime=1475142438712, loc=false,
ver=1.5.27#20160624-sha1:0fe713ae, isClient=true]
[09:47:18,721][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Topology snapshot [ver=8, servers=1, clients=1, CPUs=16, heap=5.8GB]
[09:47:18,729][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=8, minorTopVer=0], evt=NODE_JOINED,
node=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d]
[09:47:19,279][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=8, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT,
node=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d]
[09:47:19,345][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=8, minorTopVer=2], evt=DISCOVERY_CUSTOM_EVT,
node=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d]
[09:47:19,376][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=8, minorTopVer=3], evt=DISCOVERY_CUSTOM_EVT,
node=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d]
[09:47:25,611][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Node left topology: TcpDiscoveryNode
[id=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d, addrs=[0:0:0:0:0:0:0:1%lo,
10.178.148.8, 127.0.0.1], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
elssie-gridgain2.internal/10.178.148.8:0], discPort=0, order=8, intOrder=5,
lastExchangeTime=1475142438712, loc=false,
ver=1.5.27#20160624-sha1:0fe713ae, isClient=true]
[09:47:25,612][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Topology snapshot [ver=9, servers=1, clients=0, CPUs=16, heap=4.0GB]
[09:47:25,621][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=9, minorTopVer=0], evt=NODE_LEFT,
node=ea2b3ca3-f5d0-45bd-adb3-58d46bc85b7d]
[09:47:47,234][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Added new node to topology: TcpDiscoveryNode
[id=448da668-5262-46bb-951a-c6122543882a, addrs=[0:0:0:0:0:0:0:1%lo,
10.178.148.8, 127.0.0.1], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0,
elssie-gridgain2.internal/10.178.148.8:0], discPort=0, order=10,
intOrder=6, lastExchangeTime=1475142467220, loc=false,
ver=1.5.27#20160624-sha1:0fe713ae, isClient=true]
[09:47:47,235][INFO][disco-event-worker-#96%null%][GridDiscoveryManager]
Topology snapshot [ver=10, servers=1, clients=1, CPUs=16, heap=5.8GB]
[09:47:47,243][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=10, minorTopVer=0], evt=NODE_JOINED,
node=448da668-5262-46bb-951a-c6122543882a]
[09:47:47,861][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=10, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT,
node=448da668-5262-46bb-951a-c6122543882a]
[09:47:47,922][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=10, minorTopVer=2], evt=DISCOVERY_CUSTOM_EVT,
node=448da668-5262-46bb-951a-c6122543882a]
[09:47:47,955][INFO][exchange-worker-#99%null%][GridCachePartitionExchangeManager]
Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion
[topVer=10, minorTopVer=3], evt=DISCOVERY_CUSTOM_EVT,
node=448da668-5262-46bb-951a-c6122543882a]
[09:48:04,885][INFO][grid-timeout-worker-#81%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6caab193, name=null]
^-- H/N/C [hosts=1, nodes=2, CPUs=16]
^-- CPU [cur=0.03%, avg=3.31%, GC=0%]
^-- Heap [used=1219MB, free=70.23%, comm=4095MB]
^-- Public thread pool [active=0, idle=32, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[09:49:04,879][INFO][grid-timeout-worker-#81%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6caab193, name=null]
^-- H/N/C [hosts=1, nodes=2, CPUs=16]
^-- CPU [cur=0%, avg=3.23%, GC=0%]
^-- Heap [used=1222MB, free=70.14%, comm=4095MB]
^-- Public thread pool [active=0, idle=32, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[09:50:04,883][INFO][grid-timeout-worker-#81%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6caab193, name=null]
^-- H/N/C [hosts=1, nodes=2, CPUs=16]
^-- CPU [cur=0.03%, avg=3.17%, GC=0%]
^-- Heap [used=1227MB, free=70.04%, comm=4095MB]
^-- Public thread pool [active=0, idle=32, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
^-- Outbound messages queue [size=0]
[09:51:04,882][INFO][grid-timeout-worker-#81%null%][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=6caab193, name=null]
^-- H/N/C [hosts=1, nodes=2, CPUs=16]
Here is what my join query (Generated by some custom engine which work
perfectly normal with postgres with same tables and joins)looks like:
SELECT DISTINCT m1 AS m1,m1_TYP AS m1_TYP FROM (SELECT entry AS a5,QS5.a1
AS a1,QS5.a4 AS a4,QS5.m1 AS m1,m1_TYP AS m1_TYP
FROM "TABLE1".TABLE1 AS T,(SELECT entity AS m1,typ AS m1_typ,elem AS
a5,QS4.a1 AS a1,QS4.a4 AS a4
FROM "TABLE2".TABLE2 AS T,(SELECT entry AS a2,QS3.a1 AS a1,QS3.a4 AS
a4,QS3.m1 AS m1,m1_TYP AS m1_TYP
FROM "TABLE1".TABLE1 AS T,(SELECT entry AS a4,QS2.a1 AS a1,QS2.a2 AS
a2,QS2.m1 AS m1,m1_TYP AS m1_TYP
FROM "TABLE1".TABLE1 AS T,(SELECT entry AS a3,QS1.a1 AS a1,QS1.a2 AS
a2,QS1.a4 AS a4,QS1.m1 AS m1,m1_TYP AS m1_TYP
FROM "TABLE1".TABLE1 AS T,(SELECT a1 AS a1,m1 AS m1,m1_TYP AS
m1_TYP,COALESCE(S3.elem,val3) AS a3,COALESCE(S4.elem,val4) AS
a4,COALESCE(S2.elem,val2) AS a2
FROM (SELECT entry AS a1,T.val2 AS m1,T.typ2 AS m1_TYP,T.val6 AS
VAL3,T.val6 AS VAL4,T.val8 AS VAL2
FROM "TABLE1".TABLE1 AS T,(SELECT elem AS a1
FROM "TABLE2".TABLE2 AS T
WHERE entity = '3' AND typ = 5001
AND (prop = '1oh~#some_prop1')) AS QS0 WHERE entry = QS0.a1
AND (T.prop0 = '4xm~#type' AND T.prop8 = '1oh~#some_prop2' AND T.prop6
= '1oh~#some_prop3' AND T.prop6 = '1oh~#some_prop3' AND T.prop2 =
'1oh~#is_atom_of')
AND T.val0 = '7a~') AS Q1 LEFT OUTER JOIN "TABLE3".TABLE3 AS S3 ON
Q1.VAL3 = S3.list_id LEFT OUTER JOIN "TABLE3".TABLE3 AS S4 ON Q1.VAL4 =
S4.list_id LEFT OUTER JOIN "TABLE3".TABLE3 AS S2 ON Q1.VAL2 = S2.list_id
WHERE ( (a1 <> COALESCE(S4.elem,val4)
) )) AS QS1 WHERE entry = QS1.a3
AND (T.prop0 = '4xm~#type' AND T.prop5 = '1oh~#some_prop1' AND T.prop8
= '1oh~#some_prop4')
AND T.val0 = '562~' AND T.val5 = '1' AND T.val8 = '6o7~') AS QS2 WHERE
entry = QS2.a4
AND (T.prop0 = '4xm~#type' AND T.prop5 = '1oh~#some_prop1')
AND T.val0 = '7a~' AND T.val5 = '1') AS QS3 WHERE entry = QS3.a2
AND (T.prop0 = '4xm~#type' AND T.prop5 = '1oh~#some_prop1')
AND T.val0 = '562~' AND T.val5 = '1') AS QS4 WHERE entity = QS4.m1 AND
typ = QS4.m1_TYP
AND (prop = '1oh~#isome_prop5')) AS QS5 WHERE entry = QS5.a5
AND (T.prop0 = '4xm~#type' AND T.prop5 = '1oh~#some_prop1')
AND T.val0 = '1eg~' AND T.val5 = '0') AS QS6 LIMIT 100
PS: I've been able to run the similar query with join and that doesn't give
the above error logs. Please help me with that.
--
Thanks & Regard
Manish Mishra
Software Consultant,
Knoldus Software, LLP
