[MariaDB developers] Re: [MariaDB commits] [PATCH] MDEV-33856 New definition for Seconds_Behind_Master

Hi Monty, Here is my review of the MDEV-33856 patch:

commit cc516f4d9913d732065c7abef983df42e5a8bab3 (origin/bb-11.6-MDEV-33856-seconds_behind_master) Author: Monty Date: Tue May 14 23:47:59 2024 +0300

MDEV-33856 New definition for Seconds_Behind_Master

If I understand the patch correctly, in introduces a new `Master_slave_time_diff` value as an alternative to the traditional Seconds_behind_master, with a clearer semantics. And does not change how Seconds_behind_master works. I think this is fine, and can help to preserve backwards compatibility. Just maybe mention this in the commit message, and/or change the bug title to "Alternative definition for Seconds_Behind_Master".

diff --git a/mysql-test/suite/perfschema/t/relaylog.test b/mysql-test/suite/perfschema/t/relaylog.test index 12fc96a8b27..16f72efae98 100644 --- a/mysql-test/suite/perfschema/t/relaylog.test +++ b/mysql-test/suite/perfschema/t/relaylog.test @@ -43,7 +43,7 @@ select if (sum_number_of_bytes_read > 0, "MANY", "NONE") as SUM_NUMBER_OF_BYTES_READ, if (sum_number_of_bytes_write > 0, "MANY", "NONE") as SUM_NUMBER_OF_BYTES_WRITE from performance_schema.file_summary_by_instance - where file_name like "%master-%" order by file_name; + where file_name like "%master-%" and file_name not like "%sql/share%" order by file_name;

select * from performance_schema.file_summary_by_instance where file_name like "%slave-%" order by file_name; @@ -96,7 +96,7 @@ sync_slave_with_master; -- echo "============ Performance schema on slave ============"

select * from performance_schema.file_summary_by_instance - where file_name like "%master-%" order by file_name; + where file_name like "%master-%" and file_name not like "%sql/share%" order by file_name;

select substring(file_name, locate("slave-", file_name)) as FILE_NAME,

