Raise notes if indexes cannot be used:
- in case of data type or collation mismatch (diferent error messages).
- in case if a table field was replaced to something else
(e.g. Item_func_conv_charset) during a condition rewrite.
Added option to write warnings and notes to the slow query log for
slow queries.
New variables added/changed:
- note_verbosity, with is a set of the following options:
basic - All old notes
unusable_keys - Print warnings about keys that cannot be used
for select, delete or update.
explain - Print unusable_keys warnings for EXPLAIN querys.
The default is 'basic,explain'. This means that for old installations
the only notable new behavior is that one will get notes about
unusable keys when one does an EXPLAIN for a query. One can turn all
of all notes by either setting note_verbosity to "" or setting sql_notes=0.
- log_slow_verbosity has a new option 'warnings'. If this is set
then warnings and notes generated are printed in the slow query log
(up to log_slow_max_warnings times per statement).
- log_slow_max_warnings - Max number of warnings written to
slow query log.
Other things:
- One can now use =ALL for any 'set' variable to set all options at once.
For example using "note_verbosity=ALL" in a config file or
"SET @@note_verbosity=ALL' in SQL.
- mysqldump will in the future use @@note_verbosity=""' instead of
@sql_notes=0 to disable notes.
- Added "enum class Data_type_compatibility" and changing the return type
of all Field::can_optimize*() methods from "bool" to this new data type.
Reviewer & Co-author: Alexander Barkov <bar@mariadb.com>
- The code that prints out the notes comes mainly from Alexander
The new statistics is enabled by adding the "engine", "innodb" or "full"
option to --log-slow-verbosity
Example output:
# Pages_accessed: 184 Pages_read: 95 Pages_updated: 0 Old_rows_read: 1
# Pages_read_time: 17.0204 Engine_time: 248.1297
Page_read_time is time doing physical reads inside a storage engine.
(Writes cannot be tracked as these are usually done in the background).
Engine_time is the time spent inside the storage engine for the full
duration of the read/write/update calls. It uses the same code as
'analyze statement' for calculating the time spent.
The engine statistics is done with a generic interface that should be
easy for any engine to use. It can also easily be extended to provide
even more statistics.
Currently only InnoDB has counters for Pages_% and Undo_% status.
Engine_time works for all engines.
Implementation details:
class ha_handler_stats holds all engine stats. This class is included
in handler and THD classes.
While a query is running, all statistics is updated in the handler. In
close_thread_tables() the statistics is added to the THD.
handler::handler_stats is a pointer to where statistics should be
collected. This is set to point to handler::active_handler_stats if
stats are requested. If not, it is set to 0.
handler_stats has also an element, 'active' that is 1 if stats are
requested. This is to allow engines to avoid doing any 'if's while
updating the statistics.
Cloned or partition tables have the pointer set to the base table if
status are requested.
There is a small performance impact when using --log-slow-verbosity=engine:
- All engine calls in 'select' will be timed.
- IO calls for InnoDB reads will be timed.
- Incrementation of counters are done on local variables and accesses
are inline, so these should have very little impact.
- Statistics has to be reset for each statement for the THD and each
used handler. This is only 40 bytes, which should be neglectable.
- For partition tables we have to loop over all partitions to update
the handler_status as part of table_init(). Can be optimized in the
future to only do this is log-slow-verbosity changes. For this to work
we have to update handler_status for all opened partitions and
also for all partitions opened in the future.
Other things:
- Added options 'engine' and 'full' to log-slow-verbosity.
- Some of the new files in the test suite comes from Percona server, which
has similar status information.
- buf_page_optimistic_get(): Do not increment any counter, since we are
only validating a pointer, not performing any buf_pool.page_hash lookup.
- Added THD argument to save_explain_data_intern().
- Switched arguments for save_explain_.*_data() to have
always THD first (generates better code as other functions also have THD
first).
This commit is based on the work of Michal Schorm, rebased on the
earliest MariaDB version.
Th command line used to generate this diff was:
find ./ -type f \
-exec sed -i -e 's/Foundation, Inc., 59 Temple Place, Suite 330, Boston, /Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, /g' {} \; \
-exec sed -i -e 's/Foundation, Inc. 59 Temple Place.* Suite 330, Boston, /Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, /g' {} \; \
-exec sed -i -e 's/MA.*.....-1307.*USA/MA 02110-1335 USA/g' {} \; \
-exec sed -i -e 's/Foundation, Inc., 59 Temple/Foundation, Inc., 51 Franklin/g' {} \; \
-exec sed -i -e 's/Place, Suite 330, Boston, MA.*02111-1307.*USA/Street, Fifth Floor, Boston, MA 02110-1335 USA/g' {} \; \
-exec sed -i -e 's/MA.*.....-1307/MA 02110-1335/g' {} \;
This solves the following issues:
* unlike lex->m_sql_cmd and lex->sql_command, thd->query_plan_flags
is not reset in Prepared_statement::execute, it survives
till the log_slow_statement(), so slow logging behaves correctly in --ps
* using thd->query_plan_flags for both slow_log_filter and
log_slow_admin_statements means the definition of "admin" statements
for the slow log is the same no matter how it is filtered out.
This fixes MDEV-7742 and MDEV-8305 (Allow user to specify if stored
procedures should be logged in the slow and general log)
New functionality:
- Added new variables log_slow_disable_statements and log_disable_statements
that can be used to disable logging of certain queries to slow and
general log. Currently supported options are 'admin', 'call', 'slave'
and 'sp'.
Defaults are as before. Only 'sp' (stored procedure statements) is
disabled for slow and general_log.
- Slow log to files now includes the following new information:
- When logging stored procedure statements the name of stored
procedure is logged.
- Number of created tmp_tables, tmp_disk_tables and the space used
by temporary tables.
- When logging 'call', the logged status now contains the sum of all
included statements. Before only 'time' was correct.
- Added filsort_priority_queue as an option for log_slow_filter (this
variable existed before, but was not exposed)
- Added support for BIT types in my_getopt()
Mapped some old variables to bitmaps (old variables can still be used)
- Variable 'log_queries_not_using_indexes' is mapped to
log_slow_filter='not_using_index'
- Variable 'log_slow_slave_statements' is mapped to
log_slow_disabled_statements='slave'
- Variable 'log_slow_admin_statements' is mapped to
log_slow_disabled_statements='admin'
- All the above variables are changed to session variables from global
variables
Other things:
- Simplified LOGGER::log_command. We don't need to check for super if
OPTION_LOG_OFF is set as this flag can only be set if one is a super
user.
- Removed some setting of enable_slow_log as it's guaranteed to be set by
mysql_parse()
- mysql_admin_table() now sets thd->enable_slow_log
- Added prepare_logs_for_admin_command() to reset thd->enable_slow_log if
needed.
- Added new functions to store, restore and add slow query status
- Added new functions to store and restore query start time
- Reorganized Sub_statement_state according to types
- Added code in dispatch_command() to ensure that
thd->reset_for_next_command() is always called for a query.
- Added thd->last_sql_command to simplify checking of what was the type
of the last command. Needed when logging to slow log as lex->sql_command
may have changed before slow logging is called.
- Moved QPLAN_TMP_... to where status for tmp tables are updated
- Added new THD variable, affected_rows, to be able to correctly log
number of affected rows to slow log.
Also, implement MDEV-11027 a little differently from 5.5:
recv_sys_t::report(ib_time_t): Determine whether progress should
be reported.
recv_apply_hashed_log_recs(): Rename the parameter to last_batch.
This is essentially a backport of the 10.0
commit 203f4d4193
that fixes a bug and silences a GCC 6.3.0 warning
about a left shift of a signed integer.
Missing parenthesis in a macro definition caused wrong operation
in the Query_cache::send_result_to_client() statement
thd->query_plan_flags= (thd->query_plan_flags & ~QPLAN_QC_NO) | QPLAN_QC;
This would expand to
thd->query_plan_flags= (thd->query_plan_flags & ~1) << 6 | 1 << 5;
which would shift the flags by 6 and clear an unrelated flag, instead
of clearing the flag (1 << 6).
Define my_thread_id as an unsigned type, to avoid mismatch with
ulonglong. Change some parameters to this type.
Use size_t in a few more places.
Declare many flag constants as unsigned to avoid sign mismatch
when shifting bits or applying the unary ~ operator.
When applying the unary ~ operator to enum constants, explictly
cast the result to an unsigned type, because enum constants can
be treated as signed.
In InnoDB, change the source code line number parameters from
ulint to unsigned type. Also, make some InnoDB functions return
a narrower type (unsigned or uint32_t instead of ulint;
bool instead of ibool).
When macro is expanded in an expression like ~QPLAN_QC_NO (e.g. in the
Query_cache::send_result_to_client() function in sql/sql_cache.cc) then without
the parenthesis the expression will be evaluated to a wrong value.
- Make log_slow_verbosity print "Priority_queue: (Yes|No)" into the slow query log.
(but we do not add a correspoding column to P_S.*statement* tables).
Added (rewritten) patch from Percona to get extended statistics in slow.log:
- Added handling of 'set' variables to set_var.cc. Changed sql_mode to use this
- Added extra logging to slow log of 'Thread_id, Schema, Query Cache hit, Rows sent and Rows examined'
- Added optional logging to slow log, through log_slow_verbosity, of query plan statistics
- Added new user variables log_slow_rate_limit, log_slow_verbosity, log_slow_filter
- Added log-slow-file as synonym for 'slow-log-file', as most slow-log variables starts with 'log-slow'
- Added log-slow-time as synonym for long-query-time
Some trivial MyISAM optimizations:
- In prepare for drop, flush key blocks
- Don't call mi_lock_database if my_disable_locking is used
KNOWN_BUGS.txt:
Updated file to reflect MariaDB and not the Maria storage engine
README:
Updated file to reflect MariaDB
mysql-test/r/log_slow.result:
Test new options for slow query log
mysql-test/r/variables.result:
Updated result (old version cut of things at 79 characters)
mysql-test/t/log_slow.test:
Test new options for slow query log
sql/Makefile.am:
Added log_slow.h
sql/event_data_objects.cc:
Removed not needed test for enable_slow_log (is done when the flag is tested elsewhere)
sql/events.cc:
Use the general make_set() function instead of 'symbolic_mode_representation'
sql/filesort.cc:
Added status for used query plans
sql/log.cc:
Reset counters if no query_length (from Percona's patch; Not sure if needed, but can do no harm)
Added extra logging to slow log of 'Thread_id, Schema, Query Cache hit, Rows sent and Rows examined'
Added optional logging to slow log, through log_slow_verbosity, of query plan statistics
Fixed wrong test of error condition
sql/log_slow.h:
Defines and variables for log_slow_verbosity and log_slow_filter
sql/mysql_priv.h:
Include log_slow.h
sql/mysqld.cc:
Added new user variables log_slow_rate_limit, log_slow_verbosity, log_slow_filter
Added log-slow-file as synonym for 'slow-log-file', as most slow-log variables starts with 'log-slow'
Added log-slow-time as synonym for long-query-time
Added note that one should use log-slow-filter instead of log-slow-admin-statements
Updated comment from 'slow_query_log_file'
sql/set_var.cc:
Added long_slow_time as synonym for long_query_time
Added new user variables log_slow_rate_limit, log_slow_verbosity, log_slow_filter
dded handling of 'set' variables to set_var.cc. Changed sql_mode to use this
sql/set_var.h:
- Added handling of 'set' variables. Changed sql_mode to use this
sql/slave.cc:
Use global filter also for slaves
sql/sp_head.cc:
Simplify saving of general_slow_log state
Use the general make_set() function instead of 'symbolic_mode_representation'
sql/sql_cache.cc:
Added status for used query plans
sql/sql_class.cc:
Remember/restore query_plan_flags over complex statements
sql/sql_class.h:
Added variables to handle extended slow log statistics
sql/sql_parse.cc:
Added status for used query plans
Added test for filtering slow_query_log
sql/sql_select.cc:
Added status for used query plans
sql/sql_show.cc:
Use the general make_set() function instead of 'symbolic_mode_representation'
sql/strfunc.cc:
Report first error (not last) if something is wrong in a set
Removed compiler warning
storage/myisam/mi_extra.c:
In prepare for drop, flush key blocks (speed optimization)
storage/myisam/mi_locking.c:
Don't call mi_lock_database if my_disable_locking is used (speed optimization)
