database/mariadb
1
0
Fork 0
mirror of https://github.com/MariaDB/server.git synced 2026-01-06 05:22:24 +03:00
Code Activity

WL#3984 (Revise locking of mysql.general_log and mysql.slow_log)

Browse Source 
Bug#25422 (Hang with log tables)
Bug 17876 (Truncating mysql.slow_log in a SP after using cursor locks the
          thread)
Bug 23044 (Warnings on flush of a log table)
Bug 29129 (Resetting general_log while the GLOBAL READ LOCK is set causes
           a deadlock)

Prior to this fix, the server would hang when performing concurrent
ALTER TABLE or TRUNCATE TABLE statements against the LOG TABLES,
which are mysql.general_log and mysql.slow_log.

The root cause traces to the following code:
in sql_base.cc, open_table()
  if (table->in_use != thd)
  {
    /* wait_for_condition will unlock LOCK_open for us */
    wait_for_condition(thd, &LOCK_open, &COND_refresh);
  }
The problem with this code is that the current implementation of the
LOGGER creates 'fake' THD objects, like
- Log_to_csv_event_handler::general_log_thd
- Log_to_csv_event_handler::slow_log_thd
which are not associated to a real thread running in the server,
so that waiting for these non-existing threads to release table locks
cause the dead lock.

In general, the design of Log_to_csv_event_handler does not fit into the
general architecture of the server, so that the concept of general_log_thd
and slow_log_thd has to be abandoned:
- this implementation does not work with table locking
- it will not work with commands like SHOW PROCESSLIST
- having the log tables always opened does not integrate well with DDL
operations / FLUSH TABLES / SET GLOBAL READ_ONLY

With this patch, the fundamental design of the LOGGER has been changed to:
- always open and close a log table when writing a log
- remove totally the usage of fake THD objects
- clarify how locking of log tables is implemented in general.

See WL#3984 for details related to the new locking design.

Additional changes (misc bugs exposed and fixed):

1)

mysqldump which would ignore some tables in dump_all_tables_in_db(),
 but forget to ignore the same in dump_all_views_in_db().

2)

mysqldump would also issue an empty "LOCK TABLE" command when all the tables
to lock are to be ignored (numrows == 0), instead of not issuing the query.

3)

Internal errors handlers could intercept errors but not warnings
(see sql_error.cc).

4)

Implementing a nested call to open tables, for the performance schema tables,
exposed an existing bug in remove_table_from_cache(), which would perform:
  in_use->some_tables_deleted=1;
against another thread, without any consideration about thread locking.
This call inside remove_table_from_cache() was not required anyway,
since calling mysql_lock_abort() takes care of aborting -- cleanly -- threads
that might hold a lock on a table.
This line (in_use->some_tables_deleted=1) has been removed.


sql/handler.cc:
  Moved logic for system / log tables in the SQL layer.
sql/handler.h:
  Moved logic for system / log tables in the SQL layer.
sql/lock.cc:
  Revised locking of log tables
sql/log.cc:
  Major cleanup: changed how log tables are locked / written to.
sql/log.h:
  Major cleanup: changed how log tables are locked / written to.
sql/mysql_priv.h:
  performance schema helpers
sql/slave.cc:
  open_ltable() lock flags
sql/sp.cc:
  open_ltable() lock flags
sql/sql_acl.cc:
  open_ltable() lock flags
sql/sql_class.h:
  performance schema helpers
sql/sql_delete.cc:
  log tables cleanup in TRUNCATE
sql/sql_error.cc:
  Internal handlers can also intercept warnings
sql/sql_insert.cc:
  open_ltable() lock flags
sql/sql_parse.cc:
  performance schema helpers
sql/sql_plugin.cc:
  open_ltable() lock flags
sql/sql_rename.cc:
  log tables cleanup in RENAME
sql/sql_servers.cc:
  open_ltable() lock flags
sql/sql_show.cc:
  Move INFORMATION_SCHEMA_NAME to table.cc
