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 <impala-public-jenkins@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>

fe/src/main/java/org/apache/impala/analysis/AnalysisContext.java

@@ -471,7 +471,8 @@ public AnalysisResult analyzeAndAuthorize(StatementBase stmt,
     } 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.

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 EventSequence(String name) {
    */
   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;
   }