maria-developers team mailing list archive
-
maria-developers team
-
Mailing list archive
-
Message #11881
Re: [Commits] 8b545d3d414: MDEV-7409 On RBR, extend the PROCESSLIST info to include at least the name of the recently used table
Hi Andrei!
On Fri, Jun 14, 2019 at 2:04 AM <andrei.elkin@xxxxxxxxxx> 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
References