sql/sql_table.cc:
  log tables cleanup (admin operations, ALTER TABLE)
sql/sql_udf.cc:
  open_ltable() lock flags
sql/table.cc:
  Implemented TABLE_CATEGORY.
sql/share/errmsg.txt:
  Changed the wording and name of ER_CANT_READ_LOCK_LOG_TABLE
sql/table.h:
  Implemented TABLE_CATEGORY.
storage/csv/ha_tina.cc:
  Moved logic for system / log tables in the SQL layer.
storage/csv/ha_tina.h:
  Moved logic for system / log tables in the SQL layer.
storage/myisam/ha_myisam.cc:
  Moved logic for system / log tables in the SQL layer.
storage/myisam/ha_myisam.h:
  Moved logic for system / log tables in the SQL layer.
client/mysqldump.c:
  Don't lock tables in the ignore list.
  Don't issue empty LOCK TABLES queries.
sql/sql_base.cc:
  log tables cleanup
  performance schema helpers
mysql-test/r/ps.result:
  Adjust test results
mysql-test/r/show_check.result:
  Adjust test results
mysql-test/r/status.result:
  Adjust test results
mysql-test/t/log_state.test:
  Added tests for Bug#29129
mysql-test/t/ps.test:
  Make the test output deterministic
mysql-test/t/show_check.test:
  Make the test output deterministic
mysql-test/r/log_state.result:
  Changed the default location of the log output to LOG_FILE,
  for backward compatibility with MySQL 5.0
  ---
  Adjust test results
mysql-test/r/log_tables.result:
  cleanup for -ps-protocol
mysql-test/t/log_tables.test:
  cleanup for -ps-protocol
sql/set_var.cc:
  Changed the default location of the log output to LOG_FILE,
  for backward compatibility with MySQL 5.0
  ---
  log tables cleanup
This commit is contained in:
unknown
2007-07-27 00:31:06 -06:00
parent b0fcdce317
commit 4462578a1c
39 changed files with 1490 additions and 993 deletions
Download Patch File Download Diff File Expand all files Collapse all files

297
mysql-test/r/log_tables.result
View File

