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)

Reply via email to