package slowquery import ( "strings" "testing" "time" "github.com/stretchr/testify/require" ) func TestSlogLogReader_ReadNext(t *testing.T) { raw := `2022-08-31T07:12:54.233489375Z;ip-10-250-24-4.us-west-2.compute.internal;tidb61992;db-tidb-0;slowlog # Time: 2022-08-31T07:12:54.096687178Z # Txn_start_ts: 0 # User@Host: root[root] @ 10.250.24.175 [10.250.24.175] # Conn_ID: 6204412174144681481 # Query_time: 1.000883579 # Parse_time: 0.000046967 # Compile_time: 0.000166604 # Rewrite_time: 0.000063231 # Optimize_time: 0.000029576 # Wait_TS: 0 # Is_internal: false # Digest: 926597c5c848f662ee6caba21f181a5aac72d8b2aee8ebbcc8ee361b46f7d9cb # Num_cop_tasks: 0 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000006361 # Backoff_total: 0 # Write_sql_response_total: 0.000000887 # Result_rows: 1 # Succ: true # IsExplicitTxn: false # Plan: tidb_decode_plan('ffBhMAkzXzMJMAkxCXNsZWVwKDEpLT5Db2x1bW4jMQkxCXRpbWU6MXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkwIEJ5dGVzCU4vQQoxCTI1XzQJMAkxCXJvd3M6MQkxCXQBQgwyOThuGUUgCU4vQQlOL0EK') # Plan_digest: a55eaee1d30304ad05500afbbfff1409ce22376e0f062c0d06ff34b8ed9c2b47 select sleep (?);` rawLines := strings.Split(raw, "\n") slr := NewSlowLogReader(strings.NewReader(raw)) lines, err := slr.ReadNext() require.NoError(t, err) require.Equal(t, len(rawLines), len(lines)) for n := 0; n < len(rawLines); n++ { require.Equal(t, rawLines[n], lines[n]) } lines, err = slr.ReadNext() require.NoError(t, err) require.Nil(t, lines) } func TestSlogLogReader_ReadNext_TwoLogs(t *testing.T) { raw := `2022-08-31T07:12:54.233489375Z;ip-10-250-24-4.us-west-2.compute.internal;tidb61992;db-tidb-0;slowlog # Time: 2022-08-31T07:12:54.096687178Z # Txn_start_ts: 0 # User@Host: root[root] @ 10.250.24.175 [10.250.24.175] # Conn_ID: 6204412174144681481 # Query_time: 1.000883579 # Parse_time: 0.000046967 # Compile_time: 0.000166604 # Rewrite_time: 0.000063231 # Optimize_time: 0.000029576 # Wait_TS: 0 # Is_internal: false # Digest: 926597c5c848f662ee6caba21f181a5aac72d8b2aee8ebbcc8ee361b46f7d9cb # Num_cop_tasks: 0 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000006361 # Backoff_total: 0 # Write_sql_response_total: 0.000000887 # Result_rows: 1 # Succ: true # IsExplicitTxn: false # Plan: tidb_decode_plan('ffBhMAkzXzMJMAkxCXNsZWVwKDEpLT5Db2x1bW4jMQkxCXRpbWU6MXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkwIEJ5dGVzCU4vQQoxCTI1XzQJMAkxCXJvd3M6MQkxCXQBQgwyOThuGUUgCU4vQQlOL0EK') # Plan_digest: a55eaee1d30304ad05500afbbfff1409ce22376e0f062c0d06ff34b8ed9c2b47 select sleep (?); 2022-08-31T07:13:28.236100388Z;ip-10-250-24-4.us-west-2.compute.internal;tidb61992;db-tidb-0;slowlog # Time: 2022-08-31T07:13:27.899863054Z # Txn_start_ts: 0 # User@Host: root[root] @ 10.250.24.175 [10.250.24.175] # Conn_ID: 6204412174144681481 # Query_time: 7.049241269 # Parse_time: 0.000062393 # Compile_time: 0.000217623 # Rewrite_time: 0.000103079 # Optimize_time: 0.000036333 # Wait_TS: 0 # Is_internal: false # Digest: a1e5b2baf44eb501800e67b25555cf6722c416c1a49b8f500a27c5a32e8b231f # Num_cop_tasks: 0 # Mem_max: 26316 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000008436 # Backoff_total: 0 # Write_sql_response_total: 0.000001168 # Result_rows: 7 # Succ: true # IsExplicitTxn: false # Plan: tidb_decode_plan('kwHwWDAJM18zCTAJMTAwMDAJc2xlZXAoMSktPkNvbHVtbiM5CTcJdGltZTo3LjA1cywgbG9vcHM6MiwgQ29uY3VycmVuY3k6NQkyNS43IEtCCU4vQQoxCTExXzQJEVNEdGFibGU6Q0xVU1RFUl9JTkZPEVMUNDUuMW1zFVQgCU4vQQlOL0EK') # Plan_digest: e6b8ba3530968656376af094d5f47d6ce6e73afd930a2f54699bf4ffc793f3af use mysql; select sleep(?) from information_schema.cluster_info;` rawLines := strings.Split(raw, "\n") slr := NewSlowLogReader(strings.NewReader(raw)) lines1, err := slr.ReadNext() require.NoError(t, err) require.NotNil(t, lines1) lines2, err := slr.ReadNext() require.NoError(t, err) require.NotNil(t, lines2) require.Equal(t, len(rawLines), len(lines1)+len(lines2)) for n := 0; n < len(lines1); n++ { require.Equal(t, rawLines[n], lines1[n]) } for n := len(lines1); n < len(lines1)+len(lines2); n++ { require.Equal(t, rawLines[n], lines2[n-len(lines1)]) } lines3, err := slr.ReadNext() require.NoError(t, err) require.Nil(t, lines3) } func TestParseSlowLog(t *testing.T) { raw := `2022-08-31T07:12:54.233489375Z;ip-10-250-24-4.us-west-2.compute.internal;tidb61992;db-tidb-0;slowlog # Time: 2022-08-31T07:12:54.096687178Z # Txn_start_ts: 0 # User@Host: root[root] @ 10.250.24.175 [10.250.24.175] # Conn_ID: 6204412174144681481 # Query_time: 1.000883579 # Parse_time: 0.000046967 # Compile_time: 0.000166604 # Rewrite_time: 0.000063231 # Optimize_time: 0.000029576 # Wait_TS: 0 # Is_internal: false # Digest: 926597c5c848f662ee6caba21f181a5aac72d8b2aee8ebbcc8ee361b46f7d9cb # Num_cop_tasks: 0 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000006361 # Backoff_total: 0 # Write_sql_response_total: 0.000000887 # Result_rows: 1 # Succ: true # IsExplicitTxn: false # Plan: tidb_decode_plan('ffBhMAkzXzMJMAkxCXNsZWVwKDEpLT5Db2x1bW4jMQkxCXRpbWU6MXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkwIEJ5dGVzCU4vQQoxCTI1XzQJMAkxCXJvd3M6MQkxCXQBQgwyOThuGUUgCU4vQQlOL0EK') # Plan_digest: a55eaee1d30304ad05500afbbfff1409ce22376e0f062c0d06ff34b8ed9c2b47 use mysql; select sleep (?);` slr := NewSlowLogReader(strings.NewReader(raw)) lines, err := slr.ReadNext() require.NoError(t, err) require.NotNil(t, lines) sl, err := ParseSlowLog(lines) require.NoError(t, err) tm, err := time.Parse(time.RFC3339Nano, "2022-08-31T07:12:54.096687178Z") require.NoError(t, err) require.Equal(t, tm, sl.Time) require.Equal(t, "root", sl.User) require.Equal(t, "10.250.24.175", sl.Host) require.Equal(t, uint64(6204412174144681481), sl.ConnID) require.Equal(t, 1.000883579, sl.QueryTime) require.Equal(t, 0.000046967, sl.ParseTime) require.Equal(t, 0.000166604, sl.CompileTime) require.Equal(t, 0.000063231, sl.RewriteTime) require.Equal(t, 0.000029576, sl.OptimizeTime) require.Equal(t, "926597c5c848f662ee6caba21f181a5aac72d8b2aee8ebbcc8ee361b46f7d9cb", sl.Digest) require.Equal(t, 0.000006361, sl.PDTotal) require.Equal(t, 0.000000887, sl.WriteSQLResponseTotal) require.Equal(t, uint64(1), sl.ResultRows) require.True(t, sl.Succ) require.Equal(t, "tidb_decode_plan('ffBhMAkzXzMJMAkxCXNsZWVwKDEpLT5Db2x1bW4jMQkxCXRpbWU6MXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkwIEJ5dGVzCU4vQQoxCTI1XzQJMAkxCXJvd3M6MQkxCXQBQgwyOThuGUUgCU4vQQlOL0EK')", sl.Plan) require.Equal(t, "a55eaee1d30304ad05500afbbfff1409ce22376e0f062c0d06ff34b8ed9c2b47", sl.PlanDigest) require.Equal(t, "select sleep (?);", sl.Query) } func TestParseSlowLogStandardFirstLine(t *testing.T) { raw := `# Time: 2022-08-31T07:12:54.096687178Z # Txn_start_ts: 0 # User@Host: root[root] @ 10.250.24.175 [10.250.24.175] # Conn_ID: 6204412174144681481 # Query_time: 1.000883579 # Parse_time: 0.000046967 # Compile_time: 0.000166604 # Rewrite_time: 0.000063231 # Optimize_time: 0.000029576 # Wait_TS: 0 # Is_internal: false # Digest: 926597c5c848f662ee6caba21f181a5aac72d8b2aee8ebbcc8ee361b46f7d9cb # Num_cop_tasks: 0 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000006361 # Backoff_total: 0 # Write_sql_response_total: 0.000000887 # Result_rows: 1 # Succ: true # IsExplicitTxn: false # Plan: tidb_decode_plan('ffBhMAkzXzMJMAkxCXNsZWVwKDEpLT5Db2x1bW4jMQkxCXRpbWU6MXMsIGxvb3BzOjIsIENvbmN1cnJlbmN5Ok9GRgkwIEJ5dGVzCU4vQQoxCTI1XzQJMAkxCXJvd3M6MQkxCXQBQgwyOThuGUUgCU4vQQlOL0EK') # Plan_digest: a55eaee1d30304ad05500afbbfff1409ce22376e0f062c0d06ff34b8ed9c2b47 use mysql; select sleep (?);` slr := NewSlowLogReader(strings.NewReader(raw)) lines, err := slr.ReadNext() require.NoError(t, err) require.NotNil(t, lines) sl, err := ParseSlowLog(lines) require.NoError(t, err) tm, err := time.Parse(time.RFC3339Nano, "2022-08-31T07:12:54.096687178Z") require.NoError(t, err) require.Equal(t, tm, sl.Time) } func TestParseSlowLogIgnoreWarningLine(t *testing.T) { r := NewSlowLogReader(strings.NewReader(`# Time: 2023-02-28T09:38:58.511964784Z # Txn_start_ts: 0 # Keyspace_name: 3UYYKyZAXzmjdDi # Keyspace_ID: 1747 # Serverless_tenant_ID: 1369847559690647294 # Serverless_project_ID: 1369847559691367750 # Serverless_cluster_ID: 1373933076659290569 # Query_time: 1.571488935 # Parse_time: 0 # Compile_time: 0.0001519 # Rewrite_time: 0.000071983 # Optimize_time: 0.000050855 # Wait_TS: 0 # Is_internal: true # Digest: f843ce3302a32307b17a4f85469d0d68f4bbdab9134f603c7fb3b906f3e7f800 # Num_cop_tasks: 0 # Mem_max: 213984 # Prepared: false # Plan_from_cache: false # Plan_from_binding: false # Has_more_results: false # KV_total: 0 # PD_total: 0.000001239 # Backoff_total: 0 # Write_sql_response_total: 0 # Result_rows: 3 # Warnings: [{"Level":"Warning","Message":"currently we do not support get config from node type: tiflash_compute(serverless-cluster-tiflash-cn-0.serverless-cluster-tiflash-cn-peer.tidb-serverless.svc:3930)"},{"Level":"Warning","Message":"request http://10.0.96.123:10080/config failed: 404 Not Found"},{"Level":"Warning","Message":"Get \"http://10.0.103.43:10080/config\": dial tcp 10.0.103.43:10080: connect: no route to host"}] # Succ: true # IsExplicitTxn: false # IsSyncStatsFailed: false # Plan: tidb_decode_plan('lAGIMAkxXzUJMAkwLjgwCWVxKENvbHVtbiMxLCAidGlrdiIpLCAZFvBJMywgImxvZy1iYWNrdXAuZW5hYmxlIikJMwl0aW1lOjEuNTdzLCBsb29wczoyCTIwOS4wIEtCCU4vQQoxCTdfNgkwCTEJCTMwMzFKMQAkOQlOL0EJTi9BCg==') # Plan_digest: dea58e872bd7681cce36a7bbb7157f9556a7da43765d45bacc4c36ba2e71f20b # Binary_plan: tidb_decode_binary_plan('zAFsCscBCgtTZWxlY3Rpb25fNRJDCgZTaG93XzYpAAUBfPA/MNcXOAFAAVoTdGltZToxLjU3cywgbG9vcHM6OXD/EQEEAXgRCgj/ASEFOhQACEApmpkBAXzpPzADOAFAAVI3ZXEoQ29sdW1uIzEsICJ0aWt2IiksIBkWWDMsICJsb2ctYmFja3VwLmVuYWJsZSIpTnwARDJw4IcNeP///////////wEYAQ==') show config where name = 'log-backup.enable' and type = 'tikv';`)) lines, err := r.ReadNext() require.NoError(t, err) sl, err := ParseSlowLog(lines) require.NoError(t, err) require.NotNil(t, sl) }