Uploaded image for project: 'IMPALA'
  2. IMPALA-11406

Incorrect duration logged in "Authorization check took n ms"



    • Bug
    • Status: Resolved
    • Critical
    • Resolution: Fixed
    • Impala 4.0.0, Impala 3.3.0, Impala 3.4.0, Impala 3.4.1, Impala 4.1.0
    • Frontend
    • None
    • ghx-label-12


      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
          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:
          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
             - 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
           - 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:

        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_;
          return durationNs;

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


        Issue Links



              stigahuang Quanlong Huang
              stigahuang Quanlong Huang
              0 Vote for this issue
              3 Start watching this issue