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
             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 
2016-08-05 02:20:45,704 INFO  [http-bio-7070-exec-34] routing.QueryRouter:60 : 
Find candidates by table xxx and project=xxx : 
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 
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\x00p\x00\x00\x00\x00) Stop:  
(\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 
 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, 
 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 
SQL: select xxx from xxx
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

>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

Reply via email to