Hi Andrei! On Fri, Jun 14, 2019 at 2:04 AM <andrei.elkin@pp.inet.fi> wrote:

Sachin, salve.

...

revision-id: 8b545d3d41416772203cb98f06243873a4f0d8f7 (mariadb-10.4.5-24-g8b545d3d414) parent(s): e35676f5557d68c7b51ba47aa73dcdf72eafa436 author: Sachin committer: Sachin timestamp: 2019-05-31 12:02:37 +0530 message:

MDEV-7409 On RBR, extend the PROCESSLIST info to include at least the name of the recently used table

When RBR is used, add the db name to db Field and table name to Status Field of the "SHOW FULL PROCESSLIST" command for SQL thread.

So the patch deals with the State column of the Show-Processlist command. I would endorse an output like the following:

MariaDB [test]> show processlist; +----+-------------+-----------------+------+-----------+------+--------------------------------------------------+-----------------------------------------------+----------+ | Id | User | Host | db | Command | Time | State | Info | Progress | +----+-------------+-----------------+------+-----------+------+--------------------------------------------------+-----------------------------------------------+----------+ ... | 13 | system user | | test | Slave_SQL | 101 | Write_rows_log_event::write_row(-1) on table `t` | GTID 0-1-17: insert into `t` values (46),(47) | 0.000 | +----+-------------+-----------------+------+-----------+------+--------------------------------------------------+-----------------------------------------------+----------+

notice the ANSI quotes which could be more than for pretty printing considering legal names like `[:space:]+t`. Alas the text from Annotate event does not quote the table name so the actual Info is not that perfect *also* because the actual one does not display GTID..

Annotated for Status Remaining can be done in 10.5

Could we make that - the Annotate event quoted names and GTID into Progress-list Info in a separate patch for 10.5? And also to turn Progress column meaningful. It's always zero, but could print for the user the executed fraction of the whole event (sure we need to know in the Rows_log_event metadata how much rows the statement changed on the master; on slave we would just count the executed ones).

...

--- mysql-test/suite/rpl/r/rpl_rbr_monitor.result | 57 +++++++++++++++++ mysql-test/suite/rpl/t/rpl_rbr_monitor.test | 86 +++++++++++++++++++++++++ sql/debug_sync.cc | 3 +- sql/log_event.cc | 90 +++++++++++++++++++++------ 4 files changed, 215 insertions(+), 21 deletions(-)

To the test, you could really do it simpler without

...

--- /dev/null +++ b/mysql-test/suite/rpl/t/rpl_rbr_monitor.test @@ -0,0 +1,86 @@ +--source include/have_innodb.inc

...

+--source include/have_debug.inc

any debug.

Just start a slave local trx to block Rows_log_event applying at some (see $param) point:

--connection slave begin; --eval select a from t where a > $param for update;

...

+--source include/have_binlog_format_row.inc +--source include/master-slave.inc +--enable_connect_log + +--connection master +create table t1(a int primary key); +--save_master_pos + +--connection slave +--sync_with_master +SET GLOBAL debug_dbug="+d,should_wait_for_mdev7409"; +select * from t1; + +--connection master +insert into t1(a) values(1); +--save_master_pos + +--echo #monitoring write rows +--connection slave + +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Write_rows_log_event::write_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db , state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Write_rows_log_event::write_row(%) on table t1"; +set debug_sync="now signal cont"; +--sync_with_master + +--echo #monitoring update rows +--connection master +update t1 set a = a + 4194304 ; + +--connection slave +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::find_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db, state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::find_row(%) on table t1"; +set debug_sync="now signal cont1"; + +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::unpack_current_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db, state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::unpack_current_row(%) on table t1"; +set debug_sync="now signal cont2"; + +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::ha_update_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db, state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Update_rows_log_event::ha_update_row(%) on table t1"; +set debug_sync="now signal cont3"; +set debug_sync="RESET"; +--sync_with_master + +--echo #monitoring delete rows +--connection master +delete from t1 where a>1; + +--connection slave +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Delete_rows_log_event::find_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db , state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Delete_rows_log_event::find_row(%) on table t1"; +set debug_sync="now signal cont1"; + +let $wait_condition= SELECT COUNT(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Delete_rows_log_event::ha_delete_row(%) on table t1"; +--source include/wait_condition.inc +SELECT db, state FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE DB = 'test' AND STATE LIKE "Delete_rows_log_event::ha_delete_row(%) on table t1"; +set debug_sync="now signal cont2"; +set debug_sync="RESET"; +--sync_with_master +SET GLOBAL debug_dbug=""; + +#CleanUp +--connection master +drop table t1; +--sync_slave_with_master + +--source include/rpl_end.inc diff --git a/sql/debug_sync.cc b/sql/debug_sync.cc

