IGNITE-23645 Added logging of cache group partition eviction (#11672)

Author: oleg-vlsk

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/preloader/GridDhtPartitionDemander.java

@@ -1207,8 +1207,14 @@ public void requestPartitions() {
                                     return;
                                 }
 
-                                if (waitCnt.decrementAndGet() == 0)
+                                if (waitCnt.decrementAndGet() == 0) {
+                                    U.log(log, "Eviction completed successfully" +
+                                        " [grp=" + grp.cacheOrGroupName() + ", reason='preparation for rebalancing'" +
+                                        ", evictedPartsCount=" + parts.size() +
+                                        ", evictedParts=" + S.toStringSortedDistinct(d.partitions().fullSet()) + "]");
+
                                     ctx.kernalContext().closure().runLocalSafe((GridPlainRunnable)() -> requestPartitions0(node, parts, d));
+                                }
                             }
                         });
                     }

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtLocalPartition.java

@@ -132,7 +132,7 @@ public class GridDhtLocalPartition extends GridCacheConcurrentMapImpl implements
 
     /** Rent future. */
     @GridToStringExclude
-    private final GridFutureAdapter<?> rent;
+    private final RentFuture rent;
 
     /** */
     @GridToStringExclude
@@ -212,11 +212,7 @@ public GridDhtLocalPartition(
             cacheMaps = null;
         }
 
-        rent = new GridFutureAdapter<Object>() {
-            @Override public String toString() {
-                return "PartitionRentFuture [part=" + GridDhtLocalPartition.this + ']';
-            }
-        };
+        rent = new RentFuture();
 
         int delQueueSize = grp.systemCache() ? 100 :
             Math.max(MAX_DELETE_QUEUE_SIZE / grp.affinity().partitions(), 20);
