Hello! Does it happen to work on 2.9.1, or will fail too? I recommend checking it since I vaguely remember some discussions about late affinity assignments fix.
Regards, -- Ilya Kasnacheev сб, 9 янв. 2021 г. в 03:11, tschauenberg <tschauenb...@invidi.com>: > Here's my attempt to demonstrate and also provide logs > > Standup 3 node cluster and load with data > > > Using a thick client, 250k devices are loaded into the device cache. The > thick client then leaves. There's one other thick client connected the > whole time for serving requests but I think that's irrelevant for the test > but want to point it out in case someone notices there's still a client > connected. > > Show topology from logs of the client leaving: > > > > [2021-01-08T23:08:05.012Z][INFO][disco-event-worker-#40][GridDiscoveryManager] > Node left topology: TcpDiscoveryNode > [id=611e30ee-b7c6-4ead-a746-f609b206cfb4, > consistentId=611e30ee-b7c6-4ead-a746-f609b206cfb4, addrs=ArrayList > [127.0.0.1, 172.17.0.3], sockAddrs=HashSet [/127.0.0.1:0, /172.17.0.3:0], > discPort=0, order=7, intOrder=6, lastExchangeTime=1610146373751, loc=false, > ver=2.8.1#20200521-sha1:86422096, isClient=true] > > [2021-01-08T23:08:05.013Z][INFO][disco-event-worker-#40][GridDiscoveryManager] > Topology snapshot [ver=8, locNode=75e4ddea, servers=3, clients=1, > state=ACTIVE, CPUs=7, offheap=3.0GB, heap=3.1GB] > > Start visor on one of the nodes > > > Show topology from logs > > > [2021-01-08T23:30:33.461Z][INFO][tcp-disco-msg-worker-[4ea8efe1 > 10.12.3.76:47500]-#2][TcpDiscoverySpi] New next node > [newNext=TcpDiscoveryNode [id=1cca94e3-f15f-4a8b-9f65-d9b9055a5fa7, > consistentId=10.12.2.110:47501, addrs=ArrayList [10.12.2.110], > sockAddrs=HashSet [/10.12.2.110:47501], discPort=47501, order=0, > intOrder=7, > lastExchangeTime=1610148633458, loc=false, > ver=2.8.1#20200521-sha1:86422096, > isClient=false]] > > [2021-01-08T23:30:34.045Z][INFO][sys-#1011][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=75e4ddea-1927-4e93-82e9-fdfbb7b58d1c, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=9, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode > [id=1cca94e3-f15f-4a8b-9f65-d9b9055a5fa7, consistentId=10.12.2.110:47501, > addrs=ArrayList [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47501], > discPort=47501, order=9, intOrder=7, lastExchangeTime=1610148633458, > loc=false, ver=2.8.1#20200521-sha1:86422096, isClient=false], done=true, > newCrdFut=null], topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0]] > > Show data balanced in visor > > > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > | Devices(@c2) | PARTITIONED | 3 | 250000 (0 / 250000) > > | min: 80315 (0 / 80315) | min: 0 | min: 0 | min: 0 | > min: 250000 | > | | | | > > | avg: 83333.33 (0.00 / 83333.33) | avg: 0.00 | avg: 0.00 | avg: 0.00 | > avg: 250000.00 | > | | | | > > | max: 86968 (0 / 86968) | max: 0 | max: 0 | max: 0 | > max: 250000 | > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > > At this point the data is all relatively balanced and the topology > increased > when visor connected. > > Stop ignite on one node > > > Show topology and PME from logs (from a different ignite node as the ignite > process was stopped) > > > > [2021-01-08T23:35:39.333Z][INFO][disco-event-worker-#40][GridDiscoveryManager] > Node left topology: TcpDiscoveryNode > [id=75e4ddea-1927-4e93-82e9-fdfbb7b58d1c, > consistentId=3a4a497f-5a89-4f2c-8531-b2b05f2ede22, addrs=ArrayList > [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47500], discPort=47500, > order=3, intOrder=3, lastExchangeTime=1610139164908, loc=false, > ver=2.8.1#20200521-sha1:86422096, isClient=false] > > [2021-01-08T23:35:39.333Z][INFO][disco-event-worker-#40][GridDiscoveryManager] > Topology snapshot [ver=10, locNode=4ea8efe1, servers=2, clients=1, > state=ACTIVE, CPUs=5, offheap=2.0GB, heap=2.1GB] > [2021-01-08T23:35:39.333Z][INFO][disco-event-worker-#40][GridDiscoveryManager] > > ^-- Baseline [id=0, size=3, online=2, offline=1] > [2021-01-08T23:35:39.335Z][INFO][exchange-worker-#41][time] Started > exchange > init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], crd=true, > evt=NODE_LEFT, evtNode=75e4ddea-1927-4e93-82e9-fdfbb7b58d1c, > customEvt=null, > allowMerge=false, exchangeFreeSwitch=true] > [2021-01-08T23:35:39.338Z][INFO][sys-#1031][GridAffinityAssignmentCache] > Local node affinity assignment distribution is not ideal [cache=Households, > expectedPrimary=512.00, actualPrimary=548, expectedBackups=1024.00, > actualBackups=476, warningThreshold=50.00%] > [2021-01-08T23:35:39.340Z][INFO][sys-#1032][GridAffinityAssignmentCache] > Local node affinity assignment distribution is not ideal [cache=Devices, > expectedPrimary=512.00, actualPrimary=548, expectedBackups=1024.00, > actualBackups=476, warningThreshold=50.00%] > > [2021-01-08T23:35:39.354Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Finished waiting for partition release future > [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], waitTime=0ms, > futInfo=NA, mode=DISTRIBUTED] > > [2021-01-08T23:35:39.357Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Finished waiting for partitions release latch: ServerLatch [permits=0, > pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid > [id=exchange, topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0]]]] > > [2021-01-08T23:35:39.365Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=10, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], > err=null, rebalanced=true, wasRebalanced=true] > > [2021-01-08T23:35:39.370Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=10, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode > [id=75e4ddea-1927-4e93-82e9-fdfbb7b58d1c, > consistentId=3a4a497f-5a89-4f2c-8531-b2b05f2ede22, addrs=ArrayList > [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47500], discPort=47500, > order=3, intOrder=3, lastExchangeTime=1610139164908, loc=false, > ver=2.8.1#20200521-sha1:86422096, isClient=false], done=true, > newCrdFut=null], topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0]] > > [2021-01-08T23:35:39.370Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=10, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], > stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters > initialization" (0 ms), stage="Determine exchange type" (15 ms), > stage="Preloading notification" (0 ms), stage="WAL history reservation" (2 > ms), stage="Wait partitions release" (0 ms), stage="Wait partitions release > latch" (2 ms), stage="After states restored callback" (5 ms), > stage="Finalize update counters" (2 ms), stage="Detect lost partitions" (1 > ms), stage="Exchange done" (3 ms), stage="Total time" (30 ms)] > > [2021-01-08T23:35:39.370Z][INFO][exchange-worker-#41][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=10, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], > stage="Affinity initialization (exchange-free switch on fully-rebalanced > topology) [grp=Households]" (15 ms) (parent=Determine exchange type), > stage="Affinity initialization (exchange-free switch on fully-rebalanced > topology) [grp=CorpHeadend]" (14 ms) (parent=Determine exchange type), > stage="Affinity initialization (exchange-free switch on fully-rebalanced > topology) [grp=AttributeOptions]" (13 ms) (parent=Determine exchange type)] > [2021-01-08T23:35:39.370Z][INFO][exchange-worker-#41][time] Finished > exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], > crd=true] > > [2021-01-08T23:35:39.380Z][INFO][exchange-worker-#41][GridCachePartitionExchangeManager] > Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion > [topVer=10, minorTopVer=0], force=false, evt=NODE_LEFT, > node=75e4ddea-1927-4e93-82e9-fdfbb7b58d1c] > > Show data in visor with data on the two nodes > > > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > | Devices(@c2) | PARTITIONED | 2 | 250000 (0 / 250000) > > | min: 116261 (0 / 116261) | min: 0 | min: 0 | min: 0 | > min: 250000 | > | | | | > > | avg: 125000.00 (0.00 / 125000.00) | avg: 0.00 | avg: 0.00 | avg: 0.00 | > avg: 250000.00 | > | | | | > > | max: 133739 (0 / 133739) | max: 0 | max: 0 | max: 0 | > max: 250000 | > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > > At this point there's only 2 nodes with data for this cache and it got > nicely balanced when the ignite process was stopped. > > Start the stopped ignite > > > Show topology and PME from logs (on node where ignite started) > > > > [2021-01-08T23:39:42.817Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Skipped waiting for partitions release future (local node is joining) > [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0]] > > [2021-01-08T23:39:43.006Z][INFO][db-checkpoint-thread-#54][GridCacheDatabaseSharedManager] > Checkpoint started [checkpointId=07c7fa75-d1dd-4955-964e-7d61bddbf05b, > startPtr=FileWALPointer [idx=7, fileOff=39245141, len=118735], > checkpointBeforeLockTime=91ms, checkpointLockWait=0ms, > checkpointListenersExecuteTime=29ms, checkpointLockHoldTime=51ms, > walCpRecordFsyncDuration=8ms, writeCheckpointEntryDuration=5ms, > splitAndSortCpPagesDuration=14ms, pages=2079, reason='node started'] > > [2021-01-08T23:39:43.163Z][INFO][grid-nio-worker-tcp-comm-0-#24][TcpCommunicationSpi] > Established outgoing communication connection [locAddr=/10.12.2.110:34662, > rmtAddr=/10.12.3.76:47100] > [2021-01-08T23:39:43.167Z][INFO][exchange-worker-#42][time] Finished > exchange init [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], > crd=false] > [2021-01-08T23:39:43.368Z][INFO][sys-#48][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, resVer=AffinityTopologyVersion > [topVer=11, minorTopVer=0]] > [2021-01-08T23:39:43.494Z][INFO][sys-#48][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=11, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], > err=null, rebalanced=false, wasRebalanced=false] > [2021-01-08T23:39:43.554Z][INFO][sys-#48][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=b909d450-11cd-471f-b49e-85c6f300f704, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=11, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode > [id=b909d450-11cd-471f-b49e-85c6f300f704, > consistentId=3a4a497f-5a89-4f2c-8531-b2b05f2ede22, addrs=ArrayList > [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47500], discPort=47500, > order=11, intOrder=8, lastExchangeTime=1610149183525, loc=true, > ver=2.8.1#20200521-sha1:86422096, isClient=false], done=true, > newCrdFut=null], topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0]] > [2021-01-08T23:39:43.556Z][INFO][sys-#48][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=11, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], > stage="Waiting in exchange queue" (53 ms), stage="Exchange parameters > initialization" (3 ms), stage="Components activation" (22 ms), > stage="Determine exchange type" (50 ms), stage="Preloading notification" (0 > ms), stage="WAL history reservation" (5 ms), stage="Restore partition > states" (11 ms), stage="After states restored callback" (147 ms), > stage="Waiting for Full message" (392 ms), stage="Affinity recalculation" > (89 ms), stage="Full map updating" (36 ms), stage="Detect lost partitions" > (4 ms), stage="Exchange done" (57 ms), stage="Total time" (869 ms)] > [2021-01-08T23:39:43.558Z][INFO][sys-#48][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=11, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], > stage="Affinity fetch" (48 ms) (parent=Determine exchange type), > stage="Restore partition states [grp=ignite-sys-cache]" (11 ms) > (parent=Restore partition states), stage="Restore partition states > [grp=MasterVersion]" (11 ms) (parent=Restore partition states), > stage="Restore partition states [grp=Devices]" (11 ms) (parent=Restore > partition states), stage="Affinity initialization (local join) > [grp=Devices]" (89 ms) (parent=Affinity recalculation), stage="Affinity > initialization (local join) [grp=Households]" (88 ms) (parent=Affinity > recalculation), stage="Affinity initialization (local join) > [grp=MasterVersion]" (67 ms) (parent=Affinity recalculation)] > > [2021-01-08T23:39:43.588Z][INFO][exchange-worker-#42][GridCachePartitionExchangeManager] > Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion > [topVer=11, minorTopVer=0], force=false, evt=NODE_JOINED, > node=b909d450-11cd-471f-b49e-85c6f300f704] > [2021-01-08T23:39:43.642Z][INFO][main][GridDiscoveryManager] Topology > snapshot [ver=11, locNode=b909d450, servers=3, clients=1, state=ACTIVE, > CPUs=7, offheap=3.0GB, heap=3.1GB] > [2021-01-08T23:39:43.643Z][INFO][main][GridDiscoveryManager] ^-- Baseline > [id=0, size=3, online=3, offline=0] > [2021-01-08T23:39:43.645Z][INFO][main][G] Node started : [stage="Configure > system pool" (65 ms),stage="Start managers" (1113 ms),stage="Configure > binary metadata" (102 ms),stage="Start processors" (744 ms),stage="Init > metastore" (899 ms),stage="Init and start regions" (10 ms),stage="Restore > binary memory" (989 ms),stage="Restore logical state" (2450 > ms),stage="Finish recovery" (112 ms),stage="Join topology" (1498 > ms),stage="Await transition" (19 ms),stage="Await exchange" (951 > ms),stage="Total time" (8952 ms)] > > [2021-01-08T23:39:44.550Z][INFO][db-checkpoint-thread-#54][GridCacheDatabaseSharedManager] > Checkpoint finished [cpId=07c7fa75-d1dd-4955-964e-7d61bddbf05b, pages=2079, > markPos=FileWALPointer [idx=7, fileOff=39245141, len=118735], > walSegmentsCleared=0, walSegmentsCovered=[], markDuration=83ms, > pagesWrite=184ms, fsync=1359ms, total=1717ms] > > > Show data with a min of zero primaries in visor > > > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > | Devices(@c2) | PARTITIONED | 3 | 250000 (0 / 250000) > > | min: 0 (0 / 0) | min: 0 | min: 0 | min: 0 | > min: 0 | > | | | | > > | avg: 83333.33 (0.00 / 83333.33) | avg: 0.00 | avg: 0.00 | avg: 0.00 | > avg: 166666.67 | > | | | | > > | max: 133739 (0 / 133739) | max: 0 | max: 0 | max: 0 | > max: 250000 | > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > > At this point the stopped ignite process was restarted but notice the > primaries were not balanced to it upon joining. > > Stop visor > > > Show topology and PME from logs > > > > [2021-01-08T23:44:07.824Z][INFO][grid-nio-worker-tcp-comm-1-#25][TcpCommunicationSpi] > Accepted incoming communication connection [locAddr=/10.12.2.110:47100, > rmtAddr=/10.12.2.110:37510] > > [2021-01-08T23:44:35.597Z][INFO][tcp-disco-srvr-[:47500]-#3][TcpDiscoverySpi] > TCP discovery accepted incoming connection [rmtAddr=/10.12.4.242, > rmtPort=42615] > > [2021-01-08T23:44:35.598Z][INFO][tcp-disco-srvr-[:47500]-#3][TcpDiscoverySpi] > TCP discovery spawning a new thread for connection [rmtAddr=/10.12.4.242, > rmtPort=42615] > > [2021-01-08T23:44:35.598Z][INFO][tcp-disco-sock-reader-[]-#7][TcpDiscoverySpi] > Started serving remote node connection [rmtAddr=/10.12.4.242:42615, > rmtPort=42615] > [2021-01-08T23:44:35.599Z][INFO][tcp-disco-sock-reader-[63d7cf0d > 10.12.4.242:42615]-#7][TcpDiscoverySpi] Initialized connection with remote > server node [nodeId=63d7cf0d-f8b6-4fe2-ba99-4bbd26731451, > rmtAddr=/10.12.4.242:42615] > [2021-01-08T23:44:35.621Z][INFO][exchange-worker-#42][time] Started > exchange > init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], crd=false, > evt=NODE_LEFT, evtNode=1cca94e3-f15f-4a8b-9f65-d9b9055a5fa7, > customEvt=null, > allowMerge=true, exchangeFreeSwitch=false] > > [2021-01-08T23:44:35.632Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Finished waiting for partition release future > [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, > futInfo=NA, mode=DISTRIBUTED] > > [2021-01-08T23:44:35.644Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Finished waiting for partitions release latch: ClientLatch > [coordinator=TcpDiscoveryNode [id=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, > consistentId=3b21ae44-c9cc-4e04-9e79-9807d22a6d50, addrs=ArrayList > [10.12.3.76], sockAddrs=HashSet [/10.12.3.76:47500], discPort=47500, > order=1, intOrder=1, lastExchangeTime=1610149182437, loc=false, > ver=2.8.1#20200521-sha1:86422096, isClient=false], ackSent=true, > super=CompletableLatch [id=CompletableLatchUid [id=exchange, > topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]]] > > [2021-01-08T23:44:35.644Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Finished waiting for partition release future > [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, > futInfo=NA, mode=LOCAL] > [2021-01-08T23:44:35.688Z][INFO][exchange-worker-#42][time] Finished > exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], > crd=false] > [2021-01-08T23:44:35.704Z][INFO][tcp-disco-sock-reader-[1cca94e3 > 10.12.2.110:58161]-#5][TcpDiscoverySpi] Finished serving remote node > connection [rmtAddr=/10.12.2.110:58161, rmtPort=58161 > [2021-01-08T23:44:35.761Z][INFO][sys-#80][GridDhtPartitionsExchangeFuture] > Received full message, will finish exchange > [node=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, resVer=AffinityTopologyVersion > [topVer=12, minorTopVer=0]] > [2021-01-08T23:44:35.802Z][INFO][sys-#80][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=12, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], > err=null, rebalanced=true, wasRebalanced=false] > [2021-01-08T23:44:35.820Z][INFO][sys-#80][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=b909d450-11cd-471f-b49e-85c6f300f704, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=12, minorTopVer=0], evt=NODE_LEFT, evtNode=TcpDiscoveryNode > [id=1cca94e3-f15f-4a8b-9f65-d9b9055a5fa7, consistentId=10.12.2.110:47501, > addrs=ArrayList [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47501], > discPort=47501, order=9, intOrder=7, lastExchangeTime=1610149182447, > loc=false, ver=2.8.1#20200521-sha1:86422096, isClient=false], done=true, > newCrdFut=null], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]] > [2021-01-08T23:44:35.820Z][INFO][sys-#80][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=12, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], > stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters > initialization" (0 ms), stage="Determine exchange type" (0 ms), > stage="Preloading notification" (0 ms), stage="WAL history reservation" (2 > ms), stage="Wait partitions release" (13 ms), stage="Wait partitions > release > latch" (7 ms), stage="Wait partitions release" (0 ms), stage="After states > restored callback" (0 ms), stage="Finalize update counters" (19 ms), > stage="Waiting for Full message" (96 ms), stage="Affinity recalculation" > (31 > ms), stage="Full map updating" (9 ms), stage="Detect lost partitions" (2 > ms), stage="Exchange done" (15 ms), stage="Total time" (194 ms)] > [2021-01-08T23:44:35.820Z][INFO][sys-#80][GridDhtPartitionsExchangeFuture] > Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=12, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], > stage="Affinity applying from full message [grp=AttributeOptions]" (9 ms) > (parent=Affinity recalculation), stage="Affinity applying from full message > [grp=CorpHeadend]" (8 ms) (parent=Affinity recalculation), stage="Affinity > applying from full message [grp=Devices]" (6 ms) (parent=Affinity > recalculation)] > > [2021-01-08T23:44:35.824Z][INFO][exchange-worker-#42][GridCachePartitionExchangeManager] > Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion > [topVer=12, minorTopVer=0], force=false, evt=NODE_LEFT, > node=1cca94e3-f15f-4a8b-9f65-d9b9055a5fa7] > > With visor leaving the cluster now, this triggers the PME for the primary > keys. Will be starting visor again to show that. > > Start visor again > > > Show topology and PME from logs > > > > [2021-01-08T23:46:52.977Z][INFO][tcp-disco-srvr-[:47500]-#3][TcpDiscoverySpi] > TCP discovery accepted incoming connection [rmtAddr=/10.12.2.110, > rmtPort=42455] > > [2021-01-08T23:46:52.977Z][INFO][tcp-disco-srvr-[:47500]-#3][TcpDiscoverySpi] > TCP discovery spawning a new thread for connection [rmtAddr=/10.12.2.110, > rmtPort=42455] > > [2021-01-08T23:46:52.982Z][INFO][tcp-disco-sock-reader-[]-#8][TcpDiscoverySpi] > Started serving remote node connection [rmtAddr=/10.12.2.110:42455, > rmtPort=42455] > [2021-01-08T23:46:52.984Z][INFO][tcp-disco-sock-reader-[6215e66a > 10.12.2.110:42455]-#8][TcpDiscoverySpi] Initialized connection with remote > server node [nodeId=6215e66a-b021-410f-8e3a-aaa317f19609, > rmtAddr=/10.12.2.110:42455] > rmtPort=424553:46:53.041Z][INFO][tcp-disco-sock-reader-[6215e66a > 10.12.2.110:42455]-#8][TcpDiscoverySpi] Finished serving remote node > connection [rmtAddr=/10.12.2.110:42455, > [2021-01-08T23:46:53.049Z][INFO][tcp-disco-msg-worker-[4ea8efe1 > 10.12.3.76:47500]-#2][TcpDiscoverySpi] New next node > [newNext=TcpDiscoveryNode [id=6215e66a-b021-410f-8e3a-aaa317f19609, > consistentId=10.12.2.110:47501, addrs=ArrayList [10.12.2.110], > sockAddrs=HashSet [/10.12.2.110:47501], discPort=47501, order=0, > intOrder=9, > lastExchangeTime=1610149613043, loc=false, > ver=2.8.1#20200521-sha1:86422096, > isClient=false]] > [2021-01-08T23:46:53.405Z][INFO][exchange-worker-#42][time] Started > exchange > init [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], crd=false, > evt=NODE_JOINED, evtNode=6215e66a-b021-410f-8e3a-aaa317f19609, > customEvt=null, allowMerge=true, exchangeFreeSwitch=false] > > [2021-01-08T23:46:53.410Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Finished waiting for partition release future > [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], waitTime=0ms, > futInfo=NA, mode=DISTRIBUTED] > e [id=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, > consistentId=3b21ae44-c9cc-4e04-9e79-9807d22a6d50, addrs=ArrayList > [10.12.3.76], sockAddrs=HashSet [/10.12.3.76:47500], discPort=47500, > order=1, intOrder=1, lastExchangeTime=1610149182437, loc=false, > ver=2.8.1#20200521-sha1:86422096, isClient=false], ackSent=true, > super=CompletableLatch [id=CompletableLatchUid [id=exchange, > topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0]]]] > > [2021-01-08T23:46:53.412Z][INFO][exchange-worker-#42][GridDhtPartitionsExchangeFuture] > Finished waiting for partition release future > [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], waitTime=0ms, > futInfo=NA, mode=LOCAL] > [2021-01-08T23:46:53.437Z][INFO][exchange-worker-#42][time] Finished > exchange init [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], > crd=false] > nityTopologyVersion [topVer=13, minorTopVer=0]]htPartitionsExchangeFuture] > Received full message, will finish exchange > [node=4ea8efe1-0f92-4232-bbab-2cb232ed04f9, > > resVer=Affi[2021-01-08T23:46:53.587Z][INFO][sys-#98][GridDhtPartitionsExchangeFuture] > Finish exchange future [startVer=AffinityTopologyVersion [topVer=13, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], > err=null, rebalanced=true, wasRebalanced=true] > [2021-01-08T23:46:53.598Z][INFO][sys-#98][GridDhtPartitionsExchangeFuture] > Completed partition exchange > [localNode=b909d450-11cd-471f-b49e-85c6f300f704, > exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion > [topVer=13, minorTopVer=0], evt=NODE_JOINED, evtNode=TcpDiscoveryNode > [id=6215e66a-b021-410f-8e3a-aaa317f19609, consistentId=10.12.2.110:47501, > addrs=ArrayList [10.12.2.110], sockAddrs=HashSet [/10.12.2.110:47501], > discPort=47501, order=13, intOrder=9, lastExchangeTime=1610149613043, > loc=false, ver=2.8.1#20200521-sha1:86422096, isClient=false], done=true, > newCrdFut=null], topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0]] > [2021-01-08T23:46:53.602Z][INFO][sys-#98][GridDhtPartitionsExchangeFuture] > Exchange timings [startVer=AffinityTopologyVersion [topVer=13, > minorTopVer=0], resVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], > stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters > initialization" (0 ms), stage="Determine exchange type" (1 ms), > stage="Preloading notification" (0 ms), stage="WAL history reservation" (2 > ms), stage="Wait partitions release" (0 ms), stage="Wait partitions release > latch" (1 ms), stage="Wait partitions release" (0 ms), stage="After states > restored callback" (0 ms), stage="Waiting for Full message" (102 ms), > stage="Affinity recalculation" (60 ms), stage="Full map updating" (11 ms), > stage="Detect lost partitions" (2 ms), stage="Exchange done" (9 ms), > stage="Total time" (188 ms)] > AffinityTopologyVersion [topVer=13, minorTopVer=0], stage="Affinity > initialization (node join) [grp=CorpHeadend, crd=false]" (33 ms) > (parent=Affinity recalculation), stage="Affinity initialization (node join) > [grp=Devices, crd=false]" (27 ms) (parent=Affinity recalculation), > stage="Affinity initialization (node join) [grp=MasterVersion, crd=false]" > (22 ms) (parent=Affinity recalculation)] > > [2021-01-08T23:46:53.614Z][INFO][exchange-worker-#42][GridCachePartitionExchangeManager] > Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion > [topVer=13, minorTopVer=0], force=false, evt=NODE_JOINED, > node=6215e66a-b021-410f-8e3a-aaa317f19609] > > > Show data with primaries balanced in visor > > > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > | Devices(@c2) | PARTITIONED | 3 | 250000 (0 / 250000) > > | min: 80315 (0 / 80315) | min: 0 | min: 0 | min: 0 | > min: 0 | > | | | | > > | avg: 83333.33 (0.00 / 83333.33) | avg: 0.00 | avg: 0.00 | avg: 0.00 | > avg: 166666.67 | > | | | | > > | max: 86968 (0 / 86968) | max: 0 | max: 0 | max: 0 | > max: 250000 | > > +-----------------------+-------------+-------+---------------------------------+-----------------------------------+-----------+-----------+-----------+----------------+ > > Starting visor shows the keys have all been rebalanced again. > > > > > -- > Sent from: http://apache-ignite-users.70518.x6.nabble.com/ >
