[ https://issues.apache.org/jira/browse/IMPALA-11406?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Quanlong Huang resolved IMPALA-11406. ------------------------------------- Fix Version/s: Impala 4.2.0 Resolution: Fixed > 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 > Fix For: Impala 4.2.0 > > > 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-unsubscr...@impala.apache.org For additional commands, e-mail: issues-all-h...@impala.apache.org