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 "Quanlong Huang (Jira)" <ji...@apache.org> on 2022/06/30 06:46:00 UTC
[jira] [Created] (IMPALA-11406) Incorrect duration logged in "Authorization check took n ms"
Quanlong Huang created IMPALA-11406:
---------------------------------------
Summary: 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
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