devops-works/slowql

slowql.NewParser runtime error

tspotts opened this issue · 11 comments

tspotts commented

Running the example code:

$ ./example slow_query.log
panic: runtime error: index out of range [3] with length 3

goroutine 17 [running]:
github.com/devops-works/slowql/database/mysql.(*Database).parseMySQLHeader(0xc00013c000, {0xc000016aa0, 0x1b}, 0xc000102e60)
	/root/go/src/github.com/devops-works/slowql/database/mysql/mysql.go:109 +0xf71
github.com/devops-works/slowql/database/mysql.(*Database).ParseBlocks(0xc00013c000, 0x0?)
	/root/go/src/github.com/devops-works/slowql/database/mysql/mysql.go:41 +0x137
created by github.com/devops-works/slowql.NewParser
	/root/go/src/github.com/devops-works/slowql/slowql.go:71 +0x41d
tspotts commented

The bug is actually here with lines containing # InnoDB_trx_id: 0 using strings.Contains(part, "id:")

leucos commented

Thanks for the report @tspotts !

Could you paste a minimal slowql file for reproduction please ?

What MySQL version are you using ?

tspotts commented 
$ cat example_slow_query.log
/usr/sbin/mysqld, Version: 5.7.29-32-log (Percona Server (GPL), Release 32, Revision 56bce88). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2022-06-22T14:25:08.796525Z
# User@Host: user @  [127.0.0.1]  Id: 498200077
# Schema: schema_name  Last_errno: 0  Killed: 0
# Query_time: 5.390275  Lock_time: 0.000388  Rows_sent: 464  Rows_examined: 2057052  Rows_affected: 0
# Bytes_sent: 17781  Tmp_tables: 3  Tmp_disk_tables: 1  Tmp_table_sizes: 1060944
# InnoDB_trx_id: 0
# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_:IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 8191
SELECT * FROM some_table;

$ ./example example_slow_query.log
panic: runtime error: index out of range [1] with length 1

goroutine 7 [running]:
github.com/devops-works/slowql/database/mysql.(*Database).parseMySQLHeader(0xc00013c000, {0xc000020120, 0x2f}, 0xc000106e60)
	/root/go/src/github.com/devops-works/slowql/database/mysql/mysql.go:117 +0xe17
github.com/devops-works/slowql/database/mysql.(*Database).ParseBlocks(0xc00013c000, 0x0?)
	/root/go/src/github.com/devops-works/slowql/database/mysql/mysql.go:41 +0x137
created by github.com/devops-works/slowql.NewParser
	/root/go/src/github.com/devops-works/slowql/slowql.go:71 +0x41d
leucos commented

Awesome, thanks @tspotts !

We'll look into it quickly.

leucos commented

@tspotts can you give it a try on latest master please ?

tspotts commented

I checked out the develop branch and built the example cmd, here's what I'm getting with that example log:

slowql/cmd/example] $ ./main /genlogs/example_slow_query.log
panic: runtime error: index out of range [0] with length 0

goroutine 19 [running]:
github.com/devops-works/slowql/database/percona.(*Database).ParseBlocks(0xc0000c4070, 0x0?)
	/genlogs/slowql/database/percona/percona.go:40 +0x185
created by github.com/devops-works/slowql.NewParser
	/genlogs/slowql/slowql.go:76 +0x51d
leucos commented

Weird, I can not reproduce:

$ git describe --abbrev --tags
v0.1.2-1-g798ed1a

$ cat example.log 
/usr/sbin/mysqld, Version: 5.7.29-32-log (Percona Server (GPL), Release 32, Revision 56bce88). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2022-06-22T14:25:08.796525Z
# User@Host: user @  [127.0.0.1]  Id: 498200077
# Schema: schema_name  Last_errno: 0  Killed: 0
# Query_time: 5.390275  Lock_time: 0.000388  Rows_sent: 464  Rows_examined: 2057052  Rows_affected: 0
# Bytes_sent: 17781  Tmp_tables: 3  Tmp_disk_tables: 1  Tmp_table_sizes: 1060944
# InnoDB_trx_id: 0
# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_:IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 8191
SELECT * FROM some_table;

