Split thread cpu time into three metrics (#7724)

* Split thread CPU time into three metrics * fix typo
apache · Nov 18, 2021 · 9662399 · 9662399
1 parent d789ae7
commit 9662399
Show file tree

Hide file tree

Showing 17 changed files with 547 additions and 155 deletions.
diff --git a/pinot-broker/src/main/java/org/apache/pinot/broker/api/RequestStatistics.java b/pinot-broker/src/main/java/org/apache/pinot/broker/api/RequestStatistics.java
@@ -45,6 +45,61 @@ public class RequestStatistics {
   private long _numSegmentsMatched;
   private long _offlineThreadCpuTimeNs;
   private long _realtimeThreadCpuTimeNs;
+  private long _offlineSystemActivitiesCpuTimeNs;
+  private long _realtimeSystemActivitiesCpuTimeNs;
+  private long _offlineResponseSerializationCpuTimeNs;
+  private long _realtimeResponseSerializationCpuTimeNs;
+  private long _offlineTotalCpuTimeNs;
+  private long _realtimeTotalCpuTimeNs;
+
+  public long getOfflineSystemActivitiesCpuTimeNs() {
+    return _offlineSystemActivitiesCpuTimeNs;
+  }
+
+  public void setOfflineSystemActivitiesCpuTimeNs(long offlineSystemActivitiesCpuTimeNs) {
+    _offlineSystemActivitiesCpuTimeNs = offlineSystemActivitiesCpuTimeNs;
+  }
+
+  public long getRealtimeSystemActivitiesCpuTimeNs() {
+    return _realtimeSystemActivitiesCpuTimeNs;
+  }
+
+  public void setRealtimeSystemActivitiesCpuTimeNs(long realtimeSystemActivitiesCpuTimeNs) {
+    _realtimeSystemActivitiesCpuTimeNs = realtimeSystemActivitiesCpuTimeNs;
+  }
+
+  public long getOfflineResponseSerializationCpuTimeNs() {
+    return _offlineResponseSerializationCpuTimeNs;
+  }
+
+  public void setOfflineResponseSerializationCpuTimeNs(long offlineResponseSerializationCpuTimeNs) {
+    _offlineResponseSerializationCpuTimeNs = offlineResponseSerializationCpuTimeNs;
+  }
+
+  public long getOfflineTotalCpuTimeNs() {
+    return _offlineTotalCpuTimeNs;
+  }
+
+  public void setOfflineTotalCpuTimeNs(long offlineTotalCpuTimeNs) {
+    _offlineTotalCpuTimeNs = _offlineTotalCpuTimeNs;
+  }
+
+  public long getRealtimeResponseSerializationCpuTimeNs() {
+    return _realtimeResponseSerializationCpuTimeNs;
+  }
+
+  public void setRealtimeResponseSerializationCpuTimeNs(long realtimeResponseSerializationCpuTimeNs) {
+    _realtimeResponseSerializationCpuTimeNs = realtimeResponseSerializationCpuTimeNs;
+  }
+
+  public long getRealtimeTotalCpuTimeNs() {
+    return _realtimeTotalCpuTimeNs;
+  }
+
+  public void setRealtimeTotalCpuTimeNs(long realtimeTotalCpuTimeNs) {
+    _realtimeTotalCpuTimeNs = realtimeTotalCpuTimeNs;
+  }
+
   private int _numServersQueried;
   private int _numServersResponded;
   private boolean _isNumGroupsLimitReached;
@@ -123,6 +178,12 @@ public void setStatistics(BrokerResponse brokerResponse) {
     _numExceptions = brokerResponse.getExceptionsSize();
     _offlineThreadCpuTimeNs = brokerResponse.getOfflineThreadCpuTimeNs();
     _realtimeThreadCpuTimeNs = brokerResponse.getRealtimeThreadCpuTimeNs();
+    _offlineSystemActivitiesCpuTimeNs = brokerResponse.getOfflineSystemActivitiesCpuTimeNs();
+    _realtimeSystemActivitiesCpuTimeNs = brokerResponse.getRealtimeSystemActivitiesCpuTimeNs();
+    _offlineResponseSerializationCpuTimeNs = brokerResponse.getOfflineResponseSerializationCpuTimeNs();
+    _realtimeResponseSerializationCpuTimeNs = brokerResponse.getRealtimeResponseSerializationCpuTimeNs();
+    _offlineTotalCpuTimeNs = brokerResponse.getOfflineTotalCpuTimeNs();
+    _realtimeTotalCpuTimeNs = brokerResponse.getRealtimeTotalCpuTimeNs();
     _numRowsResultSet = brokerResponse.getNumRowsResultSet();
   }
 

diff --git a/...broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java b/...broker/src/main/java/org/apache/pinot/broker/requesthandler/BaseBrokerRequestHandler.java
@@ -542,7 +542,8 @@ private void logBrokerResponse(long requestId, String query, RequestStatistics r
       LOGGER.info("requestId={},table={},timeMs={},docs={}/{},entries={}/{},"
               + "segments(queried/processed/matched/consuming/unavailable):{}/{}/{}/{}/{},consumingFreshnessTimeMs={},"
               + "servers={}/{},groupLimitReached={},brokerReduceTimeMs={},exceptions={},serverStats={},"
-              + "offlineThreadCpuTimeNs={},realtimeThreadCpuTimeNs={},query={}", requestId,
+              + "offlineThreadCpuTimeNs(total/thread/sysActivity/resSer):{}/{}/{}/{},"
+              + "realtimeThreadCpuTimeNs(total/thread/sysActivity/resSer):{}/{}/{}/{}," + "query={}", requestId,
           brokerRequest.getQuerySource().getTableName(), totalTimeMs, brokerResponse.getNumDocsScanned(),
           brokerResponse.getTotalDocs(), brokerResponse.getNumEntriesScannedInFilter(),
           brokerResponse.getNumEntriesScannedPostFilter(), brokerResponse.getNumSegmentsQueried(),
@@ -551,8 +552,11 @@ private void logBrokerResponse(long requestId, String query, RequestStatistics r
           brokerResponse.getMinConsumingFreshnessTimeMs(), brokerResponse.getNumServersResponded(),
           brokerResponse.getNumServersQueried(), brokerResponse.isNumGroupsLimitReached(),
           requestStatistics.getReduceTimeMillis(), brokerResponse.getExceptionsSize(), serverStats.getServerStats(),
-          brokerResponse.getOfflineThreadCpuTimeNs(), brokerResponse.getRealtimeThreadCpuTimeNs(),
-          StringUtils.substring(query, 0, _queryLogLength));
+          brokerResponse.getOfflineTotalCpuTimeNs(), brokerResponse.getOfflineThreadCpuTimeNs(),
+          brokerResponse.getOfflineSystemActivitiesCpuTimeNs(),
+          brokerResponse.getOfflineResponseSerializationCpuTimeNs(), brokerResponse.getRealtimeTotalCpuTimeNs(),
+          brokerResponse.getRealtimeThreadCpuTimeNs(), brokerResponse.getRealtimeSystemActivitiesCpuTimeNs(),
+          brokerResponse.getRealtimeResponseSerializationCpuTimeNs(), StringUtils.substring(query, 0, _queryLogLength));
 
       // Limit the dropping log message at most once per second.
       if (_numDroppedLogRateLimiter.tryAcquire()) {
@@ -836,8 +840,9 @@ private BrokerResponseNative handlePQLRequest(long requestId, String query, Json
       // Table name might have been changed (with suffix _OFFLINE/_REALTIME appended)
       LOGGER.info("requestId={},table={},timeMs={},docs={}/{},entries={}/{},"
               + "segments(queried/processed/matched/consuming/unavailable):{}/{}/{}/{}/{},consumingFreshnessTimeMs={},"
-              + "servers={}/{},groupLimitReached={},brokerReduceTimeMs={},exceptions={},serverStats={},query={},"
-              + "offlineThreadCpuTimeNs={},realtimeThreadCpuTimeNs={}", requestId,
+              + "servers={}/{},groupLimitReached={},brokerReduceTimeMs={},exceptions={},serverStats={},"
+              + "offlineThreadCpuTimeNs(total/thread/sysActivity/resSer):{}/{}/{}/{},"
+              + "realtimeThreadCpuTimeNs(total/thread/sysActivity/resSer):{}/{}/{}/{}," + "query={}", requestId,
           brokerRequest.getQuerySource().getTableName(), totalTimeMs, brokerResponse.getNumDocsScanned(),
           brokerResponse.getTotalDocs(), brokerResponse.getNumEntriesScannedInFilter(),
           brokerResponse.getNumEntriesScannedPostFilter(), brokerResponse.getNumSegmentsQueried(),
@@ -846,8 +851,11 @@ private BrokerResponseNative handlePQLRequest(long requestId, String query, Json
           brokerResponse.getMinConsumingFreshnessTimeMs(), brokerResponse.getNumServersResponded(),
           brokerResponse.getNumServersQueried(), brokerResponse.isNumGroupsLimitReached(),
           requestStatistics.getReduceTimeMillis(), brokerResponse.getExceptionsSize(), serverStats.getServerStats(),
-          StringUtils.substring(query, 0, _queryLogLength), brokerResponse.getOfflineThreadCpuTimeNs(),
-          brokerResponse.getRealtimeThreadCpuTimeNs());
+          brokerResponse.getOfflineTotalCpuTimeNs(), brokerResponse.getOfflineThreadCpuTimeNs(),
+          brokerResponse.getOfflineSystemActivitiesCpuTimeNs(),
+          brokerResponse.getOfflineResponseSerializationCpuTimeNs(), brokerResponse.getRealtimeTotalCpuTimeNs(),
+          brokerResponse.getRealtimeThreadCpuTimeNs(), brokerResponse.getRealtimeSystemActivitiesCpuTimeNs(),
+          brokerResponse.getRealtimeResponseSerializationCpuTimeNs(), StringUtils.substring(query, 0, _queryLogLength));
 
       // Limit the dropping log message at most once per second.
       if (_numDroppedLogRateLimiter.tryAcquire()) {

diff --git a/pinot-common/src/main/java/org/apache/pinot/common/metrics/BrokerTimer.java b/pinot-common/src/main/java/org/apache/pinot/common/metrics/BrokerTimer.java
@@ -33,10 +33,24 @@ public enum BrokerTimer implements AbstractMetrics.Timer {
   // The latency of sending the request from broker to server
   NETTY_CONNECTION_SEND_REQUEST_LATENCY(false),
 
-  // aggregated query processing cost (thread cpu time in nanoseconds) from offline servers
-  OFFLINE_THREAD_CPU_TIME_NS(
-      false), // aggregated query processing cost (thread cpu time in nanoseconds) from realtime servers
-  REALTIME_THREAD_CPU_TIME_NS(false);
+  // aggregated thread cpu time in nanoseconds for query processing from offline servers
+  OFFLINE_THREAD_CPU_TIME_NS(false),
+  // aggregated thread cpu time in nanoseconds for query processing from realtime servers
+  REALTIME_THREAD_CPU_TIME_NS(false),
+  // aggregated system activities cpu time in nanoseconds for query processing from offline servers
+  OFFLINE_SYSTEM_ACTIVITIES_CPU_TIME_NS(false),
+  // aggregated system activities cpu time in nanoseconds for query processing from realtime servers
+  REALTIME_SYSTEM_ACTIVITIES_CPU_TIME_NS(false),
+  // aggregated response serialization cpu time in nanoseconds for query processing from offline servers
+  OFFLINE_RESPONSE_SER_CPU_TIME_NS(false),
+  // aggregated response serialization cpu time in nanoseconds for query processing from realtime servers
+  REALTIME_RESPONSE_SER_CPU_TIME_NS(false),
+  // aggregated total cpu time(thread + system activities + response serialization) in nanoseconds for query
+  // processing from offline servers
+  OFFLINE_TOTAL_CPU_TIME_NS(false),
+  // aggregated total cpu time(thread + system activities + response serialization) in nanoseconds for query
+  // processing from realtime servers
+  REALTIME_TOTAL_CPU_TIME_NS(false);
 
   private final String _timerName;
   private final boolean _global;

diff --git a/pinot-common/src/main/java/org/apache/pinot/common/metrics/ServerTimer.java b/pinot-common/src/main/java/org/apache/pinot/common/metrics/ServerTimer.java
@@ -32,8 +32,18 @@ public enum ServerTimer implements AbstractMetrics.Timer {
   // The latency of sending the response from server to broker
   NETTY_CONNECTION_SEND_RESPONSE_LATENCY("nettyConnection", false),
 
-  // Query cost (thread cpu time) for query processing on server
-  EXECUTION_THREAD_CPU_TIME_NS("nanoseconds", false);
+  // Query cost (execution thread cpu time) for query processing on server
+  EXECUTION_THREAD_CPU_TIME_NS("nanoseconds", false),
+
+  // Query cost (system activities cpu time) for query processing on server
+  SYSTEM_ACTIVITIES_CPU_TIME_NS("nanoseconds", false),
+
+  // Query cost (response serialization cpu time) for query processing on server
+  RESPONSE_SER_CPU_TIME_NS("nanoseconds", false),
+
+  // Total query cost (thread cpu time + system activities cpu time + response serialization cpu time) for query
+  // processing on server
+  TOTAL_CPU_TIME_NS("nanoseconds", false);
 
   private final String _timerName;
   private final boolean _global;

diff --git a/pinot-common/src/main/java/org/apache/pinot/common/response/BrokerResponse.java b/pinot-common/src/main/java/org/apache/pinot/common/response/BrokerResponse.java
@@ -51,16 +51,6 @@ public interface BrokerResponse {
    */
   void setTimeUsedMs(long timeUsedMs);
 
-  /**
-   * Set the total thread cpu time used against realtime table in request handling, into the broker response.
-   */
-  void setRealtimeThreadCpuTimeNs(long realtimeThreadCpuTimeNs);
-
-  /**
-   * Set the total thread cpu time used against offline table in request handling, into the broker response.
-   */
-  void setOfflineThreadCpuTimeNs(long offlineThreadCpuTimeNs);
-
   /**
    * Set the total number of rows in result set
    */
@@ -143,17 +133,91 @@ String toJsonString()
   List<QueryProcessingException> getProcessingExceptions();
 
   /**
-   * Get the total thread cpu time used against realtime table in request handling, into the broker response.
+   * Get the total number of rows in result set
    */
-  long getRealtimeThreadCpuTimeNs();
+  int getNumRowsResultSet();
 
   /**
-   * Get the total thread cpu time used against offline table in request handling, into the broker response.
+   * Set the total thread cpu time used against offline table in request handling, into the broker response.
+   */
+  void setOfflineThreadCpuTimeNs(long offlineThreadCpuTimeNs);
+
+  /**
+   * Get the thread cpu time used against offline table in request handling, from the broker response.
    */
   long getOfflineThreadCpuTimeNs();
 
   /**
-   * Get the total number of rows in result set
+   * Get the thread cpu time used against realtime table in request handling, from the broker response.
    */
-  int getNumRowsResultSet();
+  long getRealtimeThreadCpuTimeNs();
+
+  /**
+   * Set the total thread cpu time used against realtime table in request handling, into the broker response.
+   */
+  void setRealtimeThreadCpuTimeNs(long realtimeThreadCpuTimeNs);
+
+  /**
+   * Get the system activities cpu time used against offline table in request handling, from the broker response.
+   */
+  long getOfflineSystemActivitiesCpuTimeNs();
+
+  /**
+   * Set the system activities cpu time used against offline table in request handling, into the broker response.
+   */
+  void setOfflineSystemActivitiesCpuTimeNs(long offlineSystemActivitiesCpuTimeNs);
+
+  /**
+   * Get the system activities cpu time used against realtime table in request handling, from the broker response.
+   */
+  long getRealtimeSystemActivitiesCpuTimeNs();
+
+  /**
+   * Set the system activities cpu time used against realtime table in request handling, into the broker response.
+   */
+  void setRealtimeSystemActivitiesCpuTimeNs(long realtimeSystemActivitiesCpuTimeNs);
+
+  /**
+   * Get the response serialization cpu time used against offline table in request handling, from the broker response.
+   */
+  long getOfflineResponseSerializationCpuTimeNs();
+
+  /**
+   * Set the response serialization cpu time used against offline table in request handling, into the broker response.
+   */
+  void setOfflineResponseSerializationCpuTimeNs(long offlineResponseSerializationCpuTimeNs);
+
+  /**
+   * Get the response serialization cpu time used against realtime table in request handling, from the broker response.
+   */
+  long getRealtimeResponseSerializationCpuTimeNs();
+
+  /**
+   * Set the response serialization cpu time used against realtime table in request handling, into the broker response.
+   */
+  void setRealtimeResponseSerializationCpuTimeNs(long realtimeResponseSerializationCpuTimeNs);
+
+  /**
+   * Get the total cpu time(thread cpu time + system activities cpu time + response serialization cpu time) used
+   * against offline table in request handling, from the broker response.
+   */
+  long getOfflineTotalCpuTimeNs();
+
+  /**
+   * Set the total cpu time(thread cpu time + system activities cpu time + response serialization cpu time) used
+   * against offline table in request handling, into the broker response.
+   */
+  void setOfflineTotalCpuTimeNs(long offlineTotalCpuTimeNs);
+
+  /**
+   * Get the total cpu time(thread cpu time + system activities cpu time + response serialization cpu time) used
+   * against realtime table in request handling, from the broker response.
+   */
+  long getRealtimeTotalCpuTimeNs();
+
+  /**
+   * Set the total cpu time(thread cpu time + system activities cpu time + response serialization cpu time) used
+   * against realtime table in request handling, into the broker response.
+   */
+  void setRealtimeTotalCpuTimeNs(long realtimeTotalCpuTimeNs);
 }