[MDEV-20247] Replication hangs with "preparing" and never starts Created: 2019-08-02  Updated: 2020-08-25  Resolved: 2019-08-07

Status: Closed
Project: MariaDB Server
Component/s: Replication, Storage Engine - InnoDB
Affects Version/s: 10.2.26, 10.1.41, 10.3.17, 10.4.7
Fix Version/s: 10.2.27, 10.1.42, 10.3.18, 10.4.8

Type: Bug Priority: Blocker
Reporter: Phobos Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 9
Labels: regression
Environment:

Devuan / BSD / Linux

Attachments: Text File gdb_out_1047.txt     File my.cnf     File mysqld.err     File slave_db.err     File slave_my.cnf     HTML File trace    
Issue Links:
Duplicate
duplicates MDEV-20288 Shutdown of database and stop slave d... Closed
is duplicated by MDEV-20240 Master/Master slave sync not working Closed
is duplicated by MDEV-20398 Slave sql thread blocked by Update_ro... Closed

 Description   

Hi,

maybe first the setup. Given are 2 FreeBSD nodes running MariaDB 10.4.6 in a master <- -> master replication setup. Care has been taken that both nodes don't insert something in the same DB so that's no problem.
Additionally there's a slave running Devuan ASCII (Debian Jessie) also running MariaDB 10.4.6 installed from the repository you provide.
The slave isn't running 24x7 and primarily used for offsite backups.

The Devuan installation is fresh, since you no longer provide an init script and expect everyone is running systemd, the init script from a previous version has been taken.
Once installation is completed, the following steps have been taken (additionally on the masters).
Renaming the 'root' user to another one, dumping the mysql.user event and correcting the definer to match the new 'root' user.
At one of the masters everything except the mysql DB has been dumped with:

mysqldump -u blah -p --master-data=1 --databases db1 db2 db3 > dump.sql

That dump.sql has been copied and source'd at the slave, including the "change master" things.The host IP, username and password have been set and a "start slave" has been triggered.

Then the fun starts as replication on the slave never does anything:

*************************** 1. row ***************************
 
                Slave_IO_State: NULL
 
                   Master_Host: master_host_ip
 
                   Master_User: local-dbrep
 
                   Master_Port: 3306
 
                 Connect_Retry: 60
 
               Master_Log_File: mysql-bin.000084
 
           Read_Master_Log_Pos: 1917045
 
                Relay_Log_File: slave-relay.000001
 
                 Relay_Log_Pos: 4
 
         Relay_Master_Log_File: mysql-bin.000084
 
              Slave_IO_Running: Preparing
 
             Slave_SQL_Running: Yes
 
               Replicate_Do_DB: 
           Replicate_Ignore_DB: mysql,mysql
 
            Replicate_Do_Table: 
        Replicate_Ignore_Table: db1.session,db2.session
 
       Replicate_Wild_Do_Table: 
   Replicate_Wild_Ignore_Table: 
                    Last_Errno: 0
 
                    Last_Error: 
                  Skip_Counter: 0
 
           Exec_Master_Log_Pos: 1917045
 
               Relay_Log_Space: 512
 
               Until_Condition: None
 
                Until_Log_File: 
                 Until_Log_Pos: 0
 
            Master_SSL_Allowed: No
 
            Master_SSL_CA_File: 
            Master_SSL_CA_Path: 
               Master_SSL_Cert: 
             Master_SSL_Cipher: 
                Master_SSL_Key: 
         Seconds_Behind_Master: NULL
 
 Master_SSL_Verify_Server_Cert: No
 
                 Last_IO_Errno: 0
 
                 Last_IO_Error: 
                Last_SQL_Errno: 0
 
                Last_SQL_Error: 
   Replicate_Ignore_Server_Ids: 
              Master_Server_Id: 1
 
                Master_SSL_Crl: 
            Master_SSL_Crlpath: 
                    Using_Gtid: No
 
                   Gtid_IO_Pos: 
       Replicate_Do_Domain_Ids: 
   Replicate_Ignore_Domain_Ids: 
                 Parallel_Mode: conservative
 
                     SQL_Delay: 0
 
           SQL_Remaining_Delay: NULL
 
       Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
 
              Slave_DDL_Groups: 0
 
Slave_Non_Transactional_Groups: 0
 
    Slave_Transactional_Groups: 0
 
1 row in set (0.000 sec)

The log reports that the slave has been connected to the master, at the master the log reports a connection from the slave.
A show full processlist reports

*************************** 1. row ***************************
 
      Id: 1
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Daemon
 
    Time: NULL
 
   State: InnoDB purge worker
 
    Info: NULL
 
Progress: 0.000
 
*************************** 2. row ***************************
 
      Id: 2
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Daemon
 
    Time: NULL
 
   State: InnoDB purge worker
 
    Info: NULL
 
Progress: 0.000
 
*************************** 3. row ***************************
 
      Id: 3
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Daemon
 
    Time: NULL
 
   State: InnoDB purge worker
 
    Info: NULL
 
Progress: 0.000
 
*************************** 4. row ***************************
 
      Id: 4
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Daemon
 
    Time: NULL
 
   State: InnoDB purge coordinator
 
    Info: NULL
 
Progress: 0.000
 
*************************** 5. row ***************************
 
      Id: 5
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Daemon
 
    Time: NULL
 
   State: InnoDB shutdown handler
 
    Info: NULL
 
Progress: 0.000
 
*************************** 6. row ***************************
 
      Id: 42
 
    User: my_new_root_user
 
    Host: localhost
 
      db: NULL
 
 Command: Query
 
    Time: 0
 
   State: Init
 
    Info: show full processlist
 
Progress: 0.000
 
*************************** 7. row ***************************
 
      Id: 43
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Connect
 
    Time: 690
 
   State: NULL
 
    Info: NULL
 
Progress: 0.000
 
