Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

InnoDB's MVCC has O(N^2) behaviors #16

Open
midenok opened this issue Jul 3, 2017 · 15 comments
Open

InnoDB's MVCC has O(N^2) behaviors #16

midenok opened this issue Jul 3, 2017 · 15 comments

Comments

@midenok
Copy link
Owner

midenok commented Jul 3, 2017 •
edited
Loading

Reproduce

setup: create table t1 (a int, b int, c int, primary key(a,b), key (b,c)) engine=InnoDB;

T1: BEGIN; SELECT * FROM t1;

T2: 10000 * INSERT INTO t1 VALUES (1,2,3) ON DUPLICATE KEY UPDATE c=c+1

T1: SELECT * FROM t1 FORCE INDEX (PRIMARY)
(this will be immediate and bump Innodb_buffer_pool_read_requests by ~10k)

T1: SELECT * FROM t1 FORCE INDEX (b)
(this will be not immediate and bump Innodb_buffer_pool_read_requests by ~100000k or ~100m or....)

delimiter ~~
create or replace procedure insert_n(n int)
begin
    declare i int default 0;
    while i < n do
        insert into t1 values (1, 2, 3) on duplicate key update c= c + 1;
        set i = i + 1;
    end while;
end~~
delimiter ;
delimiter ~~
create or replace function bprrs()
returns int
begin
    declare ret int;
    select variable_value
    from information_schema.global_status
    where
        variable_name = 'innodb_buffer_pool_read_requests'
    into ret;
    return ret;
end~~
delimiter ;
@midenok
Copy link
Owner Author

midenok commented Jul 4, 2017 •
edited
Loading

ibbug.test

-- source include/have_innodb.inc

delimiter ~~;
create or replace procedure insert_n(n int)
begin
    declare i int default 0;
    while i < n do
        insert into t1 values (1, 2, 3) on duplicate key update c= c + 1;
        set i = i + 1;
    end while;
end~~

create or replace function bprrs()
returns int
begin
    declare ret int;
    select variable_value
    from information_schema.global_status
    where
        variable_name = 'innodb_buffer_pool_read_requests'
    into ret;
    return ret;
end~~
delimiter ;~~

create table t1 (a int, b int, c int, primary key(a,b), key (b,c)) engine=InnoDB;

connect (con2, localhost, root,,);

begin;
select * from t1;

connection con2;
call insert_n(100);

connection default;
set @rr1= bprrs();

select * from t1 force index (b);
set @rr2= bprrs();
select @rr2 - @rr1;

disconnect con2;
drop database test;
create database test;
b mysql_select
commands
    bt
end
ign 3
r

@midenok
Copy link
Owner Author

midenok commented Jul 5, 2017 •
edited
Loading 

./buf/buf0buf.cc:3791:  buf_pool->stat.n_page_gets++;
./buf/buf0buf.cc:4244:  buf_pool->stat.n_page_gets++;
./buf/buf0buf.cc:4969:  buf_pool->stat.n_page_gets++;
./buf/buf0buf.cc:5077:  buf_pool->stat.n_page_gets++;
./buf/buf0buf.cc:5164:  buf_pool->stat.n_page_gets++;
./btr/btr0sea.cc:1094:          ++buf_pool->stat.n_page_gets;

b buf0buf.cc:3791
b buf0buf.cc:4244
b buf0buf.cc:4969
b buf0buf.cc:5077
b buf0buf.cc:5164
b btr0sea.cc:1094

breaks.gdb

b mysql_select
commands
    bd 1
    bt
    blog buf0buf.cc:3791
    blog buf0buf.cc:4244
    blog buf0buf.cc:4969
    blog buf0buf.cc:5077
    blog buf0buf.cc:5164
    blog btr0sea.cc:1094
    logging redirect on
    logging on
    c
end
ign 3
r

@midenok
Copy link
Owner Author

midenok commented Jul 5, 2017 •
edited
Loading

ibbug result

select @rr2 - @rr1;
@rr2 - @rr1
10201

breakpoint stats

3 4 5 7 total row_search_mvcc()
15286 327 297 297 16207 10201

@midenok
Copy link
Owner Author

midenok commented Jul 5, 2017 •
edited
Loading

Breakpoint 3 + row_search_mvcc():

