perf: log4j overhead for inactive markers is too high (#16921)

Signed-off-by: Oleg Mazurov <[email protected]>
hashgraph · Dec 7, 2024 · e70582e · e70582e
1 parent faee49d
commit e70582e
Show file tree

Hide file tree

Showing 6 changed files with 109 additions and 75 deletions.
diff --git a/hedera-node/data/config/node-admin-keys.json b/hedera-node/data/config/node-admin-keys.json
@@ -0,0 +1,4 @@
+{
+  "0": "0aa8e21064c61eab86e2a9c164565b4e7a9a4146106e0a6cd03a8c395a110e92"
+}
+
diff --git a/platform-sdk/swirlds-platform-core/src/main/java/com/swirlds/platform/ConsensusImpl.java b/platform-sdk/swirlds-platform-core/src/main/java/com/swirlds/platform/ConsensusImpl.java
@@ -659,14 +659,16 @@ private void logVote(
             @NonNull final CandidateWitness candidateWitness,
             @NonNull final String votingType,
             final long diff) {
-        logger.info(
-                CONSENSUS_VOTING.getMarker(),
-                "Witness {} voted on {}. vote:{} type:{} diff:{}",
-                votingWitness,
-                candidateWitness.getWitness(),
-                votingWitness.getVote(candidateWitness),
-                votingType,
-                diff);
+        if (logger.isDebugEnabled(CONSENSUS_VOTING.getMarker())) {
+            logger.debug(
+                    CONSENSUS_VOTING.getMarker(),
+                    "Witness {} voted on {}. vote:{} type:{} diff:{}",
+                    votingWitness,
+                    candidateWitness.getWitness(),
+                    votingWitness.getVote(candidateWitness),
+                    votingType,
+                    diff);
+        }
     }
 
     private boolean firstVote(@NonNull final EventImpl voting, @NonNull final EventImpl votedOn) {

diff --git a/.../swirlds-platform-core/src/main/java/com/swirlds/platform/consensus/CandidateWitness.java b/.../swirlds-platform-core/src/main/java/com/swirlds/platform/consensus/CandidateWitness.java
@@ -98,15 +98,17 @@ public void fameDecided(final boolean isFamous) {
         this.decided = true;
         this.famous = isFamous;
 
-        logger.info(
-                CONSENSUS_VOTING.getMarker(),
-                "Fame decided for {}, election round {} unknown fame: {} ",
-                witness,
-                witness.getRoundCreated(),
-                numUnknownFame.get());
+        if (logger.isDebugEnabled(CONSENSUS_VOTING.getMarker())) {
+            logger.debug(
+                    CONSENSUS_VOTING.getMarker(),
+                    "Fame decided for {}, election round {} unknown fame: {} ",
+                    witness,
+                    witness.getRoundCreated(),
+                    numUnknownFame.get());
 
-        if (numUnknownFame.equalsInt(0)) {
-            logger.info(CONSENSUS_VOTING.getMarker(), "Fame decided for round {}", witness.getRoundCreated());
+            if (numUnknownFame.equalsInt(0)) {
+                logger.debug(CONSENSUS_VOTING.getMarker(), "Fame decided for round {}", witness.getRoundCreated());
+            }
         }
     }
 }
diff --git a/...dk/swirlds-platform-core/src/main/java/com/swirlds/platform/consensus/RoundElections.java b/...dk/swirlds-platform-core/src/main/java/com/swirlds/platform/consensus/RoundElections.java
@@ -79,10 +79,12 @@ public void setRound(final long round) {
      * @param witness the witness being added
      */
     public void addWitness(@NonNull final EventImpl witness) {
-        logger.info(
-                CONSENSUS_VOTING.getMarker(),
-                "Adding witness for election {}",
-                witness.getBaseEvent().getDescriptor());
+        if (logger.isDebugEnabled(CONSENSUS_VOTING.getMarker())) {
+            logger.debug(
+                    CONSENSUS_VOTING.getMarker(),
+                    "Adding witness for election {}",
+                    witness.getBaseEvent().getDescriptor());
+        }
         numUnknownFame.increment();
         elections.add(new CandidateWitness(witness, numUnknownFame, elections.size()));
     }

diff --git a/...m-core/src/main/java/com/swirlds/platform/gossip/shadowgraph/ShadowgraphSynchronizer.java b/...m-core/src/main/java/com/swirlds/platform/gossip/shadowgraph/ShadowgraphSynchronizer.java
@@ -421,8 +421,8 @@ private boolean sendAndReceiveEvents(
         logger.info(
                 SYNC_INFO.getMarker(),
                 "{} writing events done, wrote {} events",
-                connection::getDescription,
-                sendList::size);
+                connection.getDescription(),
+                sendList.size());
         logger.info(
                 SYNC_INFO.getMarker(),
                 "{} reading events done, read {} events",

diff --git a/...wirlds-platform-core/src/main/java/com/swirlds/platform/gossip/shadowgraph/SyncUtils.java b/...wirlds-platform-core/src/main/java/com/swirlds/platform/gossip/shadowgraph/SyncUtils.java
@@ -89,16 +89,18 @@ public static Callable<Void> writeMyTipsAndEventWindow(
 
             connection.getDos().writeTipHashes(tipHashes);
             connection.getDos().flush();
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} sent event window: {}",
-                    connection::getDescription,
-                    eventWindow::toString);
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} sent tips: {}",
-                    connection::getDescription,
-                    () -> SyncLogging.toShortShadows(tips));
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} sent event window: {}",
+                        connection::getDescription,
+                        eventWindow::toString);
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} sent tips: {}",
+                        connection::getDescription,
+                        () -> SyncLogging.toShortShadows(tips));
+            }
             return null;
         };
     }