*************************** 8. row ***************************
 
      Id: 44
 
    User: system user
 
    Host:
 
      db: NULL
 
 Command: Slave_SQL
 
    Time: 690
 
   State: Slave has read all relay log; waiting for the slave I/O thread to update it
 
    Info: NULL
 
Progress: 0.000
 
8 rows in set (0.000 sec)

No replication happens at all at the slave, while everything between the 2 masters works fine.

Manually doing a "stop slave;" at the slave hangs and nothing happens. Additionally, while the slave is still running, doing a "mysqlcheck mysql --auto-repair --optimize" the process hangs at the "mysql.gtid_slave_pos" table.

Additionally trying to shutdown MariaDB via "mysqladmin shutdown" the process gets struck, strace doesn't show anything and a processlist shows "flushing relay log" which, after being kept running for 30 minutes, was killed manually.

The entire setup has been working with MariaDB 10.1.2 and it's guaranteed to work with MySQL 8.0 without any problem at all.

 Comments   
Comment by Michael Hicke [ 2019-08-04 ]

Same problem here with version 10.2.26

Comment by bulepage [ 2019-08-04 ]

same problem with 10.3.17

Comment by Michael Hicke [ 2019-08-04 ]

downgraded 10.2.26 => 10.2.25. Replication ist working again.

Comment by Ahmet [ 2019-08-05 ]

Same here with 10.4.7 (1:10.4.7+maria~xenial)

Edit: Why is this a Minor Issue. Replication is mostly used in critical environments and should be prioritized higher.

Comment by Vik API [ 2019-08-05 ]

Same problem here. Here we are on master: MariaDB 10.1.40 and slaves on MariaDB 10.1.41. Replication is not GTID based. The behaviour is exactly the same. It just states Slave IO with status "Preparing". You cannot stop slave as well. You will have to Kill the MySQL process as restart doesn't work as well.

Looks like Issue MDEV-20240 is same as well?

VK.

Comment by Phobos [ 2019-08-05 ]

I initially thought it's just me, so I put the priority on "Minor" as the developers might have more serious issues then trying to fix a problem that just happens to me.
As it's not just my setup, I've raised the priority. And yes MDEV-20240 reports the same issue.

Uncle EDIT told me to put in other affected versions.

Comment by Ahmet [ 2019-08-05 ]

Hey phobos,
Thank you

Comment by MG [ 2019-08-05 ]

This affected me on Linux, using a 10.3.17 slave, where the master is running an old version of 10.0 (which is being decommissioned)

Downgrading the slave to 10.3.16 resolved the issue.

Comment by Sietse [ 2019-08-06 ]

10.2.26 here also. Same problem.

Comment by Alice Sherepa [ 2019-08-06 ]

Please provide error logs from both servers and .cnf file(s). Would you be able maybe to get a stack trace from the hanging process? You'd need to run

gdb --batch --eval-command="thread apply all bt" <path to mysqld binary> <mysqld pid>

Comment by Phobos [ 2019-08-06 ]

Done. Both the my.cnf files from one of the masters and the slave. The master's my.cnf's don't differ, except some memory related values.
Additionally the logs of both machines and the stack trace. The trace has been created while "mysqladmin shutdown" has been trigged.

Note to the logs - since I run Monit that accesses the socket from time to time I get some messages in the logs about "unsuccessful login" which I'm aware of. These messages have been removed.
If you need a fresh log of on of the masters, I may restart mysqld there if you need the initial messages.

Another note - the "timeout" I see in the master log, there's no network problem as I can manually connect each time without any problem via "mysql -u replica_user -p -h master_ip"

Comment by MG [ 2019-08-06 ]

@Phobos I have been able to reproduce this with `innodb_thread_concurrency = 8` but not otherwise.

Can you try commenting L53 on your slave configuration (remove the above)

Comment by Aleksandr [ 2019-08-06 ]

Yes, I have such a line. But previously it worked with this line.

Comment by Elena Stepanova [ 2019-08-07 ]

Thank you, it is very helpful.

The very first test case from rpl suite makes the slave hang when run with innodb_thread_concurrency=8 (or 2, or 32). It doesn't stop at Preparing phase, but at some point upon applying event, also in handler::ha_write_row as phobos'es stack trace shows.

perl ./mtr rpl.rpl_auto_increment --mysqld=--innodb-thread-concurrency=2

10.1.41

 
rpl.rpl_auto_increment 'mix,xtradb'      [ fail ]
 
        Test ended at 2019-08-07 02:31:31
 
...
 
analyze: sync_with_master
 
mysqltest: In included file "./extra/rpl_tests/rpl_auto_increment.test": 
included from /data/releases/10.1.41/mysql-test/suite/rpl/t/rpl_auto_increment.test at line 8:
 
At line 58: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 4176, 300, '')' returned -1 indicating timeout after 300 seconds
 
...


