| Bug #49956 | Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST | ||
|---|---|---|---|
| Submitted: | 28 Dec 2009 10:20 | Modified: | 11 Feb 2010 5:19 |
| Reporter: | Philip Stoev | Email Updates: | |
| Status: | Won't fix | Impact on me: | |
| Category: | MySQL Server: Backup | Severity: | S3 (Non-critical) |
| Version: | 6.0-backup | OS: | Any |
| Assigned to: | Satya B | CPU Architecture: | Any |
[28 Dec 2009 10:20]
Philip Stoev
[6 Jan 2010 11:24]
Satya B
Philip, Can you please give us a testcase to reproduce this ? or any steps to reproduce this would be helpful.
[7 Jan 2010 11:05]
Satya B
We use run_service_interface_sql (..) to execute sql commands from backup. Probably we can fix this interface to not to display internal sql commands. But I still need a testcase to verify this. Philip, can you please help me with this?
[8 Jan 2010 15:58]
Philip Stoev
To reproduce, restore from the backup at http://mysql-systemqa.s3.amazonaws.com/bug49956.backup.gz This should take at least 2 seconds. During that time, issue several SHOW FULL PROCESSLIST using a different connection. At least some of the SHOW commands will not show a RESTORE but rather some specific internal operation, such as LOCK TABLE `testdb_N`.`t1_part9_N` WRITE, `testdb_N`.`t1_part8_N` WRITE, `testdb_N`.`t1_part7_N` WRITE, `testdb_N`.`t1_part6_N` WRITE, `testdb_N`.`t1_part5_N` WRITE, `testdb_N`.`t1_part50_N` WRITE, `testdb_N`.`t1_part4_N` WRITE, `testdb_N`.`t1_part49_N` WRITE, `testdb_N`.`t1_part48_N` WRITE, `testdb_N`.`t1_part46_N` WRITE, `testdb_N`.`t1_part45_N` WRITE, `testdb_N`.`t1_part44_N` WRITE, `testdb_N`.`t1_part43_N` WRITE, `testdb_N`.`t1_part42_N` WRITE, `testdb_N`.`t1_part40_N` WRITE, `testdb_N`.`t1_part3_N` WRITE, `testdb_N`.`t1_part39_N` WRITE, `testdb_N`.`t1_part38_N` WRITE, `testdb_N`.`t1_part37_N` WRITE, `testdb_N`.`t1_part36_N` WRITE, `testdb_N`.`t1_part35_N` WRITE, `testdb_N`.`t1_part33_N` WRITE, `testdb_N`.`t1_part32_N` WRITE, `testdb_N`.`t1_part31_N` WRITE, `testdb_N`.`t1_part30_N` WRITE, `testdb_N`.`t1_part2_N` WRITE, `testdb_N`.`t1_part29_N` WRITE, `testdb_N`.`t1_part28_N` WRITE, `testdb_N`.`t1_part26_N` WRITE, `testdb_N`.`t1_part25_N` WRITE, `testdb_N`.`t1_part24_N` WRITE, `testdb_N`.`t1_part23_N` WRITE, `testdb_N`.`t1_part22_N` WRITE, `testdb_N`.`t1_part20_N` WRITE, `testdb_N`.`t1_part1_N` WRITE, `testdb_N`.`t1_part19_N` WRITE, `testdb_N`.`t1_part17_N` WRITE, `testdb_N`.`t1_part16_N` WRITE, `testdb_N`.`t1_part15_N` WRITE, `testdb_N`.`t1_part13_N` WRITE, `testdb_N`.`t1_part12_N` WRITE, `testdb_N`.`t1_part11_N` WRITE, `testdb_N`.`t1_part10_N` WRITE, `testdb_N`.`t1_base9_N` WRITE, `testdb_N`.`t1_base8_N` WRITE, `testdb_N`.`t1_base7_N` WRITE, `testdb_N`.`t1_base6_N` WRITE, `testdb_N`.`t1_base5_N` WRITE, `testdb_N`.`t1_base50_N` WRITE, `testdb_N`.`t1_base4_N` WRITE, `testdb_N`.`t1_base49_N` WRITE, `testdb_N`.`t1_base48_N` WRITE, `testdb_N`.`t1_base47_N` WRITE, `testdb_N`.`t1_base46_N` WRITE, `testdb_N`.`t1_base45_N` WRITE, `testdb_N`.`t1_base44_N` WRITE, `testdb_N`.`t1_base43_N` WRITE, `testdb_N`.`t1_base42_N` WRITE, `testdb_N`.`t1_base41_N` WRITE, `testdb_N`.`t1_base40_N` WRITE, `testdb_N`.`t1_base3_N` WRITE, `testdb_N`.`t1_base39_N` WRITE, `testdb_N`.`t1_base38_N` WRITE, `testdb_N`.`t1_base37_N` WRITE, `testdb_N`.`t1_base36_N` WRITE, `testdb_N`.`t1_base35_N` WRITE, `testdb_N`.`t1_base34_N` WRITE, `testdb_N`.`t1_base33_N` WRITE, `testdb_N`.`t1_base32_N` WRITE, `testdb_N`.`t1_base31_N` WRITE, `testdb_N`.`t1_base30_N` WRITE, `testdb_N`.`t1_base2_N` WRITE, `testdb_N`.`t1_base29_N` WRITE, `testdb_N`.`t1_base28_N` WRITE, `testdb_N`.`t1_base27_N` WRITE, `testdb_N`.`t1_base26_N` WRITE, `testdb_N`.`t1_base25_N` WRITE, `testdb_N`.`t1_base24_N` WRITE, `testdb_N`.`t1_base23_N` WRITE, `testdb_N`.`t1_base22_N` WRITE, `testdb_N`.`t1_base21_N` WRITE, `testdb_N`.`t1_base20_N` WRITE, `testdb_N`.`t1_base1_N` WRITE, `testdb_N`.`t1_base19_N` WRITE, `testdb_N`.`t1_base18_N` WRITE, `testdb_N`.`t1_base17_N` WRITE, `testdb_N`.`t1_base16_N` WRITE, `testdb_N`.`t1_base15_N` WRITE, `testdb_N`.`t1_base14_N` WRITE, `testdb_N`.`t1_base13_N` WRITE, `testdb_N`.`t1_base12_N` WRITE, `testdb_N`.`t1_base11_N` WRITE, `testdb_N`.`t1_base10_N` WRITE that should not be visible.
[11 Jan 2010 18:51]
Rafal Somla
I am able to reproduce symptoms after introducing new debug synchronization point: === modified file 'sql/sql_prepare.cc' --- sql/sql_prepare.cc 2009-12-16 11:54:15 +0000 +++ sql/sql_prepare.cc 2010-01-11 18:36:00 +0000 @@ -97,6 +97,7 @@ When one supplies long data for a placeh #else #include <mysql_com.h> #endif +#include "debug_sync.h" /** A result class used to send cursor rows using the binary protocol. @@ -3440,6 +3441,8 @@ Prepared_statement::execute_server_runna error= server_runnable->execute_server_code(thd); + DEBUG_SYNC(thd,"inside_ed"); + delete lex->sphead; lex->sphead= 0; /* The order is important */ And then running the following test case: ----------------------------------------------------------------------- --source include/have_debug_sync.inc CREATE DATABASE db1; CREATE TABLE db1.t1( a INT); BACKUP DATABASE db1 TO 'db1.bkp'; --connect(con1,localhost,root,,,) --connection con1 SET DEBUG_SYNC= 'inside_ed SIGNAL here WAIT_FOR continue'; send RESTORE FROM 'db1.bkp' OVERWRITE; --connection default SET DEBUG_SYNC= 'now WAIT_FOR here'; SHOW PROCESSLIST; SET DEBUG_SYNC= 'now SIGNAL continue'; DROP DATABASE db1; SET DEBUG_SYNC= 'reset'; --connection con1 reap; --exit ----------------------------------------------------------------------- SHOW PROCESSLIST shows: > SHOW PROCESSLIST; > Id User Host db Command Time State Info > 2 root localhost test Query 0 NULL SHOW PROCESSLIST > 4 root localhost NULL Query 0 debug sync point: inside_ed DROP DATABASE IF EXISTS `db1` Note that field 'info' for process 4 which is running RESTORE says "DROP DATABASE ..." instead of "RESTORE FROM ...". This means that thd->query() is changed inside Prepared_statement::execute_server_runnable() when server_runnable->execute_server_code(thd) is called. But the original value is first saved and then restored (sql_parse.cc, lines 3438 and 3454). Thus the confusing output from SHOW PROCESSLIST can be seen only during the period when the internal SQL statement is being executed - after it is completed SHOW PROCESSLIST will show "RESTORE FROM ..." again. The difference can be noticed only when it takes longer time to execute the internal SQL.
[12 Jan 2010 5:58]
Satya B
Rafal, Thanks for taking time to look into this. It is quite helpful.
[2 Feb 2010 13:44]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/98952 2943 Satya B 2010-02-02 BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST BACKUP/RESTORE command internally calls sql queries to do BACKUP/RESTORE operation which are visible via SHOW PROCESSLIST command. A new member 'query_to_display' is introduced in the THD object. This variable is set to a query name which is different from the query executing. This is useful in scenarios like BACKUP/RESTORE, where we want the original High Level Operation/Query to be displayed in the SHOW PROCESSLIST output instead of the internal queries issued during BACKUP/RESTORE operation. SHOW PROCESSLIST command is modified to display 'query_to_display' whenever it is set. @ mysql-test/suite/backup/r/backup_show_processlist.result BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Result file for BUG#49956 @ mysql-test/suite/backup/t/backup_show_processlist.test BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Testcase file for BUG#49956 @ sql/si_objects.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST thd->query_to_display is set to the High Level Query in Si_session_context::reset_si_ctx() and is set to NULL in Si_session_context::restore_si_ctx() @ sql/sql_class.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Intialize the newly introduced member 'query_to_display' to NULL @ sql/sql_class.h BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST new member 'query_to_display' is added to THD class @ sql/sql_prepare.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Introduce debug sync point 'after_prep_exec_server_code' in Prepared_statement::execute_server_runnable() @ sql/sql_show.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Fix mysqld_list_processes() to use thd->query_to_display, whenever it is set
[3 Feb 2010 16:34]
Chuck Bell
Approved pending changes. Please ask runtime team to comment on changes to server code. I am concerned when we change server code and do not notify them or allow them to comment.
[4 Feb 2010 15:26]
Ingo Strüwing
Approved pending changes. Please see email for details.
[10 Feb 2010 7:05]
Bugs System
A patch for this bug has been committed. After review, it may be pushed to the relevant source trees for release in the next version. You can access the patch from: http://lists.mysql.com/commits/99781 3086 Satya B 2010-02-10 BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST BACKUP/RESTORE command internally calls sql queries to do BACKUP/RESTORE operation which are visible via SHOW PROCESSLIST command. A new member 'query_to_display' is introduced in the THD object. This variable is set to a query name which is different from the query executing. This is useful in scenarios like BACKUP/RESTORE, where we want the original High Level Operation/Query to be displayed in the SHOW PROCESSLIST output instead of the internal queries issued during BACKUP/RESTORE operation. SHOW PROCESSLIST command is modified to display 'query_to_display' whenever it is set. @ mysql-test/suite/backup/r/backup_show_processlist.result BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Result file for BUG#49956 @ mysql-test/suite/backup/t/backup_show_processlist.test BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Testcase file for BUG#49956 @ sql/backup/kernel.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST set_query_to_display() is called in Backup_restore_ctx::prepare() and reset_query_to_display() is called in Backup_restore_ctx::close() @ sql/si_objects.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST New methods set_query_to_display(..) and reset_query_to_display(..) introduced @ sql/si_objects.h BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST New methods set_query_to_display(..) and reset_query_to_display(..) declared. @ sql/sql_class.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Intialise the newly introduced member 'query_to_display' to NULL @ sql/sql_class.h BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST new member 'query_to_display' is added to THD class @ sql/sql_prepare.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Introduce debug sync point 'after_prep_exec_server_code' in Prepared_statement::execute_server_runnable() @ sql/sql_show.cc BUG#49956 - Individual queries executed by BACKUP/RESTORE are visible in the PROCESSLIST Fix mysqld_list_processes() and fill_schema_processlist() to use thd->query_to_display, whenever it is set
[10 Feb 2010 9:43]
Konstantin Osipov
Note, that CALL p1() behaves in the same way, and it had been considered acceptable at the time. This is a CHECKED bug and the architecture risk to fix is too high. Suggestion is to set to 'Won't fix'.
[11 Feb 2010 5:19]
Satya B
See Kostja's comment and Davi's Comment in commits@lists.mysql.com: Has any user actually complained? We shouldn't do changes by worrying in advance, if users see this as something undesirable, they will complain.
