Created
November 14, 2019 13:38
-
-
Save cosven/731f58ebbd0cb0ad6e725525b1da3b79 to your computer and use it in GitHub Desktop.
parse sql statements from general logs
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
#!/usr/bin/env python3 | |
import re | |
def get_key_value(key, line): | |
"""get key's value in log line""" | |
p = re.compile(r'\[{}\='.format(key)) | |
m = p.search(line) | |
if m is None: | |
raise SystemExit("get key({})'s value failed".format(key)) | |
stack = [] | |
start = m.end() | |
end = start | |
for i, c in enumerate(line[start:]): | |
if c == '[': | |
stack.append(c) | |
continue | |
if c == ']': | |
if stack: | |
stack.pop() | |
else: | |
end = start + i + 1 | |
break | |
return line[start:end - 1] | |
def parse_line(line): | |
"""parse sql statement from line | |
:return: (conn_id, sql) tuple | |
""" | |
sql = get_key_value('sql', line) | |
conn = get_key_value('conn', line) | |
return conn, sql | |
def extract_lines(filepath): | |
"""extract lines from log file""" | |
# match log time prefix: [2019/11 | |
line_start_p = re.compile(r'\[\d{4}\/\d{2}') | |
with open(filepath) as f: | |
line = None | |
for broken_line in f: | |
if line_start_p.match(broken_line) is None: | |
assert line is not None | |
line += broken_line | |
else: # brand new line arrived | |
# check if there exists old line | |
if line is not None: | |
yield line | |
line = broken_line | |
if __name__ == '__main__': | |
import sys | |
log_filename = sys.argv[1] | |
for line in extract_lines(log_filename): | |
if 'GENERAL_LOG' not in line: | |
continue | |
conn_id, sql = parse_line(line) | |
print(conn_id, sql) |
测试用例 2
[2019/11/14 21:23:31.207 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET autocommit=0"]
[2019/11/14 21:23:31.209 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="select
@@session.transaction_read_only"]
[2019/11/14 21:23:31.209 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="update user_account set balance
= balance+1 where account_id = 'user1'"]
[2019/11/14 21:23:31.218 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=] [sql="use `tidb`"]
[2019/11/14 21:23:31.218 +08:00] [INFO] [server.go:413] ["new connection"] [conn=27604] [remoteAddr=172.16.5.98:54902]
[2019/11/14 21:23:31.226 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="/* mysql-connector-java-5.1.47 (
Revision: fe1903b1ecb4a96a917f7ed3190d80c049b1de29 ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client,
@@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server,
@@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names,
@@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS
query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"]
[2019/11/14 21:23:31.226 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET NAMES utf8mb4"]
[2019/11/14 21:23:31.227 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET character_set_results =
NULL"]
[2019/11/14 21:23:31.227 +08:00] [INFO] [set.go:192] ["set session var"] [conn=27604] [name=character_set_results] [val=NULL]
[2019/11/14 21:23:31.227 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET autocommit=1"]
[2019/11/14 21:23:31.228 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="select
@@session.transaction_read_only"]
[2019/11/14 21:23:31.228 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SELECT
@@session.transaction_isolation"]
[2019/11/14 21:23:31.229 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET autocommit=0"]
[2019/11/14 21:23:31.229 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="select
@@session.transaction_read_only"]
[2019/11/14 21:23:31.230 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="update user_account set balance
= balance+1 where account_id = 'user1'"]
[2019/11/14 21:24:31.252 +08:00] [WARN] [expensivequery.go:160] [expensive_query] [cost_time=60.022316972s] [conn_id=27604] [user=root] [database=tidb] [txn_start_ts=412545924785242125] [mem_max="0
Bytes"] [sql="update user_account set balance = balance+1 where\n\t\taccount_id = 'user1'"]
[2019/11/14 21:33:41.213 +08:00] [INFO] [2pc.go:693] ["ttlManager live up to its lifetime"] [txnStartTS=412545924772134915]
[2019/11/14 21:33:51.976 +08:00] [WARN] [adapter.go:490] ["failed to extract conflictCommitTS from a conflict error"] [conn=27604]
[2019/11/14 21:33:51.976 +08:00] [INFO] [adapter.go:493] ["pessimistic write conflict, retry statement"] [conn=27604] [txn=412545924785242125] [forUpdateTS=412545924785242125] [conflictCommitTS=0]
[2019/11/14 21:33:51.979 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=412545924785242125] [current_db=tidb] [sql=commit]
[2019/11/14 21:33:51.980 +08:00] [WARN] [session.go:446] ["commit failed"] [conn=27604] ["finished txn"="Txn{state=invalid}"] [error="conn0 txn takes too much time, txnStartTS: 412545924785242125,
comm: 412546087511130114"] [errorVerbose="conn0 txn takes too much time, txnStartTS: 412545924785242125, comm:
412546087511130114\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).execute\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1101\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).executeAndWriteFinishBinlog\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1010\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Commit\n\tgithub.com/pingcap/tidb@/store/tikv/txn.go:298\ngithub.com/pingcap/tidb/session.(*TxnState).Commit\n\tgithub.com/pingcap/tidb@/session/txn.go:197\ngithub.com/pingcap/tidb/session.(*session).doCommit\n\tgithub.com/pingcap/tidb@/session/session.go:393\ngithub.com/pingcap/tidb/session.(*session).doCommitWithRetry\n\tgithub.com/pingcap/tidb@/session/session.go:403\ngithub.com/pingcap/tidb/session.(*session).CommitTxn\n\tgithub.com/pingcap/tidb@/session/session.go:468\ngithub.com/pingcap/tidb/session.finishStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:179\ngithub.com/pingcap/tidb/session.runStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:257\ngithub.com/pingcap/tidb/session.(*session).executeStatement\n\tgithub.com/pingcap/tidb@/session/session.go:961\ngithub.com/pingcap/tidb/session.(*session).execute\n\tgithub.com/pingcap/tidb@/session/session.go:1076\ngithub.com/pingcap/tidb/session.(*session).Execute\n\tgithub.com/pingcap/tidb@/session/session.go:999\ngithub.com/pingcap/tidb/server.(*TiDBContext).Execute\n\tgithub.com/pingcap/tidb@/server/driver_tidb.go:246\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\tgithub.com/pingcap/tidb@/server/conn.go:1195\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\tgithub.com/pingcap/tidb@/server/conn.go:913\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\tgithub.com/pingcap/tidb@/server/conn.go:666\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\tgithub.com/pingcap/tidb@/server/server.go:440\nruntime.goexit\n\truntime/asm_amd64.s:1357"]
[2019/11/14 21:33:51.980 +08:00] [WARN] [session.go:964] ["run statement error"] [conn=27604] [schemaVersion=206] [error="previous statement: update user_account set balance = balance+1 where
account_id = 'user1': conn0 txn takes too much time, txnStartTS: 412545924785242125, comm: 412546087511130114"] [errorVerbose="conn0 txn takes too much time, txnStartTS: 412545924785242125, comm:
412546087511130114\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).execute\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1101\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).executeAndWriteFinishBinlog\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1010\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Commit\n\tgithub.com/pingcap/tidb@/store/tikv/txn.go:298\ngithub.com/pingcap/tidb/session.(*TxnState).Commit\n\tgithub.com/pingcap/tidb@/session/txn.go:197\ngithub.com/pingcap/tidb/session.(*session).doCommit\n\tgithub.com/pingcap/tidb@/session/session.go:393\ngithub.com/pingcap/tidb/session.(*session).doCommitWithRetry\n\tgithub.com/pingcap/tidb@/session/session.go:403\ngithub.com/pingcap/tidb/session.(*session).CommitTxn\n\tgithub.com/pingcap/tidb@/session/session.go:468\ngithub.com/pingcap/tidb/session.finishStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:179\ngithub.com/pingcap/tidb/session.runStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:257\ngithub.com/pingcap/tidb/session.(*session).executeStatement\n\tgithub.com/pingcap/tidb@/session/session.go:961\ngithub.com/pingcap/tidb/session.(*session).execute\n\tgithub.com/pingcap/tidb@/session/session.go:1076\ngithub.com/pingcap/tidb/session.(*session).Execute\n\tgithub.com/pingcap/tidb@/session/session.go:999\ngithub.com/pingcap/tidb/server.(*TiDBContext).Execute\n\tgithub.com/pingcap/tidb@/server/driver_tidb.go:246\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\tgithub.com/pingcap/tidb@/server/conn.go:1195\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\tgithub.com/pingcap/tidb@/server/conn.go:913\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\tgithub.com/pingcap/tidb@/server/conn.go:666\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\tgithub.com/pingcap/tidb@/server/server.go:440\nruntime.goexit\n\truntime/asm_amd64.s:1357\nprevious
statement: update user_account set balance = balance+1 where account_id = 'user1'"] [session="{\n \"currDBName\": \"tidb\",\n \"id\": 27604,\n \"status\": 0,\n \"strictMode\": true,\n \"user\":
{\n \"Username\": \"root\",\n \"Hostname\": \"172.16.5.98\",\n \"CurrentUser\": false,\n \"AuthUsername\": \"root\",\n \"AuthHostname\": \"%\"\n }\n}"]
[2019/11/14 21:33:51.981 +08:00] [WARN] [conn.go:682] ["dispatch error"] [conn=27604] [connInfo="id:27604, addr:172.16.5.98:54902 status:0, collation:utf8_general_ci, user:root"] [command=Query]
[status="inTxn:0, autocommit:0"] [sql=commit] [err="conn0 txn takes too much time, txnStartTS: 412545924785242125, comm:
412546087511130114\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).execute\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1101\ngithub.com/pingcap/tidb/store/tikv.(*twoPhaseCommitter).executeAndWriteFinishBinlog\n\tgithub.com/pingcap/tidb@/store/tikv/2pc.go:1010\ngithub.com/pingcap/tidb/store/tikv.(*tikvTxn).Commit\n\tgithub.com/pingcap/tidb@/store/tikv/txn.go:298\ngithub.com/pingcap/tidb/session.(*TxnState).Commit\n\tgithub.com/pingcap/tidb@/session/txn.go:197\ngithub.com/pingcap/tidb/session.(*session).doCommit\n\tgithub.com/pingcap/tidb@/session/session.go:393\ngithub.com/pingcap/tidb/session.(*session).doCommitWithRetry\n\tgithub.com/pingcap/tidb@/session/session.go:403\ngithub.com/pingcap/tidb/session.(*session).CommitTxn\n\tgithub.com/pingcap/tidb@/session/session.go:468\ngithub.com/pingcap/tidb/session.finishStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:179\ngithub.com/pingcap/tidb/session.runStmt\n\tgithub.com/pingcap/tidb@/session/tidb.go:257\ngithub.com/pingcap/tidb/session.(*session).executeStatement\n\tgithub.com/pingcap/tidb@/session/session.go:961\ngithub.com/pingcap/tidb/session.(*session).execute\n\tgithub.com/pingcap/tidb@/session/session.go:1076\ngithub.com/pingcap/tidb/session.(*session).Execute\n\tgithub.com/pingcap/tidb@/session/session.go:999\ngithub.com/pingcap/tidb/server.(*TiDBContext).Execute\n\tgithub.com/pingcap/tidb@/server/driver_tidb.go:246\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\tgithub.com/pingcap/tidb@/server/conn.go:1195\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\tgithub.com/pingcap/tidb@/server/conn.go:913\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\tgithub.com/pingcap/tidb@/server/conn.go:666\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\tgithub.com/pingcap/tidb@/server/server.go:440\nruntime.goexit\n\truntime/asm_amd64.s:1357\nprevious
statement: update user_account set balance = balance+1 where account_id = 'user1'"]
[2019/11/14 21:33:51.981 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET autocommit=1"]
[2019/11/14 21:33:51.981 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=27604] [txnStartTS=412545924785242125]
[2019/11/14 21:33:51.981 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=27604] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="select
@@session.transaction_read_only"]
[2019/11/14 21:33:51.982 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=412545924772134915] [current_db=tidb] [sql=rollback]
[2019/11/14 21:33:51.982 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="SET autocommit=1"]
[2019/11/14 21:33:51.983 +08:00] [INFO] [session.go:1877] [GENERAL_LOG] [conn=26101] [user=root@172.16.5.98] [schemaVersion=206] [txnStartTS=0] [current_db=tidb] [sql="select
@@session.transaction_read_only"]
sql
26101 "SET autocommit=0"
26101 "select
@@session.transaction_read_only"
26101 "update user_account set balance
= balance+1 where account_id = 'user1'"
27604 "use `tidb`"
27604 "/* mysql-connector-java-5.1.47 (
Revision: fe1903b1ecb4a96a917f7ed3190d80c049b1de29 ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client,
@@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server,
@@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names,
@@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@query_cache_size AS query_cache_size, @@query_cache_type AS
query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout"
27604 "SET NAMES utf8mb4"
27604 "SET character_set_results =
NULL"
27604 "SET autocommit=1"
27604 "select
@@session.transaction_read_only"
27604 "SELECT
@@session.transaction_isolation"
27604 "SET autocommit=0"
27604 "select
@@session.transaction_read_only"
27604 "update user_account set balance
= balance+1 where account_id = 'user1'"
27604 commit
27604 "SET autocommit=1"
27604 "select
@@session.transaction_read_only"
26101 rollback
26101 "SET autocommit=1"
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
测试用例
log
sql