You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues-all@impala.apache.org by "ASF subversion and git services (Jira)" <ji...@apache.org> on 2022/07/19 11:02:00 UTC
[jira] [Commented] (IMPALA-11406) Incorrect duration logged in "Authorization check took n ms"
[ https://issues.apache.org/jira/browse/IMPALA-11406?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17568474#comment-17568474 ]
ASF subversion and git services commented on IMPALA-11406:
----------------------------------------------------------
Commit 733c950dafd91460e06122b231dc4a4371e0fe85 in impala's branch refs/heads/master from stiga-huang
[ https://gitbox.apache.org/repos/asf?p=impala.git;h=733c950da ]
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>
> 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
> Reporter: Quanlong Huang
> Assignee: Quanlong Huang
> Priority: Critical
>
> 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: issues-all-unsubscribe@impala.apache.org
For additional commands, e-mail: issues-all-help@impala.apache.org