[ https://issues.apache.org/jira/browse/KYLIN-2107?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Dong Li updated KYLIN-2107: --------------------------- Description: 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:xxx;.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 was: 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 > 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:xxx;.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)