← Back to team overview

maria-developers team mailing list archive

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