Dong Li created KYLIN-2107:
------------------------------
Summary: Time delta between first log record and last log record
may be larger(around 10ms) than duration field for one query
Key: KYLIN-2107
URL: https://issues.apache.org/jira/browse/KYLIN-2107
Project: Kylin
Issue Type: Bug
Affects Versions: v1.5.4.1
Reporter: Dong Li
Assignee: Dong Li
2016-08-05 02:20:45,672 INFO [http-bio-7070-exec-34]
controller.QueryController:174 : Using project: xxx
2016-08-05 02:20:45,672 INFO [http-bio-7070-exec-34]
controller.QueryController:175 : The original query: select xxx from xxx
2016-08-05 02:20:45,704 INFO [http-bio-7070-exec-34] routing.QueryRouter:48 :
The project manager's reference is
org.apache.kylin.metadata.project.ProjectManager@7b58152e
2016-08-05 02:20:45,704 INFO [http-bio-7070-exec-34] routing.QueryRouter:60 :
Find candidates by table xxx and project=xxx :
org.apache.kylin.query.routing.Candidate@cf6e8c4,org.apache.kylin.query.routing.Candidate@262ba282,org.apache.kylin.query.routing.Candidate@7aba1861,org.apache.kylin.query.routing.Candidate@4f96c739
2016-08-05 02:20:45,705 INFO [http-bio-7070-exec-34]
cube.CubeCapabilityChecker:152 : Query joins don't macth on cube xxx
2016-08-05 02:20:45,705 INFO [http-bio-7070-exec-34]
cube.CubeCapabilityChecker:58 : Exclude cube xxx because unmatched joins
2016-08-05 02:20:45,705 INFO [http-bio-7070-exec-34]
cube.CubeCapabilityChecker:152 : Query joins don't macth on cube 3
2016-08-05 02:20:45,705 INFO [http-bio-7070-exec-34]
cube.CubeCapabilityChecker:58 : Exclude cube 3 because unmatched joins
2016-08-05 02:20:45,706 INFO [http-bio-7070-exec-34] routing.QueryRouter:49 :
Applying rule: class
org.apache.kylin.query.routing.rules.RemoveUncapableRealizationsRule,
realizations before: [xxx]
2016-08-05 02:20:45,706 INFO [http-bio-7070-exec-34] routing.QueryRouter:49 :
Applying rule: class org.apache.kylin.query.routing.rules.RealizationSortRule,
realizations before: [xxx], realizations after: [xxx]
2016-08-05 02:20:45,706 INFO [http-bio-7070-exec-34] routing.QueryRouter:72 :
The realizations remaining: [xxx] And the final chosen one is the first one
2016-08-05 02:20:45,732 DEBUG [http-bio-7070-exec-34]
enumerator.OLAPEnumerator:105 : query storage...
2016-08-05 02:20:45,733 INFO [http-bio-7070-exec-34]
gtrecord.GTCubeStorageQueryBase:242 : exactAggregation is false because cube is
partitioned and xxx is not on group by
2016-08-05 02:20:45,733 DEBUG [http-bio-7070-exec-34]
v2.CubeHBaseEndpointRPC:268 : New scanner for current segment xxx[xxx] will use
SCAN_FILTER_AGGR_CHECKMEM as endpoint's behavior
2016-08-05 02:20:45,734 DEBUG [http-bio-7070-exec-34]
v2.CubeHBaseEndpointRPC:324 : Serialized scanRequestBytes 563 bytes,
rawScanBytesString 46 bytes
2016-08-05 02:20:45,734 INFO [http-bio-7070-exec-34]
v2.CubeHBaseEndpointRPC:326 : The scan 3bdc81c0 for segment xx[xxx] is as below
with 1 separate raw scans, shard part of start/end key is set to 0
2016-08-05 02:20:45,735 INFO [http-bio-7070-exec-34] v2.CubeHBaseRPC:271 :
Visiting hbase table xxx: cuboid exact match, from 64 to 112 Start:
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x70\x00\x00\x00\x00
(\x00\x00\x00\x00\x00\x00\x00\x00\x00p\x00\x00\x00\x00) Stop:
\x00\x00\x00\x00\x00\x00\x00\x00\x00\x70\xFF\xFF\xFF\xFF\x00
(\x00\x00\x00\x00\x00\x00\x00\x00\x00p\xFF\xFF\xFF\xFF\x00), No Fuzzy Key
2016-08-05 02:20:45,735 DEBUG [http-bio-7070-exec-34]
v2.CubeHBaseEndpointRPC:331 : Submitting rpc to 1 shards starting from shard 4,
scan range count 1
2016-08-05 02:20:45,735 INFO [http-bio-7070-exec-34]
v2.CubeHBaseEndpointRPC:107 : Timeout for ExpectedSizeIterator is: 330000
2016-08-05 02:20:45,735 DEBUG [http-bio-7070-exec-34]
enumerator.OLAPEnumerator:122 : return TupleIterator...
2016-08-05 02:20:45,785 INFO [kylin-coproc--pool8-t191]
v2.CubeHBaseEndpointRPC:385 : <sub-thread for GTScanRequest 3bdc81c0> Endpoint
RPC returned from HTable KYLIN_Y8T1367HP7 Shard
\x4B\x59\x4C\x49\x4E\x5F\x59\x38\x54\x31\x33\x36\x37\x48\x50\x37\x2C\x00\x04\x2C\x31\x34\x37\x30\x30\x34\x34\x33\x39\x38\x36\x38\x35\x2E\x34\x34\x63\x31\x61\x39\x30\x62\x65\x66\x65\x36\x34\x36\x38\x33\x37\x65\x36\x34\x61\x34\x61\x61\x32\x61\x31\x64\x37\x38\x66\x62\x2E
on host: ip-10-0-0-207.Total scanned row: 7525. Total filtered/aggred row: 0.
Time elapsed in EP: 45(ms). Server CPU usage: 0.054019367635048415, server
physical mem left: 8.3144704E7, server swap mem left:5.612847104E9.Etc message:
start latency: -1745@1,agg done@40,compress done@44,server stats done@45,
debugGitTag:7acf71b130d3d11852c392890f5bf5b62b251523@KAP;297c46858e11ba7875671a4d39b46d90a5b2548a@ApacheKylin;Build
with JENKINS at 2016-08-02 00:04:20;.Normal Complete: true.
2016-08-05 02:20:45,786 DEBUG [kylin-coproc--pool8-t191]
util.CompressionUtils:67 : Original: 53084 bytes. Decompressed: 60200 bytes.
Time: 1
2016-08-05 02:20:45,805 INFO [http-bio-7070-exec-34] service.QueryService:404
: Scan count for each storageContext: 7525,
2016-08-05 02:20:45,806 INFO [http-bio-7070-exec-34]
controller.QueryController:197 : Stats of SQL response: isException: false,
duration: 134, total scan count 7525
2016-08-05 02:20:45,815 INFO [http-bio-7070-exec-34] service.QueryService:255
:
==========================[QUERY]===============================
SQL: select xxx from xxx
User: ADMIN
Success: true
Duration: 0.134
Project: xxx
Realization Names: [xxx]
Cuboid Ids: [xxx]
Total scan count: 7525
Result row count: 7525
Accept Partial: false
Is Partial Result: false
Hit Exception Cache: false
Storage cache used: false
Message: null
==========================[QUERY]===============================
>From the log above, the query starts at 2016-08-05 02:20:45,672, and ends at
>2016-08-05 02:20:45,815, the diff is 143ms
But in the query summary, the duration is: 0.134s
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
