MDEV-18432 RBR logging of system versioned tables

tempesta-tech / mariadb

MariaDB System Versioning

GNU General Public License v2.0

6 stars 5 forks source link

MDEV-18432 RBR logging of system versioned tables #578

Closed midenok closed 4 years ago

midenok commented 5 years ago

Preface (serg)

I realized that the whole RBR logging of system versioned tables is wrong.

For an update you log update_row event and write_row event separately and execute them separately. It allows trivially to manipulate the history. See a test case attached.

To fix this, the slave should ignore all events that modify the history. And generate them locally. Say, an update on the master generates update_row and write_row events. The slave executes update_row event which updates a current row and this also should generate the historical row. Then the slave ignores write_row event.

Of course, as an optimization, the master should not generate historical write_row events, but as my test case shows, they can be forged, so the slave should ignore them anyway, if they happen to come.

I've created a new https://jira.mariadb.org/browse/MDEV-18432 for that, let's not have it tied to MDEV-16370.

Description (serg)

For example, UPDATE statement. It currently writes Update_rows_event and Write_row_event for every updated row. It should write only Update_rows_event, and the slave, when executing it, should create the historical row internally. Because existing binlogs already have Update_rows_event and Write_row_event, the slave should ignore all events that modify the history.

TODO

[x] Remove linear scan for (non-)history records;
[x] Remove check_has_vers_fields();
[x] TABLE::delete_row() should be moved to ha_delete_row();
[x] Versioned UPDATE at ha_update_row();
[ ] ~Log_event protocol for passing timestamp fractions;~
[ ] RBR versioning on slave

Refactoring 1: use SQL_SELECT instead of linear iteration to filter out historical records

Multi-update case

create or replace table t1 (x int) with system versioning;
create or replace table t2 like t1;

insert into t1 values (1);
insert into t2 values (2);
set @t0= now(6);
update t1, t2 set t1.x=11, t2.x=22;

Fix

