MOD-6002: Fixes for FT.PROFILE's time reporting

CMakeLists.txt

@@ -62,7 +62,6 @@ include_directories(
     ${root})
 
 add_subdirectory(deps/rmutil)
-add_subdirectory(deps/rmutil/cxx)
 add_subdirectory(deps/friso)
 add_subdirectory(deps/snowball)
 add_subdirectory(deps/phonetics)
@@ -103,7 +102,6 @@ add_library(rscore OBJECT ${SOURCES})
 set(FINAL_OBJECTS
     $<TARGET_OBJECTS:rscore>
     $<TARGET_OBJECTS:rmutil>
-    $<TARGET_OBJECTS:rmutil-cxx>
     $<TARGET_OBJECTS:friso>
     $<TARGET_OBJECTS:snowball>
     $<TARGET_OBJECTS:metaphone>)

coord/CMakeLists.txt

@@ -77,7 +77,6 @@ include(${root}/build/hiredis/hiredis.cmake)
 set(FINAL_OBJECTS
     $<TARGET_OBJECTS:coordinator-core>
     $<TARGET_OBJECTS:rmutil>
-    $<TARGET_OBJECTS:rmutil-cxx>
     $<TARGET_OBJECTS:rmr>)
 
 if (APPLE)

src/aggregate/aggregate.h

@@ -16,7 +16,6 @@
 #include "reply.h"
 
 #include "rmutil/rm_assert.h"
-#include "rmutil/cxx/chrono-clock.h"
 
 #ifdef __cplusplus
 extern "C" {
@@ -168,10 +167,10 @@ typedef struct AREQ {
 
 
   /** Profile variables */
-  hires_clock_t initClock;  // Time of start. Reset for each cursor call
-  double totalTime;          // Total time. Used to accumulate cursors times
-  double parseTime;          // Time for parsing the query
-  double pipelineBuildTime;  // Time for creating the pipeline
+  clock_t initClock;         // Time of start. Reset for each cursor call
+  clock_t totalTime;         // Total time. Used to accumulate cursors times
+  clock_t parseTime;         // Time for parsing the query
+  clock_t pipelineBuildTime; // Time for creating the pipeline
 
   const char** requiredFields;
 

src/aggregate/aggregate_exec.c

@@ -786,17 +786,17 @@
     Profile_AddIters(&req->rootiter);
   }
 
-  hires_clock_t parseClock;
+  clock_t parseClock;
   bool is_profile = IsProfile(req);
   if (is_profile) {
-    hires_clock_get(&parseClock);
-    req->parseTime += hires_clock_diff_msec(&parseClock, &req->initClock);
+    parseClock = clock();
+    req->parseTime = parseClock - req->initClock;
   }
 
   rc = AREQ_BuildPipeline(req, status);
 
   if (is_profile) {
-    req->pipelineBuildTime = hires_clock_since_msec(&parseClock);
+    req->pipelineBuildTime = clock() - parseClock;
   }
   return rc;
 }
@@ -874,7 +874,7 @@
     if (withProfile == PROFILE_LIMITED) {
       r->reqflags |= QEXEC_F_PROFILE_LIMITED;
     }
-    hires_clock_get(&r->initClock);
+    r->initClock = clock();
   }
   return REDISMODULE_OK;
 }
@@ -1044,7 +1044,7 @@
 
   // reset profile clock for cursor reads except for 1st
   if (IsProfile(req) && req->totalTime != 0) {
-    hires_clock_get(&req->initClock);
+    req->initClock = clock();
   }
 
   // update timeout for current cursor read

src/index.c

@@ -1799,31 +1799,29 @@ typedef struct {
   IndexIterator base;
   IndexIterator *child;
   size_t counter;
-  double cpuTime;
+  clock_t cpuTime;
   int eof;
 } ProfileIterator, ProfileIteratorCtx;
 
 static int PI_Read(void *ctx, RSIndexResult **e) {
   ProfileIterator *pi = ctx;
   pi->counter++;
-  hires_clock_t t0;
-  hires_clock_get(&t0);
+  clock_t begin = clock();
   int ret = pi->child->Read(pi->child->ctx, e);
   if (ret == INDEXREAD_EOF) pi->eof = 1;
   pi->base.current = pi->child->current;
-  pi->cpuTime += hires_clock_since_msec(&t0);
+  pi->cpuTime += clock() - begin;
   return ret;
 }
 
 static int PI_SkipTo(void *ctx, t_docId docId, RSIndexResult **hit) {
   ProfileIterator *pi = ctx;
   pi->counter++;
-  hires_clock_t t0;
-  hires_clock_get(&t0);
+  clock_t begin = clock();
   int ret = pi->child->SkipTo(pi->child->ctx, docId, hit);
   if (ret == INDEXREAD_EOF) pi->eof = 1;
   pi->base.current = pi->child->current;
-  pi->cpuTime += hires_clock_since_msec(&t0);
+  pi->cpuTime += clock() - begin;
   return ret;
 }
 
