Merge pull request #2490 from terrelln/tracing

[trace] Keep track of a uint64_t tracing context

lib/common/zstd_trace.c

@@ -15,27 +15,27 @@
 
 #if ZSTD_TRACE && ZSTD_HAVE_WEAK_SYMBOLS
 
-ZSTD_WEAK_ATTR int ZSTD_trace_compress_begin(ZSTD_CCtx const* cctx)
+ZSTD_WEAK_ATTR ZSTD_TraceCtx ZSTD_trace_compress_begin(ZSTD_CCtx const* cctx)
 {
     (void)cctx;
     return 0;
 }
 
-ZSTD_WEAK_ATTR void ZSTD_trace_compress_end(ZSTD_CCtx const* cctx, ZSTD_trace const* trace)
+ZSTD_WEAK_ATTR void ZSTD_trace_compress_end(ZSTD_TraceCtx ctx, ZSTD_Trace const* trace)
 {
-    (void)cctx;
+    (void)ctx;
     (void)trace;
 }
 
-ZSTD_WEAK_ATTR int ZSTD_trace_decompress_begin(ZSTD_DCtx const* dctx)
+ZSTD_WEAK_ATTR ZSTD_TraceCtx ZSTD_trace_decompress_begin(ZSTD_DCtx const* dctx)
 {
     (void)dctx;
     return 0;
 }
 
-ZSTD_WEAK_ATTR void ZSTD_trace_decompress_end(ZSTD_DCtx const* dctx, ZSTD_trace const* trace)
+ZSTD_WEAK_ATTR void ZSTD_trace_decompress_end(ZSTD_TraceCtx ctx, ZSTD_Trace const* trace)
 {
-    (void)dctx;
+    (void)ctx;
     (void)trace;
 }
 

lib/common/zstd_trace.h

@@ -77,41 +77,67 @@ typedef struct {
      * The fully resolved CCtx parameters (NULL on decompression).
      */
     struct ZSTD_CCtx_params_s const* params;
-} ZSTD_trace;
+    /**
+     * The ZSTD_CCtx pointer (NULL on decompression).
+     */
+    struct ZSTD_CCtx_s const* cctx;
+    /**
+     * The ZSTD_DCtx pointer (NULL on compression).
+     */
+    struct ZSTD_DCtx_s const* dctx;
+} ZSTD_Trace;
+
+/**
+ * A tracing context. It must be 0 when tracing is disabled.
+ * Otherwise, any non-zero value returned by a tracing begin()
+ * function is presented to any subsequent calls to end().
+ *
+ * Any non-zero value is treated as tracing is enabled and not
+ * interpreted by the library.
+ *
+ * Two possible uses are:
+ * * A timestamp for when the begin() function was called.
+ * * A unique key identifying the (de)compression, like the
+ *   address of the [dc]ctx pointer if you need to track
+ *   more information than just a timestamp.
+ */
+typedef unsigned long long ZSTD_TraceCtx;
 
 /**
  * Trace the beginning of a compression call.
  * @param cctx The dctx pointer for the compression.
  *             It can be used as a key to map begin() to end().
- * @returns Non-zero if tracing is enabled.
+ * @returns Non-zero if tracing is enabled. The return value is
+ *          passed to ZSTD_trace_compress_end().
  */
-int ZSTD_trace_compress_begin(struct ZSTD_CCtx_s const* cctx);
+ZSTD_TraceCtx ZSTD_trace_compress_begin(struct ZSTD_CCtx_s const* cctx);
 
 /**
  * Trace the end of a compression call.
- * @param cctx The dctx pointer for the decompression.
+ * @param ctx The return value of ZSTD_trace_compress_begin().
  * @param trace The zstd tracing info.
  */
 void ZSTD_trace_compress_end(
-    struct ZSTD_CCtx_s const* cctx,
+    ZSTD_TraceCtx ctx,
-    ZSTD_trace const* trace);
+    ZSTD_Trace const* trace);
 
 /**
  * Trace the beginning of a decompression call.
  * @param dctx The dctx pointer for the decompression.
  *             It can be used as a key to map begin() to end().
- * @returns Non-zero if tracing is enabled.
+ * @returns Non-zero if tracing is enabled. The return value is
+ *          passed to ZSTD_trace_compress_end().
  */
