refactor(server): add logs for load-based request rejection (#2972)

* fix(filter): enhance load detection logging and memory management
* fix(api): refine low-memory rejection handling

Author: contrueCT

hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/LoadDetectFilter.java

@@ -19,12 +19,16 @@
 
 import java.util.List;
 import java.util.Set;
+import java.util.function.BooleanSupplier;
+import java.util.function.LongSupplier;
 
 import org.apache.hugegraph.config.HugeConfig;
 import org.apache.hugegraph.config.ServerOptions;
 import org.apache.hugegraph.define.WorkLoad;
 import org.apache.hugegraph.util.Bytes;
 import org.apache.hugegraph.util.E;
+import org.apache.hugegraph.util.Log;
+import org.slf4j.Logger;
 
 import com.google.common.collect.ImmutableSet;
 import com.google.common.util.concurrent.RateLimiter;
@@ -43,6 +47,8 @@
 @PreMatching
 public class LoadDetectFilter implements ContainerRequestFilter {
 
+    private static final Logger LOG = Log.logger(LoadDetectFilter.class);
+
     private static final Set<String> WHITE_API_LIST = ImmutableSet.of(
             "",
             "apis",
@@ -54,10 +60,44 @@ public class LoadDetectFilter implements ContainerRequestFilter {
     private static final RateLimiter GC_RATE_LIMITER =
             RateLimiter.create(1.0 / 30);
 
+    // Log at most 1 request per second to avoid too many logs when server is under heavy load
+    private static final RateLimiter BUSY_REJECT_LOG_RATE_LIMITER =
+            RateLimiter.create(1.0);
+    private static final RateLimiter MEMORY_REJECT_LOG_RATE_LIMITER =
+            RateLimiter.create(1.0);
+
     @Context
     private jakarta.inject.Provider<HugeConfig> configProvider;
     @Context
     private jakarta.inject.Provider<WorkLoad> loadProvider;
+    private BooleanSupplier gcTrigger = LoadDetectFilter::triggerGcIfNeeded;
+    private BooleanSupplier busyRejectLogPermit =
+            BUSY_REJECT_LOG_RATE_LIMITER::tryAcquire;
+    private BooleanSupplier memoryRejectLogPermit =
+            MEMORY_REJECT_LOG_RATE_LIMITER::tryAcquire;
+    private LongSupplier freeMemorySupplier = LoadDetectFilter::currentFreeMemoryInMB;
+
+    public static boolean isWhiteAPI(ContainerRequestContext context) {
+        List<PathSegment> segments = context.getUriInfo().getPathSegments();
+        E.checkArgument(!segments.isEmpty(), "Invalid request uri '%s'",
+                        context.getUriInfo().getPath());
+        String rootPath = segments.get(0).getPath();
+        return WHITE_API_LIST.contains(rootPath);
+    }
+
+    private static boolean triggerGcIfNeeded() {
+        if (GC_RATE_LIMITER.tryAcquire(1)) {
+            System.gc();
+            return true;
+        }
+        return false;
+    }
+
+    private static long currentFreeMemoryInMB() {
+        long allocatedMem = Runtime.getRuntime().totalMemory() -
+                            Runtime.getRuntime().freeMemory();
+        return (Runtime.getRuntime().maxMemory() - allocatedMem) / Bytes.MB;
+    }
 
     @Override
     public void filter(ContainerRequestContext context) {
@@ -70,20 +110,50 @@ public void filter(ContainerRequestContext context) {
         int maxWorkerThreads = config.get(ServerOptions.MAX_WORKER_THREADS);
         WorkLoad load = this.loadProvider.get();
         // There will be a thread doesn't work, dedicated to statistics
-        if (load.incrementAndGet() >= maxWorkerThreads) {
+        int currentLoad = load.incrementAndGet();
+        if (currentLoad >= maxWorkerThreads) {
+            if (this.busyRejectLogPermit.getAsBoolean()) {
+                LOG.warn("Rejected request due to high worker load, method={}, path={}, " +
+                         "currentLoad={}, maxWorkerThreads={}",
+                         context.getMethod(), context.getUriInfo().getPath(),
+                         currentLoad, maxWorkerThreads);
+            }
             throw new ServiceUnavailableException(String.format(
                     "The server is too busy to process the request, " +
                     "you can config %s to adjust it or try again later",
                     ServerOptions.MAX_WORKER_THREADS.name()));
         }
 
         long minFreeMemory = config.get(ServerOptions.MIN_FREE_MEMORY);
-        long allocatedMem = Runtime.getRuntime().totalMemory() -
-                            Runtime.getRuntime().freeMemory();
-        long presumableFreeMem = (Runtime.getRuntime().maxMemory() -
-                                  allocatedMem) / Bytes.MB;
+        long presumableFreeMem = this.freeMemorySupplier.getAsLong();
         if (presumableFreeMem < minFreeMemory) {
-            gcIfNeeded();
+            boolean gcTriggered = this.gcTrigger.getAsBoolean();
+            if (gcTriggered) {
+                long recheckedFreeMem = this.freeMemorySupplier.getAsLong();
+                if (recheckedFreeMem >= minFreeMemory) {
+                    if (this.memoryRejectLogPermit.getAsBoolean()) {
+                        LOG.warn("Low free memory recovered after GC, method={}, path={}, " +
+                                 "presumableFreeMemMB={}, recheckedFreeMemMB={}, " +
+                                 "minFreeMemoryMB={}",
+                                 context.getMethod(), context.getUriInfo().getPath(),
+                                 presumableFreeMem, recheckedFreeMem, minFreeMemory);
+                    }
+                    return;
+                }
+                if (this.memoryRejectLogPermit.getAsBoolean()) {
+                    LOG.warn("Rejected request due to low free memory after GC, " +
+                             "method={}, path={}, presumableFreeMemMB={}, " +
+                             "recheckedFreeMemMB={}, minFreeMemoryMB={}",
+                             context.getMethod(), context.getUriInfo().getPath(),
+                             presumableFreeMem, recheckedFreeMem, minFreeMemory);
+                }
+                presumableFreeMem = recheckedFreeMem;
+            } else if (this.memoryRejectLogPermit.getAsBoolean()) {
+                LOG.warn("Rejected request due to low free memory, method={}, path={}, " +
+                         "presumableFreeMemMB={}, minFreeMemoryMB={}",
+                         context.getMethod(), context.getUriInfo().getPath(),
+                         presumableFreeMem, minFreeMemory);
+            }
             throw new ServiceUnavailableException(String.format(
                     "The server available memory %s(MB) is below than " +
                     "threshold %s(MB) and can't process the request, " +
@@ -92,18 +162,4 @@ public void filter(ContainerRequestContext context) {
                     ServerOptions.MIN_FREE_MEMORY.name()));
         }
     }
-
-    public static boolean isWhiteAPI(ContainerRequestContext context) {
-        List<PathSegment> segments = context.getUriInfo().getPathSegments();
-        E.checkArgument(!segments.isEmpty(), "Invalid request uri '%s'",
-                        context.getUriInfo().getPath());
-        String rootPath = segments.get(0).getPath();
-        return WHITE_API_LIST.contains(rootPath);
-    }
-
-    private static void gcIfNeeded() {
-        if (GC_RATE_LIMITER.tryAcquire(1)) {
-            System.gc();
-        }
-    }
 }

hugegraph-server/hugegraph-test/src/main/java/org/apache/hugegraph/unit/UnitTestSuite.java

@@ -18,6 +18,7 @@
 package org.apache.hugegraph.unit;
 
 import org.apache.hugegraph.core.RoleElectionStateMachineTest;
+import org.apache.hugegraph.unit.api.filter.LoadDetectFilterTest;
 import org.apache.hugegraph.unit.api.filter.PathFilterTest;
 import org.apache.hugegraph.unit.api.gremlin.GremlinQueryAPITest;
 import org.apache.hugegraph.unit.auth.HugeGraphAuthProxyTest;
@@ -80,6 +81,7 @@
 @RunWith(Suite.class)
 @Suite.SuiteClasses({
         /* api filter */
+        LoadDetectFilterTest.class,
         PathFilterTest.class,
 
         /* api gremlin */