@@ -339,6 +340,11 @@ int mysql_update(THD *thd,
   if (open_tables(thd, &table_list, &table_count, 0))
     DBUG_RETURN(1);

+  if (select_lex->vers_setup_conds(thd, table_list))
+    DBUG_RETURN(1);
+
+  COND *conds= select_lex->where;
+
   /* Prepare views so they are handled correctly */
   if (mysql_handle_derived(thd->lex, DT_INIT))
     DBUG_RETURN(1);
@@ -867,11 +873,6 @@ int mysql_update(THD *thd,
   THD_STAGE_INFO(thd, stage_updating);
   while (!(error=info.read_record()) && !thd->killed)
   {
-    if (table->versioned() && !table->vers_end_field()->is_max())
-    {
-      continue;
-    }
-
     explain->tracker.on_record_read();
     thd->inc_examined_row_count(1);
     if (!select || select->skip_record(thd) > 0)

Bug 1: `bitmap_is_set()` assertion on partitioned

Reproduce

    create or replace table t (a int)
    with system versioning
    partition by system_time limit 1 (
        partition p0 history,
        partition pn current);
    insert into t values (1);
    update t set a= 2;

Result

#3  0x00007ffff730b142 in __GI___assert_fail (assertion=0x1539363 "bitmap_is_set(&(m_part_info->read_partitions), part_id)", file=0x15392e6 "/home/midenok/src/mariadb/trunk/src/sql/ha_partition.h", line=1500, function=0x153931d "ha_rows ha_partition::part_records(void *)") at assert.c:101
#4  0x0000000000950dcf in ha_partition::part_records (this=0x7fff840ca480, _part_elem=0x7fff840cc1d0) at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.h:1500
#5  0x0000000000949845 in partition_info::vers_set_hist_part (this=0x7fff840cc2b0, thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/partition_info.cc:842
#6  0x00000000014157bc in ha_partition::external_lock (this=0x7fff840ca480, thd=0x7fff84000cf8, lock_type=1) at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:3955
#7  0x0000000000b45624 in handler::ha_external_lock (this=0x7fff840ca480, thd=0x7fff84000cf8, lock_type=1) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6206
#8  0x0000000000ca0741 in lock_external (thd=0x7fff84000cf8, tables=0x7fff840159e0, count=1) at /home/midenok/src/mariadb/trunk/src/sql/lock.cc:397
#9  0x0000000000ca02a3 in mysql_lock_tables (thd=0x7fff84000cf8, sql_lock=0x7fff840159c0, flags=0) at /home/midenok/src/mariadb/trunk/src/sql/lock.cc:342
#10 0x0000000000c9f4b2 in mysql_lock_tables (thd=0x7fff84000cf8, tables=0x7fff840159b8, count=1, flags=0) at /home/midenok/src/mariadb/trunk/src/sql/lock.cc:305
#11 0x00000000007200e7 in lock_tables (thd=0x7fff84000cf8, tables=0x7fff84014fe0, count=1, flags=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:5398
#12 0x00000000008f5ec8 in mysql_update (thd=0x7fff84000cf8, table_list=0x7fff84014fe0, select_lex=0x7fff84005338, values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7ffff45dffe8, updated_return=0x7ffff45dffe0) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:363
#13 0x00000000007d2ec9 in mysql_execute_command (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4577
#14 0x00000000007cb0f0 in mysql_parse (thd=0x7fff84000cf8, rawbuf=0x7fff84014f10 "update t set a= 2", length=17, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8113

1497        for (; part_id < part_id_end; ++part_id)
1498        {
1499          handler *file= m_file[part_id];
1500          DBUG_ASSERT(bitmap_is_set(&(m_part_info->read_partitions), part_id));
1501          file->info(HA_STATUS_VARIABLE | HA_STATUS_NO_LOCK | HA_STATUS_OPEN);
1502          part_recs+= file->stats.records;
1503        }

(gdb) p part_id
$19 = 0
(gdb) x m_part_info->read_partitions.bitmap
0x7fff780cb618: 0x00000002
(gdb) p part_id_end
$20 = 1

Good

(gdb) x/bx m_part_info->read_partitions.bitmap
0x61d0001706b8: 0xff

midenok commented 5 years ago

Bad: `read_partitions.bitmap` overwritten

#0  __memset_sse2_unaligned_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:265
#1  0x0000000000947b01 in partition_info::prune_partition_bitmaps (this=0x7fff84042440, partition_names=0x7fff84015970) at /home/midenok/src/mariadb/trunk/src/sql/partition_info.cc:267
#2  0x0000000000947e53 in partition_info::set_partition_bitmaps (this=0x7fff84042440, partition_names=0x7fff84015970) at /home/midenok/src/mariadb/trunk/src/sql/partition_info.cc:312
#3  0x0000000001425314 in ha_partition::change_partitions_to_open (this=0x7fff84040610, partition_names=0x7fff84015970) at /home/midenok/src/mariadb/trunk/src/sql/ha_partition.cc:8454
#4  0x000000000081b163 in st_select_lex::vers_setup_conds (this=0x7fff84005338, thd=0x7fff84000cf8, tables=0x7fff84014fe0) at /home/midenok/src/mariadb/trunk/src/sql/sql_select.cc:835
#5  0x00000000008f5c88 in mysql_update (thd=0x7fff84000cf8, table_list=0x7fff84014fe0, select_lex=0x7fff84005338, values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7ffff45dffe8, updated_return=0x7ffff45dffe0) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:343
#6  0x00000000007d2ec9 in mysql_execute_command (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4577
#7  0x00000000007cb0f0 in mysql_parse (thd=0x7fff84000cf8, rawbuf=0x7fff84014f10 "update t set a= 2", length=17, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8113

Cause

Pruning to now-partition in st_select_lex::vers_setup_conds().

Fix

Avoid pruning for non-select queries.

midenok commented 5 years ago

Bug 2: DELETE HISTORY is broken

Reproduce

create or replace table t (a int)
with system versioning;
insert into t values (1), (2);
update t set a= 11 where a= 1;
set @ts1= now(6);
update t set a= 22 where a= 2;
select @ts1;
select *, row_start, row_end from t for system_time all;
delete history from t before system_time timestamp @ts1;
select * from t for system_time all;

Result

+------+
| a    |
+------+
|   11 |
|   22 |
+------+

Expected

+------+
| a    |
+------+
|   11 |
|   22 |
|    2 |
+------+

Cause

DELETE HISTORY uses vers_setup_conds() and then takes conds from table->on_expr. Now on_expr is set only for SELECT commands.

Fix

--- a/sql/sql_delete.cc
+++ b/sql/sql_delete.cc
@@ -328,8 +328,7 @@ bool mysql_delete(THD *thd, TABLE_LIST *table_list, COND *conds,
       if (select_lex->vers_setup_conds(thd, table_list))
         DBUG_RETURN(TRUE);

-      conds= table_list->on_expr;
-      table_list->on_expr= NULL;
+      conds= select_lex->where;
     }
   }

midenok commented 5 years ago

Bug 3: delete from VIEW is broken

Reproduce

create or replace table t1 (x int unsigned) with system versioning;
create or replace view vt1 as select x from t1;
delete from vt1;

Result

#0  my_error (nr=1054, MyFlags=0) at /home/midenok/src/mariadb/trunk/src/mysys/my_error.c:113
#1  0x0000000000724cee in find_field_in_tables (thd=0x7fff84000cf8, item=0x7fff84018d10, first_table=0x7fff84015008, last_table=0x0, ref=0x7fff84018f60, report_error=REPORT_ALL_ERRORS, check_privileges=true, register_tree_change=true) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:6415
#2  0x0000000000b628a0 in Item_field::fix_outer_field (this=0x7fff84018d10, thd=0x7fff84000cf8, from_field=0x7ffff45dd460, reference=0x7fff84018f60) at /home/midenok/src/mariadb/trunk/src/sql/item.cc:5524
#3  0x0000000000b63b5d in Item_field::fix_fields (this=0x7fff84018d10, thd=0x7fff84000cf8, reference=0x7fff84018f60) at /home/midenok/src/mariadb/trunk/src/sql/item.cc:5778
#4  0x00000000006985c3 in Item::fix_fields_if_needed (this=0x7fff84018d10, thd=0x7fff84000cf8, ref=0x7fff84018f60) at /home/midenok/src/mariadb/trunk/src/sql/item.h:954
#5  0x0000000000bcdee5 in Item_func::fix_fields (this=0x7fff84018ed0, thd=0x7fff84000cf8, ref=0x7ffff45de500) at /home/midenok/src/mariadb/trunk/src/sql/item_func.cc:363
#6  0x00000000006985c3 in Item::fix_fields_if_needed (this=0x7fff84018ed0, thd=0x7fff84000cf8, ref=0x7ffff45de500) at /home/midenok/src/mariadb/trunk/src/sql/item.h:954
#7  0x00000000006978a7 in Item::fix_fields_if_needed_for_scalar (this=0x7fff84018ed0, thd=0x7fff84000cf8, ref=0x7ffff45de500) at /home/midenok/src/mariadb/trunk/src/sql/item.h:958
#8  0x000000000072f585 in Item::fix_fields_if_needed_for_bool (this=0x7fff84018ed0, thd=0x7fff84000cf8, ref=0x7ffff45de500) at /home/midenok/src/mariadb/trunk/src/sql/item.h:962
#9  0x0000000000728bbc in setup_conds (thd=0x7fff84000cf8, tables=0x7fff84015008, leaves=..., conds=0x7ffff45de500) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:8281
#10 0x0000000000d34851 in mysql_prepare_delete (thd=0x7fff84000cf8, table_list=0x7fff84015008, wild_num=0, field_list=..., conds=0x7ffff45de500, delete_while_scanning=0x7ffff45de366) at /home/midenok/src/mariadb/trunk/src/sql/sql_delete.cc:945
#11 0x0000000000d3194a in mysql_delete (thd=0x7fff84000cf8, table_list=0x7fff84015008, conds=0x7fff84018ed0, order_list=0x7fff840055b8, limit=18446744073709551615, options=0, result=0x0) at /home/midenok/src/mariadb/trunk/src/sql/sql_delete.cc:336
#12 0x00000000007d4324 in mysql_execute_command (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4923
#13 0x00000000007cb0f0 in mysql_parse (thd=0x7fff84000cf8, rawbuf=0x7fff84014f40 "delete from vt1", length=15, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8120

frame 10

(gdb) p dbug_print_select(select_lex)
$12 = 0x1e51c50 <dbug_item_print_buf> "select  from dual where vt1.row_end = TIMESTAMP'2038-01-19 06:14:07.999999'"

Cause

vers_setup_conds() adds condition for VIEW.

Fix

--- a/sql/sql_select.cc
+++ b/sql/sql_select.cc
@@ -806,7 +806,7 @@ int SELECT_LEX::vers_setup_conds(THD *thd, TABLE_LIST *tables)

   for (table= tables; table; table= table->next_local)
   {
-    if (!table->table || !table->table->versioned())
+    if (!table->table || table->is_view() || !table->table->versioned())
       continue;

     vers_select_conds_t &vers_conditions= table->vers_conditions;

midenok commented 5 years ago

Remove `check_has_vers_fields()`

Use vers_write instead of additional calculation.

1. `table_list->table` assigned

#0  open_table (thd=0x7fff7c000cf8, table_list=0x7fff7c015010, ot_ctx=0x7ffff45dd9e8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:2150
#1  0x000000000071e2bb in open_and_process_table (thd=0x7fff7c000cf8, lex=0x7fff7c004b08, tables=0x7fff7c015010, counter=0x7ffff45de4a4, flags=0, prelocking_strategy=0x7ffff45ddaa8, has_prelocking_list=false, ot_ctx=0x7ffff45dd9e8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:3725
#2  0x000000000071cf5d in open_tables (thd=0x7fff7c000cf8, options=..., start=0x7ffff45de508, counter=0x7ffff45de4a4, flags=0, prelocking_strategy=0x7ffff45ddaa8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:4256
#3  0x0000000000711086 in open_tables (thd=0x7fff7c000cf8, tables=0x7ffff45de508, counter=0x7ffff45de4a4, flags=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.h:477
#4  0x00000000008f5dd8 in mysql_update (thd=0x7fff7c000cf8, table_list=0x7fff7c015010, select_lex=0x7fff7c005338, values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7ffff45dffe8, updated_return=0x7ffff45dffe0) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:340
#5  0x00000000007d2e09 in mysql_execute_command (thd=0x7fff7c000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4577
#6  0x00000000007cb030 in mysql_parse (thd=0x7fff7c000cf8, rawbuf=0x7fff7c014f40 "update t1 set a=2", length=17, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

2. TABLE inited

#0  TABLE::init (this=0x7fff7c0ac938, thd=0x7fff7c000cf8, tl=0x7fff7c015010) at /home/midenok/src/mariadb/trunk/src/sql/table.cc:4568
#1  0x000000000071a165 in open_table (thd=0x7fff7c000cf8, table_list=0x7fff7c015010, ot_ctx=0x7ffff45dd9e8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:2172
#2  0x000000000071e2bb in open_and_process_table (thd=0x7fff7c000cf8, lex=0x7fff7c004b08, tables=0x7fff7c015010, counter=0x7ffff45de4a4, flags=0, prelocking_strategy=0x7ffff45ddaa8, has_prelocking_list=false, ot_ctx=0x7ffff45dd9e8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:3725
#3  0x000000000071cf5d in open_tables (thd=0x7fff7c000cf8, options=..., start=0x7ffff45de508, counter=0x7ffff45de4a4, flags=0, prelocking_strategy=0x7ffff45ddaa8) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.cc:4256
#4  0x0000000000711086 in open_tables (thd=0x7fff7c000cf8, tables=0x7ffff45de508, counter=0x7ffff45de4a4, flags=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_base.h:477
#5  0x00000000008f5dd8 in mysql_update (thd=0x7fff7c000cf8, table_list=0x7fff7c015010, select_lex=0x7fff7c005338, values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7ffff45dffe8, updated_return=0x7ffff45dffe0) at /home/midenok/src/mariadb/trunk/src/sql/sql_update.cc:340
#6  0x00000000007d2e09 in mysql_execute_command (thd=0x7fff7c000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4577
#7  0x00000000007cb030 in mysql_parse (thd=0x7fff7c000cf8, rawbuf=0x7fff7c014f40 "update t1 set a=2", length=17, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

Moved vers_write initialization from open_table_from_share() to TABLE::init().

midenok commented 5 years ago

Bug 4: wrong trx_id after ALTER

Reproduce

create or replace table t1 (x int);
insert into t1 values (1);

alter table t1
add column s bigint unsigned as row start,
add column e bigint unsigned as row end,
add period for system_time(s, e),
add system versioning,
algorithm=copy;
select * from t1;

Result

+------+----------------+----------------------+
| x    | s              | e                    |
+------+----------------+----------------------+
|    1 | 20190227215126 | 18446744073709551615 |
+------+----------------+----------------------+

Expected

Correct trx_id value.

midenok commented 5 years ago

Info: ALTER copy assigns trx_id

1. mod_tables assigned

#0  dict_table_t::versioned_by_id (this=0x617000080e88) at /home/midenok/src/mariadb/10.4/src/storage/innobase/include/dict0mem.h:1783
#1  0x0000000001d73b08 in ha_innobase::extra (this=0x61c0000940a0, operation=HA_EXTRA_BEGIN_ALTER_COPY) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/ha_innodb.cc:15271
#2  0x0000000000ef0a87 in copy_data_between_tables (thd=0x62a0000c0208, from=0x62000004a088, to=0x62000004c088, create=..., ignore=false, order_num=0, order=0x0, copied=0x7fffd01553c0, deleted=0x7fffd01553e0, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7fffd01544b0) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:10363
#3  0x0000000000ed932b in mysql_alter_table (thd=0x62a0000c0208, new_db=0x62a0000c4910, new_name=0x62a0000c4cf8, create_info=0x7fffd01575c0, table_list=0x62b000000428, alter_info=0x7fffd01577a0, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:9856
#4  0x00000000010e5e88 in Sql_cmd_alter_table::execute (this=0x62b000000ca8, thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_alter.cc:493
#5  0x0000000000bc5c71 in mysql_execute_command (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:6330
#6  0x0000000000b9e519 in mysql_parse (thd=0x62a0000c0208, rawbuf=0x62b000000220 "alter table t1\nadd column s bigint unsigned as row start,\nadd column e bigint unsigned as row end,\nadd period for system_time(s, e),\nadd system versioning,\nalgorithm=copy", length=170, parser_state=0x7fffd015e040, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8141

    case HA_EXTRA_BEGIN_ALTER_COPY:
        m_prebuilt->table->skip_alter_undo = 1;
        if (m_prebuilt->table->is_temporary()
            || !m_prebuilt->table->versioned_by_id()) {
            break;
        }
        trx_start_if_not_started(m_prebuilt->trx, true);
        m_prebuilt->trx->mod_tables.insert(
            trx_mod_tables_t::value_type(
                const_cast<dict_table_t*>(m_prebuilt->table),
                0))
            .first->second.set_versioned(0);
        break;

2. `ins_mode` is set

#0  ha_innobase::write_row (this=0x7fff840abcc0, record=0x7fff840a9118 "\377*\002") at /home/midenok/src/mariadb/trunk/src/storage/innobase/handler/ha_innodb.cc:8037
#1  0x0000000000b46114 in handler::ha_write_row (this=0x7fff840abcc0, buf=0x7fff840a9118 "\377*\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6281
#2  0x0000000000926eb4 in TR_table::update (this=0x7ffff45da190, start_id=554, end_id=555) at /home/midenok/src/mariadb/trunk/src/sql/table.cc:8529
#3  0x0000000000b36246 in ha_commit_trans (thd=0x7fff84000cf8, all=false) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:1480
#4  0x0000000000b41556 in ha_enable_transaction (thd=0x7fff84000cf8, on=true) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:4747
#5  0x00000000008d99ac in mysql_trans_commit_alter_copy_data (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_table.cc:10181
#6  0x00000000008d925a in copy_data_between_tables (thd=0x7fff84000cf8, from=0x7fff840c82a8, to=0x7fff840cafa8, create=..., ignore=false, order_num=0, order=0x0, copied=0x7ffff45dcce0, deleted=0x7ffff45dccd8, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7ffff45dd078) at /home/midenok/src/mariadb/trunk/src/sql/sql_table.cc:10537
#7  0x00000000008d0515 in mysql_alter_table (thd=0x7fff84000cf8, new_db=0x7fff840053d8, new_name=0x7fff840057a8, create_info=0x7ffff45de350, table_list=0x7fff84015148, alter_info=0x7ffff45de298, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_table.cc:9875
#8  0x000000000097729f in Sql_cmd_alter_table::execute (this=0x7fff840159d0, thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_alter.cc:491
#9  0x00000000007d95b0 in mysql_execute_command (thd=0x7fff84000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6314
#10 0x00000000007cb030 in mysql_parse (thd=0x7fff84000cf8, rawbuf=0x7fff84014f40 "alter table t1\nadd column s bigint unsigned as row start,\nadd column e bigint unsigned as row end,\nadd period for system_time(s, e),\nadd system versioning,\nalgorithm=copy", length=170, parser_state=0x7ffff45e1640, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

8037            vers_set_fields = table->versioned_write(VERS_TRX_ID) ?
8038                    ROW_INS_VERSIONED : ROW_INS_NORMAL;
8039
8040            /* Execute insert graph that will result in actual insert. */
8041            error = row_insert_for_mysql((byte*) record, m_prebuilt, vers_set_fields);

3. TRX_ID assigned to row_start, row_end

#0  row_insert_for_mysql (mysql_rec=0x6190000b90b0 "\375\001", prebuilt=0x6210000ac988, ins_mode=ROW_INS_VERSIONED) at /home/midenok/src/mariadb/10.4/src/storage/innobase/row/row0mysql.cc:1439
#1  0x0000000001d47456 in ha_innobase::write_row (this=0x61c0000718a0, record=0x6190000b90b0 "\375\001") at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/ha_innodb.cc:8086
#2  0x0000000001616812 in handler::ha_write_row (this=0x61c0000718a0, buf=0x6190000b90b0 "\375\001") at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:6499
#3  0x0000000000ef90f1 in copy_data_between_tables (thd=0x62a0000c0208, from=0x62000003e088, to=0x620000040088, create=..., ignore=false, order_num=0, order=0x0, copied=0x7fffd034e3c0, deleted=0x7fffd034e3e0, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7fffd034d4b0) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:10428
#4  0x0000000000ee0fbb in mysql_alter_table (thd=0x62a0000c0208, new_db=0x62a0000c4918, new_name=0x62a0000c4d18, create_info=0x7fffd03505c0, table_list=0x62b000000428, alter_info=0x7fffd03507a0, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:9853
#5  0x00000000010eba78 in Sql_cmd_alter_table::execute (this=0x62b000000ca8, thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_alter.cc:493
#6  0x0000000000bccbc1 in mysql_execute_command (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:6330
#7  0x0000000000ba5469 in mysql_parse (thd=0x62a0000c0208, rawbuf=0x62b000000220 "alter table t1\nadd column s bigint unsigned as row start,\nadd column e bigint unsigned as row end,\nadd period for system_time(s, e),\nadd system versioning,\nalgorithm=copy", length=170, parser_state=0x7fffd0357040, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8141

1420            if (ins_mode != ROW_INS_NORMAL)
1421            {
1422                    ut_ad(table->vers_start != table->vers_end);
1423                    /* Return back modified fields into mysql_rec, so that
1424                       upper logic may benefit from it (f.ex. 'on duplicate key'). */
1425                    const mysql_row_templ_t* t = prebuilt->get_template_by_col(table->vers_end);
1426                    ut_ad(t);
1427                    ut_ad(t->mysql_col_len == 8);
1428
1429                    if (ins_mode == ROW_INS_HISTORICAL) {
1430                            set_tuple_col_8(node->row, table->vers_end, trx->id, node->vers_end_buf);
1431                    }
1432                    else /* ROW_INS_VERSIONED */ {
1433                            set_tuple_col_8(node->row, table->vers_end, TRX_ID_MAX, node->vers_end_buf);
1434                            int8store(&mysql_rec[t->mysql_col_offset], TRX_ID_MAX);
1435                            t = prebuilt->get_template_by_col(table->vers_start);
1436                            ut_ad(t);
1437                            ut_ad(t->mysql_col_len == 8);
1438                            set_tuple_col_8(node->row, table->vers_start, trx->id, node->vers_start_buf);
1439                            int8store(&mysql_rec[t->mysql_col_offset], trx->id);
1440                    }
1441            }

(gdb) p ins_mode
$2 = ROW_INS_VERSIONED

4. TRT updated

#0  dict_table_t::versioned_by_id (this=0x617000046108) at /home/midenok/src/mariadb/10.4/src/storage/innobase/include/dict0mem.h:1749
#1  0x0000000001d989e8 in innodb_prepare_commit_versioned (thd=0x62a0000c0208, trx_id=0x7fffd0308b90) at /home/midenok/src/mariadb/10.4/src/storage/innobase/handler/ha_innodb.cc:3615
#2  0x00000000015e1b5c in ha_commit_trans (thd=0x62a0000c0208, all=false) at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:1490
#3  0x0000000001605e53 in ha_enable_transaction (thd=0x62a0000c0208, on=true) at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:4928
#4  0x0000000000efb69d in mysql_trans_commit_alter_copy_data (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:10158
#5  0x0000000000efa083 in copy_data_between_tables (thd=0x62a0000c0208, from=0x620000039088, to=0x62000003b088, create=..., ignore=false, order_num=0, order=0x0, copied=0x7fffd030c3c0, deleted=0x7fffd030c3e0, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=0x7fffd030b4b0) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:10514
#6  0x0000000000ee0fbb in mysql_alter_table (thd=0x62a0000c0208, new_db=0x62a0000c4918, new_name=0x62a0000c4d18, create_info=0x7fffd030e5c0, table_list=0x62b000000428, alter_info=0x7fffd030e7a0, order_num=0, order=0x0, ignore=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_table.cc:9853
#7  0x00000000010eba78 in Sql_cmd_alter_table::execute (this=0x62b000000ca8, thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_alter.cc:493
#8  0x0000000000bccbc1 in mysql_execute_command (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:6330
#9  0x0000000000ba5469 in mysql_parse (thd=0x62a0000c0208, rawbuf=0x62b000000220 "alter table t1\nadd column s bigint unsigned as row start,\nadd column e bigint unsigned as row end,\nadd period for system_time(s, e),\nadd system versioning,\nalgorithm=copy", length=170, parser_state=0x7fffd0315040, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8141

frame 2

1481    #if 1 // FIXME: This should be done in ha_prepare().
1482      if (rw_trans || (thd->lex->sql_command == SQLCOM_ALTER_TABLE &&
1483                       thd->lex->alter_info.flags & ALTER_ADD_SYSTEM_VERSIONING))
1484      {
1485        ulonglong trx_start_id= 0, trx_end_id= 0;
1486        for (Ha_trx_info *ha_info= trans->ha_list; ha_info; ha_info= ha_info->next())
1487        {
1488          if (ha_info->ht()->prepare_commit_versioned)
1489          {
1490            trx_end_id= ha_info->ht()->prepare_commit_versioned(thd, &trx_start_id);
1491            if (trx_end_id)
1492              break; // FIXME: use a common ID for cross-engine transactions
1493          }
1494        }
1495
1496        if (trx_end_id)
1497        {
1498          if (!TR_table::use_transaction_registry)
1499          {
1500            my_error(ER_VERS_TRT_IS_DISABLED, MYF(0));
1501            goto err;
1502          }
1503          DBUG_ASSERT(trx_start_id);
1504          TR_table trt(thd, true);
1505          if (trt.update(trx_start_id, trx_end_id))
1506            goto err;

midenok commented 5 years ago

Cause

create_and_open_tmp_table()/open_temporary_table() doesn't do TABLE::init().

Fix

Initialize vers_write for open_temporary_table().

midenok commented 5 years ago

Bug 5: multi-UPDATE sets `vers_write` wrongly

Reproduce

create or replace table t1 (
    id bigint primary key without system versioning,
    name varchar(128),
    salary bigint without system versioning)
  with system versioning;
create or replace table t2 like t1;

insert into t1 values (1, "Jerry", 3000);
insert into t2 values (1, "Jerry", 4000);
update t1, t2 set t1.salary= 2500, t2.salary= 2500 where t1.id = t2.id and t1.name = "Jerry";

Result

History is generated while must not.

Cause

Item_field::fix_fields() is called on conditions.

Fix

Utilize thd->column_usage == MARK_COLUMNS_WRITE to detect whether the column is meant for write.

midenok commented 5 years ago

RBR versioning on slave

#0  Rows_log_event::write_row (this=0x7fff8c032698, rgi=0x7fff8c000cf0, overwrite=false) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:13115
#1  0x0000000000cc74f6 in Write_rows_log_event::do_exec_row (this=0x7fff8c032698, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:13403
#2  0x0000000000cc0f79 in Rows_log_event::do_apply_event (this=0x7fff8c032698, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11533
#3  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff8c032698, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481
#4  0x00000000006a8abb in apply_event_and_update_pos_apply (ev=0x7fff8c032698, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0, reason=0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:3943
#5  0x00000000006a865e in apply_event_and_update_pos (ev=0x7fff8c032698, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4091
#6  0x00000000006b25ed in exec_relay_log_event (thd=0x7fff8c0017c8, rli=0x2bd9438, serial_rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4391
#7  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd7770) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#8  0x00000000013ecc54 in pfs_spawn_thread (arg=0x7fff98040e48) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#9  0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#10 0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

Insert history row on UPDATE

#0  vers_insert_history_row (table=0x7fff84038748) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1638
#1  0x0000000000b4609e in handler::ha_update_row (this=0x7fff84039310, old_data=0x7fff8402f370 "\375\001", new_data=0x7fff8402f358 "\375\002") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6339
#2  0x0000000000cc9ba1 in Update_rows_log_event::do_exec_row (this=0x7fff84032698, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:14364
#3  0x0000000000cc0f39 in Rows_log_event::do_apply_event (this=0x7fff84032698, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11533
#4  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff84032698, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481
#5  0x00000000006a8abb in apply_event_and_update_pos_apply (ev=0x7fff84032698, thd=0x7fff840017c8, rgi=0x7fff84000cf0, reason=0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:3943
#6  0x00000000006a865e in apply_event_and_update_pos (ev=0x7fff84032698, thd=0x7fff840017c8, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4091
#7  0x00000000006b25ed in exec_relay_log_event (thd=0x7fff840017c8, rli=0x2bd9438, serial_rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4391
#8  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd7770) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#9  0x00000000013eca94 in pfs_spawn_thread (arg=0x7fffa0040e48) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#10 0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#11 0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

midenok commented 5 years ago

Problem 6

No seconds fractions in RBR on slave.

Seconds fractions written on master

#0  Query_log_event::write (this=0x7ffff00ae098) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:4192
#1  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00ada90, ev=0x7ffff00ae098) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#2  0x0000000000c8a4f3 in MYSQL_BIN_LOG::write_event (this=0x1e530e0 <mysql_bin_log>, ev=0x7ffff00ae098, cache_data=0x0, file=0x1e53478 <mysql_bin_log+920>) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5319
#3  0x0000000000c8e420 in MYSQL_BIN_LOG::write (this=0x1e530e0 <mysql_bin_log>, event_info=0x7ffff00ae098, with_annotate=0x0) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:6439
#4  0x000000000075f1b0 in THD::binlog_query (this=0x7fff88000cf8, qtype=THD::STMT_QUERY_TYPE, query_arg=0x7fff88012f80 "create or replace table t1 (x int) with system versioning engine innodb", query_len=71, is_trans=false, direct=false, suppress_use=false, errcode=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_class.cc:7256
#5  0x00000000008bfe54 in write_bin_log (thd=0x7fff88000cf8, clear_error=true, query=0x7fff88012f80 "create or replace table t1 (x int) with system versioning engine innodb", query_length=71, is_trans=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_table.cc:1991
#6  0x00000000008c78c8 in mysql_create_table (thd=0x7fff88000cf8, create_table=0x7fff880130b8, create_info=0x7ffff00b0328, alter_info=0x7ffff00b0270) at /home/midenok/src/mariadb/trunk/src/sql/sql_table.cc:5228
#7  0x00000000007d1c55 in mysql_execute_command (thd=0x7fff88000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4284
#8  0x00000000007cae80 in mysql_parse (thd=0x7fff88000cf8, rawbuf=0x7fff88012f80 "create or replace table t1 (x int) with system versioning engine innodb", length=71, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

4192      if (thd && thd->query_start_sec_part_used)
4193      {
4194        *start++= Q_HRNOW;
4195        get_time();
4196        int3store(start, when_sec_part);
4197        start+= 3;
4198      }

Despite when_sec_part is defined in Log_event it is used only in Query_log_event.

INSERT header writtten

#0  Log_event::write_header (this=0x7ffff00ad960, event_data_length=25) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:1766
#1  0x0000000000ccbc56 in Log_event::write (this=0x7ffff00ad960) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1379
#2  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00ad9e8, ev=0x7ffff00ad960) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#3  0x0000000000c8c143 in THD::binlog_write_table_map (this=0x7fff80000cf8, table=0x7fff80023a78, is_transactional=true, with_annotate=0x7ffff00adbff "") at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5795
#4  0x0000000000b49b64 in write_locked_table_maps (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6085
#5  0x0000000000b44ecd in binlog_log_row_internal (table=0x7fff80023a78, before_record=0x0, after_record=0x7fff8001ced8 "\375\001", log_func=0xb4a6a0 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6113
#6  0x0000000000b44e73 in binlog_log_row (table=0x7fff80023a78, before_record=0x0, after_record=0x7fff8001ced8 "\375\001", log_func=0xb4a6a0 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6160
#7  0x0000000000b45c47 in handler::ha_write_row (this=0x7fff80021d90, buf=0x7fff8001ced8 "\375\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6288
#8  0x000000000078214d in write_record (thd=0x7fff80000cf8, table=0x7fff80023a78, info=0x7ffff00ae3f0) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:2002
#9  0x000000000077e952 in mysql_insert (thd=0x7fff80000cf8, table_list=0x7fff80013060, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1063
#10 0x00000000007d337c in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4726
#11 0x00000000007cae80 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80012f80 "insert into t1 values (1)", length=25, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

1757      now= get_time();                               // Query start time
1758
1759      /*
1760        Header will be of size LOG_EVENT_HEADER_LEN for all events, except for
1761        FORMAT_DESCRIPTION_EVENT and ROTATE_EVENT, where it will be
1762        LOG_EVENT_MINIMAL_HEADER_LEN (remember these 2 have a frozen header,
1763        because we read them before knowing the format).
1764      */
1765
1766      int4store(header, now);              // timestamp
1767      header[EVENT_TYPE_OFFSET]= get_type_code();
1768      int4store(header+ SERVER_ID_OFFSET, server_id);
1769      int4store(header+ EVENT_LEN_OFFSET, data_written);
1770      int4store(header+ LOG_POS_OFFSET, log_pos);
1771      int2store(header + FLAGS_OFFSET, flags);
1772
1773      bool ret= writer->write_header(header, sizeof(header));

Info: `Query_log_event` is used only for statement logging

7206      switch (qtype) {
7207        /*
7208          ROW_QUERY_TYPE means that the statement may be logged either in
7209          row format or in statement format.  If
7210          current_stmt_binlog_format is row, it means that the
7211          statement has already been logged in row format and hence shall
7212          not be logged again.
7213        */
7214      case THD::ROW_QUERY_TYPE:
7215        DBUG_PRINT("debug",
7216                   ("is_current_stmt_binlog_format_row: %d",
7217                    is_current_stmt_binlog_format_row()));
7218        if (is_current_stmt_binlog_format_row())
7219          DBUG_RETURN(0);
7220        /* Fall through */
7221
....
7232      case THD::STMT_QUERY_TYPE:
7233        /*
7234          The MYSQL_LOG::write() function will set the STMT_END_F flag and
7235          flush the pending rows event if necessary.
7236        */
7237        {
7238          int error = 0;
....
7246          if(binlog_should_compress(query_len))
7247          {
7248            Query_compressed_log_event qinfo(this, query_arg, query_len, is_trans, direct,
7249                                suppress_use, errcode);
7250            error= mysql_bin_log.write(&qinfo);
7251          }
7252          else
7253          {
7254            Query_log_event qinfo(this, query_arg, query_len, is_trans, direct,
7255              suppress_use, errcode);
7256            error= mysql_bin_log.write(&qinfo);
7257          }
7258
7259          binlog_table_maps= 0;
7260          DBUG_RETURN(error);

Cause

Now seconds fractions ever sent in RBR mode.

midenok commented 5 years ago

Info: events on INSERT

1. Table map

#0  Log_event::write (this=0x7ffff00ad960) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1379
#1  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00ad9e8, ev=0x7ffff00ad960) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#2  0x0000000000c8c143 in THD::binlog_write_table_map (this=0x7fff80000cf8, table=0x7fff80024a98, is_transactional=true, with_annotate=0x7ffff00adbff "") at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5795
#3  0x0000000000b49b64 in write_locked_table_maps (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6085
#4  0x0000000000b44ecd in binlog_log_row_internal (table=0x7fff80024a98, before_record=0x0, after_record=0x7fff8001ced8 "\375\001", log_func=0xb4a6a0 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6113
#5  0x0000000000b44e73 in binlog_log_row (table=0x7fff80024a98, before_record=0x0, after_record=0x7fff8001ced8 "\375\001", log_func=0xb4a6a0 <Write_rows_log_event::binlog_row_logging_function(THD*, TABLE*, bool, unsigned char const*, unsigned char const*)>) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6160
#6  0x0000000000b45c47 in handler::ha_write_row (this=0x7fff80021d90, buf=0x7fff8001ced8 "\375\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6288
#7  0x000000000078214d in write_record (thd=0x7fff80000cf8, table=0x7fff80024a98, info=0x7ffff00ae3f0) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:2002
#8  0x000000000077e952 in mysql_insert (thd=0x7fff80000cf8, table_list=0x7fff80013060, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1063
#9  0x00000000007d337c in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4726
#10 0x00000000007cae80 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80012f80 "insert into t1 values (1)", length=25, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

2. Actual ROW event

#0  Rows_log_event::write_data_header (this=0x7fff80020668) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11807
#1  0x0000000000ccbc70 in Log_event::write (this=0x7fff80020668) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1379
#2  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00adb00, ev=0x7fff80020668) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#3  0x0000000000c8c93c in MYSQL_BIN_LOG::flush_and_set_pending_rows_event (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, event=0x0, is_transactional=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5936
#4  0x000000000075e409 in THD::binlog_flush_pending_rows_event (this=0x7fff80000cf8, stmt_end=true, is_transactional=true) at /home/midenok/src/mariadb/trunk/src/sql/sql_class.cc:6891
#5  0x000000000075eea3 in THD::binlog_query (this=0x7fff80000cf8, qtype=THD::ROW_QUERY_TYPE, query_arg=0x7fff80012f80 "insert into t1 values (1)", query_len=25, is_trans=true, direct=false, suppress_use=false, errcode=0) at /home/midenok/src/mariadb/trunk/src/sql/sql_class.cc:7175
#6  0x000000000077efd4 in mysql_insert (thd=0x7fff80000cf8, table_list=0x7fff80013060, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1179
#7  0x00000000007d337c in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:4726
#8  0x00000000007cae80 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80012f80 "insert into t1 values (1)", length=25, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

Rows_log_event don't have its own write_header().

3. GTID

#0  Gtid_log_event::write (this=0x7ffff00acfb0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:7962
#1  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00acec0, ev=0x7ffff00acfb0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#2  0x0000000000c8a4f3 in MYSQL_BIN_LOG::write_event (this=0x1e530e0 <mysql_bin_log>, ev=0x7ffff00acfb0, cache_data=0x0, file=0x1e53478 <mysql_bin_log+920>) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5319
#3  0x00000000006b9c6a in MYSQL_BIN_LOG::write_event (this=0x1e530e0 <mysql_bin_log>, ev=0x7ffff00acfb0) at /home/midenok/src/mariadb/trunk/src/sql/log.h:813
#4  0x0000000000c8cf0d in MYSQL_BIN_LOG::write_gtid_event (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, standalone=false, is_transactional=true, commit_id=0) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:6034
#5  0x0000000000c9459c in MYSQL_BIN_LOG::write_transaction_or_stmt (this=0x1e530e0 <mysql_bin_log>, entry=0x7ffff00ad698, commit_id=0) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8125
#6  0x0000000000c92eb5 in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x1e530e0 <mysql_bin_log>, leader=0x7ffff00ad698) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7884
#7  0x0000000000c9177c in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x1e530e0 <mysql_bin_log>, entry=0x7ffff00ad698) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7681
#8  0x0000000000c9169e in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, end_ev=0x7ffff00ad928, all=false, using_stmt_cache=true, using_trx_cache=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7355
#9  0x0000000000c9afc5 in binlog_flush_cache (thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, end_ev=0x7ffff00ad928, all=false, using_stmt=true, using_trx=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1781
#10 0x0000000000c9877b in binlog_commit_flush_xid_caches (thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, all=false, xid=115) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1889
#11 0x0000000000c985a3 in MYSQL_BIN_LOG::log_and_order (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, xid=115, all=false, need_prepare_ordered=false, need_commit_ordered=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:9623
#12 0x0000000000b360d3 in ha_commit_trans (thd=0x7fff80000cf8, all=false) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:1538
#13 0x0000000000987b36 in trans_commit_stmt (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/transaction.cc:520
#14 0x00000000007d97a8 in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6391
#15 0x00000000007cae80 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80012f80 "insert into t1 values (1)", length=25, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

4. XID

#0  Xid_log_event::write (this=0x7ffff00ad928) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:8866
#1  0x0000000000c9da3a in Log_event_writer::write (this=0x7ffff00ad020, ev=0x7ffff00ad928) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:5212
#2  0x0000000000c8a4f3 in MYSQL_BIN_LOG::write_event (this=0x1e530e0 <mysql_bin_log>, ev=0x7ffff00ad928, cache_data=0x0, file=0x1e53478 <mysql_bin_log+920>) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:5319
#3  0x00000000006b9c6a in MYSQL_BIN_LOG::write_event (this=0x1e530e0 <mysql_bin_log>, ev=0x7ffff00ad928) at /home/midenok/src/mariadb/trunk/src/sql/log.h:813
#4  0x0000000000c94944 in MYSQL_BIN_LOG::write_transaction_or_stmt (this=0x1e530e0 <mysql_bin_log>, entry=0x7ffff00ad698, commit_id=0) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:8163
#5  0x0000000000c92eb5 in MYSQL_BIN_LOG::trx_group_commit_leader (this=0x1e530e0 <mysql_bin_log>, leader=0x7ffff00ad698) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7884
#6  0x0000000000c9177c in MYSQL_BIN_LOG::write_transaction_to_binlog_events (this=0x1e530e0 <mysql_bin_log>, entry=0x7ffff00ad698) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7681
#7  0x0000000000c9169e in MYSQL_BIN_LOG::write_transaction_to_binlog (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, end_ev=0x7ffff00ad928, all=false, using_stmt_cache=true, using_trx_cache=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:7355
#8  0x0000000000c9afc5 in binlog_flush_cache (thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, end_ev=0x7ffff00ad928, all=false, using_stmt=true, using_trx=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1781
#9  0x0000000000c9877b in binlog_commit_flush_xid_caches (thd=0x7fff80000cf8, cache_mngr=0x7fff800678b8, all=false, xid=115) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:1889
#10 0x0000000000c985a3 in MYSQL_BIN_LOG::log_and_order (this=0x1e530e0 <mysql_bin_log>, thd=0x7fff80000cf8, xid=115, all=false, need_prepare_ordered=false, need_commit_ordered=true) at /home/midenok/src/mariadb/trunk/src/sql/log.cc:9623
#11 0x0000000000b360d3 in ha_commit_trans (thd=0x7fff80000cf8, all=false) at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:1538
#12 0x0000000000987b36 in trans_commit_stmt (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/transaction.cc:520
#13 0x00000000007d97a8 in mysql_execute_command (thd=0x7fff80000cf8) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:6391
#14 0x00000000007cae80 in mysql_parse (thd=0x7fff80000cf8, rawbuf=0x7fff80012f80 "insert into t1 values (1)", length=25, parser_state=0x7ffff00b15e0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/trunk/src/sql/sql_parse.cc:8116

midenok commented 5 years ago

Slave reads Log_event

#0  Log_event::read_log_event (buf=0x7fff8c02a5a8 "W\353\200\\\017\002", event_len=252, error=0x7ffff00fb820, fdle=0x7fff98012d38, crc_check=1 '\001') at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:1998
#1  0x0000000000ca6829 in Log_event::read_log_event (file=0x2bd9af8, fdle=0x7fff98012d38, crc_check=1 '\001') at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:1938
#2  0x00000000006b5472 in next_event (rgi=0x7fff8c000cf0, event_size=0x7ffff00fbe18) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:7489
#3  0x00000000006b1cce in exec_relay_log_event (thd=0x7fff8c0017c8, rli=0x2bd9288, serial_rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4236
#4  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd75c0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#5  0x00000000013ecaf4 in pfs_spawn_thread (arg=0x7fff98040e18) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#6  0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#7  0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

THD assigned to Log_event

#0  apply_event_and_update_pos_setup (ev=0x7fff8c032788, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:3919
#1  0x00000000006a856f in apply_event_and_update_pos (ev=0x7fff8c032788, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4075
#2  0x00000000006b25ed in exec_relay_log_event (thd=0x7fff8c0017c8, rli=0x2bd9288, serial_rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4391
#3  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd75c0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#4  0x00000000013ecaf4 in pfs_spawn_thread (arg=0x7fff98040e18) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#5  0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#6  0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

THD start_time is set

#0  THD::set_time (this=0x7fff8c0017c8, t=1551953272, sec_part=18446744073709551615) at /home/midenok/src/mariadb/trunk/src/sql/sql_class.h:3500
#1  0x0000000000cc0aaa in Rows_log_event::do_apply_event (this=0x7fff8c032788, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11470
#2  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff8c032788, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481
#3  0x00000000006a8abb in apply_event_and_update_pos_apply (ev=0x7fff8c032788, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0, reason=0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:3943
#4  0x00000000006a865e in apply_event_and_update_pos (ev=0x7fff8c032788, thd=0x7fff8c0017c8, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4091
#5  0x00000000006b25ed in exec_relay_log_event (thd=0x7fff8c0017c8, rli=0x2bd9288, serial_rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4391
#6  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd75c0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554

11452     if (table)
11453     {
.....
11462       /*
11463         It's not needed to set_time() but
11464         1) it continues the property that "Time" in SHOW PROCESSLIST shows how
11465         much slave is behind
11466         2) it will be needed when we allow replication from a table with no
11467         TIMESTAMP column to a table with one.
11468         So we call set_time(), like in SBR. Presently it changes nothing.
11469       */
11470       thd->set_time(when, when_sec_part);

midenok commented 5 years ago

Bug 6: lost history record on RBR-slave for InnoDB timestamp

Reproduce

--source include/master-slave.inc
--source include/have_innodb.inc

create or replace table t1 (x int) with system versioning engine innodb;
sync_slave_with_master;
connection master;
insert into t1 values (1);
sync_slave_with_master;

connection master;
update t1 set x= 2;
select *, row_start, row_end from t1 for system_time all;

sync_slave_with_master;
select *, row_start, row_end from t1 for system_time all;

connection master;
drop table t1;

--source include/rpl_end.inc

Result

connection master;
update t1 set x= 2;
select *, row_start, row_end from t1 for system_time all;
x       row_start       row_end
2       2019-03-07 16:49:11.083167      2038-01-19 06:14:07.999999
1       2019-03-07 16:49:11.072842      2019-03-07 16:49:11.083167
connection slave;
select *, row_start, row_end from t1 for system_time all;
x       row_start       row_end
2       2019-03-07 16:49:11.083167      2038-01-19 06:14:07.999999

Expected

History record x=1 on slave.

Good

Without first

sync_slave_with_master;
connection master;

it goes well:

--source include/master-slave.inc
--source include/have_innodb.inc

create or replace table t1 (x int) with system versioning engine innodb;
insert into t1 values (1);
sync_slave_with_master;

connection master;
update t1 set x= 2;
select *, row_start, row_end from t1 for system_time all;

sync_slave_with_master;
select *, row_start, row_end from t1 for system_time all;

connection master;
drop table t1;

--source include/rpl_end.inc

Reproduce 2

--source include/master-slave.inc
--source include/have_innodb.inc

create or replace table t1 (x int) with system versioning engine innodb;
set timestamp= unix_timestamp('2019-03-07 12:00:00.5');
insert into t1 values (1);
sync_slave_with_master;

connection master;
set timestamp= unix_timestamp('2019-03-07 12:00:00.6');
update t1 set x= 2;
select *, row_start, row_end from t1 for system_time all;

sync_slave_with_master;
select *, row_start, row_end from t1 for system_time all;

connection master;
drop table t1;

--source include/rpl_end.inc

Result 2

connection master;
set timestamp= unix_timestamp('2019-03-07 12:00:00.6');
update t1 set x= 2;
select *, row_start, row_end from t1 for system_time all;
x       row_start       row_end
2       2019-03-07 12:00:00.600000      2038-01-19 06:14:07.999999
1       2019-03-07 12:00:00.500000      2019-03-07 12:00:00.600000
connection slave;
select *, row_start, row_end from t1 for system_time all;
x       row_start       row_end
2       2019-03-07 12:00:00.600000      2038-01-19 06:14:07.999999

midenok commented 5 years ago

Wrong value restored

#0  Field::store_timestamp (this=0x7fff8402f610, timestamp=1551949200, sec_part=1) at /home/midenok/src/mariadb/trunk/src/sql/field.h:790
#1  0x000000000092445b in TABLE::vers_update_end (this=0x7fff84038838) at /home/midenok/src/mariadb/trunk/src/sql/table.cc:7865
#2  0x00000000007835bc in vers_insert_history_row (table=0x7fff84038838) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1642
#3  0x0000000000b4609e in handler::ha_update_row (this=0x7fff84039400, old_data=0x7fff8402f400 "\375\001", new_data=0x7fff8402f3e8 "\375\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6339
#4  0x0000000000cc9c01 in Update_rows_log_event::do_exec_row (this=0x7fff84032788, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:14367
#5  0x0000000000cc0f39 in Rows_log_event::do_apply_event (this=0x7fff84032788, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11533
#6  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff84032788, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481
#7  0x00000000006a8abb in apply_event_and_update_pos_apply (ev=0x7fff84032788, thd=0x7fff840017c8, rgi=0x7fff84000cf0, reason=0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:3943
#8  0x00000000006a865e in apply_event_and_update_pos (ev=0x7fff84032788, thd=0x7fff840017c8, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4091
#9  0x00000000006b25ed in exec_relay_log_event (thd=0x7fff840017c8, rli=0x2bd9288, serial_rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4391
#10 0x000000000069f9b2 in handle_slave_sql (arg=0x2bd75c0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#11 0x00000000013ecaf4 in pfs_spawn_thread (arg=0x7fffa0040e18) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#12 0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#13 0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

(gdb) p in_use->query_start_sec_part_used
$7 = true
(gdb) p in_use->start_time_sec_part 
$9 = 1

1. `THD::start_time_sec_part` set from `when_sec_part` which is `TIME_MAX_SECOND_PART`

#0  THD::set_time (this=0x7fff840017c8, t=1552002866, sec_part=18446744073709551615) at /home/midenok/src/mariadb/trunk/src/sql/sql_class.h:3504
#1  0x0000000000cc0aaa in Rows_log_event::do_apply_event (this=0x7fff84032788, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11470
#2  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff84032788, rgi=0x7fff84000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481

And it actually gets it from system_time:

3491          if (sec_part <= TIME_MAX_SECOND_PART)
3492          {
3493            start_time= system_time.sec= t;
3494            start_time_sec_part= system_time.sec_part= sec_part;
3495          }
3496          else if (t != system_time.sec)
3497          {
3498            start_time= system_time.sec= t;
3499            start_time_sec_part= system_time.sec_part= 0;
3500          }
3501          else
3502          {
3503            start_time= t;
3504            start_time_sec_part= ++system_time.sec_part;
3505          }

2. history row inserted

#0  vers_insert_history_row (table=0x7fff8c038838) at /home/midenok/src/mariadb/trunk/src/sql/sql_insert.cc:1644
#1  0x0000000000b4609e in handler::ha_update_row (this=0x7fff8c039400, old_data=0x7fff8c02f400 "\375\001", new_data=0x7fff8c02f3e8 "\375\001") at /home/midenok/src/mariadb/trunk/src/sql/handler.cc:6339
#2  0x0000000000cc9c01 in Update_rows_log_event::do_exec_row (this=0x7fff8c032788, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:14367
#3  0x0000000000cc0f39 in Rows_log_event::do_apply_event (this=0x7fff8c032788, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:11533
#4  0x00000000006b94a0 in Log_event::apply_event (this=0x7fff8c032788, rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:1481

Cause

History row gets second fractions from system time, not from master time.

midenok commented 5 years ago

Log_event protocol for passing timestamp fractions

Info

/* 
   Event header offsets; 
   these point to places inside the fixed header.
*/

#define EVENT_TYPE_OFFSET    4
#define SERVER_ID_OFFSET     5
#define EVENT_LEN_OFFSET     9
#define LOG_POS_OFFSET       13
#define FLAGS_OFFSET         17

bool Log_event::write_header(size_t event_data_length)
{
  uchar header[LOG_EVENT_HEADER_LEN];
  ...
  /* Store number of bytes that will be written by this event */
  data_written= event_data_length + sizeof(header) + writer->checksum_len;
  ...
  int4store(header, now);              // timestamp
  header[EVENT_TYPE_OFFSET]= get_type_code();
  int4store(header+ SERVER_ID_OFFSET, server_id);
  int4store(header+ EVENT_LEN_OFFSET, data_written);
  int4store(header+ LOG_POS_OFFSET, log_pos);
  int2store(header + FLAGS_OFFSET, flags);

  bool ret= writer->write_header(header, sizeof(header));

Log_event stores only total size, not header size. So it is needed to add flag that will indicate presence of second fractions.

After first attempt this check failed:

#0  Format_description_log_event::header_is_valid (this=0x7fff8c02a848) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:2822
#1  0x0000000000c9d4c9 in Format_description_log_event::is_valid (this=0x7fff8c02a848) at /home/midenok/src/mariadb/trunk/src/sql/log_event.h:2829
#2  0x0000000000ca8336 in Log_event::read_log_event (buf=0x7fff8c02a5a8 "\n\230\207\\\017\002", event_len=256, error=0x7ffff00fb820, fdle=0x7fff98012d38, crc_check=1 '\001') at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:2267
#3  0x0000000000ca68c9 in Log_event::read_log_event (file=0x2bd9af8, fdle=0x7fff98012d38, crc_check=1 '\001') at /home/midenok/src/mariadb/trunk/src/sql/log_event.cc:1943
#4  0x00000000006b5472 in next_event (rgi=0x7fff8c000cf0, event_size=0x7ffff00fbe18) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:7489
#5  0x00000000006b1cce in exec_relay_log_event (thd=0x7fff8c0017c8, rli=0x2bd9288, serial_rgi=0x7fff8c000cf0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:4236
#6  0x000000000069f9b2 in handle_slave_sql (arg=0x2bd75c0) at /home/midenok/src/mariadb/trunk/src/sql/slave.cc:5554
#7  0x00000000013ecb94 in pfs_spawn_thread (arg=0x7fff98040e18) at /home/midenok/src/mariadb/trunk/src/storage/perfschema/pfs.cc:1862
#8  0x00007ffff7f82164 in start_thread (arg=<optimized out>) at pthread_create.c:486
#9  0x00007ffff73f3def in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

midenok commented 5 years ago

Bug 7: mtr --ps-protocol fails

Caused by Refactoring 1

Failing tests:

update,myisam \
delete_history,myisam \
rpl,row,myisam

Halting tests:

delete,timestamp \
delete_history,timestamp \
rpl,row,timestamp

Reproduce

create or replace table t1 (
  id int primary key auto_increment,
  x int)
with system versioning;

insert into t1 (x) values (1);
update t1 set x= 2 where id = 1;
execute immediate 'update t1 set x= 3 where id = 1';

Result

ERROR 1062 (23000): Duplicate entry '1' for key 'PRIMARY'

Expected

No error.

midenok commented 5 years ago

DUP error printed

#7  0x00000000015fc0b8 in handler::print_error (this=0x61c00004f8a0, error=121, errflag=0) at /home/midenok/src/mariadb/10.4/src/sql/handler.cc:3870
#8  0x0000000000f5f105 in mysql_update (thd=0x62a0000c0208, table_list=0x62b00001dcc0, select_lex=0x62b00001ca48, values=..., limit=18446744073709551615, handle_duplicates=DUP_ERROR, ignore=false, found_return=0x7fffd0329910, updated_return=0x7fffd0329930) at /home/midenok/src/mariadb/10.4/src/sql/sql_update.cc:984
#9  0x0000000000bbdf2d in mysql_execute_command (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:4623
#10 0x0000000000c397fb in Prepared_statement::execute (this=0x6190000b0e88, expanded_query=0x7fffd032ede0, open_cursor=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_prepare.cc:4754
#11 0x0000000000c2c79d in Prepared_statement::execute_loop (this=0x6190000b0e88, expanded_query=0x7fffd032ede0, open_cursor=false, packet=0x0, packet_end=0x0) at /home/midenok/src/mariadb/10.4/src/sql/sql_prepare.cc:4230
#12 0x0000000000c28185 in Prepared_statement::execute_immediate (this=0x6190000b0e88, query=0x62b0000002f0 "update t1 set x= 3 where id = 1", query_len=31) at /home/midenok/src/mariadb/10.4/src/sql/sql_prepare.cc:4878
#13 0x0000000000c278d2 in mysql_sql_stmt_execute_immediate (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_prepare.cc:2906
#14 0x0000000000bb8990 in mysql_execute_command (thd=0x62a0000c0208) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:3831
#15 0x0000000000ba5469 in mysql_parse (thd=0x62a0000c0208, rawbuf=0x62b000000220 "execute immediate 'update t1 set x= 3 where id = 1'", length=51, parser_state=0x7fffd0335040, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/10.4/src/sql/sql_parse.cc:8141

frame 8

(gdb) pitem(conds)
$2 = 0x5242ca0 <dbug_item_print_buf> "t1.`id` = 1"

Cause

conds do not contain versioning conditions. vers_setup_conds() exits on this check:

769       if (!thd->stmt_arena->is_conventional() &&
770           !thd->stmt_arena->is_stmt_prepare_or_first_sp_execute())
771       {
772         // statement is already prepared
773         DBUG_RETURN(0);
774       }

midenok commented 5 years ago

Info: how it works for SELECT

Source

on prepare:

#0  setup_for_system_time (thd=0x7f1253016070, tables=0x7f12530f8800, conds=0x7f125305e5a0, select_lex=0x7f12530f78a0) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:676
#1  0x00000000006d02d6 in JOIN::prepare (this=0x7f125305e1a8, tables_init=0x7f12530f8800, wild_num=0x1, conds_init=0x7f12530f90f0, og_num=0x0, order_init=0x0, skip_order_by=0x0, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0x7f12530f78a0, unit_arg=0x7f12530f7158) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:856
#2  0x00000000007703be in st_select_lex_unit::prepare (this=0x7f12530f7158, thd_arg=0x7f1253016070, sel_result=0x0, additional_options=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_union.cc:439
#3  0x00000000006b590d in mysql_test_select (stmt=0x7f125306c470, tables=0x7f12530f8800) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:1540
#4  0x00000000006b72c3 in check_prepared_statement (stmt=0x7f125306c470) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:2325
#5  0x00000000006ba416 in Prepared_statement::prepare (this=0x7f125306c470, packet=0x7f125305e180 "select * from t1 where sys_end > now()", packet_len=0x26) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:3700
#6  0x00000000006b7ed4 in mysql_sql_stmt_prepare (thd=0x7f1253016070) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:2755
#7  0x0000000000691c8d in mysql_execute_command (thd=0x7f1253016070) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:3358
#8  0x000000000069fcd3 in mysql_parse (thd=0x7f1253016070, rawbuf=0x7f125305e088 "prepare stmt from \"select * from t1 where sys_end > now()\"", length=0x3a, parser_state=0x7f127ae71f70, is_com_multi=0x0, is_next_command=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:7792

on execute:

#0  setup_for_system_time (thd=0x7f1253016070, tables=0x7f12530f8800, conds=0x7f125305e608, select_lex=0x7f12530f78a0) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:676
#1  0x00000000006d02d6 in JOIN::prepare (this=0x7f125305e210, tables_init=0x7f12530f8800, wild_num=0x0, conds_init=0x7f12530f90f0, og_num=0x0, order_init=0x0, skip_order_by=0x0, group_init=0x0, having_init=0x0, proc_param_init=0x0, select_lex_arg=0x7f12530f78a0, unit_arg=0x7f12530f7158) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:856
#2  0x00000000006d9efd in mysql_select (thd=0x7f1253016070, tables=0x7f12530f8800, wild_num=0x0, fields=..., conds=0x7f12530f90f0, og_num=0x0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=0x90040b00, result=0x7f12530f9258, unit=0x7f12530f7158, select_lex=0x7f12530f78a0) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:3626
#3  0x00000000006ce89e in handle_select (thd=0x7f1253016070, lex=0x7f12530f7090, result=0x7f12530f9258, setup_tables_done_option=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_select.cc:377
#4  0x000000000069c279 in execute_sqlcom_select (thd=0x7f1253016070, all_tables=0x7f12530f8800) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:6320
#5  0x0000000000691c70 in mysql_execute_command (thd=0x7f1253016070) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:3352
#6  0x00000000006bbbe9 in Prepared_statement::execute (this=0x7f125306c470, expanded_query=0x7f127ae70f00, open_cursor=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:4277
#7  0x00000000006baa15 in Prepared_statement::execute_loop (this=0x7f125306c470, expanded_query=0x7f127ae70f00, open_cursor=0x0, packet=0x0, packet_end=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:3908
#8  0x00000000006b89e1 in mysql_sql_stmt_execute (thd=0x7f1253016070) at /home/midenok/src/mariadb/midenok/src/sql/sql_prepare.cc:3036
#9  0x0000000000691ca1 in mysql_execute_command (thd=0x7f1253016070) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:3363
#10 0x000000000069fcd3 in mysql_parse (thd=0x7f1253016070, rawbuf=0x7f125305e088 "execute stmt", length=0xc, parser_state=0x7f127ae71f70, is_com_multi=0x0, is_next_command=0x0) at /home/midenok/src/mariadb/midenok/src/sql/sql_parse.cc:7792

Fix

Move vers_setup_conds() from mysql_update() to mysql_prepare_update().

midenok commented 5 years ago

Back to Bug 6

Info: Slave unpacks records for UPDATE

14276   Update_rows_log_event::do_exec_row(rpl_group_info *rgi)
14277   {
.....
14292     int error= find_row(rgi);  // <- Old record restored
14293     if (unlikely(error))
.....
14316     store_record(m_table,record[1]);
.....
14329     if (unlikely((error= unpack_current_row(rgi, &m_cols_ai)))) // <- New record restored
14330       goto err;
.....
14342     DBUG_DUMP("old record", m_table->record[1], m_table->s->reclength);
14343     DBUG_DUMP("new values", m_table->record[0], m_table->s->reclength);

Fix

Get THD timestamp from vers_start_field() of new row.

@@ -4664,8 +4665,14 @@ class Rows_log_event : public Log_event
     DBUG_ASSERT(m_table);

     ASSERT_OR_RETURN_ERROR(m_curr_row <= m_rows_end, HA_ERR_CORRUPT_EVENT);
-    return ::unpack_row(rgi, m_table, m_width, m_curr_row, cols,
+    const int result= ::unpack_row(rgi, m_table, m_width, m_curr_row, cols,
                                    &m_curr_row_end, &m_master_reclength, m_rows_end);
+    if (!result && !m_master_unversioned && m_table->versioned(VERS_TIMESTAMP))
+    {
+      when= m_table->vers_start_field()->get_timestamp(&when_sec_part);
+      thd->set_time(when, when_sec_part);
+    }
+    return result;
   }

   // Unpack the current row into m_table->record[0]

tempesta-tech / mariadb

MDEV-18432 RBR logging of system versioned tables #578

Preface (serg)

Description (serg)

TODO

Refactoring 1: use SQL_SELECT instead of linear iteration to filter out historical records

Multi-update case

Fix

Bug 1: bitmap_is_set() assertion on partitioned

Reproduce

Result

Good

Bad: read_partitions.bitmap overwritten

Cause

Fix

Bug 2: DELETE HISTORY is broken

Reproduce

Result

Expected

Cause

Fix

Bug 3: delete from VIEW is broken

Reproduce

Result

frame 10

Cause

Fix

Remove check_has_vers_fields()

1. table_list->table assigned

2. TABLE inited

Bug 4: wrong trx_id after ALTER

Reproduce

Result

Expected

Info: ALTER copy assigns trx_id

1. mod_tables assigned

2. ins_mode is set

3. TRX_ID assigned to row_start, row_end

4. TRT updated

frame 2

Cause

Fix

Bug 5: multi-UPDATE sets vers_write wrongly

Reproduce

Result

Cause

Fix

RBR versioning on slave

Insert history row on UPDATE

Problem 6

Seconds fractions written on master

INSERT header writtten

Info: Query_log_event is used only for statement logging

Cause

Info: events on INSERT

1. Table map

2. Actual ROW event

3. GTID

4. XID

Slave reads Log_event

THD assigned to Log_event

THD start_time is set

Bug 6: lost history record on RBR-slave for InnoDB timestamp

Reproduce

Result

Expected

Good

Reproduce 2

Result 2

Wrong value restored

1. THD::start_time_sec_part set from when_sec_part which is TIME_MAX_SECOND_PART

2. history row inserted

Cause

Log_event protocol for passing timestamp fractions

Info

After first attempt this check failed:

Bug 7: mtr --ps-protocol fails

Failing tests:

Halting tests:

Reproduce

Bug 1: `bitmap_is_set()` assertion on partitioned

Bad: `read_partitions.bitmap` overwritten

Remove `check_has_vers_fields()`

1. `table_list->table` assigned

2. `ins_mode` is set

Bug 5: multi-UPDATE sets `vers_write` wrongly

Info: `Query_log_event` is used only for statement logging

1. `THD::start_time_sec_part` set from `when_sec_part` which is `TIME_MAX_SECOND_PART`