使用AWK規整KyLin日誌
我們需要解析Kylin的日誌,獲取查詢的相關資訊.
但是Kylin的日誌是併發寫的,也就是併發情況下,查詢日誌會有交叉。
另外,Kylin彙總的行需要提取出來
最後,涉及SQL的行，需要把多行合併為一行。
KyLin原始日誌如下
2018-06-22 18:17:05,341 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:428 : Using project: h_test
2018-06-22 18:17:05,342 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:429 : The original query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1 LIMIT 5000
2018-06-22 18:17:05,345 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:893 : Setting current statement's max rows to 0
2018-06-22 18:17:05,360 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:58 : Find candidates by table ODS.O_M_T_SCORE and project=h_test : CUBE[name=CubeT_1]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveBlackoutRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveUncapableRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] rules.RealizationSortRule:40 : CUBE[name=CubeT_1] priority 1 cost 14200.
2018-06-22 18:17:05,362 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RealizationSortRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,362 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:75 : The realizations remaining: [CUBE[name=CubeT_1]],and the final chosen one for current olap context 0 is CUBE[name=CubeT_1]
2018-06-22 18:17:05,373 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] enumerator.OLAPEnumerator:108 : query storage...
2018-06-22 18:17:05,373 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] cube.RawQueryLastHacker:43 : No group by and aggregation found in this query, will hack some result for better look of output...
2018-06-22 18:17:05,373 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:308 : Does not need storage aggregation
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:579 : exactAggregation is true, cuboid id is 511
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:289 : Filter column set for query: []
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:298 : Filter mask is: 0
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] storage.StorageContext:165 : Enabling limit push down: 5000 at level: LIMIT_ON_SCAN
2018-06-22 18:17:05,375 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:463 : Aggregate partition results is not beneficial because no storage aggregation
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:170 : Cuboid identified: cube=CubeT_1, cuboidId=511, groupsD=[ODS.O_M_T_STUDENT.CITY, ODS.O_M_T_STUDENT.ID, ODS.O_M_T_SUBJECT.ID, ODS.O_M_T_SCORE.SUBJECT_ID, ODS.O_M_T_STUDENT.USER_NAME, ODS.O_M_T_SCORE.USER_ID, ODS.O_M_T_SUBJECT.SUBJECT_NAME, ODS.O_M_T_STUDENT.SEX, ODS.O_M_T_STUDENT.PROVINCE], filterD=[], limitPushdown=5000, limitLevel=LIMIT_ON_SCAN, storageAggr=false
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.CubeSegmentScanner:56 : Init CubeSegmentScanner for segment FULL_BUILD
2018-06-22 18:17:05,376 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseRPC:315 : hbase.rpc.timeout = 60000 ms, use 54000 ms as timeout for coprocessor
2018-06-22 18:17:05,376 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:152 : Serialized scanRequestBytes 1460 bytes, rawScanBytesString 56 bytes
2018-06-22 18:17:05,377 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:154 : The scan 7b4870f for segment CubeT_1[FULL_BUILD] is as below with 1 separate raw scans, shard part of start/end key is set to 0
2018-06-22 18:17:05,377 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseRPC:288 : Visiting hbase table KYLIN_D52DC4HQKR: cuboid exact match, from 511 to 511 Start: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00) Stop: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00), No Fuzzy Key
2018-06-22 18:17:05,377 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:159 : Submitting rpc to 1 shards starting from shard 0, scan range count 1
2018-06-22 18:17:05,378 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.KylinConfig:319 : Loading kylin-defaults.properties from file:/opt/soft/apache-kylin-2.3.0-bin/tomcat/webapps/kylin/WEB-INF/lib/kylin-core-common-2.3.0.jar!/kylin-defaults.properties
2018-06-22 18:17:05,385 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.KylinConfig:278 : KYLIN_CONF property was not set, will seek KYLIN_HOME env variable
2018-06-22 18:17:05,385 WARN [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.BackwardCompatibilityConfig:93 : Config 'kylin.job.mr.lib.dir' is deprecated, use 'kylin.engine.mr.lib-dir' instead
2018-06-22 18:17:05,386 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.SequentialCubeTupleIterator:73 : Using Iterators.concat to merge segment results
2018-06-22 18:17:05,386 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] enumerator.OLAPEnumerator:120 : return TupleIterator...
2018-06-22 18:17:05,387 INFO [kylin-coproc--pool2-t1175] v2.CubeHBaseEndpointRPC:217 : Query-1235b6a5-ae41-431d-bd75-bef0dae0bf57: send request to the init region server tjtx-89-89.58os.org on table KYLIN_D52DC4HQKR
2018-06-22 18:17:05,393 INFO [kylin-coproc--pool2-t1175] v2.CubeHBaseEndpointRPC:284 : <sub-thread for Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57 GTScanRequest 7b4870f>Endpoint RPC returned from HTable KYLIN_D52DC4HQKR Shard \x4B\x59\x4C\x49\x4E\x5F\x44\x35\x32\x44\x43\x34\x48\x51\x4B\x52\x2C\x2C\x31\x35\x32\x35\x34\x32\x34\x30\x39\x37\x36\x39\x36\x2E\x30\x62\x32\x39\x38\x62\x64\x33\x31\x37\x30\x39\x33\x37\x36\x63\x34\x32\x38\x34\x64\x31\x37\x66\x33\x33\x34\x39\x66\x62\x63\x63\x2E on host: tjtx-89-89.58os.org.Total scanned row: 70. Total scanned bytes: 3430. Total filtered row: 0. Total aggred row: 0. Time elapsed in EP: 2(ms). Server CPU usage: 0.01470260637112943, server physical mem left: 5.6562040832E10, server swap mem left:3.3554427904E10.Etc message: start latency: 8@1,agg done@2,compress done@2,server stats done@2, debugGitTag:1179ee72d0a2a2c629a649751ef43ae9e82dc87a;.Normal Complete: true.Compressed row size: 265
2018-06-22 18:17:05,393 DEBUG [kylin-coproc--pool2-t1175] util.CompressionUtils:67 : Original: 265 bytes. Decompressed: 700 bytes. Time: 0
2018-06-22 18:17:05,393 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.SortMergedPartitionResultIterator:76 : Using SortMergedPartitionResultIterator to merge 1 partition results out of 1 partitions
2018-06-22 18:17:05,394 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:1068 : Processed rows for each storageContext: 70
2018-06-22 18:17:05,394 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:510 : Stats of SQL response: isException: false, duration: 55, total scan count 70
2018-06-22 18:17:05,394 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] util.CheckUtil:35 : query is too lightweight with duration: 55 (threshold 2000), scan count: 70 (threshold 10240), scan bytes: 3430 (threshold 1048576)
2018-06-22 18:17:05,395 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:328 :
==========================[QUERY]===============================
Query Id: 1235b6a5-ae41-431d-bd75-bef0dae0bf57
SQL: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1 LIMIT 5000
User: ADMIN
Success: true
Duration: 0.056
Project: h_test
Realization Names: [CUBE[name=CubeT_1]]
Cuboid Ids: [511]
Total scan count: 70
Total scan bytes: 3430
Result row count: 70
Accept Partial: false
Is Partial Result: false
Hit Exception Cache: false
Storage cache used: false
Is Query Push-Down: false
Is Prepare: false
Trace URL: null
Message: null
==========================[QUERY]===============================
2018-06-22 18:17:14,141 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:428 : Using project: h_test
2018-06-22 18:17:14,141 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:429 : The original query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
2018-06-22 18:17:14,145 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:646 : The corrected query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
LIMIT 50000
2018-06-22 18:17:14,164 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:58 : Find candidates by table ODS.O_M_T_SCORE and project=h_test : CUBE[name=CubeT_1]
2018-06-22 18:17:14,164 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveBlackoutRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveUncapableRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] rules.RealizationSortRule:40 : CUBE[name=CubeT_1] priority 1 cost 14200.
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RealizationSortRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:75 : The realizations remaining: [CUBE[name=CubeT_1]],and the final chosen one for current olap context 0 is CUBE[name=CubeT_1]
2018-06-22 18:17:14,176 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] enumerator.OLAPEnumerator:108 : query storage...
2018-06-22 18:17:14,177 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] cube.RawQueryLastHacker:43 : No group by and aggregation found in this query, will hack some result for better look of output...
2018-06-22 18:17:14,177 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:308 : Does not need storage aggregation
2018-06-22 18:17:14,177 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:579 : exactAggregation is true, cuboid id is 511
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:289 : Filter column set for query: []
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:298 : Filter mask is: 0
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] storage.StorageContext:165 : Enabling limit push down: 50000 at level: LIMIT_ON_SCAN
2018-06-22 18:17:14,178 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:463 : Aggregate partition results is not beneficial because no storage aggregation
2018-06-22 18:17:14,179 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:170 : Cuboid identified: cube=CubeT_1, cuboidId=511, groupsD=[ODS.O_M_T_STUDENT.CITY, ODS.O_M_T_STUDENT.ID, ODS.O_M_T_SUBJECT.ID, ODS.O_M_T_SCORE.SUBJECT_ID, ODS.O_M_T_STUDENT.USER_NAME, ODS.O_M_T_SCORE.USER_ID, ODS.O_M_T_SUBJECT.SUBJECT_NAME, ODS.O_M_T_STUDENT.SEX, ODS.O_M_T_STUDENT.PROVINCE], filterD=[], limitPushdown=50000, limitLevel=LIMIT_ON_SCAN, storageAggr=false
2018-06-22 18:17:14,179 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.CubeSegmentScanner:56 : Init CubeSegmentScanner for segment FULL_BUILD
2018-06-22 18:17:14,180 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseRPC:315 : hbase.rpc.timeout = 60000 ms, use 54000 ms as timeout for coprocessor
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:152 : Serialized scanRequestBytes 1460 bytes, rawScanBytesString 56 bytes
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:154 : The scan 31d3d2c8 for segment CubeT_1[FULL_BUILD] is as below with 1 separate raw scans, shard part of start/end key is set to 0
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseRPC:288 : Visiting hbase table KYLIN_D52DC4HQKR: cuboid exact match, from 511 to 511 Start: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00) Stop: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00), No Fuzzy Key
2018-06-22 18:17:14,182 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:159 : Submitting rpc to 1 shards starting from shard 0, scan range count 1
2018-06-22 18:17:14,182 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.KylinConfig:319 : Loading kylin-defaults.properties from file:/opt/soft/apache-kylin-2.3.0-bin/tomcat/webapps/kylin/WEB-INF/lib/kylin-core-common-2.3.0.jar!/kylin-defaults.properties
2018-06-22 18:17:14,188 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.KylinConfig:278 : KYLIN_CONF property was not set, will seek KYLIN_HOME env variable
2018-06-22 18:17:14,189 WARN [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.BackwardCompatibilityConfig:93 : Config 'kylin.job.mr.lib.dir' is deprecated, use 'kylin.engine.mr.lib-dir' instead
2018-06-22 18:17:14,190 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.SequentialCubeTupleIterator:73 : Using Iterators.concat to merge segment results
2018-06-22 18:17:14,190 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] enumerator.OLAPEnumerator:120 : return TupleIterator...
2018-06-22 18:17:14,190 INFO [kylin-coproc--pool2-t1176] v2.CubeHBaseEndpointRPC:217 : Query-2b31728e-585f-437e-ac9e-b04aaea8637c: send request to the init region server tjtx-89-89.58os.org on table KYLIN_D52DC4HQKR
2018-06-22 18:17:14,198 INFO [kylin-coproc--pool2-t1176] v2.CubeHBaseEndpointRPC:284 : <sub-thread for Query 2b31728e-585f-437e-ac9e-b04aaea8637c GTScanRequest 31d3d2c8>Endpoint RPC returned from HTable KYLIN_D52DC4HQKR Shard \x4B\x59\x4C\x49\x4E\x5F\x44\x35\x32\x44\x43\x34\x48\x51\x4B\x52\x2C\x2C\x31\x35\x32\x35\x34\x32\x34\x30\x39\x37\x36\x39\x36\x2E\x30\x62\x32\x39\x38\x62\x64\x33\x31\x37\x30\x39\x33\x37\x36\x63\x34\x32\x38\x34\x64\x31\x37\x66\x33\x33\x34\x39\x66\x62\x63\x63\x2E on host: tjtx-89-89.58os.org.Total scanned row: 70. Total scanned bytes: 3430. Total filtered row: 0. Total aggred row: 0. Time elapsed in EP: 3(ms). Server CPU usage: 0.013044872937234914, server physical mem left: 5.6559546368E10, server swap mem left:3.3554427904E10.Etc message: start latency: 8@2,agg done@3,compress done@3,server stats done@3, debugGitTag:1179ee72d0a2a2c629a649751ef43ae9e82dc87a;.Normal Complete: true.Compressed row size: 265
2018-06-22 18:17:14,198 DEBUG [kylin-coproc--pool2-t1176] util.CompressionUtils:67 : Original: 265 bytes. Decompressed: 700 bytes. Time: 0
2018-06-22 18:17:14,198 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.SortMergedPartitionResultIterator:76 : Using SortMergedPartitionResultIterator to merge 1 partition results out of 1 partitions
2018-06-22 18:17:14,199 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:1068 : Processed rows for each storageContext: 70
2018-06-22 18:17:14,200 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:510 : Stats of SQL response: isException: false, duration: 62, total scan count 70
2018-06-22 18:17:14,200 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] util.CheckUtil:35 : query is too lightweight with duration: 62 (threshold 2000), scan count: 70 (threshold 10240), scan bytes: 3430 (threshold 1048576)
2018-06-22 18:17:14,200 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:328 :
==========================[QUERY]===============================
Query Id: 2b31728e-585f-437e-ac9e-b04aaea8637c
SQL: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
User: ADMIN
Success: true
Duration: 0.062
Project: h_test
Realization Names: [CUBE[name=CubeT_1]]
Cuboid Ids: [511]
Total scan count: 70
Total scan bytes: 3430
Result row count: 70
Accept Partial: true
Is Partial Result: false
Hit Exception Cache: false
Storage cache used: false
Is Query Push-Down: false
Is Prepare: false
Trace URL: null
Message: null
==========================[QUERY]===============================
將上述的日誌儲存為 test.log
然後執行如下awk
time awk '
function ltrim(s) { sub(/^[ \t\r\n]+/, "", s); return s }
function rtrim(s) { sub(/[ \t\r\n]+$/, "", s); return s }
function trim(s) { return rtrim(ltrim(s)); }
/^Query Id:/{split($0,rowdata,":");}
/^SQL:/{s=trim($0);next;}
/^User:/{print "19700101 000000000 INFO [Query "trim(rowdata[2])" "s;s="";print $0;}
/^==========================/{delete rowdata;}
{
if(rowdata[2]!="")
if(s!="") s=(s" "trim($0))
else
print "19700101 000000000 INFO [Query "trim(rowdata[2])" "$0;
else gsub("[,:-]","",$1);gsub("[,:-]","",$2);$5=substr($5,0,36);print ($0);
}
' test.log | grep "\\[Query" | sort -k5,5 -k2n,2 -k3n,3 > t1.txt
首先定義 trim rtrim ltrim 三個函式
如果是Query Id 開頭,說明是kylin的彙總第一行,提取QueryId
如果是SQL:開頭,則將SQL文字儲存在 s變數中,主要是多行合併為一行
如果是User:開頭,則說明 SQL段結束,因為SQL段的下一段就是 User段.先列印儲存在變數s中的SQL文字,然後列印User段本行.在列印文字的時候,日期時間採用預設值,並且拼湊格式,將QueryId也列印出來,這方便後續的分組和排序.
如果是 =========開頭,說明是分隔符行,則刪除儲存的queryId資訊.
然後判斷是否是彙總行,rowdata[2]有值，則說明是彙總行.彙總行有兩種情況，一種情況是多行的SQL，這種情況只是把sql儲存到變數s,等待到User段再輸出.另外一種情況是普通的彙總行,這種情況拼接預設值後輸出.如果是日誌行,則將日期時間的下劃線，冒號去掉,以便作為數字排序.
grep "\\[Query" 則過濾與查詢無關的日誌資訊
sort 先按照 第五列 queryid排序後,再按照 日期，時間排序.
這樣併發的kylin日誌,就順序化了,方便後續的資訊提取.
但是Kylin的日誌是併發寫的,也就是併發情況下,查詢日誌會有交叉。
另外,Kylin彙總的行需要提取出來
最後,涉及SQL的行，需要把多行合併為一行。
KyLin原始日誌如下
2018-06-22 18:17:05,341 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:428 : Using project: h_test
2018-06-22 18:17:05,342 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:429 : The original query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1 LIMIT 5000
2018-06-22 18:17:05,345 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:893 : Setting current statement's max rows to 0
2018-06-22 18:17:05,360 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:58 : Find candidates by table ODS.O_M_T_SCORE and project=h_test : CUBE[name=CubeT_1]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveBlackoutRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveUncapableRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,361 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] rules.RealizationSortRule:40 : CUBE[name=CubeT_1] priority 1 cost 14200.
2018-06-22 18:17:05,362 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RealizationSortRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:05,362 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] routing.QueryRouter:75 : The realizations remaining: [CUBE[name=CubeT_1]],and the final chosen one for current olap context 0 is CUBE[name=CubeT_1]
2018-06-22 18:17:05,373 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] enumerator.OLAPEnumerator:108 : query storage...
2018-06-22 18:17:05,373 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] cube.RawQueryLastHacker:43 : No group by and aggregation found in this query, will hack some result for better look of output...
2018-06-22 18:17:05,373 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:308 : Does not need storage aggregation
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:579 : exactAggregation is true, cuboid id is 511
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:289 : Filter column set for query: []
2018-06-22 18:17:05,374 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:298 : Filter mask is: 0
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] storage.StorageContext:165 : Enabling limit push down: 5000 at level: LIMIT_ON_SCAN
2018-06-22 18:17:05,375 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:463 : Aggregate partition results is not beneficial because no storage aggregation
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.GTCubeStorageQueryBase:170 : Cuboid identified: cube=CubeT_1, cuboidId=511, groupsD=[ODS.O_M_T_STUDENT.CITY, ODS.O_M_T_STUDENT.ID, ODS.O_M_T_SUBJECT.ID, ODS.O_M_T_SCORE.SUBJECT_ID, ODS.O_M_T_STUDENT.USER_NAME, ODS.O_M_T_SCORE.USER_ID, ODS.O_M_T_SUBJECT.SUBJECT_NAME, ODS.O_M_T_STUDENT.SEX, ODS.O_M_T_STUDENT.PROVINCE], filterD=[], limitPushdown=5000, limitLevel=LIMIT_ON_SCAN, storageAggr=false
2018-06-22 18:17:05,375 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.CubeSegmentScanner:56 : Init CubeSegmentScanner for segment FULL_BUILD
2018-06-22 18:17:05,376 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseRPC:315 : hbase.rpc.timeout = 60000 ms, use 54000 ms as timeout for coprocessor
2018-06-22 18:17:05,376 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:152 : Serialized scanRequestBytes 1460 bytes, rawScanBytesString 56 bytes
2018-06-22 18:17:05,377 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:154 : The scan 7b4870f for segment CubeT_1[FULL_BUILD] is as below with 1 separate raw scans, shard part of start/end key is set to 0
2018-06-22 18:17:05,377 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseRPC:288 : Visiting hbase table KYLIN_D52DC4HQKR: cuboid exact match, from 511 to 511 Start: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00) Stop: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00), No Fuzzy Key
2018-06-22 18:17:05,377 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] v2.CubeHBaseEndpointRPC:159 : Submitting rpc to 1 shards starting from shard 0, scan range count 1
2018-06-22 18:17:05,378 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.KylinConfig:319 : Loading kylin-defaults.properties from file:/opt/soft/apache-kylin-2.3.0-bin/tomcat/webapps/kylin/WEB-INF/lib/kylin-core-common-2.3.0.jar!/kylin-defaults.properties
2018-06-22 18:17:05,385 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.KylinConfig:278 : KYLIN_CONF property was not set, will seek KYLIN_HOME env variable
2018-06-22 18:17:05,385 WARN [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] common.BackwardCompatibilityConfig:93 : Config 'kylin.job.mr.lib.dir' is deprecated, use 'kylin.engine.mr.lib-dir' instead
2018-06-22 18:17:05,386 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.SequentialCubeTupleIterator:73 : Using Iterators.concat to merge segment results
2018-06-22 18:17:05,386 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] enumerator.OLAPEnumerator:120 : return TupleIterator...
2018-06-22 18:17:05,387 INFO [kylin-coproc--pool2-t1175] v2.CubeHBaseEndpointRPC:217 : Query-1235b6a5-ae41-431d-bd75-bef0dae0bf57: send request to the init region server tjtx-89-89.58os.org on table KYLIN_D52DC4HQKR
2018-06-22 18:17:05,393 INFO [kylin-coproc--pool2-t1175] v2.CubeHBaseEndpointRPC:284 : <sub-thread for Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57 GTScanRequest 7b4870f>Endpoint RPC returned from HTable KYLIN_D52DC4HQKR Shard \x4B\x59\x4C\x49\x4E\x5F\x44\x35\x32\x44\x43\x34\x48\x51\x4B\x52\x2C\x2C\x31\x35\x32\x35\x34\x32\x34\x30\x39\x37\x36\x39\x36\x2E\x30\x62\x32\x39\x38\x62\x64\x33\x31\x37\x30\x39\x33\x37\x36\x63\x34\x32\x38\x34\x64\x31\x37\x66\x33\x33\x34\x39\x66\x62\x63\x63\x2E on host: tjtx-89-89.58os.org.Total scanned row: 70. Total scanned bytes: 3430. Total filtered row: 0. Total aggred row: 0. Time elapsed in EP: 2(ms). Server CPU usage: 0.01470260637112943, server physical mem left: 5.6562040832E10, server swap mem left:3.3554427904E10.Etc message: start latency: 8@1,agg done@2,compress done@2,server stats done@2, debugGitTag:1179ee72d0a2a2c629a649751ef43ae9e82dc87a;.Normal Complete: true.Compressed row size: 265
2018-06-22 18:17:05,393 DEBUG [kylin-coproc--pool2-t1175] util.CompressionUtils:67 : Original: 265 bytes. Decompressed: 700 bytes. Time: 0
2018-06-22 18:17:05,393 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] gtrecord.SortMergedPartitionResultIterator:76 : Using SortMergedPartitionResultIterator to merge 1 partition results out of 1 partitions
2018-06-22 18:17:05,394 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:1068 : Processed rows for each storageContext: 70
2018-06-22 18:17:05,394 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:510 : Stats of SQL response: isException: false, duration: 55, total scan count 70
2018-06-22 18:17:05,394 DEBUG [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] util.CheckUtil:35 : query is too lightweight with duration: 55 (threshold 2000), scan count: 70 (threshold 10240), scan bytes: 3430 (threshold 1048576)
2018-06-22 18:17:05,395 INFO [Query 1235b6a5-ae41-431d-bd75-bef0dae0bf57-144391] service.QueryService:328 :
==========================[QUERY]===============================
Query Id: 1235b6a5-ae41-431d-bd75-bef0dae0bf57
SQL: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1 LIMIT 5000
User: ADMIN
Success: true
Duration: 0.056
Project: h_test
Realization Names: [CUBE[name=CubeT_1]]
Cuboid Ids: [511]
Total scan count: 70
Total scan bytes: 3430
Result row count: 70
Accept Partial: false
Is Partial Result: false
Hit Exception Cache: false
Storage cache used: false
Is Query Push-Down: false
Is Prepare: false
Trace URL: null
Message: null
==========================[QUERY]===============================
2018-06-22 18:17:14,141 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:428 : Using project: h_test
2018-06-22 18:17:14,141 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:429 : The original query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
2018-06-22 18:17:14,145 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:646 : The corrected query: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
LIMIT 50000
2018-06-22 18:17:14,164 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:58 : Find candidates by table ODS.O_M_T_SCORE and project=h_test : CUBE[name=CubeT_1]
2018-06-22 18:17:14,164 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveBlackoutRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RemoveUncapableRealizationsRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] rules.RealizationSortRule:40 : CUBE[name=CubeT_1] priority 1 cost 14200.
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:51 : Applying rule: class org.apache.kylin.query.routing.rules.RealizationSortRule, realizations before: [CUBE[name=CubeT_1]], realizations after: [CUBE[name=CubeT_1]]
2018-06-22 18:17:14,165 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] routing.QueryRouter:75 : The realizations remaining: [CUBE[name=CubeT_1]],and the final chosen one for current olap context 0 is CUBE[name=CubeT_1]
2018-06-22 18:17:14,176 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] enumerator.OLAPEnumerator:108 : query storage...
2018-06-22 18:17:14,177 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] cube.RawQueryLastHacker:43 : No group by and aggregation found in this query, will hack some result for better look of output...
2018-06-22 18:17:14,177 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:308 : Does not need storage aggregation
2018-06-22 18:17:14,177 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:579 : exactAggregation is true, cuboid id is 511
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:289 : Filter column set for query: []
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:298 : Filter mask is: 0
2018-06-22 18:17:14,178 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] storage.StorageContext:165 : Enabling limit push down: 50000 at level: LIMIT_ON_SCAN
2018-06-22 18:17:14,178 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:463 : Aggregate partition results is not beneficial because no storage aggregation
2018-06-22 18:17:14,179 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.GTCubeStorageQueryBase:170 : Cuboid identified: cube=CubeT_1, cuboidId=511, groupsD=[ODS.O_M_T_STUDENT.CITY, ODS.O_M_T_STUDENT.ID, ODS.O_M_T_SUBJECT.ID, ODS.O_M_T_SCORE.SUBJECT_ID, ODS.O_M_T_STUDENT.USER_NAME, ODS.O_M_T_SCORE.USER_ID, ODS.O_M_T_SUBJECT.SUBJECT_NAME, ODS.O_M_T_STUDENT.SEX, ODS.O_M_T_STUDENT.PROVINCE], filterD=[], limitPushdown=50000, limitLevel=LIMIT_ON_SCAN, storageAggr=false
2018-06-22 18:17:14,179 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.CubeSegmentScanner:56 : Init CubeSegmentScanner for segment FULL_BUILD
2018-06-22 18:17:14,180 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseRPC:315 : hbase.rpc.timeout = 60000 ms, use 54000 ms as timeout for coprocessor
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:152 : Serialized scanRequestBytes 1460 bytes, rawScanBytesString 56 bytes
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:154 : The scan 31d3d2c8 for segment CubeT_1[FULL_BUILD] is as below with 1 separate raw scans, shard part of start/end key is set to 0
2018-06-22 18:17:14,181 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseRPC:288 : Visiting hbase table KYLIN_D52DC4HQKR: cuboid exact match, from 511 to 511 Start: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\x00\x00\x00\x00\x00\x00\x00\x00\x00) Stop: \x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00 (\x00\x00\x00\x00\x00\x00\x00\x00\x01\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\x00), No Fuzzy Key
2018-06-22 18:17:14,182 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] v2.CubeHBaseEndpointRPC:159 : Submitting rpc to 1 shards starting from shard 0, scan range count 1
2018-06-22 18:17:14,182 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.KylinConfig:319 : Loading kylin-defaults.properties from file:/opt/soft/apache-kylin-2.3.0-bin/tomcat/webapps/kylin/WEB-INF/lib/kylin-core-common-2.3.0.jar!/kylin-defaults.properties
2018-06-22 18:17:14,188 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.KylinConfig:278 : KYLIN_CONF property was not set, will seek KYLIN_HOME env variable
2018-06-22 18:17:14,189 WARN [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] common.BackwardCompatibilityConfig:93 : Config 'kylin.job.mr.lib.dir' is deprecated, use 'kylin.engine.mr.lib-dir' instead
2018-06-22 18:17:14,190 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.SequentialCubeTupleIterator:73 : Using Iterators.concat to merge segment results
2018-06-22 18:17:14,190 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] enumerator.OLAPEnumerator:120 : return TupleIterator...
2018-06-22 18:17:14,190 INFO [kylin-coproc--pool2-t1176] v2.CubeHBaseEndpointRPC:217 : Query-2b31728e-585f-437e-ac9e-b04aaea8637c: send request to the init region server tjtx-89-89.58os.org on table KYLIN_D52DC4HQKR
2018-06-22 18:17:14,198 INFO [kylin-coproc--pool2-t1176] v2.CubeHBaseEndpointRPC:284 : <sub-thread for Query 2b31728e-585f-437e-ac9e-b04aaea8637c GTScanRequest 31d3d2c8>Endpoint RPC returned from HTable KYLIN_D52DC4HQKR Shard \x4B\x59\x4C\x49\x4E\x5F\x44\x35\x32\x44\x43\x34\x48\x51\x4B\x52\x2C\x2C\x31\x35\x32\x35\x34\x32\x34\x30\x39\x37\x36\x39\x36\x2E\x30\x62\x32\x39\x38\x62\x64\x33\x31\x37\x30\x39\x33\x37\x36\x63\x34\x32\x38\x34\x64\x31\x37\x66\x33\x33\x34\x39\x66\x62\x63\x63\x2E on host: tjtx-89-89.58os.org.Total scanned row: 70. Total scanned bytes: 3430. Total filtered row: 0. Total aggred row: 0. Time elapsed in EP: 3(ms). Server CPU usage: 0.013044872937234914, server physical mem left: 5.6559546368E10, server swap mem left:3.3554427904E10.Etc message: start latency: 8@2,agg done@3,compress done@3,server stats done@3, debugGitTag:1179ee72d0a2a2c629a649751ef43ae9e82dc87a;.Normal Complete: true.Compressed row size: 265
2018-06-22 18:17:14,198 DEBUG [kylin-coproc--pool2-t1176] util.CompressionUtils:67 : Original: 265 bytes. Decompressed: 700 bytes. Time: 0
2018-06-22 18:17:14,198 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] gtrecord.SortMergedPartitionResultIterator:76 : Using SortMergedPartitionResultIterator to merge 1 partition results out of 1 partitions
2018-06-22 18:17:14,199 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:1068 : Processed rows for each storageContext: 70
2018-06-22 18:17:14,200 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:510 : Stats of SQL response: isException: false, duration: 62, total scan count 70
2018-06-22 18:17:14,200 DEBUG [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] util.CheckUtil:35 : query is too lightweight with duration: 62 (threshold 2000), scan count: 70 (threshold 10240), scan bytes: 3430 (threshold 1048576)
2018-06-22 18:17:14,200 INFO [Query 2b31728e-585f-437e-ac9e-b04aaea8637c-149402] service.QueryService:328 :
==========================[QUERY]===============================
Query Id: 2b31728e-585f-437e-ac9e-b04aaea8637c
SQL: SELECT
O_M_T_STUDENT.USER_NAME as O_M_T_STUDENT_USER_NAME
,O_M_T_STUDENT.CITY as O_M_T_STUDENT_CITY
,O_M_T_STUDENT.ID as O_M_T_STUDENT_ID
,O_M_T_STUDENT.SEX as O_M_T_STUDENT_SEX
,O_M_T_STUDENT.PROVINCE as O_M_T_STUDENT_PROVINCE
,O_M_T_SCORE.USER_ID as O_M_T_SCORE_USER_ID
,O_M_T_SCORE.SUBJECT_ID as O_M_T_SCORE_SUBJECT_ID
,O_M_T_SUBJECT.ID as O_M_T_SUBJECT_ID
,O_M_T_SUBJECT.SUBJECT_NAME as O_M_T_SUBJECT_SUBJECT_NAME
,O_M_T_SCORE.SCORE as O_M_T_SCORE_SCORE
FROM ODS.O_M_T_SCORE as O_M_T_SCORE
LEFT JOIN ODS.O_M_T_STUDENT as O_M_T_STUDENT
ON O_M_T_SCORE.USER_ID = O_M_T_STUDENT.ID
LEFT JOIN ODS.O_M_T_SUBJECT as O_M_T_SUBJECT
ON O_M_T_SCORE.SUBJECT_ID = O_M_T_SUBJECT.ID
WHERE 1=1
User: ADMIN
Success: true
Duration: 0.062
Project: h_test
Realization Names: [CUBE[name=CubeT_1]]
Cuboid Ids: [511]
Total scan count: 70
Total scan bytes: 3430
Result row count: 70
Accept Partial: true
Is Partial Result: false
Hit Exception Cache: false
Storage cache used: false
Is Query Push-Down: false
Is Prepare: false
Trace URL: null
Message: null
==========================[QUERY]===============================
將上述的日誌儲存為 test.log
然後執行如下awk
time awk '
function ltrim(s) { sub(/^[ \t\r\n]+/, "", s); return s }
function rtrim(s) { sub(/[ \t\r\n]+$/, "", s); return s }
function trim(s) { return rtrim(ltrim(s)); }
/^Query Id:/{split($0,rowdata,":");}
/^SQL:/{s=trim($0);next;}
/^User:/{print "19700101 000000000 INFO [Query "trim(rowdata[2])" "s;s="";print $0;}
/^==========================/{delete rowdata;}
{
if(rowdata[2]!="")
if(s!="") s=(s" "trim($0))
else
print "19700101 000000000 INFO [Query "trim(rowdata[2])" "$0;
else gsub("[,:-]","",$1);gsub("[,:-]","",$2);$5=substr($5,0,36);print ($0);
}
' test.log | grep "\\[Query" | sort -k5,5 -k2n,2 -k3n,3 > t1.txt
首先定義 trim rtrim ltrim 三個函式
如果是Query Id 開頭,說明是kylin的彙總第一行,提取QueryId
如果是SQL:開頭,則將SQL文字儲存在 s變數中,主要是多行合併為一行
如果是User:開頭,則說明 SQL段結束,因為SQL段的下一段就是 User段.先列印儲存在變數s中的SQL文字,然後列印User段本行.在列印文字的時候,日期時間採用預設值,並且拼湊格式,將QueryId也列印出來,這方便後續的分組和排序.
如果是 =========開頭,說明是分隔符行,則刪除儲存的queryId資訊.
然後判斷是否是彙總行,rowdata[2]有值，則說明是彙總行.彙總行有兩種情況，一種情況是多行的SQL，這種情況只是把sql儲存到變數s,等待到User段再輸出.另外一種情況是普通的彙總行,這種情況拼接預設值後輸出.如果是日誌行,則將日期時間的下劃線，冒號去掉,以便作為數字排序.
grep "\\[Query" 則過濾與查詢無關的日誌資訊
sort 先按照 第五列 queryid排序後,再按照 日期，時間排序.
這樣併發的kylin日誌,就順序化了,方便後續的資訊提取.
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/29254281/viewspace-2156713/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 使用AWK規整KyLin日誌改進
- awk分析日誌
- 【awk】按小時切割日誌
- awk多行日誌排序輸出排序
- AWK應用之統計訪問日誌
- 日誌規約
- oracle線上調整重做日誌Oracle
- Oracle重做日誌調整技巧Oracle
- 日誌--列印規範
- Oracle調整redo log日誌大小Oracle
- Oracle補充日誌及日誌記錄規則Oracle
- 日誌分析常規操作
- 開發日誌：Kylin麒麟作業系統部署ASP.NET CORE作業系統ASP.NET
- 用AWK來過濾nginx日誌中的特定值~~~薦Nginx
- 管理oracle日誌之調整檢查點Oracle
- Node.js + ELK 日誌規範Node.js
- 【Logback日誌級別】動態調整Logback的日誌級別
- dg庫日誌應用慢引數調整
- Layui+larave-log-view日誌頁面調整UIView
- 日誌服務之使用Nginx模式採集日誌Nginx模式
- wazuh日誌審計--定製規則
- oracle效能調優:管理oracle日誌之調整線上日誌檔案Oracle
- RMAN備份整庫和歸檔日誌的方法
- Kylin安裝與使用
- Spring Boot日誌使用Spring Boot
- 使用Kafka做日誌收集Kafka
- Android日誌Log使用Android
- 使用慢查詢日誌
- 使用sql查alert日誌SQL
- .NET 8使用日誌功能以及自定義日誌提供程式
- Java日誌記錄的5條規則Java
- 什麼樣的日誌審計產品才能達到合規要求——日誌易
- log4j日誌列印級別動態調整
- mysql之 日誌體系（錯誤日誌、查詢日誌、二進位制日誌、事務日誌、中繼日誌）MySql中繼
- 使用 shell 命令統計日誌
- java日誌列印使用指南Java
- 記錄騰訊雲使用日誌
- YARN的日誌聚集配置使用Yarn