feat(log): slow signature verifications above 50ms

Author: halibobo1205

chainbase/src/main/java/org/tron/core/capsule/TransactionCapsule.java

@@ -35,6 +35,7 @@
 import java.util.List;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Future;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
 import lombok.Getter;
 import lombok.Setter;
@@ -94,6 +95,8 @@ public class TransactionCapsule implements ProtoCapsule<Transaction> {
       .newFixedThreadPool(esName, CommonParameter.getInstance()
           .getValidContractProtoThreadNum());
   private static final String OWNER_ADDRESS = "ownerAddress_";
+  // 2-6 ms in general, so we set 50 ms as the threshold for slow signature verification.
+  private static final long SLOW_SIG_VERIFY_MS = 50;
 
   private Transaction transaction;
   @Setter
@@ -648,6 +651,7 @@ public boolean validatePubSignature(AccountStore accountStore,
 
       byte[] hash = getTransactionId().getBytes();
 
+      long startNs = System.nanoTime();
       try {
         if (!validateSignature(this.transaction, hash, accountStore, dynamicPropertiesStore)) {
           isVerified = false;
@@ -656,12 +660,27 @@ public boolean validatePubSignature(AccountStore accountStore,
       } catch (SignatureException | PermissionException | SignatureFormatException e) {
         isVerified = false;
         throw new ValidateSignatureException(e.getMessage());
+      } finally {
+        logSlowSigVerify(startNs);
       }
       isVerified = true;
     }
     return true;
   }
 
+  /**
+   * INFO-logs when a single signature verification exceeds
+   * {@link #SLOW_SIG_VERIFY_MS}. Package-private so it can be exercised from
+   * tests without forcing a real slow crypto path.
+   */
+  void logSlowSigVerify(long startNs) {
+    long costMs = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNs);
+    if (costMs > SLOW_SIG_VERIFY_MS) {
+      logger.info("slow verify: txId={}, sigCount={}, cost={} ms",
+          getTransactionId(), this.transaction.getSignatureCount(), costMs);
+    }
+  }
+
   /**
    * validate signature
    */

framework/src/test/java/org/tron/core/capsule/TransactionCapsuleTest.java

@@ -4,12 +4,20 @@
 import static org.tron.protos.Protocol.Transaction.Result.contractResult.PRECOMPILED_CONTRACT;
 import static org.tron.protos.Protocol.Transaction.Result.contractResult.SUCCESS;
 
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import com.google.protobuf.ByteString;
+import java.util.List;
+import java.util.concurrent.TimeUnit;
+import java.util.stream.Collectors;
 import lombok.extern.slf4j.Slf4j;
 import org.junit.Assert;
 import org.junit.Before;
 import org.junit.BeforeClass;
 import org.junit.Test;
+import org.slf4j.LoggerFactory;
 import org.tron.common.BaseTest;
 import org.tron.common.TestConstants;
 import org.tron.common.utils.StringUtil;
@@ -69,4 +77,61 @@ public void testRemoveRedundantRet() {
     Assert.assertEquals(1, transactionCapsule.getInstance().getRetCount());
     Assert.assertEquals(SUCCESS, transactionCapsule.getInstance().getRet(0).getContractRet());
   }
+
+  @Test
+  public void slowVerify() {
+    Logger capsuleLogger = (Logger) LoggerFactory.getLogger("capsule");
+    Level originalLevel = capsuleLogger.getLevel();
+    capsuleLogger.setLevel(Level.INFO);
+    ListAppender<ILoggingEvent> appender = new ListAppender<>();
+    appender.start();
+    capsuleLogger.addAppender(appender);
+    try {
+      TransactionCapsule cap = new TransactionCapsule(Transaction.newBuilder().build());
+      long startNs = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos(51);
+      cap.logSlowSigVerify(startNs);
+
+      List<ILoggingEvent> infos = appender.list.stream()
+          .filter(e -> e.getLevel() == Level.INFO)
+          .collect(Collectors.toList());
+      Assert.assertEquals("expected one INFO for a slow verify", 1, infos.size());
+      String rendered = infos.get(0).getFormattedMessage();
+      Assert.assertTrue("INFO should mention slow verify: " + rendered,
+          rendered.contains("slow verify"));
+      Assert.assertTrue("INFO should echo the txId: " + rendered,
+          rendered.contains(cap.getTransactionId().toString()));
+      Assert.assertTrue("INFO should include sigCount: " + rendered,
+          rendered.contains("sigCount="));
+      Assert.assertTrue("INFO should include cost in ms: " + rendered,
+          rendered.contains("cost="));
+      Assert.assertTrue("INFO should render ms suffix: " + rendered,
+          rendered.contains(" ms"));
+    } finally {
+      appender.stop();
+      capsuleLogger.detachAppender(appender);
+      capsuleLogger.setLevel(originalLevel);
+    }
+  }
+
+  @Test
+  public void fastVerify() {
+    Logger capsuleLogger = (Logger) LoggerFactory.getLogger("capsule");
+    Level originalLevel = capsuleLogger.getLevel();
+    capsuleLogger.setLevel(Level.INFO);
+    ListAppender<ILoggingEvent> appender = new ListAppender<>();
+    appender.start();
+    capsuleLogger.addAppender(appender);
+    try {
+      TransactionCapsule cap = new TransactionCapsule(Transaction.newBuilder().build());
+      cap.logSlowSigVerify(System.nanoTime());
+      long infoCount = appender.list.stream()
+          .filter(e -> e.getLevel() == Level.INFO)
+          .count();
+      Assert.assertEquals("no INFO should fire below the threshold", 0, infoCount);
+    } finally {
+      appender.stop();
+      capsuleLogger.detachAppender(appender);
+      capsuleLogger.setLevel(originalLevel);
+    }
+  }
 }