[jira] [Created] (KYLIN-2107) Time delta between first log record and last log record may be larger(around 10ms) than duration field for one query

["Dong Li (JIRA)" <ji...@apache.org>]

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)