That would make all the simulation and synchronization in the source code incl the following changes unnecessary:

For the time I am going with debug_sync

...

index bf721bddb85..7ca8d8a8ecb 100644 --- a/sql/debug_sync.cc +++ b/sql/debug_sync.cc @@ -1360,7 +1360,8 @@ static void debug_sync_execute(THD *thd, st_debug_sync_action *action) Do this before emitting the signal, so other threads can see it if they awake before we enter_cond() below. */ - if (action->wait_for.length()) + if (action->wait_for.length() && + DBUG_EVALUATE_IF("should_wait_for_mdev7409", 0, 1)) { st_debug_sync_control *ds_control= thd->debug_sync_control; strxnmov(ds_control->ds_proc_info, sizeof(ds_control->ds_proc_info)-1,

...

diff --git a/sql/log_event.cc b/sql/log_event.cc index f25ebd56792..8c944a6e282 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -54,6 +54,7 @@ #include "rpl_constants.h" #include "sql_digest.h" #include "zlib.h" +#include "debug_sync.h"

#define my_b_write_string(A, B) my_b_write((A), (uchar*)(B), (uint) (sizeof(B) - 1))

@@ -13693,19 +13694,29 @@ Write_rows_log_event::do_exec_row(rpl_group_info *rgi) { DBUG_ASSERT(m_table != NULL); const char *tmp= thd->get_proc_info(); - const char *message= "Write_rows_log_event::write_row()"; + LEX_CSTRING *tmp_db= &thd->db; + char *message, msg[128]; + my_snprintf(msg, sizeof(msg),"Write_rows_log_event::write_row() on table %s", + m_table->s->table_name.str); + thd->set_db(&m_table->s->db); + message= msg; int error;

#ifdef WSREP_PROC_INFO my_snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Write_rows_log_event::write_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Write_rows_log_event::write_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str); message= thd->wsrep_info; #endif /* WSREP_PROC_INFO */

thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont")); + };); error= write_row(rgi, slave_exec_mode == SLAVE_EXEC_MODE_IDEMPOTENT); thd_proc_info(thd, tmp); + thd->set_db(tmp_db);

if (unlikely(error) && unlikely(!thd->is_error())) { @@ -14368,32 +14379,47 @@ int Delete_rows_log_event::do_exec_row(rpl_group_info *rgi) { int error; const char *tmp= thd->get_proc_info(); - const char *message= "Delete_rows_log_event::find_row()"; + LEX_CSTRING *tmp_db= &thd->db; + char *message, msg[128]; + my_snprintf(msg, sizeof(msg),"Delete_rows_log_event::find_row() on table %s", + m_table->s->table_name.str); + thd->set_db(&m_table->s->db); + message= msg; const bool invoke_triggers= slave_run_triggers_for_rbr && !master_had_triggers && m_table->triggers; DBUG_ASSERT(m_table != NULL);

#ifdef WSREP_PROC_INFO my_snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Delete_rows_log_event::find_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Delete_rows_log_event::find_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str) ; message= thd->wsrep_info; #endif /* WSREP_PROC_INFO */

thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont1")); + };); if (likely(!(error= find_row(rgi)))) { /* Delete the record found, located in record[0] */ - message= "Delete_rows_log_event::ha_delete_row()"; + my_snprintf(msg, sizeof(msg),"Delete_rows_log_event::ha_delete_row() on table %s", + m_table->s->table_name.str); + message= msg; #ifdef WSREP_PROC_INFO snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Delete_rows_log_event::ha_delete_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Delete_rows_log_event::ha_delete_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str) ; message= thd->wsrep_info; #endif thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont2")); + };);

if (invoke_triggers && unlikely(process_triggers(TRG_EVENT_DELETE, TRG_ACTION_BEFORE, FALSE))) @@ -14422,6 +14448,7 @@ int Delete_rows_log_event::do_exec_row(rpl_group_info *rgi) m_table->file->ha_index_or_rnd_end(); } thd_proc_info(thd, tmp); + thd->set_db(tmp_db); return error; }

