[IMPALA-11406] Incorrect duration logged in "Authorization check took n ms"

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Affects Version/s: Impala 4.0.0, Impala 3.3.0, Impala 3.4.0, Impala 3.4.1, Impala 4.1.0
• Fix Version/s: Impala 3.4.2, Impala 4.2.0, Impala 4.1.1
• Component/s: Frontend
• Epic Color: ghx-label-12
• Assignee: Quanlong Huang
• Reporter: Quanlong Huang
• Created: 30/Jun/22 06:45
• Updated: 05/Feb/24 08:27
• Resolved: 22/Jul/22 02:44

Description

While debugging a catalogd restart issue, I found some misleading logs of long authorization check duration, although I haven't enabled authorization in my cluster.

I0630 14:21:53.239120 15712 Frontend.java:1877] 92423a19e75422e1:cb71252200000000] Analyzing query: use tpch_orc_def db: default
...
I0630 14:21:56.293681 15712 BaseAuthorizationChecker.java:112] 92423a19e75422e1:cb71252200000000] Authorization check took 3054 ms
I0630 14:21:56.293723 15712 Frontend.java:2021] 92423a19e75422e1:cb71252200000000] Analysis and authorization finished.

However, the profile shows the duration is spent in the analyze phase, and the authorization only took 61.832us:

Query (id=92423a19e75422e1:cb71252200000000):
  DEBUG MODE WARNING: Query profile created while running a DEBUG build of Impala. Use RELEASE builds to measure query performance.
   - InactiveTotalTime: 0.000ns
   - TotalTime: 0.000ns
  Summary:
    Session ID: d24cdf845c7c43de:4fce33cdbfc479ab
    Session Type: HIVESERVER2
    HiveServer2 Protocol Version: V6
    Start Time: 2022-06-30 14:21:53.238869000
    End Time: 2022-06-30 14:21:56.295063000
    Query Type: DDL
    Query State: FINISHED
    Impala Query State: FINISHED
    Query Status: OK
    Impala Version: impalad version 4.2.0-SNAPSHOT DEBUG (build bb610dee09a8069bb993b4c668f7e481c1774b70)
    User: quanlong
    Connected User: quanlong
    Delegated User: 
    Network Address: 127.0.0.1:33164
    Default Db: default
    Sql Statement: use tpch_orc_def
    Coordinator: quanlong-OptiPlex-BJ:27000
    Query Options (set by configuration): TIMEZONE=PRC,CLIENT_IDENTIFIER=impala shell build version not available
    Query Options (set by configuration and planner): MT_DOP=0,TIMEZONE=PRC,CLIENT_IDENTIFIER=impala shell build version not available
    DDL Type: USE
    DDL execution mode: synchronous
    Query Compilation: 3s054ms
       - Metadata of all 0 tables cached: 254.609us (254.609us)
       - Analysis finished: 3s054ms (3s054ms)  <---------------- Time spent here
       - Authorization finished (noop): 3s054ms (61.832us)
       - Planning finished: 3s054ms (204.218us)
    Query Timeline: 3s056ms
       - Query submitted: 21.206us (21.206us)
       - Planning finished: 3s055ms (3s055ms)
       - Request finished: 3s055ms (487.686us)
       - Unregister query: 3s056ms (568.376us)
     - InactiveTotalTime: 0.000ns
     - TotalTime: 0.000ns
    Frontend:
       - CatalogFetch.DatabaseList.Hits: 1
       - CatalogFetch.DatabaseList.Misses: 0
       - CatalogFetch.DatabaseList.Requests: 1
       - CatalogFetch.DatabaseList.Time: 0
       - CatalogFetch.Databases.Hits: 0
       - CatalogFetch.Databases.Misses: 1
       - CatalogFetch.Databases.Requests: 1
       - CatalogFetch.Databases.Time: 3s054ms
       - CatalogFetch.RPCs.Bytes: 181.00 B (181)
       - CatalogFetch.RPCs.Requests: 1
       - CatalogFetch.RPCs.Time: 3s053ms
       - InactiveTotalTime: 0.000ns
       - TotalTime: 0.000ns
  ImpalaServer:
     - ClientFetchWaitTimer: 559.030us
     - InactiveTotalTime: 0.000ns
     - NumRowsFetched: 0 (0)
     - NumRowsFetchedFromCache: 0 (0)
     - RowMaterializationRate: 0
     - RowMaterializationTimer: 0.000ns
     - TotalTime: 0.000ns

Looking into the code where this is logged:

  @Override
  public void postAuthorize(AuthorizationContext authzCtx, boolean authzOk) {
    if (authzCtx.getTimeline().isPresent()) {
      EventSequence timeline = authzCtx.getTimeline().get();
      long durationMs = timeline.markEvent(String.format("Authorization finished (%s)",
          config_.getProviderName())) / 1000000;
      LOG.debug("Authorization check took {} ms", durationMs);
    }
  }

The duration comes from markEvent():

  /**
   * Saves an event at the current time with the given label.
   * It returns the duration in nano seconds between the last and the current event.
   */
  public long markEvent(String label) {
    // Timestamps should be in ns resolution
    long durationNs = System.nanoTime() - startTime_;
    timestamps_.add(durationNs);
    labels_.add(label);
    return durationNs;
  }

However, the above code never updates startTime_, which causes the duration become a cumulative time since start.

Issue Links

• is caused by: IMPALA-8443 Record time spent in authorization in the runtime profile
• links to: Code Review