[Maria-developers] EXPLAIN in the slow query log
Hello, After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it. @@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this: # Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY'; It seems, pt-slow-query-log has no problem parsing this. Open questions: - Is this syntax OK? - Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok? (*) something like EXPLAIN ANALYZE, with numbers from actual execution, would be better but we are not there yet. BR Sergei -- Sergei Petrunia, Software Developer MariaDB | Skype: sergefp | Blog: http://s.petrunia.net/blog
Hi, Sergei! On Oct 18, Sergei Petrunia wrote:
Hello,
After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it.
@@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this:
# Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY';
It seems, pt-slow-query-log has no problem parsing this.
Open questions:
- Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
- Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok?
Yes. If users will complain we can always change it back later. Regards, Sergei
I don't understand why you need both the <explain> xml style tag and the double # to denote an explain entry. I would prefer to see each line prefixed with # explain: to make it similar to the other info lines above and get rid of the <explain>. By prefixing each line with # explain: it makes grepping explain plans easier than looking for a start and end tag on different lines. On Fri, Oct 18, 2013 at 4:59 PM, Sergei Golubchik <serg@mariadb.org> wrote:
Hi, Sergei!
On Oct 18, Sergei Petrunia wrote:
Hello,
After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it.
@@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this:
# Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY';
It seems, pt-slow-query-log has no problem parsing this.
Open questions:
- Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
- Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok?
Yes. If users will complain we can always change it back later.
Regards, Sergei
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
-- Eric Bergen eric.bergen@gmail.com http://www.ebergen.net
Agreed. Make it easy to grep and don't pretend the log is an XML file. :-) Jeremy On Sat, Oct 19, 2013 at 8:26 AM, Eric Bergen <eric.bergen@gmail.com> wrote:
I don't understand why you need both the <explain> xml style tag and the double # to denote an explain entry. I would prefer to see each line prefixed with # explain: to make it similar to the other info lines above and get rid of the <explain>.
By prefixing each line with # explain: it makes grepping explain plans easier than looking for a start and end tag on different lines.
On Fri, Oct 18, 2013 at 4:59 PM, Sergei Golubchik <serg@mariadb.org> wrote:
Hi, Sergei!
On Oct 18, Sergei Petrunia wrote:
Hello,
After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it.
@@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this:
# Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY';
It seems, pt-slow-query-log has no problem parsing this.
Open questions:
- Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
- Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok?
Yes. If users will complain we can always change it back later.
Regards, Sergei
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
-- Eric Bergen eric.bergen@gmail.com http://www.ebergen.net
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
Ok, thanks for the input. I'll change the formatting to prefix each line with 'explain:', and remove XML-like tags. On Sat, Oct 19, 2013 at 08:32:51AM -0700, Jeremy Zawodny wrote:
Agreed. Make it easy to grep and don't pretend the log is an XML file. :-)
Jeremy
On Sat, Oct 19, 2013 at 8:26 AM, Eric Bergen <eric.bergen@gmail.com> wrote:
I don't understand why you need both the <explain> xml style tag and the double # to denote an explain entry. I would prefer to see each line prefixed with # explain: to make it similar to the other info lines above and get rid of the <explain>.
By prefixing each line with # explain: it makes grepping explain plans easier than looking for a start and end tag on different lines.
On Fri, Oct 18, 2013 at 4:59 PM, Sergei Golubchik <serg@mariadb.org> wrote:
Hi, Sergei!
On Oct 18, Sergei Petrunia wrote:
Hello,
After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it.
@@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this:
# Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY';
It seems, pt-slow-query-log has no problem parsing this.
Open questions:
- Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
- Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok?
Yes. If users will complain we can always change it back later.
Regards, Sergei
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
-- Eric Bergen eric.bergen@gmail.com http://www.ebergen.net
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
-- BR Sergei -- Sergei Petrunia, Software Developer MariaDB | Skype: sergefp | Blog: http://s.petrunia.net/blog
Hi, On 10/19/2013 7:26 PM, Eric Bergen wrote:
I don't understand why you need both the <explain> xml style tag and the double # to denote an explain entry. I would prefer to see each line prefixed with # explain: to make it similar to the other info lines above and get rid of the <explain>.
Regardless the <explain> tags (it's a different story), it was my suggestion to go with double ## rather than with '# explain' which Sergei actually suggested himself. It seems to me that it's just as easy to grep for '^##' as it is for '# explain:', while the variant with double # is less excessive and more readable when you just look through the log without pre-grepping. I don't insist on the above though, if those who care prefer the prefix with '# explain:' :) Regards, Elena
By prefixing each line with # explain: it makes grepping explain plans easier than looking for a start and end tag on different lines.
On Fri, Oct 18, 2013 at 4:59 PM, Sergei Golubchik <serg@mariadb.org> wrote:
Hi, Sergei!
On Oct 18, Sergei Petrunia wrote:
Hello,
After recent changes in the [SHOW] EXPLAIN architecture in MariaDB, it became really easy to add an option to print EXPLAIN(*) output into the slow query log, so I went ahead and implemented it.
@@log_slow_verbosity has got a 'explain' flag, and if it is on, the slow query log entries look like this:
# Time: 131017 21:26:02 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: dbt3sf1 QC_hit: No # Query_time: 5.535819 Lock_time: 0.000350 Rows_sent: 1 Rows_examined: 65633 ## <explain> ## id select_type table type possible_keys key key_len ref rows Extra ## 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1 Using where; Using index ## 1 SIMPLE customer ref PRIMARY,i_c_nationkey i_c_nationkey 5 dbt3sf1.nation.n_nationkey 25124 Using index ## 1 SIMPLE orders ref i_o_custkey i_o_custkey 5 dbt3sf1.customer.c_custkey 7 Using index ## </explain> SET timestamp=1382030762; select count(*) from customer, orders, nation where c_custkey=o_custkey and c_nationkey=n_nationkey and n_name='GERMANY';
It seems, pt-slow-query-log has no problem parsing this.
Open questions:
- Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
- Currently, some statements (like SHOW KEYS) print a dumb explain that shows that full table scan is used. There is a suggestion to not print EXPLAIN for any SHOW statements. Is this ok?
Yes. If users will complain we can always change it back later.
Regards, Sergei
_______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers@lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp
Hi, Sergei! On Oct 18, Sergei Golubchik wrote:
On Oct 18, Sergei Petrunia wrote:
Open questions: - Is this syntax OK?
Yes, assuming you use tabs as column separators, not spaces.
Just to make it clear, "yes" above means I'm ok with that, it doesn't mean I particularly prefer that variant. I don't care much whether there's one or two #-chars, or about <explain> tags. But I'm glad that others - who do care - replied :) Regards, Sergei
participants (5)
-
Elena Stepanova -
Eric Bergen -
Jeremy Zawodny -
Sergei Golubchik -
Sergei Petrunia