@@ -14590,17 +14617,27 @@ Update_rows_log_event::do_exec_row(rpl_group_info *rgi) const bool invoke_triggers= slave_run_triggers_for_rbr && !master_had_triggers && m_table->triggers; const char *tmp= thd->get_proc_info(); - const char *message= "Update_rows_log_event::find_row()"; + LEX_CSTRING *tmp_db= &thd->db; + char *message, msg[128]; DBUG_ASSERT(m_table != NULL); + my_snprintf(msg, sizeof(msg),"Update_rows_log_event::find_row() on table %s", + m_table->s->table_name.str); + thd->set_db(&m_table->s->db); + message= msg;

#ifdef WSREP_PROC_INFO my_snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Update_rows_log_event::find_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Update_rows_log_event::find_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str) ; message= thd->wsrep_info; #endif /* WSREP_PROC_INFO */

thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont1")); + };); + int error= find_row(rgi); if (unlikely(error)) { @@ -14611,6 +14648,7 @@ Update_rows_log_event::do_exec_row(rpl_group_info *rgi) if ((m_curr_row= m_curr_row_end)) unpack_current_row(rgi, &m_cols_ai); thd_proc_info(thd, tmp); + thd->db= *tmp_db; return error; }

@@ -14628,16 +14666,22 @@ Update_rows_log_event::do_exec_row(rpl_group_info *rgi) store_record(m_table,record[1]);

m_curr_row= m_curr_row_end; - message= "Update_rows_log_event::unpack_current_row()"; + my_snprintf(msg, sizeof(msg),"Update_rows_log_event::unpack_current_row() on table %s", + m_table->s->table_name.str); + message= msg; #ifdef WSREP_PROC_INFO my_snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Update_rows_log_event::unpack_current_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Update_rows_log_event::unpack_current_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str) ; message= thd->wsrep_info; #endif /* WSREP_PROC_INFO */

/* this also updates m_curr_row_end */ thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont2")); + };); if (unlikely((error= unpack_current_row(rgi, &m_cols_ai)))) goto err;

@@ -14655,15 +14699,21 @@ Update_rows_log_event::do_exec_row(rpl_group_info *rgi) DBUG_DUMP("new values", m_table->record[0], m_table->s->reclength); #endif

- message= "Update_rows_log_event::ha_update_row()"; + my_snprintf(msg, sizeof(msg),"Update_rows_log_event::ha_update_row() on table %s", + m_table->s->table_name.str); + message= msg; #ifdef WSREP_PROC_INFO my_snprintf(thd->wsrep_info, sizeof(thd->wsrep_info) - 1, - "Update_rows_log_event::ha_update_row(%lld)", - (long long) wsrep_thd_trx_seqno(thd)); + "Update_rows_log_event::ha_update_row(%lld) on table %s", + (long long) wsrep_thd_trx_seqno(thd), m_table->s->table_name.str) ; message= thd->wsrep_info; #endif /* WSREP_PROC_INFO */

thd_proc_info(thd, message); + DBUG_EXECUTE_IF("should_wait_for_mdev7409",{ + debug_sync_set_action + (thd, STRING_WITH_LEN("now WAIT_FOR cont3")); + };); if (invoke_triggers && unlikely(process_triggers(TRG_EVENT_UPDATE, TRG_ACTION_BEFORE, TRUE))) { @@ -14693,9 +14743,9 @@ Update_rows_log_event::do_exec_row(rpl_group_info *rgi) unlikely(process_triggers(TRG_EVENT_UPDATE, TRG_ACTION_AFTER, TRUE))) error= HA_ERR_GENERIC; // in case if error is not set yet

- thd_proc_info(thd, tmp); - err: + thd_proc_info(thd, tmp); + thd->set_db(tmp_db); m_table->file->ha_index_or_rnd_end(); return error; }

Cheers,

Andrei

http://lists.askmonty.org/pipermail/commits/2019-June/013860.html -- Regards Sachin Setiya Software Engineer at MariaDB