@@ -29,30 +29,83 @@ on (mysql.general_log.command_type = join_test.command_type)
drop table join_test;
flush logs;
lock tables mysql.general_log WRITE;
ERROR HY000: You can't write-lock a log table. Only read access is possible
ERROR HY000: You can't use locks with log tables.
lock tables mysql.slow_log WRITE;
ERROR HY000: You can't write-lock a log table. Only read access is possible
ERROR HY000: You can't use locks with log tables.
lock tables mysql.general_log READ;
ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
ERROR HY000: You can't use locks with log tables.
lock tables mysql.slow_log READ;
ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
ERROR HY000: You can't use locks with log tables.
lock tables mysql.slow_log READ LOCAL, mysql.general_log READ LOCAL;
unlock tables;
lock tables mysql.general_log READ LOCAL;
ERROR HY000: You can't use locks with log tables.
show create table mysql.general_log;
Table Create Table
general_log CREATE TABLE `general_log` (
`event_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`user_host` mediumtext,
`thread_id` int(11) DEFAULT NULL,
`server_id` int(11) DEFAULT NULL,
`command_type` varchar(64) DEFAULT NULL,
`argument` mediumtext
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='General log'
show fields from mysql.general_log;
Field Type Null Key Default Extra
event_time timestamp NO CURRENT_TIMESTAMP
user_host mediumtext YES NULL
thread_id int(11) YES NULL
server_id int(11) YES NULL
command_type varchar(64) YES NULL
argument mediumtext YES NULL
show create table mysql.slow_log;
Table Create Table
slow_log CREATE TABLE `slow_log` (
`start_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`user_host` mediumtext NOT NULL,
`query_time` time NOT NULL,
`lock_time` time NOT NULL,
`rows_sent` int(11) NOT NULL,
`rows_examined` int(11) NOT NULL,
`db` varchar(512) DEFAULT NULL,
`last_insert_id` int(11) DEFAULT NULL,
`insert_id` int(11) DEFAULT NULL,
`server_id` int(11) DEFAULT NULL,
`sql_text` mediumtext NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
show fields from mysql.slow_log;
Field Type Null Key Default Extra
start_time timestamp NO CURRENT_TIMESTAMP
user_host mediumtext NO
query_time time NO
lock_time time NO
rows_sent int(11) NO
rows_examined int(11) NO
db varchar(512) YES NULL
last_insert_id int(11) YES NULL
insert_id int(11) YES NULL
server_id int(11) YES NULL
sql_text mediumtext NO
flush logs;
unlock tables;
select "Mark that we woke up from flush logs in the test"
as "test passed";
test passed
Mark that we woke up from flush logs in the test
lock tables mysql.general_log READ LOCAL;
truncate mysql.general_log;
unlock tables;
select "Mark that we woke up from TRUNCATE in the test"
as "test passed";
test passed
Mark that we woke up from TRUNCATE in the test
use test;
flush tables;
SET GLOBAL GENERAL_LOG=ON;
SET GLOBAL SLOW_QUERY_LOG=ON;
show open tables;
Database Table In_use Name_locked
mysql general_log 0 0
flush logs;
show open tables;
Database Table In_use Name_locked
mysql general_log 0 0
flush tables;
show open tables;
Database Table In_use Name_locked
mysql general_log 0 0
SET GLOBAL GENERAL_LOG=OFF;
SET GLOBAL SLOW_QUERY_LOG=OFF;
flush tables;
show open tables;
Database Table In_use Name_locked
SET GLOBAL GENERAL_LOG=ON;
SET GLOBAL SLOW_QUERY_LOG=ON;
truncate table mysql.general_log;
set names utf8;
create table bug16905 (s char(15) character set utf8 default 'пусто');
@@ -71,7 +124,7 @@ sleep(2)
0
select * from mysql.slow_log;
start_time user_host query_time lock_time rows_sent rows_examined db last_insert_id insert_id server_id sql_text
TIMESTAMP USER_HOST QUERY_TIME 00:00:00 1 0 test 0 0 1 select sleep(2)
TIMESTAMP USER_HOST QUERY_TIME 00:00:00 1 0 mysql 0 0 1 select sleep(2)
alter table mysql.general_log engine=myisam;
ERROR HY000: You cannot 'ALTER' a log table if logging is enabled
alter table mysql.slow_log engine=myisam;
@@ -158,15 +211,13 @@ TIMESTAMP USER_HOST THREAD_ID 1 Query set global slow_query_log='ON'
TIMESTAMP USER_HOST THREAD_ID 1 Query select * from mysql.general_log
flush logs;
lock tables mysql.general_log WRITE;
ERROR HY000: You can't write-lock a log table. Only read access is possible
ERROR HY000: You can't use locks with log tables.
lock tables mysql.slow_log WRITE;
ERROR HY000: You can't write-lock a log table. Only read access is possible
ERROR HY000: You can't use locks with log tables.
lock tables mysql.general_log READ;
ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
ERROR HY000: You can't use locks with log tables.
lock tables mysql.slow_log READ;
ERROR HY000: You can't use usual read lock with log tables. Try READ LOCAL instead
lock tables mysql.slow_log READ LOCAL, mysql.general_log READ LOCAL;
unlock tables;
ERROR HY000: You can't use locks with log tables.
set global general_log='OFF';
set global slow_query_log='OFF';
set @save_storage_engine= @@session.storage_engine;
@@ -217,6 +268,7 @@ flush tables with read lock;
unlock tables;
use mysql;
lock tables general_log read local, help_category read local;
ERROR HY000: You can't use locks with log tables.
unlock tables;
use mysql;
RENAME TABLE general_log TO renamed_general_log;
@@ -258,9 +310,9 @@ RENAME TABLE general_log TO general_log2;
set global slow_query_log='OFF';
RENAME TABLE slow_log TO slow_log2;
set global general_log='ON';
ERROR HY000: Cannot activate 'general' log
ERROR 42S02: Table 'mysql.general_log' doesn't exist
set global slow_query_log='ON';
ERROR HY000: Cannot activate 'slow query' log
ERROR 42S02: Table 'mysql.slow_log' doesn't exist
RENAME TABLE general_log2 TO general_log;
RENAME TABLE slow_log2 TO slow_log;
set global general_log='ON';
@@ -355,3 +407,192 @@ SET SESSION long_query_time =@old_long_query_time;
FLUSH LOGS;
ALTER TABLE mysql.slow_log DROP COLUMN seq;
ALTER TABLE mysql.slow_log ENGINE = CSV;
drop procedure if exists proc25422_truncate_slow;
drop procedure if exists proc25422_truncate_general;
drop procedure if exists proc25422_alter_slow;
drop procedure if exists proc25422_alter_general;
use test//
create procedure proc25422_truncate_slow (loops int)
begin
declare v1 int default 0;
while v1 < loops do
truncate mysql.slow_log;
set v1 = v1 + 1;
end while;
end//
create procedure proc25422_truncate_general (loops int)
begin
declare v1 int default 0;
while v1 < loops do
truncate mysql.general_log;
set v1 = v1 + 1;
end while;
end//
create procedure proc25422_alter_slow (loops int)
begin
declare v1 int default 0;
declare ER_BAD_LOG_STATEMENT condition for 1575;
declare continue handler for ER_BAD_LOG_STATEMENT begin end;
while v1 < loops do
set @old_log_state = @@global.slow_query_log;
set global slow_query_log = 'OFF';
alter table mysql.slow_log engine = CSV;
set global slow_query_log = @old_log_state;
set v1 = v1 + 1;
end while;
end//
create procedure proc25422_alter_general (loops int)
begin
declare v1 int default 0;
declare ER_BAD_LOG_STATEMENT condition for 1575;
declare continue handler for ER_BAD_LOG_STATEMENT begin end;
while v1 < loops do
set @old_log_state = @@global.general_log;
set global general_log = 'OFF';
alter table mysql.general_log engine = CSV;
set global general_log = @old_log_state;
set v1 = v1 + 1;
end while;
end//
"Serial test (proc25422_truncate_slow)"
call proc25422_truncate_slow(100);
"Serial test (proc25422_truncate_general)"
call proc25422_truncate_general(100);
"Serial test (proc25422_alter_slow)"
call proc25422_alter_slow(100);
"Serial test (proc25422_alter_general)"
call proc25422_alter_general(100);
"Parallel test"
call proc25422_truncate_slow(100);
call proc25422_truncate_slow(100);
call proc25422_truncate_general(100);
call proc25422_truncate_general(100);
call proc25422_alter_slow(100);
call proc25422_alter_slow(100);
call proc25422_alter_general(100);
call proc25422_alter_general(100);
drop procedure proc25422_truncate_slow;
drop procedure proc25422_truncate_general;
drop procedure proc25422_alter_slow;
drop procedure proc25422_alter_general;
FLUSH TABLE mysql.general_log;
show warnings;
Level Code Message
FLUSH TABLE mysql.slow_log;
show warnings;
Level Code Message
DROP TABLE IF EXISTS `db_17876.slow_log_data`;
DROP TABLE IF EXISTS `db_17876.general_log_data`;
DROP PROCEDURE IF EXISTS `db_17876.archiveSlowLog`;
DROP PROCEDURE IF EXISTS `db_17876.archiveGeneralLog`;
DROP DATABASE IF EXISTS `db_17876`;
CREATE DATABASE db_17876;
CREATE TABLE `db_17876.slow_log_data` (
`start_time` timestamp default CURRENT_TIMESTAMP on update CURRENT_TIMESTAMP,
`user_host` mediumtext ,
`query_time` time ,
`lock_time` time ,
`rows_sent` int(11) ,
`rows_examined` int(11) ,
`db` varchar(512) default NULL,
`last_insert_id` int(11) default NULL,
`insert_id` int(11) default NULL,
`server_id` int(11) default NULL,
`sql_text` mediumtext
);
CREATE TABLE `db_17876.general_log_data` (
`event_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`user_host` mediumtext,
`thread_id` int(11) DEFAULT NULL,
`server_id` int(11) DEFAULT NULL,
`command_type` varchar(64) DEFAULT NULL,
`argument` mediumtext
);
CREATE procedure `db_17876.archiveSlowLog`()
BEGIN
DECLARE start_time, query_time, lock_time CHAR(20);
DECLARE user_host MEDIUMTEXT;
DECLARE rows_set, rows_examined, last_insert_id, insert_id, server_id INT;
DECLARE dbname MEDIUMTEXT;
DECLARE sql_text BLOB;
DECLARE done INT DEFAULT 0;
DECLARE ER_SP_FETCH_NO_DATA CONDITION for 1329;
DECLARE cur1 CURSOR FOR SELECT * FROM mysql.slow_log;
OPEN cur1;
REPEAT
BEGIN
BEGIN
DECLARE CONTINUE HANDLER FOR ER_SP_FETCH_NO_DATA SET done = 1;
FETCH cur1 INTO
start_time, user_host, query_time, lock_time,
rows_set, rows_examined, dbname, last_insert_id,
insert_id, server_id, sql_text;
END;
IF NOT done THEN
BEGIN
INSERT INTO
`db_17876.slow_log_data`
VALUES(start_time, user_host, query_time, lock_time, rows_set, rows_examined,
dbname, last_insert_id, insert_id, server_id, sql_text);
END;
END IF;
END;
UNTIL done END REPEAT;
CLOSE cur1;
TRUNCATE mysql.slow_log;
END //
CREATE procedure `db_17876.archiveGeneralLog`()
BEGIN
DECLARE event_time CHAR(20);
DECLARE user_host, argument MEDIUMTEXT;
DECLARE thread_id, server_id INT;
DECLARE sql_text BLOB;
DECLARE done INT DEFAULT 0;
DECLARE command_type VARCHAR(64);
DECLARE ER_SP_FETCH_NO_DATA CONDITION for 1329;
DECLARE cur1 CURSOR FOR SELECT * FROM mysql.general_log;
OPEN cur1;
REPEAT
BEGIN
BEGIN
DECLARE CONTINUE HANDLER FOR ER_SP_FETCH_NO_DATA SET done = 1;
FETCH cur1 INTO
event_time, user_host, thread_id, server_id,
command_type, argument;
END;
IF NOT done THEN
BEGIN
INSERT INTO
`db_17876.general_log_data`
VALUES(event_time, user_host, thread_id, server_id,
command_type, argument);
END;
END IF;
END;
UNTIL done END REPEAT;
CLOSE cur1;
TRUNCATE mysql.general_log;
END //
SET @old_general_log_state = @@global.general_log;
SET @old_slow_log_state = @@global.slow_query_log;
SET GLOBAL general_log = ON;
SET GLOBAL slow_query_log = ON;
select "put something into general_log";
put something into general_log
put something into general_log
select "... and something more ...";
... and something more ...
... and something more ...
call `db_17876.archiveSlowLog`();
call `db_17876.archiveGeneralLog`();
SET GLOBAL general_log = OFF;
SET GLOBAL slow_query_log = OFF;
call `db_17876.archiveSlowLog`();
call `db_17876.archiveGeneralLog`();
DROP TABLE `db_17876.slow_log_data`;
DROP TABLE `db_17876.general_log_data`;
DROP PROCEDURE IF EXISTS `db_17876.archiveSlowLog`;
DROP PROCEDURE IF EXISTS `db_17876.archiveGeneralLog`;
DROP DATABASE IF EXISTS `db_17876`;
SET GLOBAL general_log = @old_general_log_state;
SET GLOBAL slow_query_log = @old_slow_log_state;