#0  buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x5555568d2e58 "/home/midenok/src/mariadb/ibbug/src/storage/innobase/include/trx0undo.ic", line=180, mtr=0x7ffff0a84640, err=0x0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/buf/buf0buf.cc:4244
#1  0x00005555562233b7 in trx_undo_page_get_s_latched (page_id=..., mtr=0x7ffff0a84640) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/trx0undo.ic:179
#2  0x00005555562286b7 in trx_undo_get_undo_rec_low (roll_ptr=844424951895779, is_temp=false, heap=0x7fffa80332f0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/trx/trx0rec.cc:2084
#3  0x00005555562287ec in trx_undo_get_undo_rec (roll_ptr=844424951895779, is_temp=false, heap=0x7fffa80332f0, trx_id=1284, name=..., undo_rec=0x7ffff0a84c28) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/trx/trx0rec.cc:2122
#4  0x0000555556228a61 in trx_undo_prev_version_build (index_rec=0x7ffff128007e "\200", index_mtr=0x7ffff0a85cf0, rec=0x7ffff128007e "\200", index=0x7fffa8030408, offsets=0x7ffff0a859d0, heap=0x7fffa80332f0, old_vers=0x7ffff0a84d38, v_heap=0x0, vrow=0x0, v_status=0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/trx/trx0rec.cc:2206
#5  0x00005555561dc167 in row_vers_build_for_consistent_read (rec=0x7ffff128007e "\200", mtr=0x7ffff0a85cf0, index=0x7fffa8030408, offsets=0x7ffff0a85148, view=0x555557dfb7a0, offset_heap=0x7ffff0a85140, in_heap=0x7fffa8033190, old_vers=0x7ffff0a84ef0, vrow=0x0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0vers.cc:1159
#6  0x00005555561a9fd5 in row_sel_build_prev_vers_for_mysql (read_view=0x555557dfb7a0, clust_index=0x7fffa8030408, prebuilt=0x7fff9c01e1b8, rec=0x7ffff128007e "\200", offsets=0x7ffff0a85148, offset_heap=0x7ffff0a85140, old_vers=0x7ffff0a84ef0, vrow=0x0, mtr=0x7ffff0a85cf0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0sel.cc:3323
#7  0x00005555561aa91b in row_sel_get_clust_rec_for_mysql (prebuilt=0x7fff9c01e1b8, sec_index=0x7fffa8023128, rec=0x7ffff128407e "\200", thr=0x7fff9c01e930, out_rec=0x7ffff0a85128, offsets=0x7ffff0a85148, offset_heap=0x7ffff0a85140, vrow=0x0, mtr=0x7ffff0a85cf0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0sel.cc:3534
#8  0x00005555561ae865 in row_search_mvcc (buf=0x7fff9c01c7f8 "\377", '\245' <repeats 15 times>, "\377\001", mode=PAGE_CUR_G, prebuilt=0x7fff9c01e1b8, match_mode=0, direction=0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0sel.cc:5294
#9  0x000055555601abfc in ha_innobase::index_read (this=0x7fff9c01bff8, buf=0x7fff9c01c7f8 "\377", '\245' <repeats 15 times>, "\377\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10024
#10 0x000055555601bf75 in ha_innobase::index_first (this=0x7fff9c01bff8, buf=0x7fff9c01c7f8 "\377", '\245' <repeats 15 times>, "\377\001") at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10452
#11 0x0000555555dff0f8 in handler::ha_index_first (this=0x7fff9c01bff8, buf=0x7fff9c01c7f8 "\377", '\245' <repeats 15 times>, "\377\001") at /home/midenok/src/mariadb/ibbug/src/sql/handler.cc:2740
#12 0x0000555555bcaffc in join_read_first (tab=0x7fffa8014228) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:19798
#13 0x0000555555bc8927 in sub_select (join=0x7fffa8012eb8, join_tab=0x7fffa8014228, end_of_records=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18815
#14 0x0000555555bc7e30 in do_select (join=0x7fffa8012eb8, procedure=0x0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18358
#15 0x0000555555ba1bcd in JOIN::exec_inner (this=0x7fffa8012eb8) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3820
#16 0x0000555555ba0f5a in JOIN::exec (this=0x7fffa8012eb8) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3623
#17 0x0000555555ba234b in mysql_select (thd=0x7fffa8000b00, tables=0x7fffa8012798, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=0x7fffa8012e98, unit=0x7fffa80046e0, select_lex=0x7fffa8004e40) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:4015
#18 0x0000555555b94b9c in handle_select (thd=0x7fffa8000b00, lex=0x7fffa8004618, result=0x7fffa8012e98, setup_tables_done_option=0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:363
#19 0x0000555555b5fdcf in execute_sqlcom_select (thd=0x7fffa8000b00, all_tables=0x7fffa8012798) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:6455
#20 0x0000555555b57aa5 in mysql_execute_command (thd=0x7fffa8000b00) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:3574
#21 0x0000555555b63110 in mysql_parse (thd=0x7fffa8000b00, rawbuf=0x7fffa8012558 "select * from t1 force index (b)", length=32, parser_state=0x7ffff0a87660, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:7902

@midenok
Copy link
Owner Author

midenok commented Jul 5, 2017 •
edited
Loading

1st loop: row_vers_build_for_consistent_read();
2nd loop: row_search_mvcc().

@midenok
Copy link
Owner Author

midenok commented Jul 6, 2017 •
edited
Loading

At row0sel.cc:4699:

