Merge branch 'fix/ZSTAC-72079-similarity-perf' into '5.5.12'

<fix>[utils]: fix StringSimilarity concurrency, distance filter, slow log (ZSTAC-72079)

See merge request zstackio/zstack!9269

Author: gitlab

core/src/main/java/org/zstack/core/CoreGlobalProperty.java

@@ -12,6 +12,8 @@ public class CoreGlobalProperty {
     @GlobalProperty(name = "unitTestOn", defaultValue = "false")
     @AvailableValues(value ={"true","false"})
     public static boolean UNIT_TEST_ON;
+    @GlobalProperty(name = "elaboration.slowThresholdMs", defaultValue = "0")
+    public static long ELABORATION_SLOW_THRESHOLD_MS;
     @GlobalProperty(name = "beanRefContextConf", defaultValue = "beanRefContext.xml")
     public static String BEAN_REF_CONTEXT_CONF;
     @GlobalProperty(name = "beanConf", defaultValue = "zstack.xml")

core/src/main/java/org/zstack/core/Platform.java

@@ -936,7 +936,14 @@ public static boolean killProcess(int pid, Integer timeout) {
         }
     }
 
+    private static volatile boolean slowElaborationWired = false;
+
     private static ErrorCodeElaboration elaborate(String fmt, Object...args) {
+        if (!slowElaborationWired) {
+            StringSimilarity.slowElaborationThresholdMs = CoreGlobalProperty.ELABORATION_SLOW_THRESHOLD_MS;
+            slowElaborationWired = true;
+        }
+
         try {
             ErrorCodeElaboration elaboration = StringSimilarity.findSimilar(fmt, args);
             if (elaboration == null) {

test/src/test/resources/zstack.properties

@@ -45,6 +45,7 @@ Zdfs.agentPort=8989
 ApiMediator.apiWorkerNum=50
 
 unitTestOn=true
+elaboration.slowThresholdMs=200
 exitJVMOnStop=false
 
 #CloudBus.closeTracker=true

utils/src/main/java/org/zstack/utils/string/StringSimilarity.java

@@ -32,6 +32,9 @@ public class StringSimilarity {
 
     private static final int mapLength = 1500;
     public static int maxElaborationRegex = 8192;
+    // slow elaboration warn threshold in ms; 0 = disabled (default)
+    // enable via GlobalProperty or test setup: StringSimilarity.slowElaborationThresholdMs = 200;
+    public static long slowElaborationThresholdMs = 0;
 
     // matched errors
     private static final Map<String, ErrorCodeElaboration> errors = new LinkedHashMap<String, ErrorCodeElaboration>(mapLength, 0.9f, true) {
@@ -280,8 +283,15 @@ private static boolean isRedundant(String sub) {
     }
 
     private static void logSearchSpend(String sub, long start, boolean found) {
-        logger.debug(String.format("[%s] spend %s ms to search elaboration \"%s\"", found, System.currentTimeMillis() - start,
-                sub.length() > 50 ? sub.substring(0 , 50) + "..." : sub));
+        long cost = System.currentTimeMillis() - start;
+        if (slowElaborationThresholdMs > 0 && cost > slowElaborationThresholdMs) {
+            logger.warn(String.format("[SLOW-ELABORATION] cost %d ms, found=%s, input_len=%d, input=%s",
+                    cost, found, sub.length(),
+                    sub.length() > 100 ? sub.substring(0, 100) + "..." : sub));
+        } else {
+            logger.debug(String.format("[%s] spend %s ms to search elaboration \"%s\"", found, cost,
+                    sub.length() > 50 ? sub.substring(0, 50) + "..." : sub));
+        }
     }
 
     /**
@@ -306,7 +316,10 @@ public static ErrorCodeElaboration findSimilar(String sub, Object...args) {
         }
 
         long start = System.currentTimeMillis();
-        ErrorCodeElaboration err = errors.get(sub);
+        ErrorCodeElaboration err;
+        synchronized (errors) {
+            err = errors.get(sub);
+        }
         if (err != null && verifyElaboration(err, sub, args)) {
             logSearchSpend(sub, start, true);
             return err;
@@ -317,20 +330,26 @@ public static ErrorCodeElaboration findSimilar(String sub, Object...args) {
         // same cause will happen
         // invalid cache, generate elaboration again
         if (err != null) {
-            errors.remove(sub);
+            synchronized (errors) {
+                errors.remove(sub);
+            }
         }
 
         // check missed cache for both fmt template and formatted string
-        if (missed.get(sub) != null) {
-            logSearchSpend(sub, start, false);
-            return null;
+        synchronized (missed) {
+            if (missed.get(sub) != null) {
+                logSearchSpend(sub, start, false);
+                return null;
+            }
         }
         if (args != null) {
             try {
                 String formatted = String.format(sub, args);
-                if (missed.get(formatted) != null) {
-                    logSearchSpend(sub, start, false);
-                    return null;
+                synchronized (missed) {
+                    if (missed.get(formatted) != null) {
+                        logSearchSpend(sub, start, false);
+                        return null;
+                    }
                 }
             } catch (Exception e) {
                 logger.trace(String.format("failed to format elaboration key: %s", e.getMessage()));