Thread 27 (Thread 0x7f7f73770700 (LWP 7317)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=2000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9af083a in innobase_srv_conc_enter_innodb (trx=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/handler/ha_innodb.cc:1955
 
#3  0x000055ddd9b09f9d in ha_innobase::write_row (this=0x7f7f5cca4020, record=0x7f7f5cc67820 "\377\n") at /home/buildbot/buildbot/build/storage/xtradb/handler/ha_innodb.cc:9062
 
#4  0x000055ddd98e69c7 in handler::ha_write_row (this=0x7f7f5cca4020, buf=0x7f7f5cc67820 "\377\n") at /home/buildbot/buildbot/build/sql/handler.cc:6009
 
#5  0x000055ddd9745a71 in write_record (thd=thd@entry=0x7f7f5cc2b008, table=table@entry=0x7f7f5cc81c08, info=info@entry=0x7f7f7376d560) at /home/buildbot/buildbot/build/sql/sql_insert.cc:1912
 
#6  0x000055ddd9748811 in mysql_insert (thd=thd@entry=0x7f7f5cc2b008, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/buildbot/buildbot/build/sql/sql_insert.cc:1039
 
#7  0x000055ddd9760368 in mysql_execute_command (thd=thd@entry=0x7f7f5cc2b008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:3669
 
#8  0x000055ddd9766a05 in mysql_parse (thd=0x7f7f5cc2b008, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f7f7376edc0) at /home/buildbot/buildbot/build/sql/sql_parse.cc:7209
 
#9  0x000055ddd99a73ac in Query_log_event::do_apply_event (this=0x7f7f5e13f148, rgi=0x7f7f5cc12600, query_arg=0x7f7f5cc58253 "insert into t1 values (NULL),(5),(NULL)", q_len_arg=0) at /home/buildbot/buildbot/build/sql/log_event.cc:4533
 
#10 0x000055ddd96f2c11 in Log_event::apply_event (this=0x7f7f5e13f148, rgi=rgi@entry=0x7f7f5cc12600) at /home/buildbot/buildbot/build/sql/log_event.h:1343
 
#11 0x000055ddd96e6223 in apply_event_and_update_pos_apply (ev=ev@entry=0x7f7f5e13f148, thd=thd@entry=0x7f7f5cc2b008, rgi=rgi@entry=0x7f7f5cc12600, reason=<optimized out>) at /home/buildbot/buildbot/build/sql/slave.cc:3479
 
#12 0x000055ddd96e8b1a in apply_event_and_update_pos (ev=ev@entry=0x7f7f5e13f148, thd=thd@entry=0x7f7f5cc2b008, rgi=rgi@entry=0x7f7f5cc12600) at /home/buildbot/buildbot/build/sql/slave.cc:3600
 
#13 0x000055ddd96ebfdd in exec_relay_log_event (serial_rgi=0x7f7f5cc12600, rli=0x7f7f6c6459d0, thd=0x7f7f5cc2b008) at /home/buildbot/buildbot/build/sql/slave.cc:3885
 
#14 handle_slave_sql (arg=arg@entry=0x7f7f6c644000) at /home/buildbot/buildbot/build/sql/slave.cc:4981
 
#15 0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f5e01a208) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#16 0x00007f7f743b44a4 in start_thread (arg=0x7f7f73770700) at pthread_create.c:456
 
#17 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97

all threads

 
Thread 29 (Thread 0x7f7f736da700 (LWP 7322)):
 
#0  0x00007f7f73a678bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9e11384 in vio_io_wait (vio=vio@entry=0x7f7f72c3f808, event=event@entry=VIO_IO_EVENT_READ, timeout=28800000) at /home/buildbot/buildbot/build/vio/viosocket.c:992
 
#2  0x000055ddd9e11423 in vio_socket_io_wait (vio=vio@entry=0x7f7f72c3f808, event=event@entry=VIO_IO_EVENT_READ) at /home/buildbot/buildbot/build/vio/viosocket.c:108
 
#3  0x000055ddd9e116ad in vio_read (vio=0x7f7f72c3f808, buf=0x7f7f67259008 "\001", size=4) at /home/buildbot/buildbot/build/vio/viosocket.c:184
 
#4  0x000055ddd96d6872 in my_real_read (net=0x7f7f67253240, complen=complen@entry=0x7f7f736d9960, header=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:877
 
#5  0x000055ddd96d756d in my_net_read_packet (net=0x7f7f67253240, read_from_server=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:1140
 
#6  0x000055ddd976998c in do_command (thd=0x7f7f67253008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1002
 
#7  0x000055ddd982d69b in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f7f67253008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1331
 
#8  0x000055ddd982d747 in handle_one_connection (arg=arg@entry=0x7f7f67253008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1242
 
#9  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3fa08) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#10 0x00007f7f743b44a4 in start_thread (arg=0x7f7f736da700) at pthread_create.c:456
 
#11 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 28 (Thread 0x7f7f73725700 (LWP 7321)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9822d46 in inline_mysql_cond_timedwait (abstime=0x7f7f73721c60, mutex=0x7f7f6c647390, that=0x7f7f6c647460, src_file=<optimized out>, src_line=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1191
 
#2  Relay_log_info::wait_for_pos (this=this@entry=0x7f7f6c6459d0, thd=thd@entry=0x7f7f67248008, log_name=log_name@entry=0x7f7f5c820168, log_pos=log_pos@entry=4176, timeout=timeout@entry=300) at /home/buildbot/buildbot/build/sql/rpl_rli.cc:947
 
#3  0x000055ddd9931e0c in Item_master_pos_wait::val_int (this=0x7f7f5c820478) at /home/buildbot/buildbot/build/sql/item_func.cc:3943
 
#4  0x000055ddd98ec0bc in Item::send (this=0x7f7f5c820478, protocol=0x7f7f67248510, buffer=0x7f7f73722010) at /home/buildbot/buildbot/build/sql/item.cc:6432
 
#5  0x000055ddd96dc194 in Protocol::send_result_set_row (this=this@entry=0x7f7f67248510, row_items=<optimized out>) at /home/buildbot/buildbot/build/sql/protocol.cc:914
 
#6  0x000055ddd97347a8 in select_send::send_data (this=0x7f7f5c8206b8, items=...) at /home/buildbot/buildbot/build/sql/sql_class.cc:2761
 
#7  0x000055ddd97b76e6 in JOIN::exec_inner (this=this@entry=0x7f7f5c8206d8) at /home/buildbot/buildbot/build/sql/sql_select.cc:2643
 
#8  0x000055ddd97b8e2e in JOIN::exec (this=this@entry=0x7f7f5c8206d8) at /home/buildbot/buildbot/build/sql/sql_select.cc:2564
 
#9  0x000055ddd97b581a in mysql_select (thd=thd@entry=0x7f7f67248008, rref_pointer_array=rref_pointer_array@entry=0x7f7f6724c348, tables=<optimized out>, wild_num=<optimized out>, fields=..., conds=<optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608, result=result@entry=0x7f7f5c8206b8, unit=unit@entry=0x7f7f6724b998, select_lex=select_lex@entry=0x7f7f6724c0a0) at /home/buildbot/buildbot/build/sql/sql_select.cc:3501
 
#10 0x000055ddd97b9115 in handle_select (thd=thd@entry=0x7f7f67248008, lex=lex@entry=0x7f7f6724b8d0, result=result@entry=0x7f7f5c8206b8, setup_tables_done_option=setup_tables_done_option@entry=0) at /home/buildbot/buildbot/build/sql/sql_select.cc:389
 
#11 0x000055ddd9757740 in execute_sqlcom_select (thd=thd@entry=0x7f7f67248008, all_tables=0x0) at /home/buildbot/buildbot/build/sql/sql_parse.cc:5691
 
#12 0x000055ddd975f91e in mysql_execute_command (thd=thd@entry=0x7f7f67248008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:3038
 
#13 0x000055ddd9766a05 in mysql_parse (thd=0x7f7f67248008, rawbuf=<optimized out>, length=<optimized out>, parser_state=0x7f7f73724200) at /home/buildbot/buildbot/build/sql/sql_parse.cc:7209
 
#14 0x000055ddd976946e in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x7f7f67248008, packet=packet@entry=0x7f7f6724e009 "", packet_length=1552023584, packet_length@entry=58) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1499
 
#15 0x000055ddd9769a47 in do_command (thd=0x7f7f67248008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1131
 
#16 0x000055ddd982d69b in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f7f67248008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1331
 
#17 0x000055ddd982d747 in handle_one_connection (arg=arg@entry=0x7f7f67248008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1242
 
#18 0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3f608) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#19 0x00007f7f743b44a4 in start_thread (arg=0x7f7f73725700) at pthread_create.c:456
 
#20 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 27 (Thread 0x7f7f73770700 (LWP 7317)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=2000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9af083a in innobase_srv_conc_enter_innodb (trx=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/handler/ha_innodb.cc:1955
 
#3  0x000055ddd9b09f9d in ha_innobase::write_row (this=0x7f7f5cca4020, record=0x7f7f5cc67820 "\377\n") at /home/buildbot/buildbot/build/storage/xtradb/handler/ha_innodb.cc:9062
 
#4  0x000055ddd98e69c7 in handler::ha_write_row (this=0x7f7f5cca4020, buf=0x7f7f5cc67820 "\377\n") at /home/buildbot/buildbot/build/sql/handler.cc:6009
 
#5  0x000055ddd9745a71 in write_record (thd=thd@entry=0x7f7f5cc2b008, table=table@entry=0x7f7f5cc81c08, info=info@entry=0x7f7f7376d560) at /home/buildbot/buildbot/build/sql/sql_insert.cc:1912
 
#6  0x000055ddd9748811 in mysql_insert (thd=thd@entry=0x7f7f5cc2b008, table_list=<optimized out>, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/buildbot/buildbot/build/sql/sql_insert.cc:1039
 
#7  0x000055ddd9760368 in mysql_execute_command (thd=thd@entry=0x7f7f5cc2b008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:3669
 
#8  0x000055ddd9766a05 in mysql_parse (thd=0x7f7f5cc2b008, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f7f7376edc0) at /home/buildbot/buildbot/build/sql/sql_parse.cc:7209
 
#9  0x000055ddd99a73ac in Query_log_event::do_apply_event (this=0x7f7f5e13f148, rgi=0x7f7f5cc12600, query_arg=0x7f7f5cc58253 "insert into t1 values (NULL),(5),(NULL)", q_len_arg=0) at /home/buildbot/buildbot/build/sql/log_event.cc:4533
 
#10 0x000055ddd96f2c11 in Log_event::apply_event (this=0x7f7f5e13f148, rgi=rgi@entry=0x7f7f5cc12600) at /home/buildbot/buildbot/build/sql/log_event.h:1343
 
#11 0x000055ddd96e6223 in apply_event_and_update_pos_apply (ev=ev@entry=0x7f7f5e13f148, thd=thd@entry=0x7f7f5cc2b008, rgi=rgi@entry=0x7f7f5cc12600, reason=<optimized out>) at /home/buildbot/buildbot/build/sql/slave.cc:3479
 
#12 0x000055ddd96e8b1a in apply_event_and_update_pos (ev=ev@entry=0x7f7f5e13f148, thd=thd@entry=0x7f7f5cc2b008, rgi=rgi@entry=0x7f7f5cc12600) at /home/buildbot/buildbot/build/sql/slave.cc:3600
 
#13 0x000055ddd96ebfdd in exec_relay_log_event (serial_rgi=0x7f7f5cc12600, rli=0x7f7f6c6459d0, thd=0x7f7f5cc2b008) at /home/buildbot/buildbot/build/sql/slave.cc:3885
 
#14 handle_slave_sql (arg=arg@entry=0x7f7f6c644000) at /home/buildbot/buildbot/build/sql/slave.cc:4981
 
#15 0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f5e01a208) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#16 0x00007f7f743b44a4 in start_thread (arg=0x7f7f73770700) at pthread_create.c:456
 
#17 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 26 (Thread 0x7f7f74e8e700 (LWP 7316)):
 
#0  0x00007f7f73a678bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9e11384 in vio_io_wait (vio=vio@entry=0x7f7f5d03d208, event=event@entry=VIO_IO_EVENT_READ, timeout=120000) at /home/buildbot/buildbot/build/vio/viosocket.c:992
 
#2  0x000055ddd9e11423 in vio_socket_io_wait (vio=vio@entry=0x7f7f5d03d208, event=event@entry=VIO_IO_EVENT_READ) at /home/buildbot/buildbot/build/vio/viosocket.c:108
 
#3  0x000055ddd9e116ad in vio_read (vio=vio@entry=0x7f7f5d03d208, buf=0x7f7f5d045008 "%", size=size@entry=16384) at /home/buildbot/buildbot/build/vio/viosocket.c:184
 
#4  0x000055ddd9e11782 in vio_read_buff (vio=0x7f7f5d03d208, buf=0x7f7f5d04a008 "", size=4) at /home/buildbot/buildbot/build/vio/viosocket.c:232
 
#5  0x000055ddd96d6872 in my_real_read (net=0x7f7f5d01db08, complen=complen@entry=0x7f7f74e8d550, header=header@entry=0 '\000') at /home/buildbot/buildbot/build/sql/net_serv.cc:877
 
#6  0x000055ddd96d756d in my_net_read_packet (net=net@entry=0x7f7f5d01db08, read_from_server=read_from_server@entry=0 '\000') at /home/buildbot/buildbot/build/sql/net_serv.cc:1140
 
#7  0x000055ddd98b75d7 in cli_safe_read (mysql=0x7f7f5d01db08) at /home/buildbot/buildbot/build/sql-common/client.c:587
 
#8  0x000055ddd96ed910 in read_event (suppress_warnings=0x7f7f74e8d6c0, mi=0x7f7f6c644000, mysql=0x7f7f5d01db08) at /home/buildbot/buildbot/build/sql/slave.cc:3320
 
#9  handle_slave_io (arg=arg@entry=0x7f7f6c644000) at /home/buildbot/buildbot/build/sql/slave.cc:4332
 
#10 0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3ee08) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#11 0x00007f7f743b44a4 in start_thread (arg=0x7f7f74e8e700) at pthread_create.c:456
 
#12 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 25 (Thread 0x7f7f74ed9700 (LWP 7313)):
 
#0  0x00007f7f73a678bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9e11384 in vio_io_wait (vio=vio@entry=0x7f7f72c3f008, event=event@entry=VIO_IO_EVENT_READ, timeout=28800000) at /home/buildbot/buildbot/build/vio/viosocket.c:992
 
#2  0x000055ddd9e11423 in vio_socket_io_wait (vio=vio@entry=0x7f7f72c3f008, event=event@entry=VIO_IO_EVENT_READ) at /home/buildbot/buildbot/build/vio/viosocket.c:108
 
#3  0x000055ddd9e116ad in vio_read (vio=0x7f7f72c3f008, buf=0x7f7f67243008 "\001", size=4) at /home/buildbot/buildbot/build/vio/viosocket.c:184
 
#4  0x000055ddd96d6872 in my_real_read (net=0x7f7f6723d240, complen=complen@entry=0x7f7f74ed8960, header=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:877
 
#5  0x000055ddd96d756d in my_net_read_packet (net=0x7f7f6723d240, read_from_server=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:1140
 
#6  0x000055ddd976998c in do_command (thd=0x7f7f6723d008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1002
 
#7  0x000055ddd982d69b in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f7f6723d008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1331
 
#8  0x000055ddd982d747 in handle_one_connection (arg=arg@entry=0x7f7f6723d008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1242
 
#9  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3f208) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#10 0x00007f7f743b44a4 in start_thread (arg=0x7f7f74ed9700) at pthread_create.c:456
 
#11 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 24 (Thread 0x7f7f74f24700 (LWP 7311)):
 
#0  0x00007f7f73a678bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9e11384 in vio_io_wait (vio=vio@entry=0x7f7f72c3ec08, event=event@entry=VIO_IO_EVENT_READ, timeout=28800000) at /home/buildbot/buildbot/build/vio/viosocket.c:992
 
#2  0x000055ddd9e11423 in vio_socket_io_wait (vio=vio@entry=0x7f7f72c3ec08, event=event@entry=VIO_IO_EVENT_READ) at /home/buildbot/buildbot/build/vio/viosocket.c:108
 
#3  0x000055ddd9e116ad in vio_read (vio=0x7f7f72c3ec08, buf=0x7f7f67238008 "\001", size=4) at /home/buildbot/buildbot/build/vio/viosocket.c:184
 
#4  0x000055ddd96d6872 in my_real_read (net=0x7f7f6c63e240, complen=complen@entry=0x7f7f74f23960, header=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:877
 
#5  0x000055ddd96d756d in my_net_read_packet (net=0x7f7f6c63e240, read_from_server=<optimized out>) at /home/buildbot/buildbot/build/sql/net_serv.cc:1140
 
#6  0x000055ddd976998c in do_command (thd=0x7f7f6c63e008) at /home/buildbot/buildbot/build/sql/sql_parse.cc:1002
 
#7  0x000055ddd982d69b in do_handle_one_connection (thd_arg=thd_arg@entry=0x7f7f6c63e008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1331
 
#8  0x000055ddd982d747 in handle_one_connection (arg=arg@entry=0x7f7f6c63e008) at /home/buildbot/buildbot/build/sql/sql_connect.cc:1242
 
#9  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3ee08) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#10 0x00007f7f743b44a4 in start_thread (arg=0x7f7f74f24700) at pthread_create.c:456
 
#11 0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 23 (Thread 0x7f7f74f6f700 (LWP 7301)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x000055ddd96e49b9 in inline_mysql_cond_wait (src_line=336, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1154
 
#2  handle_slave_background (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/sql/slave.cc:336
 
#3  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3e608) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f74f6f700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 22 (Thread 0x7f7f74fba700 (LWP 7300)):
 
#0  do_sigwait (set=<optimized out>, set@entry=0x7f7f74fb9dd0, sig=sig@entry=0x7f7f74fb9d60) at ../sysdeps/unix/sysv/linux/sigwait.c:64
 
#1  0x00007f7f743bdd0d in __sigwait (set=0x7f7f74fb9dd0, sig=0x7f7f74fb9d60) at ../sysdeps/unix/sysv/linux/sigwait.c:96
 
#2  0x000055ddd96cb77f in signal_hand (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/sql/mysqld.cc:3408
 
#3  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3e208) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f74fba700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 21 (Thread 0x7f7f75005700 (LWP 7299)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x000055ddd99914a3 in inline_mysql_cond_wait (src_line=9851, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1154
 
#2  binlog_background_thread (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/sql/log.cc:9851
 
#3  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3e408) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f75005700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 20 (Thread 0x7f7f5f7fe700 (LWP 7298)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=1000000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9c497e3 in btr_defragment_thread () at /home/buildbot/buildbot/build/storage/xtradb/btr/btr0defragment.cc:705
 
#3  0x00007f7f743b44a4 in start_thread (arg=0x7f7f5f7fe700) at pthread_create.c:456
 
#4  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 19 (Thread 0x7f7f5ffff700 (LWP 7297)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x000055ddd9b6dc23 in os_cond_wait (fast_mutex=0x7f7f6e3de2b0, cond=0x7f7f6e3de2e8) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:193
 
#2  os_event_wait_low (event=0x7f7f6e3de2b0, reset_sig_count=<optimized out>, reset_sig_count@entry=0) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:474
 
#3  0x000055ddd9c5e6f9 in buf_dump_thread () at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0dump.cc:731
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f5ffff700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 18 (Thread 0x7f7f60fff700 (LWP 7296)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=1000000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9c6759f in page_cleaner_sleep_if_needed (next_loop_time=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2678
 
#3  page_cleaner_sleep_if_needed (next_loop_time=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2948
 
#4  buf_flush_lru_manager_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2979
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f60fff700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 17 (Thread 0x7f7f667fe700 (LWP 7295)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=1000000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9c664b3 in page_cleaner_sleep_if_needed (next_loop_time=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2678
 
#3  page_cleaner_sleep_if_needed (next_loop_time=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2785
 
#4  buf_flush_page_cleaner_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/buf/buf0flu.cc:2819
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f667fe700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 16 (Thread 0x7f7f62bfc700 (LWP 7287)):
 
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
 
#1  0x000055ddd9b6dc23 in os_cond_wait (fast_mutex=0x7f7f6e3de160, cond=0x7f7f6e3de198) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:193
 
#2  os_event_wait_low (event=0x7f7f6e3de160, reset_sig_count=<optimized out>, reset_sig_count@entry=1) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:474
 
#3  0x000055ddd9be3e84 in srv_resume_thread (timeout_usec=0, wait=true, sig_count=1, slot=0x55dddaece7e8 <srv_sys+488>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:1082
 
#4  srv_purge_coordinator_suspend (rseg_history_len=6, slot=0x55dddaece7e8 <srv_sys+488>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:3487
 
#5  srv_purge_coordinator_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:3578
 
#6  0x00007f7f743b44a4 in start_thread (arg=0x7f7f62bfc700) at pthread_create.c:456
 
#7  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 15 (Thread 0x7f7f637fd700 (LWP 7286)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9b6ddb7 in os_cond_wait_timed (abstime=0x7f7f637fcdb0, fast_mutex=0x7f7f6e3dfc10, cond=0x7f7f6e3dfc48) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:156
 
#2  os_event_wait_time_low (event=0x7f7f6e3dfc10, time_in_usec=time_in_usec@entry=5000000, reset_sig_count=<optimized out>, reset_sig_count@entry=1) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:571
 
#3  0x000055ddd9c15bf8 in ib_wqueue_timedwait (wq=wq@entry=0x7f7f6f7cf368, wait_in_usecs=wait_in_usecs@entry=5000000) at /home/buildbot/buildbot/build/storage/xtradb/ut/ut0wqueue.cc:155
 
#4  0x000055ddd9ce7227 in fts_optimize_thread (arg=0x7f7f6f7cf368) at /home/buildbot/buildbot/build/storage/xtradb/fts/fts0opt.cc:2905
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f637fd700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 14 (Thread 0x7f7f63ffe700 (LWP 7285)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9b6ddb7 in os_cond_wait_timed (abstime=0x7f7f63ffddf0, fast_mutex=0x7f7f6e3df890, cond=0x7f7f6e3df8c8) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:156
 
#2  os_event_wait_time_low (event=0x7f7f6e3df890, time_in_usec=time_in_usec@entry=10000000, reset_sig_count=<optimized out>, reset_sig_count@entry=0) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:571
 
#3  0x000055ddd9ca4753 in dict_stats_thread () at /home/buildbot/buildbot/build/storage/xtradb/dict/dict0stats_bg.cc:534
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f63ffe700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 13 (Thread 0x7f7f647ff700 (LWP 7284)):
 
#0  0x00007f7f73a69603 in select () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd9b6e46f in os_thread_sleep (tm=tm@entry=1000000) at /home/buildbot/buildbot/build/storage/xtradb/os/os0thread.cc:307
 
#2  0x000055ddd9be20e0 in srv_master_sleep () at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:3111
 
#3  srv_master_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:3161
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f647ff700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 12 (Thread 0x7f7f657fc700 (LWP 7283)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9b6ddb7 in os_cond_wait_timed (abstime=0x7f7f657fbdc0, fast_mutex=0x7f7f6e3de1d0, cond=0x7f7f6e3de208) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:156
 
#2  os_event_wait_time_low (event=0x7f7f6e3de1d0, time_in_usec=time_in_usec@entry=1000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:571
 
#3  0x000055ddd9be0d0f in srv_error_monitor_thread () at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:2425
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f657fc700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 11 (Thread 0x7f7f65ffd700 (LWP 7282)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9b6ddb7 in os_cond_wait_timed (abstime=0x7f7f65ffcde0, fast_mutex=0x7f7f6e3df5f0, cond=0x7f7f6e3df628) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:156
 
#2  os_event_wait_time_low (event=event@entry=0x7f7f6e3df5f0, time_in_usec=time_in_usec@entry=1000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:571
 
#3  0x000055ddd9b3f00e in lock_wait_timeout_thread () at /home/buildbot/buildbot/build/storage/xtradb/lock/lock0wait.cc:574
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f65ffd700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 10 (Thread 0x7f7f66fff700 (LWP 7280)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9b6ddb7 in os_cond_wait_timed (abstime=0x7f7f66ffedf0, fast_mutex=0x7f7f6e3de240, cond=0x7f7f6e3de278) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:156
 
#2  os_event_wait_time_low (event=0x7f7f6e3de240, time_in_usec=time_in_usec@entry=5000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/os/os0sync.cc:571
 
#3  0x000055ddd9be0917 in srv_monitor_thread () at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0srv.cc:2184
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f66fff700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 9 (Thread 0x7f7f68396700 (LWP 7279)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c91320) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=5, message1=message1@entry=0x7f7f68395e50, message2=message2@entry=0x7f7f68395e60, type=type@entry=0x7f7f68395e70, space_id=space_id@entry=0x7f7f68395e80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=5) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f68396700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 8 (Thread 0x7f7f68b97700 (LWP 7278)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c91320) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=4, message1=message1@entry=0x7f7f68b96e50, message2=message2@entry=0x7f7f68b96e60, type=type@entry=0x7f7f68b96e70, space_id=space_id@entry=0x7f7f68b96e80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=4) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f68b97700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 7 (Thread 0x7f7f69398700 (LWP 7277)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c91200) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=3, message1=message1@entry=0x7f7f69397e50, message2=message2@entry=0x7f7f69397e60, type=type@entry=0x7f7f69397e70, space_id=space_id@entry=0x7f7f69397e80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=3) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f69398700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 6 (Thread 0x7f7f69b99700 (LWP 7276)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c91200) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=2, message1=message1@entry=0x7f7f69b98e50, message2=message2@entry=0x7f7f69b98e60, type=type@entry=0x7f7f69b98e70, space_id=space_id@entry=0x7f7f69b98e80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=2) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f69b99700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 5 (Thread 0x7f7f6a39a700 (LWP 7275)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c91260) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=1, message1=message1@entry=0x7f7f6a399e50, message2=message2@entry=0x7f7f6a399e60, type=type@entry=0x7f7f6a399e70, space_id=space_id@entry=0x7f7f6a399e80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=1) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f6a39a700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 4 (Thread 0x7f7f6ab9b700 (LWP 7274)):
 
#0  0x00007f7f74c0e6ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
 
#1  0x000055ddd9b6b06e in os_aio_linux_collect (seg_size=256, segment=<optimized out>, array=0x7f7f72c912c0) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5609
 
#2  os_aio_linux_handle (global_seg=global_seg@entry=0, message1=message1@entry=0x7f7f6ab9ae50, message2=message2@entry=0x7f7f6ab9ae60, type=type@entry=0x7f7f6ab9ae70, space_id=space_id@entry=0x7f7f6ab9ae80) at /home/buildbot/buildbot/build/storage/xtradb/os/os0file.cc:5763
 
#3  0x000055ddd9cb206c in fil_aio_wait (segment=segment@entry=0) at /home/buildbot/buildbot/build/storage/xtradb/fil/fil0fil.cc:6266
 
#4  0x000055ddd9be4400 in io_handler_thread (arg=<optimized out>) at /home/buildbot/buildbot/build/storage/xtradb/srv/srv0start.cc:584
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f6ab9b700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 3 (Thread 0x7f7f6c3ff700 (LWP 7273)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9a9a42b in inline_mysql_cond_timedwait (abstime=0x7f7f6c3feda0, mutex=0x55dddaea1100 <LOCK_checkpoint>, that=0x55dddaea1140 <COND_checkpoint>, src_file=<optimized out>, src_line=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1191
 
#2  my_service_thread_sleep (control=control@entry=0x55ddda5ec340 <checkpoint_control>, sleep_time=<optimized out>) at /home/buildbot/buildbot/build/storage/maria/ma_servicethread.c:115
 
#3  0x000055ddd9a92bb7 in ma_checkpoint_background (arg=arg@entry=0x1e) at /home/buildbot/buildbot/build/storage/maria/ma_checkpoint.c:708
 
#4  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3de08) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#5  0x00007f7f743b44a4 in start_thread (arg=0x7f7f6c3ff700) at pthread_create.c:456
 
#6  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 2 (Thread 0x7f7f6dfff700 (LWP 7272)):
 
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225
 
#1  0x000055ddd9d85724 in inline_mysql_cond_timedwait (abstime=0x7f7f6dffee20, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1191
 
#2  timer_handler (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/mysys/thr_timer.c:292
 
#3  0x000055ddd9a4ecbd in pfs_spawn_thread (arg=0x7f7f72c3dc08) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1861
 
#4  0x00007f7f743b44a4 in start_thread (arg=0x7f7f6dfff700) at pthread_create.c:456
 
#5  0x00007f7f73a70d0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
 
 
Thread 1 (Thread 0x7f7f75013080 (LWP 7255)):
 
#0  0x00007f7f73a678bd in poll () at ../sysdeps/unix/syscall-template.S:84
 
#1  0x000055ddd96cd80a in handle_connections_sockets () at /home/buildbot/buildbot/build/sql/mysqld.cc:6548
 
#2  0x000055ddd96d5700 in mysqld_main (argc=155, argv=0x7f7f72c6ea58) at /home/buildbot/buildbot/build/sql/mysqld.cc:5973
 
#3  0x00007f7f739a82e1 in __libc_start_main (main=0x55ddd96b2820 <main(int, char**)>, argc=22, argv=0x7ffe06bf0198, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffe06bf0188) at ../csu/libc-start.c:291
 
#4  0x000055ddd96c8b89 in _start ()

The problem was apparently introduced by this commit:

commit ab6dd774082c57f48d998e03655c06b672799b2d
 
Author: Marko Mäkelä <marko.makela@mariadb.com>
 
Date:   Wed Jul 24 19:43:37 2019 +0300
 
 
 
    MDEV-14154: Remove ut_time_us()
 
    
    Use microsecond_interval_timer()
 
    or my_interval_timer() [in nanoseconds] instead.

There is one remaining mystery, though.
phobos, your initial bug description says that you first experienced the problem on 10.4.6. But it appears to be impossible, not only the commit above didn't make it to 10.4.6, but there were no related changes introduced between 10.3.16 release which did not have the problem and 10.4.6. All other versions are consistent, 10.1.41, 10.2.26, 10.3.17, 10.4.7 are all the same release bundle, but 10.4.6 stands out. Are you sure your slave hadn't already been upgraded to 10.4.7 by the time you first experienced the problem?

Comment by Phobos [ 2019-08-07 ]

Well,

sorry for the confusion. I've updated my master servers to 10.4.6, then the slave, then the slave within some days to 10.4.7 and then noticed the problem so yes, chances are good it was introduced with 10.4.7.
Since your Debian repos don't provide previous versions, I haven't been able to downgrade.
About the thread concurrency mentioned above, I've been able to reproduce the problem that once giving the option an value != 0, the problem starts to happen.
Setting it to 0 or commenting it out, everything starts working again as expected.

Changing this setting was only required on the slave, there has been no configuration change @ the master servers.

Comment by Ahmet [ 2019-08-07 ]

Hey phobos,
my problem occured from 10.4.6 to 10.4.7. After a downgrade to 10.4.6 everything worked well again.

BTW there is a source you can use. See: https://downloads.mariadb.org/mariadb/10.4.6/
You can just add:

deb [arch=amd64,ppc64el,arm64] http://mirrors.n-ix.net/mariadb/mariadb-10.4.6/repo/ubuntu/ xenial main

to /etc/apt/sources.list - After that, you can downgrade with: 

apt install mariadb-server=1:10.4.6+maria~xenial mariadb-server-10.4=1:10.4.6+maria~xenial mariadb-client=1:10.4.6+maria~xenial mariadb-client-10.4=1:10.4.6+maria~xenial mariadb-server-core-10.4=1:10.4.6+maria~xenial mariadb-client-core-10.4=1:10.4.6+maria~xenial mysql-common=1:10.4.6+maria~xenial mariadb-client=1:10.4.6+maria~xenial libmariadb3=1:10.4.6+maria~xenial

An finally don't forget to hold Mariadb:

apt-mark hold mariadb-server*

In my case, replication is working again. But an update to 10.4.7 is not an option for me, until the problem is fixed.

Comment by Luke Alexander [ 2019-08-12 ]

Just to add more weight to this - we recently upgraded our slave from 10.4.6 to 10.4.7 on Ubuntu Xenial - this was actually in the hope of fixing another issue (https://jira.mariadb.org/browse/MDEV-20115) instead we noticed replication lag steadily increasing, both slave Running/IO processes appeared to be OK though (not stuck on `Preparing`) but the lag continued to increase. I had a hunch it was likely to with the upgrade and then stumbled across this post, after downgrading the slave the replication started flowing again... I've attached a gdb output of the process in case it's of use gdb_out_1047.txt

Comment by Alice Sherepa [ 2019-08-12 ]

mtr test:

--source include/have_innodb.inc
 
 
 
--connect (master1,127.0.0.1,root,,,$SERVER_MYPORT_1)
 
--connect (master2,127.0.0.1,root,,,$SERVER_MYPORT_2)
 
 
 
#setup master-master replication
 
--connection master1
 
 
 
ALTER TABLE mysql.gtid_slave_pos engine=innodb;
 
GRANT REPLICATION SLAVE ON *.* TO 'root'@'127.0.0.1';
 
--replace_result $SERVER_MYPORT_2 MYPORT_2
 
eval CHANGE MASTER TO master_port=$SERVER_MYPORT_2, master_host='127.0.0.1', master_user='root';
 
start slave;
 
--source include/wait_for_slave_to_start.inc
 
 
 
--connection master2
 
 
 
ALTER TABLE mysql.gtid_slave_pos engine=innodb;
 
GRANT REPLICATION SLAVE ON *.* TO 'root'@'127.0.0.1';
 
--replace_result $SERVER_MYPORT_1 MYPORT_1
 
eval CHANGE MASTER TO master_port=$SERVER_MYPORT_1, master_host='127.0.0.1', master_user='root';
 
start slave;
 
--source include/wait_for_slave_to_start.inc
 
 
 
--connection master1
 
stop slave;
 
--source include/wait_for_slave_to_stop.inc
 
 
 
# restart server with innodb-thread-concurrency!=0
 
--connection master2
 
-- let $restart_parameters=--innodb-thread-concurrency=8
 
-- source include/restart_mysqld.inc
 
 
 
start slave;
 
 
 
--source include/wait_for_slave_sql_to_start.inc
 
--vertical_results
 
show slave status;
 
--source include/wait_for_slave_io_to_start.inc 
 
 
stop slave;
 
--source include/wait_for_slave_to_stop.inc
 
--disconnect master1
 
--disconnect master2


!include suite/rpl/my.cnf
 
 
 
[mysqld.1]
 
log-bin=master-bin
 
 
 
[mysqld.2]
 
log-bin=master-bin
 
 
 
[ENV]
 
SERVER_MYPORT_1= @mysqld.1.port
 
SERVER_MYPORT_2= @mysqld.2.port


# restart: --innodb-thread-concurrency=8
 
start slave;
 
include/wait_for_slave_sql_to_start.inc
 
show slave status;
 
Slave_IO_State	NULL
 
Master_Host	127.0.0.1
 
Master_User	root
 
Master_Port	16000
 
Connect_Retry	60
 
Master_Log_File	master-bin.000001
 
Read_Master_Log_Pos	661
 
Relay_Log_File	slave-relay-bin.000003
 
Relay_Log_Pos	4
 
Relay_Master_Log_File	master-bin.000001
 
Slave_IO_Running	Preparing
 
Slave_SQL_Running	Yes

Comment by Faustin Lammler [ 2019-09-11 ]

Thanks thiru for your report!

Just a little clarification regarding init script:
> ... since you no longer provide an init script and expect everyone is running systemd, the init script from a previous version has been taken.

We still provide init script in `/usr/share/mysql` :
See https://github.com/MariaDB/server/commit/a4cc6fb91f3855e0ed803a6e1762440cfcf8cb5c

Generated at Thu Feb 08 08:58:00 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.