Modify clock type and time measurement

src/core/lib/iomgr/executor/mpmcqueue.cc

@@ -25,6 +25,8 @@ namespace grpc_core {
 DebugOnlyTraceFlag thread_pool(false, "thread_pool_trace");
 
 inline void* InfLenFIFOQueue::PopFront() {
+  // Caller should already checked queue is not empty and has already hold the
+  // mutex. This function will only do the job of removal.
   void* result = queue_head_->content;
   Node* head_to_remove = queue_head_;
   queue_head_ = queue_head_->next;
@@ -33,29 +35,29 @@ inline void* InfLenFIFOQueue::PopFront() {
 
   if (GRPC_TRACE_FLAG_ENABLED(thread_pool)) {
     gpr_timespec wait_time =
-        gpr_time_sub(gpr_now(GPR_CLOCK_PRECISE), head_to_remove->insert_time);
+        gpr_time_sub(gpr_now(GPR_CLOCK_MONOTONIC), head_to_remove->insert_time);
 
     // Updates Stats info
     stats_.num_completed++;
-    stats_.total_queue_cycles =
-        gpr_time_add(stats_.total_queue_cycles, wait_time);
-    stats_.max_queue_cycles = gpr_time_max(
-        gpr_convert_clock_type(stats_.max_queue_cycles, GPR_TIMESPAN),
+    stats_.total_queue_time =
+        gpr_time_add(stats_.total_queue_time, wait_time);
+    stats_.max_queue_time = gpr_time_max(
+        gpr_convert_clock_type(stats_.max_queue_time, GPR_TIMESPAN),
         wait_time);
 
     if (count_.Load(MemoryOrder::RELAXED) == 0) {
-      stats_.busy_time_cycles =
-          gpr_time_add(stats_.busy_time_cycles,
-                       gpr_time_sub(gpr_now(GPR_CLOCK_PRECISE), busy_time));
+      stats_.busy_queue_time =
+          gpr_time_add(stats_.busy_queue_time,
+                       gpr_time_sub(gpr_now(GPR_CLOCK_MONOTONIC), busy_time));
     }
 
     gpr_log(GPR_INFO,
-            "[InfLenFIFOQueue Get] num_completed:        %" PRIu64
-            " total_queue_cycles: %" PRId32 " max_queue_cycles:   %" PRId32
-            " busy_time_cycles:   %" PRId32,
-            stats_.num_completed, gpr_time_to_millis(stats_.total_queue_cycles),
-            gpr_time_to_millis(stats_.max_queue_cycles),
-            gpr_time_to_millis(stats_.busy_time_cycles));
+            "[InfLenFIFOQueue PopFront] num_completed:        %" PRIu64
+            " total_queue_time: %f max_queue_time:   %f busy_queue_time:   %f",
+            stats_.num_completed,
+            gpr_timespec_to_micros(stats_.total_queue_time),
+            gpr_timespec_to_micros(stats_.max_queue_time),
+            gpr_timespec_to_micros(stats_.busy_queue_time));
   }
 
   Delete(head_to_remove);
@@ -81,7 +83,7 @@ void InfLenFIFOQueue::Put(void* elem) {
   Node* new_node = New<Node>(elem);
   if (count_.Load(MemoryOrder::RELAXED) == 0) {
     if (GRPC_TRACE_FLAG_ENABLED(thread_pool)) {
-      busy_time = gpr_now(GPR_CLOCK_PRECISE);
+      busy_time = gpr_now(GPR_CLOCK_MONOTONIC);
     }
     queue_head_ = queue_tail_ = new_node;
   } else {

src/core/lib/iomgr/executor/mpmcqueue.h

@@ -52,8 +52,7 @@ class MPMCQueueInterface {
 
 class InfLenFIFOQueue : public MPMCQueueInterface {
  public:
-  // Creates a new MPMC Queue. The queue created
-  // will have infinite length.
+  // Creates a new MPMC Queue. The queue created will have infinite length.
   InfLenFIFOQueue();
 
   // Releases all resources hold by the queue. The queue must be empty, and no
@@ -92,24 +91,24 @@ class InfLenFIFOQueue : public MPMCQueueInterface {
   };
 
   // Stats of queue. This will only be collect when debug trace mode is on.
-  // All printed stats info will have time measurement in millisecond.
+  // All printed stats info will have time measurement in microsecond.
   struct Stats {
     uint64_t num_started;    // Number of elements have been added to queue
     uint64_t num_completed;  // Number of elements have been removed from
                              // the queue
-    gpr_timespec total_queue_cycles;  // Total waiting time that all the
+    gpr_timespec total_queue_time;  // Total waiting time that all the
                                     // removed elements have spent in queue
-    gpr_timespec max_queue_cycles;    // Max waiting time among all removed
+    gpr_timespec max_queue_time;    // Max waiting time among all removed
                                     // elements
-    gpr_timespec busy_time_cycles;    // Accumulated amount of time that queue
+    gpr_timespec busy_queue_time;   // Accumulated amount of time that queue
                                     // was not empty
 
     Stats() {
       num_started = 0;
       num_completed = 0;
-      total_queue_cycles = gpr_time_0(GPR_TIMESPAN);
-      max_queue_cycles = gpr_time_0(GPR_TIMESPAN);
-      busy_time_cycles = gpr_time_0(GPR_TIMESPAN);
+      total_queue_time = gpr_time_0(GPR_TIMESPAN);
+      max_queue_time = gpr_time_0(GPR_TIMESPAN);
+      busy_queue_time = gpr_time_0(GPR_TIMESPAN);
     }
   };