[impala] 21/27: IMPALA-11406: Fix incorrect duration log for authorization

[st...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

stigahuang pushed a commit to branch branch-4.1.1
in repository https://gitbox.apache.org/repos/asf/impala.git

commit f767619dc6ba94dc09fb6c43e53d4f6dd2238a7b
Author: stiga-huang <hu...@gmail.com>
AuthorDate: Thu Jun 30 14:59:41 2022 +0800

    IMPALA-11406: Fix incorrect duration log for authorization
    
    IMPALA-8443 extends EventSequence.markEvent() to return the duration
    between the last and the current event. However, the duration is
    calculated using the start time, not the last time it's invoked, which
    causes misleading time in logs of "Authorization check took n ms".
    
    This fixes the bug and also adds a log for the analysis duration.
    
    Change-Id: I8b665f1b4ac86577711598ce9d845cf82fedbcd7
    Reviewed-on: http://gerrit.cloudera.org:8080/18682
    Reviewed-by: Impala Public Jenkins <im...@cloudera.com>
    Tested-by: Impala Public Jenkins <im...@cloudera.com>
---
 fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java | 3 ++-
 fe/src/main/java/org/apache/impala/util/EventSequence.java       | 8 ++++++--
 2 files changed, 8 insertions(+), 3 deletions(-)

diff --git a/fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java b/fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java
index 8442a27a4..9304ffbe5 100644
--- a/fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java
+++ b/fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java
@@ -471,7 +471,8 @@ public class AnalysisContext {
     } finally {
       authzChecker.postAnalyze(authzCtx);
     }
-    timeline_.markEvent("Analysis finished");
+    long durationMs = timeline_.markEvent("Analysis finished") / 1000000;
+    LOG.info("Analysis took {} ms", durationMs);
 
     // Authorize statement and record exception. Authorization relies on information
     // collected during analysis.
diff --git a/fe/src/main/java/org/apache/impala/util/EventSequence.java b/fe/src/main/java/org/apache/impala/util/EventSequence.java
index d137208c1..72b1126d9 100644
--- a/fe/src/main/java/org/apache/impala/util/EventSequence.java
+++ b/fe/src/main/java/org/apache/impala/util/EventSequence.java
@@ -33,10 +33,12 @@ public class EventSequence {
 
   private final long startTime_;
   private final String name_;
+  private long lastTime_;
 
   public EventSequence(String name) {
     name_ = name;
     startTime_ = System.nanoTime();
+    lastTime_ = startTime_;
   }
 
   /**
@@ -45,8 +47,10 @@ public class EventSequence {
    */
   public long markEvent(String label) {
     // Timestamps should be in ns resolution
-    long durationNs = System.nanoTime() - startTime_;
-    timestamps_.add(durationNs);
+    long currentTime = System.nanoTime();
+    long durationNs = currentTime - lastTime_;
+    lastTime_ = currentTime;
+    timestamps_.add(currentTime - startTime_);
     labels_.add(label);
     return durationNs;
   }