From 011e239125c9571af9aaf1510ff2c4d7770d7963 Mon Sep 17 00:00:00 2001 From: Kaveh Shahedi Date: Wed, 19 Feb 2025 14:38:20 -0500 Subject: [PATCH] Use system timestamp since the unix epoch Previously, we used System.nanoTime() to capture system's timestamp in nanoseconds, which works fine. However, since this method returns the timestamp since the machine's boot, it might not be precise for aligning the trace time with the current actual time. We now capture the offset of System.nanoTime() with the actual system's time, and after that, every captured timestamp will sum-up with the offset. Signed-off-by: Kaveh Shahedi --- .../traceeventlogger/LogUtils.java | 54 ++++++++++++++----- 1 file changed, 40 insertions(+), 14 deletions(-) diff --git a/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java b/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java index a92d866..c7f28fc 100644 --- a/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java +++ b/src/main/java/org/eclipse/tracecompass/traceeventlogger/LogUtils.java @@ -144,6 +144,32 @@ public interface IFlowScopeLog { private static final Format FORMAT = new DecimalFormat("#.###"); //$NON-NLS-1$ + /** + * Offset between System.currentTimeMillis() and System.nanoTime() in nanoseconds. + * Used to convert between the two time bases while maintaining nanosecond precision. + */ + private static final long TIME_OFFSET; + static { + // Get current time in both bases + long currentMillis = System.currentTimeMillis(); + long nanoTime = System.nanoTime(); + + // Convert millis to nanos and calculate offset, handling potential overflow + long millisToNanos = currentMillis * 1_000_000L; + TIME_OFFSET = millisToNanos - nanoTime; + } + + /** + * Gets the current time in nanoseconds since the Unix epoch. + * This maintains nanosecond precision while being comparable to timestamps from + * System.currentTimeMillis(). + * + * @return Current time in nanoseconds since Unix epoch + */ + private static long currentTimeNanos() { + return System.nanoTime() + TIME_OFFSET; + } + /* * Field names */ @@ -250,7 +276,7 @@ public static class ScopeLog implements AutoCloseable { * beginning of the scope */ public ScopeLog(Logger log, Level level, String label, Object... args) { - fTime = System.nanoTime(); + fTime = currentTimeNanos(); fLogger = log; fLevel = level; fThreadId = Thread.currentThread().getId(); @@ -289,7 +315,7 @@ public void addData(String name, Object value) { @Override public void close() { - long time = System.nanoTime(); + long time = currentTimeNanos(); char phase = 'E'; Supplier msgSupplier = () -> { StringBuilder sb = new StringBuilder(); @@ -487,7 +513,7 @@ public static class FlowScopeLog implements IFlowScopeLog, AutoCloseable { * value2.... typically arguments */ private FlowScopeLog(Logger log, Level level, String label, String category, int id, boolean startFlow, Object... args) { - fTime = System.nanoTime(); + fTime = currentTimeNanos(); fId = id; fLogger = log; fLevel = level; @@ -531,7 +557,7 @@ private FlowScopeLog(Logger log, Level level, String label, String category, int * the arguments to log */ public void step(String label, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); char phase = 't'; validateArgs(args); Supplier msgSupplier = () -> { @@ -578,7 +604,7 @@ public int getId() { @Override public void close() { - long time = System.nanoTime(); + long time = currentTimeNanos(); char phase = 'E'; Supplier msgSupplier = () -> { StringBuilder sb = new StringBuilder(); @@ -612,7 +638,7 @@ public void close() { * @return The unique ID of this object (there may be collisions) */ public static int traceObjectCreation(Logger logger, Level level, Object item) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); int identityHashCode = System.identityHashCode(item); char phase = 'N'; @@ -643,7 +669,7 @@ public static int traceObjectCreation(Logger logger, Level level, Object item) { * the Object to trace */ public static void traceObjectDestruction(Logger logger, Level level, Object item) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'D'; Supplier msgSupplier = () -> { @@ -673,7 +699,7 @@ public static void traceObjectDestruction(Logger logger, Level level, Object ite * The unique ID */ public static void traceObjectDestruction(Logger logger, Level level, Object item, int uniqueId) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'D'; Supplier msgSupplier = () -> { @@ -706,7 +732,7 @@ public static void traceObjectDestruction(Logger logger, Level level, Object ite * Additional arguments to log */ public static void traceAsyncStart(Logger logger, Level level, String name, String category, int id, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'b'; validateArgs(args); @@ -741,7 +767,7 @@ public static void traceAsyncStart(Logger logger, Level level, String name, Stri * Additional arguments to log */ public static void traceAsyncNested(Logger logger, Level level, String name, String category, int id, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'n'; validateArgs(args); @@ -776,7 +802,7 @@ public static void traceAsyncNested(Logger logger, Level level, String name, Str * Additional arguments to log */ public static void traceAsyncEnd(Logger logger, Level level, String name, String category, int id, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'e'; validateArgs(args); @@ -810,7 +836,7 @@ public static void traceAsyncEnd(Logger logger, Level level, String name, String * Additional arguments to log */ public static void traceInstant(Logger logger, Level level, String name, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'i'; validateArgs(args); @@ -838,7 +864,7 @@ public static void traceInstant(Logger logger, Level level, String name, Object. * The counters to log in the format : "title", value */ public static void traceCounter(Logger logger, Level level, String name, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'C'; validateArgs(args); @@ -870,7 +896,7 @@ public static void traceCounter(Logger logger, Level level, String name, Object. * "color" and an rbga will be used */ public static void traceMarker(Logger logger, Level level, String name, long duration, Object... args) { - long time = System.nanoTime(); + long time = currentTimeNanos(); long threadId = Thread.currentThread().getId(); char phase = 'R'; validateArgs(args);