@@ -2049,8 +2047,8 @@ PRINT_PROFILE_SINGLE(printOptimusIt, OptimizerIterator, "OPTIMIZER");
 
 PRINT_PROFILE_FUNC(printProfileIt) {
   ProfileIterator *pi = (ProfileIterator *)root;
-  printIteratorProfile(reply, pi->child, pi->counter - pi->eof, \
-                       (double)pi->cpuTime, depth, limited, config);
+  printIteratorProfile(reply, pi->child, pi->counter - pi->eof,
+    (double)(pi->cpuTime / CLOCKS_PER_MILLISEC), depth, limited, config);
 }
 
 void printIteratorProfile(RedisModule_Reply *reply, IndexIterator *root, size_t counter,

src/info_command.c

@@ -14,6 +14,8 @@
 #include "redismodule.h"
 #include "reply_macros.h"
 
+#define CLOCKS_PER_MILLISEC (CLOCKS_PER_SEC / 1000)
+
 static void renderIndexOptions(RedisModule_Reply *reply, IndexSpec *sp) {
 
 #define ADD_NEGATIVE_OPTION(flag, str)               \
@@ -237,7 +239,7 @@ int IndexInfoCommand(RedisModuleCtx *ctx, RedisModuleString **argv, int argc) {
   // TODO: remove this once "hash_indexing_failures" is deprecated
   // Legacy for not breaking changes
   REPLY_KVINT("hash_indexing_failures", sp->stats.indexError.error_count);
-  REPLY_KVNUM("total_indexing_time", sp->stats.totalIndexTime / 1000.0);
+  REPLY_KVNUM("total_indexing_time", (float)(sp->stats.totalIndexTime / (float)CLOCKS_PER_MILLISEC));
   REPLY_KVINT("indexing", !!global_spec_scanner || sp->scan_in_progress);
 
   IndexesScanner *scanner = global_spec_scanner ? global_spec_scanner : sp->scanner;

src/profile.c

@@ -86,7 +86,7 @@ static double _recursiveProfilePrint(RedisModule_Reply *reply, ResultProcessor *
     return upstreamTime;
   }
 
-  double totalRPTime = RPProfile_GetDurationMSec(rp);
+  double totalRPTime = (double)(RPProfile_GetClock(rp) / CLOCKS_PER_MILLISEC);
   if (printProfileClock) {
     printProfileTime(totalRPTime - upstreamTime);
   }
@@ -101,26 +101,27 @@ static double printProfileRP(RedisModule_Reply *reply, ResultProcessor *rp, int
 
 void Profile_Print(RedisModule_Reply *reply, AREQ *req, bool timedout) {
   bool has_map = RedisModule_HasMap(reply);
-  req->totalTime += hires_clock_since_msec(&req->initClock);
+  req->totalTime += clock() - req->initClock;
 
   //-------------------------------------------------------------------------------------------
   if (has_map) { // RESP3 variant
-    hires_clock_t now;
-
     RedisModule_ReplyKV_Map(reply, "profile"); // profile
 
       int profile_verbose = req->reqConfig.printProfileClock;
       // Print total time
       if (profile_verbose)
-        RedisModule_ReplyKV_Double(reply, "Total profile time", (double)req->totalTime);
+        RedisModule_ReplyKV_Double(reply, "Total profile time",
+          (double)(req->totalTime / CLOCKS_PER_MILLISEC));
 
       // Print query parsing time
       if (profile_verbose)
-        RedisModule_ReplyKV_Double(reply, "Parsing time", (double)req->parseTime);
+        RedisModule_ReplyKV_Double(reply, "Parsing time",
+          (double)(req->parseTime / CLOCKS_PER_MILLISEC));
 
       // Print iterators creation time
         if (profile_verbose)
-          RedisModule_ReplyKV_Double(reply, "Pipeline creation time", (double)req->pipelineBuildTime);
+          RedisModule_ReplyKV_Double(reply, "Pipeline creation time",
+            (double)(req->pipelineBuildTime / CLOCKS_PER_MILLISEC));
 
       // Print whether a warning was raised throughout command execution
       if (timedout) {
@@ -153,29 +154,28 @@ void Profile_Print(RedisModule_Reply *reply, AREQ *req, bool timedout) {
   //-------------------------------------------------------------------------------------------
   else // ! has_map (RESP2 variant)
   {
-    hires_clock_t now;
     RedisModule_Reply_Array(reply);
 
     int profile_verbose = req->reqConfig.printProfileClock;
     // Print total time
     RedisModule_Reply_Array(reply);
       RedisModule_Reply_SimpleString(reply, "Total profile time");
       if (profile_verbose)
-        RedisModule_Reply_Double(reply, (double)req->totalTime);
+        RedisModule_Reply_Double(reply, (double)(req->totalTime / CLOCKS_PER_MILLISEC));
     RedisModule_Reply_ArrayEnd(reply);
 
     // Print query parsing time
     RedisModule_Reply_Array(reply);
       RedisModule_Reply_SimpleString(reply, "Parsing time");
       if (profile_verbose)
-        RedisModule_Reply_Double(reply, (double)req->parseTime);
+        RedisModule_Reply_Double(reply, (double)(req->parseTime / CLOCKS_PER_MILLISEC));
     RedisModule_Reply_ArrayEnd(reply);
 
     // Print iterators creation time
     RedisModule_Reply_Array(reply);
     RedisModule_Reply_SimpleString(reply, "Pipeline creation time");
     if (profile_verbose)
-      RedisModule_Reply_Double(reply, (double)req->pipelineBuildTime);
+      RedisModule_Reply_Double(reply, (double)(req->pipelineBuildTime / CLOCKS_PER_MILLISEC));
     RedisModule_Reply_ArrayEnd(reply);
 
     // Print whether a warning was raised throughout command execution

src/result_processor.c

@@ -11,7 +11,6 @@
 #include <util/minmax_heap.h>
 #include "ext/default.h"
 #include "rmutil/rm_assert.h"
-#include "rmutil/cxx/chrono-clock.h"
 #include "util/timeout.h"
 #include "util/arr.h"
 
@@ -950,17 +949,16 @@ void RP_DumpChain(const ResultProcessor *rp) {
 
 typedef struct {
   ResultProcessor base;
-  double profileTime;
+  clock_t profileTime;
   uint64_t profileCount;
 } RPProfile;
 
 static int rpprofileNext(ResultProcessor *base, SearchResult *r) {
   RPProfile *self = (RPProfile *)base;
 
-  hires_clock_t t0;
-  hires_clock_get(&t0);
+  clock_t rpStartTime = clock();
   int rc = base->upstream->Next(base->upstream, r);
-  self->profileTime += hires_clock_since_msec(&t0);
+  self->profileTime += clock() - rpStartTime;
   self->profileCount++;
   return rc;
 }
@@ -983,7 +981,7 @@ ResultProcessor *RPProfile_New(ResultProcessor *rp, QueryIterator *qiter) {
   return &rpp->base;
 }
 
-double RPProfile_GetDurationMSec(ResultProcessor *rp) {
+clock_t RPProfile_GetClock(ResultProcessor *rp) {
   RPProfile *self = (RPProfile *)rp;
   return self->profileTime;
 }

src/result_processor.h

@@ -255,7 +255,7 @@ ResultProcessor *RPProfile_New(ResultProcessor *rp, QueryIterator *qiter);
  *******************************************************************************************************************/
 ResultProcessor *RPCounter_New();
 
-double RPProfile_GetDurationMSec(ResultProcessor *rp);
+clock_t RPProfile_GetClock(ResultProcessor *rp);
 uint64_t RPProfile_GetCount(ResultProcessor *rp);
 
 void Profile_AddRPs(QueryIterator *qiter);

src/spec.c

@@ -30,7 +30,6 @@
 #include "doc_types.h"
 #include "rdb.h"
 #include "commands.h"
-#include "rmutil/cxx/chrono-clock.h"
 #include "util/workers.h"
 
 #define INITIAL_DOC_TABLE_SIZE 1000
@@ -2746,8 +2745,7 @@ int IndexSpec_UpdateDoc(IndexSpec *spec, RedisModuleCtx *ctx, RedisModuleString
     return REDISMODULE_ERR;
   }
 
-  hires_clock_t t0;
-  hires_clock_get(&t0);
+  clock_t startDocTime = clock();
 
   QueryError status = {0};
   Document doc = {0};
@@ -2786,7 +2784,7 @@ int IndexSpec_UpdateDoc(IndexSpec *spec, RedisModuleCtx *ctx, RedisModuleString
 
   Document_Free(&doc);
 
-  spec->stats.totalIndexTime += hires_clock_since_usec(&t0);
+  spec->stats.totalIndexTime += clock() - startDocTime;
   RedisSearchCtx_UnlockSpec(&sctx);
   return REDISMODULE_OK;
 }