Add more logging to the real memory circuit breaker and lower minimum interval (#102396) (#102443)

It lowers the minimumInterval from 5000ms to 500ms as we observed high number of CBEs when there are bursting 
allocations in newer JDKs.

Author: iverase

docs/changelog/102396.yaml

@@ -0,0 +1,5 @@
+pr: 102396
+summary: Add more logging to the real memory circuit breaker and lower minimum interval
+area: "Infra/Circuit Breakers"
+type: bug
+issues: []

server/src/main/java/org/elasticsearch/indices/breaker/HierarchyCircuitBreakerService.java

@@ -520,7 +520,7 @@ static OverLimitStrategy createOverLimitStrategy(boolean trackRealMemoryUsage) {
                 HierarchyCircuitBreakerService::realMemoryUsage,
                 createYoungGcCountSupplier(),
                 System::currentTimeMillis,
-                5000,
+                500,
                 lockTimeout
             );
         } else {
@@ -561,6 +561,8 @@ static class G1OverLimitStrategy implements OverLimitStrategy {
 
         private long blackHole;
         private final ReleasableLock lock = new ReleasableLock(new ReentrantLock());
+        // used to throttle logging
+        private int attemptNo;
 
         G1OverLimitStrategy(
             JvmInfo jvmInfo,
@@ -607,9 +609,12 @@ public MemoryUsage overLimit(MemoryUsage memoryUsed) {
             boolean leader = false;
             int allocationIndex = 0;
             long allocationDuration = 0;
+            long begin = 0;
+            int attemptNoCopy = 0;
             try (ReleasableLock locked = lock.tryAcquire(lockTimeout)) {
                 if (locked != null) {
-                    long begin = timeSupplier.getAsLong();
+                    attemptNoCopy = ++this.attemptNo;
+                    begin = timeSupplier.getAsLong();
                     leader = begin >= lastCheckTime + minimumInterval;
                     overLimitTriggered(leader);
                     if (leader) {
@@ -641,9 +646,11 @@ public MemoryUsage overLimit(MemoryUsage memoryUsed) {
                         long now = timeSupplier.getAsLong();
                         this.lastCheckTime = now;
                         allocationDuration = now - begin;
+                        this.attemptNo = 0;
                     }
                 }
             } catch (InterruptedException e) {
+                logger.info("could not acquire lock when attempting to trigger G1GC due to high heap usage");
                 Thread.currentThread().interrupt();
                 // fallthrough
             }
@@ -658,6 +665,13 @@ public MemoryUsage overLimit(MemoryUsage memoryUsed) {
                         allocationIndex,
                         allocationDuration
                     );
+                } else if (attemptNoCopy < 10 || Long.bitCount(attemptNoCopy) == 1) {
+                    logger.info(
+                        "memory usage down after [{}], before [{}], after [{}]",
+                        begin - lastCheckTime,
+                        memoryUsed.baseUsage,
+                        current
+                    );
                 }
                 return new MemoryUsage(
                     current,
@@ -674,6 +688,13 @@ public MemoryUsage overLimit(MemoryUsage memoryUsed) {
                         allocationIndex,
                         allocationDuration
                     );
+                } else if (attemptNoCopy < 10 || Long.bitCount(attemptNoCopy) == 1) {
+                    logger.info(
+                        "memory usage not down after [{}], before [{}], after [{}]",
+                        begin - lastCheckTime,
+                        memoryUsed.baseUsage,
+                        current
+                    );
                 }
                 // prefer original measurement when reporting if heap usage was not brought down.
                 return memoryUsed;