What is the reason for these changes (adding match on "%sql/share%" ? I don't understand the relation to the subject of the patch.

diff --git a/mysql-test/suite/rpl/t/master_last_event_time.inc b/mysql-test/suite/rpl/t/master_last_event_time.inc new file mode 100644 index 00000000000..0790d557a7b --- /dev/null +++ b/mysql-test/suite/rpl/t/master_last_event_time.inc

+--connection server_3 +--sleep 1 +--source include/start_slave.inc +--source include/sync_with_master_gtid.inc

What is the purpose of --sleep 1 here? Usually it's wrong to have sleeps in the tests. Sometimes it is correct, but then there should be a comment explaining why a sleep is necessary (and sufficient) here. This sleep looks wrong, since there's a proper wait immediately after for the slave to sync up.

diff --git a/mysql-test/suite/rpl/t/master_last_event_time_stmt.test b/mysql-test/suite/rpl/t/master_last_event_time_stmt.test new file mode 100644 index 00000000000..fe0f16a3db3 --- /dev/null +++ b/mysql-test/suite/rpl/t/master_last_event_time_stmt.test @@ -0,0 +1,84 @@ +# +# Statement specific tests for master_last_event_time +# +--source include/have_binlog_format_statement.inc

+# Slave will replicate the above with a row event which will be very fast +# compared to the master event.

I don't understand this comment. Why will the slave replicate using a row event, when the test case sets binlog_format=statement?

diff --git a/sql/log.cc b/sql/log.cc index 1cc0fa77f08..63d9c756911 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -1898,10 +1898,20 @@ static inline int binlog_commit_flush_xid_caches(THD *thd, binlog_cache_mngr *cache_mngr, bool all, my_xid xid)

Xid_log_event end_evt(thd, xid, TRUE); - return (binlog_flush_cache(thd, cache_mngr, &end_evt, all, TRUE, TRUE)); + if (!thd->slave_thread && ! thd->user_time.val) + { + /* + Ensure that on the master the event time is the time of commit, + not the start of statement time. + */ + my_hrtime_t hrtime= my_hrtime(); + end_evt.when= hrtime_to_my_time(hrtime); + } + DBUG_RETURN(binlog_flush_cache(thd, cache_mngr, &end_evt, all, TRUE, TRUE));

Ok, so correct me if I'm wrong, but I think the purpose here is: You want to have the time when the transaction ended (in case of long-running query). But for auto-committed query, there is no explicit COMMIT query, so the thd->start_time is the start of the transaction. So here you ensure that the XID_EVENT will have the time at start of commit in either case. If this is correct, probably could use a comment explaining this. Some comments: 1. It is better to check for thd->rgi_slave being non-NULL than for thd->slave_thread. The thd->rgi_slave is associated with the replication of some event or transaction. The thd->slave_thread just identifies the thread/connection. (This is mostly style/code clarity, as in current code the two values would track each other.) 2. Why the condition on thd->user_time.val? What is the situation where we are not replicating an event, but user_time is set and we do not want to put the current time in the XID_EVENT? 3. This handles an XID end event, which is for InnoDB transactions. But MyISAM/Aria use a different end event, a COMMIT query, and there are are few other cases as well. Don't you want consistently to have the end of the query as the time in all end events? Then this code should probably instead be in binlog_flush_cache() or perhaps write_transaction_to_binlog()? 4. Even given (3), there are still cases (eg. DDL) where there is no end event, and thus there is no event containing the time for the end of the operation on the master. Won't this cause some inconsistency in how the slave determines and displays its timings with this patch? If not, why not?

for (; has_xid && !entry.need_unlog && ha_info; ha_info= ha_info->next()) { if (ha_info->is_started() && ha_info->ht() != binlog_hton && !ha_info->ht()->commit_checkpoint_request) + { entry.need_unlog= true; + break; + } }

Agree, this code always irritated me ;-) You could also move the condition (!entry.need_unlog && ha_info) out of the loop in an outer if () to not have to check it on every loop iteration (just an observation, entirely up to you, it's not something your patch introduced).

diff --git a/sql/log_event.cc b/sql/log_event.cc index 3802f76efe0..706a4903eb0 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc

@@ -1104,10 +1116,12 @@ Log_event* Log_event::read_log_event(const uchar *buf, uint event_len, switch(event_type) { case QUERY_EVENT: ev= new Query_log_event(buf, event_len, fdle, QUERY_EVENT); + set_orig_exec_time_in_thd(((Query_log_event*) ev)->exec_time); break; case QUERY_COMPRESSED_EVENT: ev= new Query_compressed_log_event(buf, event_len, fdle, - QUERY_COMPRESSED_EVENT); + QUERY_COMPRESSED_EVENT); + set_orig_exec_time_in_thd(((Query_compressed_log_event*) ev)->exec_time);

@@ -964,6 +964,18 @@ Log_event* Log_event::read_log_event(IO_CACHE* file, DBUG_RETURN(res); }

+/* + Update thd->orig_exec_time +*/ + +inline void set_orig_exec_time_in_thd(my_time_t exec_time) +{ +#if !defined(MYSQL_CLIENT) && defined(HAVE_REPLICATION) + THD *thd= current_thd; + if (likely(thd)) + thd->orig_exec_time= exec_time; +#endif +}

Using current_thd doesn't seem right here, and in fact it's not, as seen by this part of the patch where thd->orig_exec_time has to be set again for parallel replication:

diff --git a/sql/rpl_parallel.cc b/sql/rpl_parallel.cc index 51ca3b183ec..d279761767a 100644 --- a/sql/rpl_parallel.cc +++ b/sql/rpl_parallel.cc @@ -60,7 +60,10 @@ rpt_handle_event(rpl_parallel_thread::queued_event *qev, rgi->future_event_relay_log_pos= qev->future_event_relay_log_pos; strcpy(rgi->future_event_master_log_name, qev->future_event_master_log_name); if (event_can_update_last_master_timestamp(ev)) + { rgi->last_master_timestamp= ev->when + ev->exec_time; + thd->orig_exec_time= ev->exec_time; + }

So let's not set thd->orig_exec_time from Log_event::read_log_event(), it's redundant (for parallel replication), and logically setting it should be done when applying the event, not when reading the event. Instead, set the thd->orig_exec_time in exec_relay_log_event(), so we retain similarity with how replication is done in the parallel and non-parallel case. There is already a similar if (event_can_update_last_master_timestamp(ev)) in exec_relay_log_event(). (Also see comments below about moving this from THD to rpl_group_info to not increase THD just for this very specific case).

+ +/* + Get the time when the event had been executed on the master. + This works for both query events and load data events. +*/ + +#if Q_EXEC_TIME_OFFSET != L_EXEC_TIME_OFFSET +#error "Q_EXEC_TIME_OFFSET is not same as L_EXEC_TIME_OFFSET" +#endif + +time_t query_event_get_time(const uchar *buf, + const Format_description_log_event + *description_event) +{ + time_t when= uint4korr(buf); + buf+= description_event->common_header_len; + return when + uint4korr(buf + Q_EXEC_TIME_OFFSET);

Suggestion: Add an assert here: DBUG_ASSERT(LOG_EVENT_IS_QUERY(buf[EVENT_TYPE_OFFSET]) || LOG_EVENT_IS_LOAD_DATA(buf[EVENT_TYPE_OFFSET])); just to avoid someone mistakenly adding code later to call this for a wrong event type.

diff --git a/sql/sql_class.h b/sql/sql_class.h index 2d671139a6c..05c9c4e8012 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -3168,6 +3168,7 @@ class THD: public THD_count, /* this must be first */ ulonglong start_utime, utime_after_lock, utime_after_query; /* This can be used by handlers to send signals to the SQL level */ ulonglong replication_flags; + my_time_t orig_exec_time; // Exec time for last read binlog event

@@ -1348,8 +1346,14 @@ Query_log_event::Query_log_event(THD* thd_arg, const char* query_arg, memset(&host, 0, sizeof(host)); error_code= errcode;

- end_time= my_time(0); - exec_time = (ulong) (end_time - thd_arg->start_time); + /* + For slave threads, remember the original master exec time. + This is needed to be able to calculate the master commit time. + */ + exec_time= ((thd->slave_thread) ? + thd->orig_exec_time : + (my_time(0) - thd_arg->start_time)); +

I think we can here avoid increasing the THD size, which is sad for a special case like this. Instead put the orig_exec_time into THD::rgi_slave, extending the struct rpl_group_info. Then the assignment above will be to rgi->orig_exec_time instead of thd->orig_exec_time, and the check here will be for thd->rgi_slave instead of thd->slave_thread. The rgi is the appropriate place for orig_exec_time, as it is a property of the transaction/event group being replicated. @@ -3171,146 +2856,170 @@ static const LEX_CSTRING msg_ignored= { STRING_WITH_LEN("Ignored") }; #endif

-static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full, - String *gtid_pos) +inline void store_string_or_null(Field **field, const char *str) +{

- mysql_mutex_unlock(&mi->run_lock); +void store_master_info(THD *thd, Master_info *mi, TABLE *table,

- protocol->store_string_or_null(mi->host, &my_charset_bin); - protocol->store_string_or_null(mi->user, &my_charset_bin); - protocol->store((uint32) mi->port); - protocol->store((uint32) mi->connect_retry); - protocol->store(mi->master_log_name, strlen(mi->master_log_name), + store_string_or_null(field++, mi->host); + store_string_or_null(field++, mi->user); + (*field++)->store((uint32) mi->port); + (*field++)->store((uint32) mi->connect_retry); + (*field++)->store(mi->master_log_name, strlen(mi->master_log_name),

So this patch refactors the code for SHOW SLAVE STATUS to use a shared code path with information_schema tables? That sounds like a good change. But for the future, please do such refactoring as a separate patch, you can see my patch series of pre-computing binlog checksums (MDEV-31273) for an example. Doing it together makes it very hard to review the actual code changes and see what is refactoring and what is new logic for master_slave_time_diff.

+ if (unlikely(!rli->slave_timestamp) && Log_event::is_group_event(typ)) + { + /* + First event for this slave. Assume that all the slave was up to date + with the master just before the current event. + */ + rli->slave_timestamp= (time_t) ev->when + (time_t) ev->exec_time-1;

I think the comment is meant to explain why there is the "-1" / minus-one in this expression, but it's not really clear exactly what is meant, so perhaps elaborate it a bit. Does it mean that master_slave_time_diff will start out as "1 second" just after the slave restarts? One way or the other, I do not have a strong opinion. But I want to give a general remark, from my experience with the troubles over the years with Seconds_Behind_Master. The problem with Seconds_Behind_Master was always that it didn't quite do what someone expected in some particular case, and then a new special case was added to try to accomodate. And after a number of iterations of this, we ended up with a semantics for Seconds_Behind_Master that no-one _really_ understands, and which still doesn't quite always do what people expect (which is in any case impossible if different people have different expectations). This "-1" here is clearly on the same road towards adding special cases. So my strong advice would be that, going forward, be _extremely_ conservative about modifying the semantics of master_slave_time_diff. The one good thing about the new status is that it has a (hopefully) clear semantics that can be documented (now including this "-1") and completely understood by users. Let's stick to that no matter who comes and wants just another small tweak, unless such tweaks actually make the semantics and documentation _simpler_.

+ /* + replay_log.description_event_for_exec can be null if the slave thread + is getting killed + */ + if (LOG_EVENT_IS_QUERY((Log_event_type) buf[EVENT_TYPE_OFFSET]) || + LOG_EVENT_IS_LOAD_DATA((Log_event_type) buf[EVENT_TYPE_OFFSET])) + { + time_t exec_time= query_event_get_time(buf, rli->relay_log. + description_event_for_queue); + set_if_bigger(rli->newest_master_timestamp, exec_time); + }

This confused me, because in Query_log_event, the exec_time is the duration of the query (a time interval), not an absolute time. So please use the name "end_time" for the variable instead of "exec_time", and consider renaming query_event_get_time() to query_event_get_end_time().

+static int make_slave_status_old_format(THD *thd, ST_SCHEMA_TABLE *schema_table) +{ + ST_FIELD_INFO *field_info= schema_table->fields_info; + Name_resolution_context *context= &thd->lex->first_select_lex()->context; + DBUG_ASSERT(thd->lex->sql_command == SQLCOM_SHOW_SLAVE_STAT); + bool all_slaves= thd->lex->mi.show_all_slaves; + ulonglong used_fields= ~0ULL; + + if (!all_slaves) + { + /* Remove 2 first fields and all fields above and including field 55 */ + used_fields&= ~((1ULL << 0) | (1ULL << 1)); + used_fields&= ((1ULL << 56)-1);

Should there be some constant used for the magic numbers 55/56? And/or an assertion that this value is correct? Also, is the intention here that we will from here on never add more fields to legacy SHOW SLAVE STATUS? If so, there should probably be a comment about this; also see the test case mysql-test/suite/rpl/t/rpl_show_slave_status.test which has comments that might need updating. - Kristian