[
https://issues.apache.org/jira/browse/IMPALA-11406?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Quanlong Huang updated IMPALA-11406:
------------------------------------
Fix Version/s: Impala 3.4.2
> Incorrect duration logged in "Authorization check took n ms"
> ------------------------------------------------------------
>
> Key: IMPALA-11406
> URL: https://issues.apache.org/jira/browse/IMPALA-11406
> Project: IMPALA
> Issue Type: Bug
> Components: Frontend
> Affects Versions: Impala 4.0.0, Impala 3.3.0, Impala 3.4.0, Impala 3.4.1,
> Impala 4.1.0
> Reporter: Quanlong Huang
> Assignee: Quanlong Huang
> Priority: Critical
> Fix For: Impala 3.4.2, Impala 4.2.0, Impala 4.1.1
>
>
> 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.
> {noformat}
> 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.{noformat}
> However, the profile shows the duration is spent in the analyze phase, and
> the authorization only took 61.832us:
> {noformat}
> 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{noformat}
> Looking into the code where this is logged:
> {code:java}
> @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);
> }
> }
> {code}
> The duration comes from markEvent():
> {code:java}
> /**
> * 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;
> }
> {code}
> However, the above code never updates {{startTime_}}, which causes the
> duration become a cumulative time since start.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