-int ZSTD_trace_decompress_begin(struct ZSTD_DCtx_s const* dctx);
+ZSTD_TraceCtx ZSTD_trace_decompress_begin(struct ZSTD_DCtx_s const* dctx);
 
 /**
  * Trace the end of a decompression call.
- * @param dctx The dctx pointer for the decompression.
+ * @param ctx The return value of ZSTD_trace_decompress_begin().
  * @param trace The zstd tracing info.
  */
 void ZSTD_trace_decompress_end(
-    struct ZSTD_DCtx_s const* dctx,
+    ZSTD_TraceCtx ctx,
-    ZSTD_trace const* trace);
+    ZSTD_Trace const* trace);
 
 #endif /* ZSTD_TRACE */
 

lib/compress/zstd_compress.c

@@ -3386,7 +3386,7 @@ static size_t ZSTD_compressBegin_internal(ZSTD_CCtx* cctx,
                                     ZSTD_buffered_policy_e zbuff)
 {
 #if ZSTD_TRACE
-    cctx->tracingEnabled = ZSTD_trace_compress_begin(cctx);
+    cctx->traceCtx = ZSTD_trace_compress_begin(cctx);
 #endif
     DEBUGLOG(4, "ZSTD_compressBegin_internal: wlog=%u", params->cParams.windowLog);
     /* params are supposed to be fully validated at this point */
@@ -3512,12 +3512,12 @@ static size_t ZSTD_writeEpilogue(ZSTD_CCtx* cctx, void* dst, size_t dstCapacity)
     return op-ostart;
 }
 
