Print time

dlg99 · May 16, 2024 · 98a3d25 · 98a3d25
1 parent 1887c44
commit 98a3d25
Showing 1 changed file with 11 additions and 1 deletion.
diff --git a/managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java b/managed-ledger/src/main/java/org/apache/bookkeeper/mledger/impl/ManagedCursorImpl.java
@@ -3289,6 +3289,7 @@ private static ByteBuf toByteBuf(LightMLDataFormats.PositionInfo pi) {
     }
 
     void persistPositionToLedger(final LedgerHandle lh, MarkDeleteEntry mdEntry, final VoidCallback callback) {
+        long now = System.nanoTime();
         PositionImpl position = mdEntry.newPosition;
 
         LightMLDataFormats.PositionInfo pi = piThreadLocal.get();
@@ -3307,10 +3308,13 @@ void persistPositionToLedger(final LedgerHandle lh, MarkDeleteEntry mdEntry, fin
 
         requireNonNull(lh);
         ByteBuf rawData = toByteBuf(pi);
+        long endSer = System.nanoTime();
 
         // rawData is released by compressDataIfNeeded if needed
         ByteBuf data = compressDataIfNeeded(rawData, lh);
 
+        long endCompress = System.nanoTime();
+
         int maxSize = 1024 * 1024;
         int offset = 0;
         final int len = data.readableBytes();
@@ -3321,6 +3325,12 @@ void persistPositionToLedger(final LedgerHandle lh, MarkDeleteEntry mdEntry, fin
                     ledger.getName(), name, lh.getId(),
                     position, len, numParts);
         }
+        log.info("[{}] Cursor {} Appending to ledger={} position={} data size {} bytes, "
+                        + "numParts {}, serializeTime {} ms"
+                        + " compressTime {} ms, total {} ms", ledger.getName(), name, lh.getId(),
+                position, len, numParts,
+                (endSer - now) / 1000000,
+                (endCompress - endSer)  / 1000000, (endCompress - now) / 1000000);
 
         if (numParts == 1) {
             // no need for chunking
@@ -3335,7 +3345,7 @@ void persistPositionToLedger(final LedgerHandle lh, MarkDeleteEntry mdEntry, fin
                 boolean isLast = part == numParts - 1;
 
                 if (log.isDebugEnabled()) {
-                    log.info("[{}] Cursor {} Appending to ledger={} position={} data size {} bytes, numParts {} "
+                    log.debug("[{}] Cursor {} Appending to ledger={} position={} data size {} bytes, numParts {} "
                                     + "part {} offset {} len {}",
                             ledger.getName(), name, lh.getId(),
                             position, len, numParts, part, offset, currentLen);