@@ -120,16 +122,18 @@ public static Callable<TheirTipsAndEventWindow> readTheirTipsAndEventWindow(
 
             final List<Hash> tips = connection.getDis().readTipHashes(numberOfNodes);
 
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} received event window: {}",
-                    connection::getDescription,
-                    eventWindow::toString);
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} received tips: {}",
-                    connection::getDescription,
-                    () -> SyncLogging.toShortHashes(tips));
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} received event window: {}",
+                        connection::getDescription,
+                        eventWindow::toString);
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} received tips: {}",
+                        connection::getDescription,
+                        () -> SyncLogging.toShortHashes(tips));
+            }
 
             return new TheirTipsAndEventWindow(eventWindow, tips);
         };
@@ -148,11 +152,13 @@ public static Callable<Void> writeTheirTipsIHave(final Connection connection, fi
         return () -> {
             connection.getDos().writeBooleanList(theirTipsIHave);
             connection.getDos().flush();
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} sent booleans: {}",
-                    connection::getDescription,
-                    () -> SyncLogging.toShortBooleans(theirTipsIHave));
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} sent booleans: {}",
+                        connection::getDescription,
+                        () -> SyncLogging.toShortBooleans(theirTipsIHave));
+            }
             return null;
         };
     }
@@ -171,11 +177,13 @@ public static Callable<List<Boolean>> readMyTipsTheyHave(final Connection connec
             if (booleans == null) {
                 throw new SyncException(connection, "peer sent null booleans");
             }
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} received booleans: {}",
-                    connection::getDescription,
-                    () -> SyncLogging.toShortBooleans(booleans));
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} received booleans: {}",
+                        connection::getDescription,
+                        () -> SyncLogging.toShortBooleans(booleans));
+            }
             return booleans;
         };
     }
