[ https://issues.apache.org/jira/browse/IGNITE-10658?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Pavel Voronkin updated IGNITE-10658: ------------------------------------ Description: There are log messages about finishing rebalance: 2018-07-06 02:25:53.976[INFO ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander] [REB]Fin reb part CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif .formats.UnifDictionary, p=GridDhtLocalPartition [rmvQueueMaxSize=32, rmvdEntryTtl=10000, id=10698, delayedRenting=false, clear=false, updateSeqOnDestroy=false, grp=CACHEGROUP_PART ICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary, state=MOVING, reservations=1, empty=true, createTime=07/05/2018 23:30:40], dir=[topVer=(351, 0), idx=6, sup=10.126.12.142 :47500] 2018-07-06 02:25:53.976[INFO ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander]Completed (final) rebalancing [fromNode=d38ca303-91a3-4805-b2bc-8231 721924e2, cacheOrGroup=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary, topology=AffinityTopologyVersion [topVer=351, minorTopVer=0], time=20 ms] 2018-07-06 02:25:53.976[INFO ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander]Completed rebalance future: RebalanceFuture [grp=CacheGroupContext [ grp=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary], topVer=AffinityTopologyVersion [topVer=351, minorTopVer=0], rebalanceId=2018] 2018-07-06 02:25:53.977[INFO ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager]WAL enabled for [grp=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb. unif.formats.UnifDictionary] But Visor still showed 99,99% status on that node. Later on when a client node left topology Visor status has changed to Rebalnce completed See log messages: 2018-07-06 02:57:46.629[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.ignite.internal.exchange.time]Started exchange init [topVer=AffinityTopologyVersion [topVer=352, minorTopVer=0], crd=false, evt=NODE_LEFT, evtNode=1d2dcbc7-f143-42cd-9130-145e4c199c0e, customEvt=null, allowMerge=true] 2018-07-06 02:57:47.376[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq BGP_BGPConfigurationImpl_gbk-main -> 243 [A FTER_EXCHANGE] 2018-07-06 02:57:47.376[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq BGP_ExpiryEntryImpl_BGP -> 243 [AFTER_EXCHA NGE] 2018-07-06 02:57:47.376[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.ca rd.cdm.api.dictionaries.sys.PartitioningCriteriaTen -> 1158 [AFTER_EXCHANGE] 2018-07-06 02:57:47.383[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq CACHEGROUP_PARTICLE_union-module_ru.sbrf.au totransact.model.keys.DateKey -> 1157 [AFTER_EXCHANGE] 2018-07-06 02:57:47.390[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.tw .data.dpl.entity.ServiceZone -> 1159 [AFTER_EXCHANGE] 2018-07-06 02:57:47.397[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.ac quiring.processing.entities.dictionaries.PublishedDepTerBank -> 1158 [AFTER_EXCHANGE] 2018-07-06 02:57:47.403[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] Top upd seq BGP_Locks_auto-transact -> 244 [AFTER_EXCHA NGE] 2018-07-06 02:57:47.912[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager] WAL enabled for [grp=CACHEGROUP_PARTICLE_gbk-main_com.s bt.gbk.entities.Segmentation] 2018-07-06 02:57:47.912[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager] WAL enabled for [grp=CACHEGROUP_PARTICLE_union-module_c om.sbt.gbk.entities.Segmentation] 2018-07-06 02:57:47.913[INFO ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=Affinity TopologyVersion [topVer=352, minorTopVer=0], evt=NODE_LEFT, node=1d2dcbc7-f143-42cd-9130-145e4c199c0e] > Rebalance status in Visor stays on 99.99%. > ------------------------------------------ > > Key: IGNITE-10658 > URL: https://issues.apache.org/jira/browse/IGNITE-10658 > Project: Ignite > Issue Type: Bug > Reporter: Pavel Voronkin > Priority: Major > > There are log messages about finishing rebalance: > 2018-07-06 02:25:53.976[INFO > ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander] > [REB]Fin reb part CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif > .formats.UnifDictionary, p=GridDhtLocalPartition [rmvQueueMaxSize=32, > rmvdEntryTtl=10000, id=10698, delayedRenting=false, clear=false, > updateSeqOnDestroy=false, grp=CACHEGROUP_PART > ICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary, state=MOVING, > reservations=1, empty=true, createTime=07/05/2018 23:30:40], > dir=[topVer=(351, 0), idx=6, sup=10.126.12.142 > :47500] > 2018-07-06 02:25:53.976[INFO > ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander]Completed > (final) rebalancing [fromNode=d38ca303-91a3-4805-b2bc-8231 > 721924e2, > cacheOrGroup=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary, > topology=AffinityTopologyVersion [topVer=351, minorTopVer=0], time=20 ms] > 2018-07-06 02:25:53.976[INFO > ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander]Completed > rebalance future: RebalanceFuture [grp=CacheGroupContext [ > grp=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb.unif.formats.UnifDictionary], > topVer=AffinityTopologyVersion [topVer=351, minorTopVer=0], rebalanceId=2018] > 2018-07-06 02:25:53.977[INFO > ][sys-#1365%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#1365%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager]WAL > enabled for [grp=CACHEGROUP_PARTICLE_union-module_ru.sbt.pprb. > unif.formats.UnifDictionary] > But Visor still showed 99,99% status on that node. > Later on when a client node left topology Visor status has changed to > Rebalnce completed > See log messages: > 2018-07-06 02:57:46.629[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.ignite.internal.exchange.time]Started > exchange init [topVer=AffinityTopologyVersion [topVer=352, > minorTopVer=0], crd=false, evt=NODE_LEFT, > evtNode=1d2dcbc7-f143-42cd-9130-145e4c199c0e, customEvt=null, allowMerge=true] > 2018-07-06 02:57:47.376[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq BGP_BGPConfigurationImpl_gbk-main -> 243 [A > FTER_EXCHANGE] > 2018-07-06 02:57:47.376[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq BGP_ExpiryEntryImpl_BGP -> 243 [AFTER_EXCHA > NGE] > 2018-07-06 02:57:47.376[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.ca > rd.cdm.api.dictionaries.sys.PartitioningCriteriaTen -> 1158 [AFTER_EXCHANGE] > 2018-07-06 02:57:47.383[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq CACHEGROUP_PARTICLE_union-module_ru.sbrf.au > totransact.model.keys.DateKey -> 1157 [AFTER_EXCHANGE] > 2018-07-06 02:57:47.390[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.tw > .data.dpl.entity.ServiceZone -> 1159 [AFTER_EXCHANGE] > 2018-07-06 02:57:47.397[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq CACHEGROUP_PARTICLE_union-module_com.sbt.ac > quiring.processing.entities.dictionaries.PublishedDepTerBank -> 1158 > [AFTER_EXCHANGE] > 2018-07-06 02:57:47.403[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.d.d.GridDhtPartitionTopologyImpl] > Top upd seq BGP_Locks_auto-transact -> 244 [AFTER_EXCHA > NGE] > 2018-07-06 02:57:47.912[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager] > WAL enabled for [grp=CACHEGROUP_PARTICLE_gbk-main_com.s > bt.gbk.entities.Segmentation] > 2018-07-06 02:57:47.912[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.p.GridCacheDatabaseSharedManager] > WAL enabled for [grp=CACHEGROUP_PARTICLE_union-module_c > om.sbt.gbk.entities.Segmentation] > 2018-07-06 02:57:47.913[INFO > ][exchange-worker-#152%DPL_GRID%DplGridNodeName%|https://ggsystems.atlassian.net/browse/GG-13983#152%DPL_GRID%DplGridNodeName%][o.a.i.i.p.c.GridCachePartitionExchangeManager] > Skipping rebalancing (nothing scheduled) [top=Affinity > TopologyVersion [topVer=352, minorTopVer=0], evt=NODE_LEFT, > node=1d2dcbc7-f143-42cd-9130-145e4c199c0e] -- This message was sent by Atlassian JIRA (v7.6.3#76005)