--- cur1.log    2017-07-06 10:12:27.667384452 +0300
+++ cur2.log    2017-07-06 10:12:19.190576743 +0300
@@ -1,9 +1,9 @@
-$43 = {
+$44 = {
   btr_cur = {
     index = 0x7fffa8023128,
     page_cur = {
       index = 0x0,
-      rec = 0x7ffff12840ea "\200",
+      rec = 0x7ffff12840fc "\200",
       offsets = 0x0,
       block = 0x7ffff0d5dc00
     },

There are many records in secondary index (history?), for every one of them it scans whole history of clustered index (row_sel_get_clust_rec_for_mysql()).

@midenok
Copy link
Owner Author

midenok commented Aug 2, 2017 •
edited
Loading

pcur->btr_cur->page_cur->rec changed

#0  page_cur_move_to_next (cur=0x7fff8c01e150) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/page0cur.ic:185
#1  0x00005555561a2912 in btr_pcur_move_to_next_on_page (cursor=0x7fff8c01e148) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/btr0pcur.ic:262
#2  0x00005555561a2a73 in btr_pcur_move_to_next (cursor=0x7fff8c01e148, mtr=0x7fffe5719db0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/btr0pcur.ic:402
#3  0x00005555561af247 in row_search_mvcc (buf=0x7fff8c019f18 "\375\001", mode=PAGE_CUR_G, prebuilt=0x7fff8c01df68, match_mode=0, direction=1) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0sel.cc:5599
#4  0x000055555601bc15 in ha_innobase::general_fetch (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\375\001", direction=1, match_mode=0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10343
#5  0x000055555601bea4 in ha_innobase::index_next (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\375\001") at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10410
#6  0x0000555555dfeb7b in handler::ha_index_next (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\375\001") at /home/midenok/src/mariadb/ibbug/src/sql/handler.cc:2699
#7  0x0000555555bcb0be in join_read_next (info=0x7fff8c012d90) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:19812
#8  0x0000555555bc8a84 in sub_select (join=0x7fff8c011958, join_tab=0x7fff8c012cc8, end_of_records=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18837
#9  0x0000555555bc7e30 in do_select (join=0x7fff8c011958, procedure=0x0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18358
#10 0x0000555555ba1bcd in JOIN::exec_inner (this=0x7fff8c011958) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3820
#11 0x0000555555ba0f5a in JOIN::exec (this=0x7fff8c011958) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3623
#12 0x0000555555ba234b in mysql_select (thd=0x7fff8c000b00, tables=0x7fff8c011238, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148797184, result=0x7fff8c011938, unit=0x7fff8c0046e0, select_lex=0x7fff8c004e40) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:4015
#13 0x0000555555b94b9c in handle_select (thd=0x7fff8c000b00, lex=0x7fff8c004618, result=0x7fff8c011938, setup_tables_done_option=0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:363
#14 0x0000555555b5fdcf in execute_sqlcom_select (thd=0x7fff8c000b00, all_tables=0x7fff8c011238) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:6455
#15 0x0000555555b57aa5 in mysql_execute_command (thd=0x7fff8c000b00) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:3574
#16 0x0000555555b63110 in mysql_parse (thd=0x7fff8c000b00, rawbuf=0x7fff8c010ff8 "select * from t1 force index (b)", length=32, parser_state=0x7fffe571b6b0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:7902

(gdb) p pcur->btr_cur->index->name
$11 = {
  m_name = 0x7fffcc0132c8 "b"
}

Don't see any allusion to history in secondary index. What is multiple records' nature of secondary index? Should dump some data to see how it behaves...

@midenok
Copy link
Owner Author

midenok commented Aug 3, 2017

1 record on disk as expected:

innodb_space -s ibdata1 -T test/t1 -I b index-recurse
ROOT NODE #4: 1 records, 18 bytes
  RECORD: (b=2, c=32) → (a=1, b=-2145386408)

@midenok
Copy link
Owner Author

midenok commented Aug 5, 2017

From 14.3 InnoDB Multi-Versioning:

When a secondary index column is updated, old secondary index records are delete-marked, new records are inserted, and delete-marked records are eventually purged. When a secondary index record is delete-marked or the secondary index page is updated by a newer transaction, InnoDB looks up the database record in the clustered index. In the clustered index, the record's DB_TRX_ID is checked, and the correct version of the record is retrieved from the undo log if the record was modified after the reading transaction was initiated.

@midenok
Copy link
Owner Author

midenok commented Aug 6, 2017 •
edited
Loading

Mark deleted on secondary index

#0  btr_cur_del_mark_set_sec_rec (flags=0, cursor=0x7fffe56e7870, val=1, thr=0x7fff8c01ee48, mtr=0x7fffe56e7af0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/btr/btr0cur.cc:4758
#1  0x00005555561d02fa in row_upd_sec_index_entry (node=0x7fff8c01eae0, thr=0x7fff8c01ee48) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0upd.cc:2394
#2  0x00005555561d063d in row_upd_sec_step (node=0x7fff8c01eae0, thr=0x7fff8c01ee48) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0upd.cc:2502
#3  0x00005555561d245b in row_upd (node=0x7fff8c01eae0, thr=0x7fff8c01ee48) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0upd.cc:3289
#4  0x00005555561d27da in row_upd_step (thr=0x7fff8c01ee48) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0upd.cc:3406
#5  0x00005555561725a3 in row_update_for_mysql_using_upd_graph (mysql_rec=0x7fff8c019f28 "\375\001", prebuilt=0x7fff8c01df68, vers_set_fields=false) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0mysql.cc:2048
#6  0x00005555561731a7 in row_update_for_mysql (mysql_rec=0x7fff8c019f28 "\375\001", prebuilt=0x7fff8c01df68, vers_set_fields=false) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0mysql.cc:2268
#7  0x0000555556019dc4 in ha_innobase::update_row (this=0x7fff8c01d308, old_row=0x7fff8c019f28 "\375\001", new_row=0x7fff8c019f18 "\375\001") at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:9544
#8  0x0000555555e070b1 in handler::ha_update_row (this=0x7fff8c01d308, old_data=0x7fff8c019f28 "\375\001", new_data=0x7fff8c019f18 "\375\001") at /home/midenok/src/mariadb/ibbug/src/sql/handler.cc:6045
#9  0x0000555555b2af1e in write_record (thd=0x7fff90000b00, table=0x7fff8c01c6f0, info=0x7fffe56e8980) at /home/midenok/src/mariadb/ibbug/src/sql/sql_insert.cc:1826
#10 0x0000555555b28dea in mysql_insert (thd=0x7fff90000b00, table_list=0x7fff9002b410, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_UPDATE, ignore=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_insert.cc:1058
#11 0x0000555555b59fb2 in mysql_execute_command (thd=0x7fff90000b00) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:4535
#12 0x0000555555f7db68 in sp_instr_stmt::exec_core (this=0x7fff9002e210, thd=0x7fff90000b00, nextp=0x7fffe56e9424) at /home/midenok/src/mariadb/ibbug/src/sql/sp_head.cc:3344
#13 0x0000555555f7d0fb in sp_lex_keeper::reset_lex_and_exec_core (this=0x7fff9002e258, thd=0x7fff90000b00, nextp=0x7fffe56e9424, open_tables=false, instr=0x7fff9002e210) at /home/midenok/src/mariadb/ibbug/src/sql/sp_head.cc:3088
#14 0x0000555555f7d7ff in sp_instr_stmt::execute (this=0x7fff9002e210, thd=0x7fff90000b00, nextp=0x7fffe56e9424) at /home/midenok/src/mariadb/ibbug/src/sql/sp_head.cc:3260
#15 0x0000555555f77bfb in sp_head::execute (this=0x7fff90029b88, thd=0x7fff90000b00, merge_da_on_success=true) at /home/midenok/src/mariadb/ibbug/src/sql/sp_head.cc:1233
#16 0x0000555555f79e59 in sp_head::execute_procedure (this=0x7fff90029b88, thd=0x7fff90000b00, args=0x7fff90005440) at /home/midenok/src/mariadb/ibbug/src/sql/sp_head.cc:2059
#17 0x0000555555b55e94 in do_execute_sp (thd=0x7fff90000b00, sp=0x7fff90029b88) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:2882
#18 0x0000555555b5dabd in mysql_execute_command (thd=0x7fff90000b00) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:5810
#19 0x0000555555b63110 in mysql_parse (thd=0x7fff90000b00, rawbuf=0x7fff90010ff8 "call insert_n(10)", length=17, parser_state=0x7fffe56ea6b0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:7902

grep "Breakpoint 1" gdb.log |wc -l
100

@midenok
Copy link
Owner Author

midenok commented Aug 7, 2017 •
edited
Loading

1. Get secondary index record

#0 page_cur_get_rec (cur=0x7fff8c01e150) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/page0cur.ic:96
#1 0x00005555561a21fd in btr_cur_get_rec (cursor=0x7fff8c01e148) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/btr0cur.ic:72
#2 0x00005555561a250d in btr_pcur_get_rec (cursor=0x7fff8c01e148) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/include/btr0pcur.ic:112
#3 0x00005555561ad1cf in row_search_mvcc (buf=0x7fff8c019f18 "\377", '\245' <repeats 15 times>, "\377\001", mode=PAGE_CUR_G, prebuilt=0x7fff8c01df68, match_mode=0, direction=0) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/row/row0sel.cc:4697
#4 0x000055555601abfc in ha_innobase::index_read (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\377", '\245' <repeats 15 times>, "\377\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10024
#5 0x000055555601bf75 in ha_innobase::index_first (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\377", '\245' <repeats 15 times>, "\377\001") at /home/midenok/src/mariadb/ibbug/src/storage/innobase/handler/ha_innodb.cc:10452
#6 0x0000555555dff13e in handler::ha_index_first (this=0x7fff8c01d308, buf=0x7fff8c019f18 "\377", '\245' <repeats 15 times>, "\377\001") at /home/midenok/src/mariadb/ibbug/src/sql/handler.cc:2740
#7 0x0000555555bcaffc in join_read_first (tab=0x7fff8c012cc8) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:19798
#8 0x0000555555bc8927 in sub_select (join=0x7fff8c011958, join_tab=0x7fff8c012cc8, end_of_records=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18815
#9 0x0000555555bc7e30 in do_select (join=0x7fff8c011958, procedure=0x0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:18358
#10 0x0000555555ba1bcd in JOIN::exec_inner (this=0x7fff8c011958) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3820
#11 0x0000555555ba0f5a in JOIN::exec (this=0x7fff8c011958) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:3623
#12 0x0000555555ba234b in mysql_select (thd=0x7fff8c000b00, tables=0x7fff8c011238, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2148797184, result=0x7fff8c011938, unit=0x7fff8c0046e0, select_lex=0x7fff8c004e40) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:4015
#13 0x0000555555b94b9c in handle_select (thd=0x7fff8c000b00, lex=0x7fff8c004618, result=0x7fff8c011938, setup_tables_done_option=0) at /home/midenok/src/mariadb/ibbug/src/sql/sql_select.cc:363
#14 0x0000555555b5fdcf in execute_sqlcom_select (thd=0x7fff8c000b00, all_tables=0x7fff8c011238) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:6455
#15 0x0000555555b57aa5 in mysql_execute_command (thd=0x7fff8c000b00) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:3574
#16 0x0000555555b63110 in mysql_parse (thd=0x7fff8c000b00, rawbuf=0x7fff8c010ff8 "select * from t1 force index (b)", length=32, parser_state=0x7fffe571b6b0, is_com_multi=false, is_next_command=false) at /home/midenok/src/mariadb/ibbug/src/sql/sql_parse.cc:7902

2. ICP_MATCH case

   5126                         if (!srv_read_only_mode
   5127                             && !lock_sec_rec_cons_read_sees(
   5128                                         rec, index, trx->read_view)) {
   5129                                 /* We should look at the clustered index.
   5130                                 However, as this is a non-locking read,
   5131                                 we can skip the clustered index lookup if
   5132                                 the condition does not match the secondary
   5133                                 index entry. */
   5134                                 switch (row_search_idx_cond_check(
   5135                                                 buf, prebuilt, rec, offsets)) {
   5136                                 case ICP_NO_MATCH:
   5137                                         goto next_rec;
   5138                                 case ICP_OUT_OF_RANGE:
   5139                                 case ICP_ABORTED_BY_USER:
   5140                                 case ICP_ERROR:
   5141                                         err = DB_RECORD_NOT_FOUND;
   5142                                         goto idx_cond_failed;
   5143                                 case ICP_MATCH:
   5144                                         goto requires_clust_rec;
   5145                                 }
/**
  Return values of index_cond_func_xxx functions.

  0=ICP_NO_MATCH  - index tuple doesn't satisfy the pushed index condition (the
                    engine should discard the tuple and go to the next one)
  1=ICP_MATCH     - index tuple satisfies the pushed index condition (the
                    engine should fetch and return the record)
  2=ICP_OUT_OF_RANGE - index tuple is out range that we're scanning, e.g. this
                      if we're scanning "t.key BETWEEN 10 AND 20" and got a
                      "t.key=21" tuple (the engine should stop scanning and
                      return HA_ERR_END_OF_FILE right away).
  3=ICP_ABORTED_BY_USER - engine must stop scanning and should return 
                         HA_ERR_ABORTED_BY_USER right away
 -1= ICP_ERROR    - Reserved for internal errors in engines. Should not be
                    returned by index_cond_func_xxx
*/

@midenok
Copy link
Owner Author

midenok commented Aug 7, 2017 •
edited
Loading

There are several options to fix the problem:

  1. Modify algorithm of secondary -> clustered index search for more strong coupling (long and complex solution);
  2. Don't make so many secondary index records: if record is not locked by transaction, just overwrite it instead of delete marking (doubtful if it is ever possible);
  3. Purge secondary index before using in SELECT (might not win anything).
  4. Find first valid clustered index record, then find secondary index records (relatively easy to implement, seems it will work).

@midenok
Copy link
Owner Author

midenok commented Aug 8, 2017 •
edited
Loading

row_sel_get_clust_rec_for_mysql()

  1. get clust_rec
	clust_rec = btr_pcur_get_rec(prebuilt->clust_pcur);
  1. build previous version of clust_rec:
			err = row_sel_build_prev_vers_for_mysql(
				trx->read_view, clust_index, prebuilt,
				clust_rec, offsets, offset_heap, &old_vers,
				vrow, mtr);
  1. check if it is for secondary record:
		    && !row_sel_sec_rec_is_for_clust_rec(
			    rec, sec_index, clust_rec, clust_index, thr)) {

Seems that it does 2. spuriously for each secondary row. clust_rec is same each time (like it should).

@midenok
Copy link
Owner Author

midenok commented Aug 12, 2017 •
edited
Loading

After patch ibbug.test stats:

$ grep "^#8.*row_search_mvcc" gdb.log|wc -l
9900
$ grep row_sel_build_prev_vers_for_mysql gdb.log|wc -l
9900

Nothing (or not much) changed when run from mysql-test, though when run from console stats are good.

@midenok
Copy link
Owner Author

midenok commented Aug 12, 2017

We should also preserve NULL value: 'row not found' is also result.

midenok pushed a commit that referenced this issue Nov 19, 2021
@kevgs
TSAN: data race on vptr (ctor/dtor vs virtual call)
78084fa 
  Read of size 8 at 0x7fecf2e75fc8 by thread T2 (mutexes: write M1318):
    #0 tpool::thread_pool_generic::submit_task(tpool::task*) /tpool/tpool_generic.cc:823:9 (mariadbd+0x25fd2d2)
    #1 (anonymous namespace)::aio_uring::thread_routine((anonymous namespace)::aio_uring*) /tpool/aio_liburing.cc:173:20 (mariadbd+0x260b21b)
    #2 void std::__invoke_impl<void, void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*>(std::__invoke_other, void (*&&)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:61:14 (mariadbd+0x260c62a)
    #3 std::__invoke_result<void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*>::type std::__invoke<void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*>(void (*&&)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:96:14 (mariadbd+0x260c4ba)
    #4 void std::thread::_Invoker<std::tuple<void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*> >::_M_invoke<0ul, 1ul>(std::_Index_tuple<0ul, 1ul>) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:253:13 (mariadbd+0x260c442)
    #5 std::thread::_Invoker<std::tuple<void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*> >::operator()() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:260:11 (mariadbd+0x260c3c5)
    #6 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)((anonymous namespace)::aio_uring*), (anonymous namespace)::aio_uring*> > >::_M_run() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:211:13 (mariadbd+0x260c189)
    #7 <null> <null> (libstdc++.so.6+0xd230f)

  Previous write of size 8 at 0x7fecf2e75fc8 by main thread:
    #0 tpool::task::task(void (*)(void*), void*, tpool::task_group*) /tpool/task.cc:40:46 (mariadbd+0x260a138)
    #1 tpool::aiocb::aiocb() /tpool/tpool.h:147:13 (mariadbd+0x2355943)
    #2 void std::_Construct<tpool::aiocb>(tpool::aiocb*) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_construct.h:109:38 (mariadbd+0x2355845)
    #3 tpool::aiocb* std::__uninitialized_default_n_1<false>::__uninit_default_n<tpool::aiocb*, unsigned long>(tpool::aiocb*, unsigned long) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_uninitialized.h:579:3 (mariadbd+0x235576c)
    #4 tpool::aiocb* std::__uninitialized_default_n<tpool::aiocb*, unsigned long>(tpool::aiocb*, unsigned long) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_uninitialized.h:638:14 (mariadbd+0x23556e9)
    #5 tpool::aiocb* std::__uninitialized_default_n_a<tpool::aiocb*, unsigned long, tpool::aiocb>(tpool::aiocb*, unsigned long, std::allocator<tpool::aiocb>&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_uninitialized.h:704:14 (mariadbd+0x2355641)
    #6 std::vector<tpool::aiocb, std::allocator<tpool::aiocb> >::_M_default_initialize(unsigned long) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_vector.h:1606:4 (mariadbd+0x2354f3d)
    #7 std::vector<tpool::aiocb, std::allocator<tpool::aiocb> >::vector(unsigned long, std::allocator<tpool::aiocb> const&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/stl_vector.h:512:9 (mariadbd+0x2354a19)
    #8 tpool::cache<tpool::aiocb>::cache(unsigned long, tpool::cache_notification_mode) /tpool/tpool_structs.h:73:20 (mariadbd+0x2354784)
    #9 io_slots::io_slots(int, int) /storage/innobase/os/os0file.cc:93:3 (mariadbd+0x235343b)
    #10 os_aio_init() /storage/innobase/os/os0file.cc:3780:22 (mariadbd+0x234ebce)
    #11 srv_start(bool) /storage/innobase/srv/srv0start.cc:1190:6 (mariadbd+0x256720c)
    #12 innodb_init(void*) /storage/innobase/handler/ha_innodb.cc:4188:8 (mariadbd+0x1ed3bda)
    #13 ha_initialize_handlerton(st_plugin_int*) /sql/handler.cc:659:31 (mariadbd+0xf7be06)
    #14 plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) /sql/sql_plugin.cc:1463:9 (mariadbd+0x160fa1b)
    #15 plugin_init(int*, char**, int) /sql/sql_plugin.cc:1756:15 (mariadbd+0x160f07f)
    #16 init_server_components() /sql/mysqld.cc:5043:7 (mariadbd+0xd70fb2)
    #17 mysqld_main(int, char**) /sql/mysqld.cc:5655:7 (mariadbd+0xd6a9d7)
    #18 main /sql/main.cc:34:10 (mariadbd+0xd65d18)

I think the report is incorrect: it's not possible to have such a race
condition. I've checked it by reading the code and putting assertions.
Namely, no aio I/O is possible before the end of os_aio_init().
Most probably it's some bug in TSAN. But the patch fixes around 5 related
reports and this is a step toward TSAN usefullness. Currently it reports too
much noise.

std::unique_ptr is a step toward https://isocpp.github.io/CppCoreGuidelines/CppCoreGuidelines#r11-avoid-calling-new-and-delete-explicitly
There is no std::make_unique() in C++11, however.
midenok pushed a commit that referenced this issue Nov 19, 2021
@kevgs
TSAN: unprotected global counter
c8aa812 
WARNING: ThreadSanitizer: data race (pid=1506937)
  Write of size 8 at 0x0000067ab740 by thread T6:
    #0 buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /storage/innobase/buf/buf0buf.cc:2946:8 (mariadbd+0x2014c7f)
    #1 buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /storage/innobase/buf/buf0buf.cc:3047:10 (mariadbd+0x2016216)
    #2 btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, ssux_lock_impl<true>*, mtr_t*, unsigned long) /storage/innobase/btr/btr0cur.cc:1613:10 (mariadbd+0x1fb5bff)
    #3 btr_pcur_open_low(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, unsigned long, mtr_t*) /storage/innobase/include/btr0pcur.ic:439:8 (mariadbd+0x24ddead)
    #4 row_search_on_row_ref(btr_pcur_t*, unsigned long, dict_table_t const*, dtuple_t const*, mtr_t*) /storage/innobase/row/row0row.cc:1215:7 (mariadbd+0x24dd537)
    #5 row_purge_reposition_pcur(unsigned long, purge_node_t*, mtr_t*) /storage/innobase/row/row0purge.cc:81:23 (mariadbd+0x24c5369)
    #6 row_purge_reset_trx_id(purge_node_t*, mtr_t*) /storage/innobase/row/row0purge.cc:748:6 (mariadbd+0x24c90c7)
    #7 row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool) /storage/innobase/row/row0purge.cc:1174:4 (mariadbd+0x24c8262)
    #8 row_purge(purge_node_t*, unsigned char*, que_thr_t*) /storage/innobase/row/row0purge.cc:1218:18 (mariadbd+0x24c5af3)
    #9 row_purge_step(que_thr_t*) /storage/innobase/row/row0purge.cc:1267:3 (mariadbd+0x24c5996)
    #10 que_thr_step(que_thr_t*) /storage/innobase/que/que0que.cc:653:9 (mariadbd+0x23d5298)
    #11 que_run_threads_low(que_thr_t*) /storage/innobase/que/que0que.cc:709:25 (mariadbd+0x23d3f29)
    #12 que_run_threads(que_thr_t*) /storage/innobase/que/que0que.cc:729:2 (mariadbd+0x23d3bdf)
    #13 srv_task_execute() /storage/innobase/srv/srv0srv.cc:1692:3 (mariadbd+0x2562841)
    #14 purge_worker_callback(void*) /storage/innobase/srv/srv0srv.cc:1864:10 (mariadbd+0x255f361)
    #15 tpool::task_group::execute(tpool::task*) /tpool/task_group.cc:55:9 (mariadbd+0x260a5ca)
    #16 tpool::task::execute() /tpool/task.cc:47:16 (mariadbd+0x260adf6)
    #17 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /tpool/tpool_generic.cc:550:11 (mariadbd+0x25fc590)
    #18 void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:74:14 (mariadbd+0x26061b5)
    #19 std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:96:14 (mariadbd+0x2605f57)
    #20 void std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:253:13 (mariadbd+0x2605ecb)
    #21 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:260:11 (mariadbd+0x2605e35)
    #22 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:211:13 (mariadbd+0x2605ac9)
    #23 <null> <null> (libstdc++.so.6+0xd230f)

  Previous write of size 8 at 0x0000067ab740 by thread T8:
    #0 buf_page_get_low(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /storage/innobase/buf/buf0buf.cc:2946:8 (mariadbd+0x2014c7f)
    #1 buf_page_get_gen(page_id_t, unsigned long, unsigned long, buf_block_t*, unsigned long, mtr_t*, dberr_t*, bool) /storage/innobase/buf/buf0buf.cc:3047:10 (mariadbd+0x2016216)
    #2 btr_cur_search_to_nth_level_func(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, ssux_lock_impl<true>*, mtr_t*, unsigned long) /storage/innobase/btr/btr0cur.cc:1613:10 (mariadbd+0x1fb5bff)
    #3 btr_pcur_open_low(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_pcur_t*, unsigned long, mtr_t*) /storage/innobase/include/btr0pcur.ic:439:8 (mariadbd+0x24ddead)
    #4 row_search_on_row_ref(btr_pcur_t*, unsigned long, dict_table_t const*, dtuple_t const*, mtr_t*) /storage/innobase/row/row0row.cc:1215:7 (mariadbd+0x24dd537)
    #5 row_purge_reposition_pcur(unsigned long, purge_node_t*, mtr_t*) /storage/innobase/row/row0purge.cc:81:23 (mariadbd+0x24c5369)
    #6 row_purge_reset_trx_id(purge_node_t*, mtr_t*) /storage/innobase/row/row0purge.cc:748:6 (mariadbd+0x24c90c7)
    #7 row_purge_record_func(purge_node_t*, unsigned char*, que_thr_t const*, bool) /storage/innobase/row/row0purge.cc:1174:4 (mariadbd+0x24c8262)
    #8 row_purge(purge_node_t*, unsigned char*, que_thr_t*) /storage/innobase/row/row0purge.cc:1218:18 (mariadbd+0x24c5af3)
    #9 row_purge_step(que_thr_t*) /storage/innobase/row/row0purge.cc:1267:3 (mariadbd+0x24c5996)
    #10 que_thr_step(que_thr_t*) /storage/innobase/que/que0que.cc:653:9 (mariadbd+0x23d5298)
    #11 que_run_threads_low(que_thr_t*) /storage/innobase/que/que0que.cc:709:25 (mariadbd+0x23d3f29)
    #12 que_run_threads(que_thr_t*) /storage/innobase/que/que0que.cc:729:2 (mariadbd+0x23d3bdf)
    #13 trx_purge(unsigned long, bool) /storage/innobase/trx/trx0purge.cc:1271:2 (mariadbd+0x25841b4)
    #14 srv_do_purge(unsigned long*) /storage/innobase/srv/srv0srv.cc:1784:20 (mariadbd+0x2563224)
    #15 purge_coordinator_callback_low() /storage/innobase/srv/srv0srv.cc:1881:35 (mariadbd+0x2562b3b)
    #16 purge_coordinator_callback(void*) /storage/innobase/srv/srv0srv.cc:1910:3 (mariadbd+0x255f4ab)
    #17 tpool::task_group::execute(tpool::task*) /tpool/task_group.cc:55:9 (mariadbd+0x260a5ca)
    #18 tpool::task::execute() /tpool/task.cc:47:16 (mariadbd+0x260adf6)
    #19 tpool::thread_pool_generic::worker_main(tpool::worker_data*) /tpool/tpool_generic.cc:550:11 (mariadbd+0x25fc590)
    #20 void std::__invoke_impl<void, void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(std::__invoke_memfun_deref, void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:74:14 (mariadbd+0x26061b5)
    #21 std::__invoke_result<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>::type std::__invoke<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*>(void (tpool::thread_pool_generic::*&&)(tpool::worker_data*), tpool::thread_pool_generic*&&, tpool::worker_data*&&) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:96:14 (mariadbd+0x2605f57)
    #22 void std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::_M_invoke<0ul, 1ul, 2ul>(std::_Index_tuple<0ul, 1ul, 2ul>) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:253:13 (mariadbd+0x2605ecb)
    #23 std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> >::operator()() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:260:11 (mariadbd+0x2605e35)
    #24 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (tpool::thread_pool_generic::*)(tpool::worker_data*), tpool::thread_pool_generic*, tpool::worker_data*> > >::_M_run() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:211:13 (mariadbd+0x2605ac9)
    #25 <null> <null> (libstdc++.so.6+0xd230f)

  Location is global 'buf_dbg_counter' of size 8 at 0x0000067ab740 (mariadbd+0x67ab740)

  The obvious fix is to make counter atomic.
midenok pushed a commit that referenced this issue Nov 19, 2021
@kevgs
TSAN: unprotected global variable
d089b51 
WARNING: ThreadSanitizer: data race (pid=1510842)
  Write of size 8 at 0x0000067b1e98 by main thread:
    #0 os_file_pwrite(IORequest const&, int, unsigned char const*, unsigned long, unsigned long, dberr_t*) /storage/innobase/os/os0file.cc:2928:2 (mariadbd+0x234c5ac)
    #1 os_file_write_func(IORequest const&, char const*, int, void const*, unsigned long, unsigned long) /storage/innobase/os/os0file.cc:2963:20 (mariadbd+0x234c019)
    #2 file_os_io::write(char const*, unsigned long, st_::span<unsigned char const>) /storage/innobase/log/log0log.cc:320:10 (mariadbd+0x22eaa50)
    #3 log_file_t::write(unsigned long, st_::span<unsigned char const>) /storage/innobase/log/log0log.cc:434:18 (mariadbd+0x22eb1d8)
    #4 log_t::file::write(unsigned long, st_::span<unsigned char>) /storage/innobase/log/log0log.cc:496:29 (mariadbd+0x22ebb55)
    #5 log_write_buf(unsigned char*, unsigned long, unsigned long, unsigned long, unsigned long) /storage/innobase/log/log0log.cc:614:14 (mariadbd+0x22f1b51)
    #6 log_write(bool) /storage/innobase/log/log0log.cc:755:2 (mariadbd+0x22ed2ec)
    #7 log_write_up_to(unsigned long, bool, bool, completion_callback const*) /storage/innobase/log/log0log.cc:817:5 (mariadbd+0x22eca44)
    #8 log_checkpoint_low(unsigned long, unsigned long) /storage/innobase/buf/buf0flu.cc:1734:5 (mariadbd+0x20d37c1)
    #9 log_checkpoint() /storage/innobase/buf/buf0flu.cc:1787:10 (mariadbd+0x20cd155)
    #10 buf_flush_wait_flushed(unsigned long) /storage/innobase/buf/buf0flu.cc:1867:5 (mariadbd+0x20ccf8f)
    #11 log_make_checkpoint() /storage/innobase/buf/buf0flu.cc:1793:3 (mariadbd+0x20cc4c9)
    #12 buf_dblwr_t::create() /storage/innobase/buf/buf0dblwr.cc:216:3 (mariadbd+0x209076a)
    #13 srv_start(bool) /storage/innobase/srv/srv0start.cc:1685:20 (mariadbd+0x256b4aa)
    #14 innodb_init(void*) /storage/innobase/handler/ha_innodb.cc:4188:8 (mariadbd+0x1ed40da)
    #15 ha_initialize_handlerton(st_plugin_int*) /sql/handler.cc:659:31 (mariadbd+0xf7c2b6)
    #16 plugin_initialize(st_mem_root*, st_plugin_int*, int*, char**, bool) /sql/sql_plugin.cc:1463:9 (mariadbd+0x160fedb)
    #17 plugin_init(int*, char**, int) /sql/sql_plugin.cc:1756:15 (mariadbd+0x160f53f)
    #18 init_server_components() /sql/mysqld.cc:5043:7 (mariadbd+0xd71462)
    #19 mysqld_main(int, char**) /sql/mysqld.cc:5655:7 (mariadbd+0xd6ae87)
    #20 main /sql/main.cc:34:10 (mariadbd+0xd661c8)

  Previous write of size 8 at 0x0000067b1e98 by thread T3:
    #0 os_file_pwrite(IORequest const&, int, unsigned char const*, unsigned long, unsigned long, dberr_t*) /storage/innobase/os/os0file.cc:2928:2 (mariadbd+0x234c5ac)
    #1 os_file_write_func(IORequest const&, char const*, int, void const*, unsigned long, unsigned long) /storage/innobase/os/os0file.cc:2963:20 (mariadbd+0x234c019)
    #2 file_os_io::write(char const*, unsigned long, st_::span<unsigned char const>) /storage/innobase/log/log0log.cc:320:10 (mariadbd+0x22eaa50)
    #3 log_file_t::write(unsigned long, st_::span<unsigned char const>) /storage/innobase/log/log0log.cc:434:18 (mariadbd+0x22eb1d8)
    #4 log_t::file::write(unsigned long, st_::span<unsigned char>) /storage/innobase/log/log0log.cc:496:29 (mariadbd+0x22ebb55)
    #5 log_write_checkpoint_info(unsigned long) /storage/innobase/log/log0log.cc:911:14 (mariadbd+0x22edd4e)
    #6 log_checkpoint_low(unsigned long, unsigned long) /storage/innobase/buf/buf0flu.cc:1755:3 (mariadbd+0x20d3a3d)
    #7 buf_flush_sync_for_checkpoint(unsigned long) /storage/innobase/buf/buf0flu.cc:1947:7 (mariadbd+0x20d4163)
    #8 buf_flush_page_cleaner() /storage/innobase/buf/buf0flu.cc:2186:9 (mariadbd+0x20cdab1)
    #9 void std::__invoke_impl<void, void (*)()>(std::__invoke_other, void (*&&)()) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:61:14 (mariadbd+0x20c3aaa)
    #10 std::__invoke_result<void (*)()>::type std::__invoke<void (*)()>(void (*&&)()) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/invoke.h:96:14 (mariadbd+0x20c39bd)
    #11 void std::thread::_Invoker<std::tuple<void (*)()> >::_M_invoke<0ul>(std::_Index_tuple<0ul>) /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:253:13 (mariadbd+0x20c3965)
    #12 std::thread::_Invoker<std::tuple<void (*)()> >::operator()() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:260:11 (mariadbd+0x20c3905)
    #13 std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)()> > >::_M_run() /usr/lib/gcc/x86_64-linux-gnu/11/../../../../include/c++/11/bits/std_thread.h:211:13 (mariadbd+0x20c37f9)
    #14 <null> <null> (libstdc++.so.6+0xd230f)

  Location is global 'os_n_file_writes' of size 8 at 0x0000067b1e98 (mariadbd+0x67b1e98)

  Make variable atomic.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@midenok