@@ -199,23 +207,27 @@ public static Callable<Void> sendEventsTheyNeed(
             final AtomicBoolean writeAborted,
             final Duration syncKeepalivePeriod) {
         return () -> {
-            logger.info(
-                    SYNC_INFO.getMarker(),
-                    "{} writing events start. send list size: {}",
-                    connection.getDescription(),
-                    events.size());
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(
+                        SYNC_INFO.getMarker(),
+                        "{} writing events start. send list size: {}",
+                        connection.getDescription(),
+                        events.size());
+            }
             for (final PlatformEvent event : events) {
                 connection.getDos().writeByte(ByteConstants.COMM_EVENT_NEXT);
                 connection.getDos().writePbjRecord(event.getGossipEvent(), GossipEvent.PROTOBUF);
             }
             if (writeAborted.get()) {
                 logger.info(SYNC_INFO.getMarker(), "{} writing events aborted", connection.getDescription());
             } else {
-                logger.info(
-                        SYNC_INFO.getMarker(),
-                        "{} writing events done, wrote {} events",
-                        connection.getDescription(),
-                        events.size());
+                if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                    logger.debug(
+                            SYNC_INFO.getMarker(),
+                            "{} writing events done, wrote {} events",
+                            connection.getDescription(),
+                            events.size());
+                }
                 connection.getDos().writeByte(ByteConstants.COMM_EVENT_DONE);
             }
             connection.getDos().flush();
@@ -232,7 +244,9 @@ public static Callable<Void> sendEventsTheyNeed(
             connection.getDos().writeByte(ByteConstants.COMM_SYNC_DONE);
             connection.getDos().flush();
 
-            logger.debug(SYNC_INFO.getMarker(), "{} sent COMM_SYNC_DONE", connection.getDescription());
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(SYNC_INFO.getMarker(), "{} sent COMM_SYNC_DONE", connection.getDescription());
+            }
 
             // (ignored)
             return null;
@@ -263,7 +277,9 @@ public static Callable<Integer> readEventsINeed(
             @NonNull final Duration maxSyncTime) {
 
         return () -> {
-            logger.info(SYNC_INFO.getMarker(), "{} reading events start", connection.getDescription());
+            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                logger.debug(SYNC_INFO.getMarker(), "{} reading events start", connection.getDescription());
+            }
             int eventsRead = 0;
             try {
                 final long startTime = System.nanoTime();
@@ -299,11 +315,13 @@ public static Callable<Integer> readEventsINeed(
                             eventsRead = Integer.MIN_VALUE;
                         }
                         case ByteConstants.COMM_EVENT_DONE -> {
-                            logger.info(
-                                    SYNC_INFO.getMarker(),
-                                    "{} reading events done, read {} events",
-                                    connection.getDescription(),
-                                    eventsRead);
+                            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                                logger.debug(
+                                        SYNC_INFO.getMarker(),
+                                        "{} reading events done, read {} events",
+                                        connection.getDescription(),
+                                        eventsRead);
+                            }
                             syncMetrics.eventsReceived(startTime, eventsRead);
                             // we are done reading event, tell the writer thread to send a COMM_SYNC_DONE
                             eventReadingDone.countDown();
@@ -313,14 +331,20 @@ public static Callable<Integer> readEventsINeed(
                             // if they are still busy reading events
                         case ByteConstants.COMM_SYNC_ONGOING -> {
                             // peer is still reading events, waiting for them to finish
-                            logger.debug(
-                                    SYNC_INFO.getMarker(),
-                                    "{} received COMM_SYNC_ONGOING",
-                                    connection.getDescription());
+                            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                                logger.debug(
+                                        SYNC_INFO.getMarker(),
+                                        "{} received COMM_SYNC_ONGOING",
+                                        connection.getDescription());
+                            }
                         }
                         case ByteConstants.COMM_SYNC_DONE -> {
-                            logger.debug(
-                                    SYNC_INFO.getMarker(), "{} received COMM_SYNC_DONE", connection.getDescription());
+                            if (logger.isDebugEnabled(SYNC_INFO.getMarker())) {
+                                logger.debug(
+                                        SYNC_INFO.getMarker(),
+                                        "{} received COMM_SYNC_DONE",
+                                        connection.getDescription());
+                            }
                             return eventsRead;
                         }
                         default -> throw new SyncException(