@@ -694,7 +690,7 @@ public boolean markLost() {
      * @return Future to signal that this node is no longer an owner or backup or null if corresponding partition
      * state is {@code RENTING} or {@code EVICTED}.
      */
-    public IgniteInternalFuture<?> rent() {
+    public RentFuture rent() {
         long state0 = this.state.get();
 
         GridDhtPartitionState partState = getPartState(state0);
@@ -1409,4 +1405,17 @@ public void dumpDebugInfo(SB buf) {
 
         buf.a(']');
     }
+
+    /** */
+    public class RentFuture extends GridFutureAdapter<Void> {
+        /** */
+        public int partitionId() {
+            return id;
+        }
+
+        /** {@inheritDoc} */
+        @Override public String toString() {
+            return S.toString(RentFuture.class, this);
+        }
+    }
 }

modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtPartitionTopologyImpl.java

@@ -62,6 +62,7 @@
 import org.apache.ignite.internal.util.GridLongList;
 import org.apache.ignite.internal.util.GridPartitionStateMap;
 import org.apache.ignite.internal.util.StripedCompositeReadWriteLock;
+import org.apache.ignite.internal.util.future.GridCompoundFuture;
 import org.apache.ignite.internal.util.tostring.GridToStringExclude;
 import org.apache.ignite.internal.util.typedef.F;
 import org.apache.ignite.internal.util.typedef.X;
@@ -467,6 +468,8 @@ else if (added)
             else {
                 // If preloader is disabled, then we simply clear out
                 // the partitions this node is not responsible for.
+                GridCompoundFuture<Void, Void> grpRentFut = new GridCompoundFuture<>();
+
                 for (int p = 0; p < partitions; p++) {
                     GridDhtLocalPartition locPart = localPartition0(p, affVer, false, true);
 
@@ -477,7 +480,7 @@ else if (added)
                             GridDhtPartitionState state = locPart.state();
 
                             if (state.active()) {
-                                locPart.rent();
+                                grpRentFut.add(locPart.rent());
 
                                 updateSeq = updateLocal(p, locPart.state(), updateSeq, affVer);
 
@@ -502,6 +505,8 @@ else if (belongs) {
                         updateLocal(p, locPart.state(), updateSeq, affVer);
                     }
                 }
+
+                logEvictionResults(grpRentFut, "rebalancing is disabled (partitions do not belong to affinity)");
             }
         }
 
@@ -804,6 +809,8 @@ private boolean partitionLocalNode(int p, AffinityTopologyVersion topVer) {
 
                 // Skip partition updates in case of not real exchange.
                 if (!ctx.localNode().isClient() && exchFut.exchangeType() == ALL) {
+                    GridCompoundFuture<Void, Void> grpRentFut = new GridCompoundFuture<>();
+
                     for (int p = 0; p < partitions; p++) {
                         GridDhtLocalPartition locPart = localPartition0(p, topVer, false, true);
 
@@ -835,7 +842,7 @@ private boolean partitionLocalNode(int p, AffinityTopologyVersion topVer) {
                                 GridDhtPartitionState state = locPart.state();
 
                                 if (state == MOVING) {
-                                    locPart.rent();
+                                    grpRentFut.add(locPart.rent());
 
                                     updateSeq = updateLocal(p, locPart.state(), updateSeq, topVer);
 
@@ -849,6 +856,8 @@ private boolean partitionLocalNode(int p, AffinityTopologyVersion topVer) {
                             }
                         }
                     }
+
+                    logEvictionResults(grpRentFut, "MOVING partitions do not belong to affinity");
                 }
 
                 AffinityAssignment aff = grp.affinity().readyAffinity(topVer);
@@ -2538,6 +2547,8 @@ private boolean checkEvictions(long updateSeq, AffinityAssignment aff) {
 
         UUID locId = ctx.localNodeId();
 
+        GridCompoundFuture<Void, Void> grpRentFut = new GridCompoundFuture<>();
+
         for (int p = 0; p < locParts.length(); p++) {
             GridDhtLocalPartition part = locParts.get(p);
 
@@ -2557,7 +2568,7 @@ private boolean checkEvictions(long updateSeq, AffinityAssignment aff) {
             if (nodeIds.containsAll(nodeIds(affNodes))) {
                 GridDhtPartitionState state0 = part.state();
 
-                part.rent();
+                grpRentFut.add(part.rent());
 
                 updateSeq = updateLocal(part.id(), part.state(), updateSeq, aff.topologyVersion());
 
@@ -2586,7 +2597,7 @@ private boolean checkEvictions(long updateSeq, AffinityAssignment aff) {
                         if (locId.equals(n.id())) {
                             GridDhtPartitionState state0 = part.state();
 
-                            part.rent();
+                            grpRentFut.add(part.rent());
 
                             updateSeq = updateLocal(part.id(), part.state(), updateSeq, aff.topologyVersion());
 
@@ -2607,6 +2618,8 @@ private boolean checkEvictions(long updateSeq, AffinityAssignment aff) {
             }
         }
 
+        logEvictionResults(grpRentFut, "partitions no longer belong to affinity");
+
         return hasEvictedPartitions;
     }
 
@@ -3360,6 +3373,41 @@ private String dumpPartitionStates() {
         return sb.toString();
     }
 
+    /**
+     * Prints eviction results to the log.
+     *
+     * @param grpRentFut Group rent future.
+     * @param reason Eviction reason.
+     */
+    private void logEvictionResults(GridCompoundFuture<Void, Void> grpRentFut, String reason) {
+        grpRentFut.markInitialized();
+
+        grpRentFut.listen(() -> {
+            Collection<GridDhtLocalPartition.RentFuture> futs =
+                F.viewReadOnly(grpRentFut.futures(), f -> (GridDhtLocalPartition.RentFuture)f);
+
+            if (futs.isEmpty())
+                return;
+
+            Collection<Integer> evicted = F.viewReadOnly(futs, GridDhtLocalPartition.RentFuture::partitionId, f -> f.error() == null);
+            Collection<Integer> failed = F.viewReadOnly(futs, GridDhtLocalPartition.RentFuture::partitionId, f -> f.error() != null);
+
+            boolean allEvicted = failed.isEmpty();
+
+            String msg = "Eviction completed" +
+                (allEvicted ? " successfully" : " with failures (some partitions failed to evict)") +
+                " [grp=" + grp.cacheOrGroupName() + ", reason='" + reason + "'" +
+                ", evictedPartsCount=" + evicted.size() + ", evictedParts=" + S.toStringSortedDistinct(evicted) +
+                (allEvicted ? "" : ", nonEvictedPartsCount=" + failed.size() +
+                ", nonEvictedParts=" + S.toStringSortedDistinct(failed)) + "]";
+
+            if (allEvicted)
+                log.info(msg);
+            else
+                log.warning(msg);
+        });
+    }
+
     /**
      * Iterator over current local partitions.
      */

modules/core/src/test/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtLocalPartitionSyncEviction.java

@@ -19,7 +19,6 @@
 
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.TimeUnit;
-import org.apache.ignite.internal.IgniteInternalFuture;
 import org.apache.ignite.internal.IgniteInterruptedCheckedException;
 import org.apache.ignite.internal.NodeStoppingException;
 import org.apache.ignite.internal.processors.cache.CacheGroupContext;
@@ -75,7 +74,7 @@ public GridDhtLocalPartitionSyncEviction(
     }
 
     /** {@inheritDoc} */
-    @Override public IgniteInternalFuture<?> rent() {
+    @Override public RentFuture rent() {
         if (mode == 0)
             sync();