-static void ZSTD_CCtx_trace(ZSTD_CCtx const* cctx, size_t extraCSize)
+void ZSTD_CCtx_trace(ZSTD_CCtx* cctx, size_t extraCSize)
 {
 #if ZSTD_TRACE
-    if (cctx->tracingEnabled) {
+    if (cctx->traceCtx) {
         int const streaming = cctx->inBuffSize > 0 || cctx->outBuffSize > 0 || cctx->appliedParams.nbWorkers > 0;
-        ZSTD_trace trace;
+        ZSTD_Trace trace;
         ZSTD_memset(&trace, 0, sizeof(trace));
         trace.version = ZSTD_VERSION_NUMBER;
         trace.streaming = streaming;
@@ -3526,8 +3526,10 @@ static void ZSTD_CCtx_trace(ZSTD_CCtx const* cctx, size_t extraCSize)
         trace.uncompressedSize = cctx->consumedSrcSize;
         trace.compressedSize = cctx->producedCSize + extraCSize;
         trace.params = &cctx->appliedParams;
-        ZSTD_trace_compress_end(cctx, &trace);
+        trace.cctx = cctx;
+        ZSTD_trace_compress_end(cctx->traceCtx, &trace);
     }
+    cctx->traceCtx = 0;
 #else
     (void)cctx;
     (void)extraCSize;
@@ -4441,7 +4443,7 @@ static size_t ZSTD_CCtx_init_compressStream2(ZSTD_CCtx* cctx,
     }
     if (params.nbWorkers > 0) {
 #if ZSTD_TRACE
-        cctx->tracingEnabled = ZSTD_trace_compress_begin(cctx);
+        cctx->traceCtx = ZSTD_trace_compress_begin(cctx);
 #endif
         /* mt context creation */
         if (cctx->mtctx == NULL) {

lib/compress/zstd_compress_internal.h

@@ -19,6 +19,7 @@
 *  Dependencies
 ***************************************/
 #include "../common/zstd_internal.h"
+#include "../common/zstd_trace.h"  /* ZSTD_TraceCtx */
 #include "zstd_cwksp.h"
 #ifdef ZSTD_MULTITHREAD
 #  include "zstdmt_compress.h"
@@ -324,7 +325,9 @@ struct ZSTD_CCtx_s {
 #endif
 
     /* Tracing */
-    int tracingEnabled;
+#if ZSTD_TRACE
+    ZSTD_TraceCtx traceCtx;
+#endif
 };
 
 typedef enum { ZSTD_dtlm_fast, ZSTD_dtlm_full } ZSTD_dictTableLoadMethod_e;
@@ -1204,4 +1207,9 @@ size_t ZSTD_referenceExternalSequences(ZSTD_CCtx* cctx, rawSeq* seq, size_t nbSe
  *  condition for correct operation : hashLog > 1 */
 U32 ZSTD_cycleLog(U32 hashLog, ZSTD_strategy strat);
 
+/** ZSTD_CCtx_trace() :
+ *  Trace the end of a compression call.
+ */
+void ZSTD_CCtx_trace(ZSTD_CCtx* cctx, size_t extraCSize);
+
 #endif /* ZSTD_COMPRESS_H */

lib/compress/zstdmt_compress.c

@@ -683,6 +683,8 @@ static void ZSTDMT_compressionJob(void* jobDescription)
     if (job->jobID != 0) jobParams.fParams.checksumFlag = 0;
     /* Don't run LDM for the chunks, since we handle it externally */
     jobParams.ldmParams.enableLdm = 0;
+    /* Correct nbWorkers to 0. */
+    jobParams.nbWorkers = 0;
 
 
     /* init */
@@ -750,6 +752,7 @@ static void ZSTDMT_compressionJob(void* jobDescription)
             if (ZSTD_isError(cSize)) JOB_ERROR(cSize);
             lastCBlockSize = cSize;
     }   }
+    ZSTD_CCtx_trace(cctx, 0);
 
 _endJob:
     ZSTDMT_serialState_ensureFinished(job->serial, job->jobID, job->cSize);

lib/decompress/zstd_decompress.c

@@ -789,8 +789,8 @@ static size_t ZSTD_setRleBlock(void* dst, size_t dstCapacity,
 static void ZSTD_DCtx_trace_end(ZSTD_DCtx const* dctx, U64 uncompressedSize, U64 compressedSize, unsigned streaming)
 {
 #if ZSTD_TRACE
-    if (dctx->tracingEnabled) {
+    if (dctx->traceCtx) {
-        ZSTD_trace trace;
+        ZSTD_Trace trace;
         ZSTD_memset(&trace, 0, sizeof(trace));
         trace.version = ZSTD_VERSION_NUMBER;
         trace.streaming = streaming;
@@ -801,7 +801,8 @@ static void ZSTD_DCtx_trace_end(ZSTD_DCtx const* dctx, U64 uncompressedSize, U64
         }
         trace.uncompressedSize = (size_t)uncompressedSize;
         trace.compressedSize = (size_t)compressedSize;
-        ZSTD_trace_decompress_end(dctx, &trace);
+        trace.dctx = dctx;
+        ZSTD_trace_decompress_end(dctx->traceCtx, &trace);
     }
 #else
     (void)dctx;
@@ -1383,7 +1384,7 @@ size_t ZSTD_decompressBegin(ZSTD_DCtx* dctx)
 {
     assert(dctx != NULL);
 #if ZSTD_TRACE
-    dctx->tracingEnabled = ZSTD_trace_decompress_begin(dctx);
+    dctx->traceCtx = ZSTD_trace_decompress_begin(dctx);
 #endif
     dctx->expected = ZSTD_startingInputLength(dctx->format);  /* dctx->format must be properly set */
     dctx->stage = ZSTDds_getFrameHeaderSize;

lib/decompress/zstd_decompress_internal.h

@@ -21,6 +21,7 @@
  *********************************************************/
 #include "../common/mem.h"             /* BYTE, U16, U32 */
 #include "../common/zstd_internal.h"   /* ZSTD_seqSymbol */
+#include "../common/zstd_trace.h"      /* ZSTD_TraceCtx */
 
 
 
@@ -178,7 +179,9 @@ struct ZSTD_DCtx_s
 #endif
 
     /* Tracing */
-    int tracingEnabled;
+#if ZSTD_TRACE
+    ZSTD_TraceCtx traceCtx;
+#endif
 };  /* typedef'd to ZSTD_DCtx within "zstd.h" */
 
 

programs/zstdcli_trace.c

@@ -30,6 +30,7 @@
 static FILE* g_traceFile = NULL;
 static int g_mutexInit = 0;
 static ZSTD_pthread_mutex_t g_mutex;
+static UTIL_time_t g_enableTime = UTIL_TIME_INITIALIZER;
 
 void TRACE_enable(char const* filename)
 {
@@ -54,6 +55,7 @@ void TRACE_enable(char const* filename)
         */
         fprintf(g_traceFile, "Algorithm, Version, Method, Mode, Level, Workers, Dictionary Size, Uncompressed Size, Compressed Size, Duration Nanos, Compression Ratio, Speed MB/s\n");
     }
+    g_enableTime = UTIL_getTime();
     if (!g_mutexInit) {
         if (!ZSTD_pthread_mutex_init(&g_mutex, NULL)) {
             g_mutexInit = 1;
@@ -75,7 +77,7 @@ void TRACE_finish(void)
     }
 }
 
-static void TRACE_log(char const* method, PTime duration, ZSTD_trace const* trace)
+static void TRACE_log(char const* method, PTime duration, ZSTD_Trace const* trace)
 {
     int level = 0;
     int workers = 0;
@@ -87,6 +89,7 @@ static void TRACE_log(char const* method, PTime duration, ZSTD_trace const* trac
     }
     assert(g_traceFile != NULL);
 
+    ZSTD_pthread_mutex_lock(&g_mutex);
     /* Fields:
      * algorithm
      * version
@@ -114,70 +117,47 @@ static void TRACE_log(char const* method, PTime duration, ZSTD_trace const* trac
         (unsigned long long)duration,
         ratio,
         speed);
+    ZSTD_pthread_mutex_unlock(&g_mutex);
 }
 
-static ZSTD_CCtx const* g_cctx;
-static ZSTD_DCtx const* g_dctx;
-static UTIL_time_t g_begin = UTIL_TIME_INITIALIZER;
-
 /**
  * These symbols override the weak symbols provided by the library.
  */
 
-int ZSTD_trace_compress_begin(ZSTD_CCtx const* cctx)
+ZSTD_TraceCtx ZSTD_trace_compress_begin(ZSTD_CCtx const* cctx)
 {
-    int enabled = 0;
+    (void)cctx;
     if (g_traceFile == NULL)
         return 0;
-    ZSTD_pthread_mutex_lock(&g_mutex);
+    return (ZSTD_TraceCtx)UTIL_clockSpanNano(g_enableTime);
-    if (g_cctx == NULL) {
-        g_cctx = cctx;
-        g_dctx = NULL;
-        g_begin = UTIL_getTime();
-        enabled = 1;
-    }
-    ZSTD_pthread_mutex_unlock(&g_mutex);
-    return enabled;
 }
 
-void ZSTD_trace_compress_end(ZSTD_CCtx const* cctx, ZSTD_trace const* trace)
+void ZSTD_trace_compress_end(ZSTD_TraceCtx ctx, ZSTD_Trace const* trace)
 {
+    PTime const beginNanos = (PTime)ctx;
+    PTime const endNanos = UTIL_clockSpanNano(g_enableTime);
+    PTime const durationNanos = endNanos > beginNanos ? endNanos - beginNanos : 0;
     assert(g_traceFile != NULL);
-    ZSTD_pthread_mutex_lock(&g_mutex);
+    assert(trace->version == ZSTD_VERSION_NUMBER); /* CLI version must match. */
-    assert(g_cctx == cctx);
+    TRACE_log("compress", durationNanos, trace);
-    assert(g_dctx == NULL);
-    if (cctx == g_cctx && trace->version == ZSTD_VERSION_NUMBER)
-        TRACE_log("compress", UTIL_clockSpanNano(g_begin), trace);
-    g_cctx = NULL;
-    ZSTD_pthread_mutex_unlock(&g_mutex);
 }
 
-int ZSTD_trace_decompress_begin(ZSTD_DCtx const* dctx)
+ZSTD_TraceCtx ZSTD_trace_decompress_begin(ZSTD_DCtx const* dctx)
 {
-    int enabled = 0;
+    (void)dctx;
     if (g_traceFile == NULL)
         return 0;
-    ZSTD_pthread_mutex_lock(&g_mutex);
+    return (ZSTD_TraceCtx)UTIL_clockSpanNano(g_enableTime);
-    if (g_dctx == NULL) {
-        g_cctx = NULL;
-        g_dctx = dctx;
-        g_begin = UTIL_getTime();
-        enabled = 1;
-    }
-    ZSTD_pthread_mutex_unlock(&g_mutex);
-    return enabled;
 }
 
-void ZSTD_trace_decompress_end(ZSTD_DCtx const* dctx, ZSTD_trace const* trace)
+void ZSTD_trace_decompress_end(ZSTD_TraceCtx ctx, ZSTD_Trace const* trace)
 {
+    PTime const beginNanos = (PTime)ctx;
+    PTime const endNanos = UTIL_clockSpanNano(g_enableTime);
+    PTime const durationNanos = endNanos > beginNanos ? endNanos - beginNanos : 0;
     assert(g_traceFile != NULL);
-    ZSTD_pthread_mutex_lock(&g_mutex);
+    assert(trace->version == ZSTD_VERSION_NUMBER); /* CLI version must match. */
-    assert(g_cctx == NULL);
+    TRACE_log("decompress", durationNanos, trace);
-    assert(g_dctx == dctx);
-    if (dctx == g_dctx && trace->version == ZSTD_VERSION_NUMBER)
-        TRACE_log("decompress", UTIL_clockSpanNano(g_begin), trace);
-    g_dctx = NULL;
-    ZSTD_pthread_mutex_unlock(&g_mutex);
 }
 
 #else /* ZSTD_TRACE */