$ go run cmd/example/main.go example.log 
Binary: /usr/sbin/mysqld
Version short: 5.7.29
Version: 5.7.29-32-log
Version description: Percona Server (GPL), Release 32, Revision 56bce88
Socket: /tmp/mysql.sock
Port: 3306

parsed 1 queries in 36.078µs

$ go run ./cmd/slowql-digest/ -f example.log -k percona
INFO[0000] log file has 15 lines                        
INFO[0000] digest duration: 171.393µs                   
INFO[0000] parsed 1 queries                             
INFO[0000] found 1 different queries hashs              

=-= Server meta =-=
	
Binary              : /usr/sbin/mysqld
Port                : 3306
Socket              : /tmp/mysql.sock
Version             : 5.7.29-32-log
Version short       : 5.7.29
Version description : Percona Server (GPL), Release 32, Revision 56bce88

Digest duration     : 171.393µs
Real duration       : 0s

Bytes handled       : 17781
	
=-= Queries stats =-=

Sorted by: random, increasing
Showing top 3 queries

Query #1
Calls                  : 1
Hash                   : 837785d8ba6f0564ef452a2974f1ae98
Fingerprint            : select * from some_table;
Schema                 : schema_name
Min/Max/Mean time      : 5.390275s/5.390275s/5.390275s
p50/p95                : 5.390275s/5.390275s
Concurrency            : +Inf%
Standard deviation     : 0s
Cum Query Time         : 5.390275s
Cum Lock Time          : 388µs
Cum Bytes sent         : 17781
Cum Rows Examined/Sent : 2057052/464
Cum Killed             : 0

May be you have a different slow query log file ?

tspotts commented

🤷

$ git describe --abbrev --tags
v0.1.2-1-g798ed1a

$ cat example.log
/usr/sbin/mysqld, Version: 5.7.29-32-log (Percona Server (GPL), Release 32, Revision 56bce88). started with:
Tcp port: 3306  Unix socket: /tmp/mysql.sock
Time                 Id Command    Argument
# Time: 2022-06-22T14:25:08.796525Z
# User@Host: user @  [127.0.0.1]  Id: 498200077
# Schema: schema_name  Last_errno: 0  Killed: 0
# Query_time: 5.390275  Lock_time: 0.000388  Rows_sent: 464  Rows_examined: 2057052  Rows_affected: 0
# Bytes_sent: 17781  Tmp_tables: 3  Tmp_disk_tables: 1  Tmp_table_sizes: 1060944
# InnoDB_trx_id: 0
# QC_Hit: No  Full_scan: Yes  Full_join: No  Tmp_table: Yes  Tmp_table_on_disk: Yes
# Filesort: Yes  Filesort_on_disk: No  Merge_passes: 0
#   InnoDB_IO_r_ops: 0  InnoDB_:IO_r_bytes: 0  InnoDB_IO_r_wait: 0.000000
#   InnoDB_rec_lock_wait: 0.000000  InnoDB_queue_wait: 0.000000
#   InnoDB_pages_distinct: 8191
SELECT * FROM some_table;



$ go run cmd/example/main.go example.log
panic: runtime error: index out of range [0] with length 0

goroutine 7 [running]:
github.com/devops-works/slowql/database/percona.(*Database).ParseBlocks(0xc000120070, 0x0?)
	/genlogs/slowql/database/percona/percona.go:40 +0x185
created by github.com/devops-works/slowql.NewParser
	/genlogs/slowql/slowql.go:76 +0x51d
exit status 2
  • 👀1
leucos commented

Ok so this was the empty lines. should be fixed by a5005e8

tspotts commented

That latest commit looks to have fixed it, thank you! 🙇

  • 🎉1
leucos commented

Cool. Thanks for reporting this Terry 👍