Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.3.7
-
Windows 10, 32 GB RAM, SSD
Description
We have a Windows server that has been running MariaDB 10.1 successfully for over a year. The server remains mostly idle for long times with some read access, but occasionally there are transactions that add data (about 500k rows per commit). There can be up to 10 such transactions (one per database) at the same time and during those times the server is under quite some load (the code processing the data resides on the same server as the database).
When trying to use MariaDB 10.3, during those load times the database crashes and logs "[FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung."
I figure it could be related to MariaDB switching from XtraDB to InnoDB and on the mailing list it was suggested to file a bug.
I'm attaching the error log. I cannot attach a minidump as-is because upon inspection it contained sensitive data that I'm not allowed to disclose. If absolutely neccessary, I can try and reproduce the problem with random test data, but this might take a few days.
The mailing list entry mentioned above can be found here: https://lists.launchpad.net/maria-discuss/msg05139.html
Regards,
Tom.
Attachments
Issue Links
- relates to
-
MDEV-13196 Remove handler::store_lock()
-
- Open
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Confirmed
-
-
-
- Closed
-
Activity
10.3 issue should've been fixed already
10.2 issue is fixed by backporting one of 10.3 fixes to 10.1 and 10.2
Given that original 10.3.7 mariadb_clean.err contains ADD FOREIGN KEY:
insert into `Project` (`dataVersion`, `name`, `sortIndex`, `area_id`, `customer_id`, `id`) values (0, 'Basic Course', 0, NULL, NULL, 'c2aa6a6f-a612-4b23-8993-5ffdb09a4d27')
|
insert into `Project` (`dataVersion`, `name`, `sortIndex`, `area_id`, `customer_id`, `id`) values (0, 'Merits', 0, NULL, NULL, 'bd31bd37-cd4a-4ae6-b27d-6cc1df3bb039')
|
insert into `Project` (`dataVersion`, `name`, `sortIndex`, `area_id`, `customer_id`, `id`) values (0, 'Station 14', 0, NULL, NULL, 'e316509e-123b-49bb-8ff8-55b51a5131be')
|
insert into `Customer` (`dataVersion`, `name`, `area_id`, `id`) values (0, '****', NULL, 'f1f611de-2964-432a-a670-22cc0ff7c8fb')
|
alter table `Project` add constraint `FKr9hirbv06ir3se75hy9f9urpo` foreign key (`area_id`) references `Area` (`id`), add constraint `FKfdttvh81kur1ulwxu1t4vst6n` foreign key (`customer_id`) references `Customer` (`id`)
|
It feels like similar problem was fixed by MDEV-16465 and MDEV-16060.
Looking at the gdb_short.txt (which is by far the most useful attachment), culprit is:
Thread 61 (
|
Thread 0x7f5a100d0700 (LWP 184312)):
|
#0 0x00007f5a174c1334 in __lll_lock_wait () from /lib64/libpthread.so.0
|
#1 0x00007f5a174bc60e in _L_lock_995 () from /lib64/libpthread.so.0
|
#2 0x00007f5a174bc576 in pthread_mutex_lock () from /lib64/libpthread.so.0
|
#3 0x00007f5a17def3fd in inline_mysql_mutex_lock (that=0x7f5a18dd9680, src_line=Unhandled dwarf expression opcode 0xf3
|
#4 inline_mysql_mutex_lock (that=0x7f5a18dd9680, src_line=Unhandled dwarf expression opcode 0xf3
|
#5 0x00007f5a17df1773 in thd_get_error_context_description (thd=0x7f13f00009a8, buffer=0x7f5a100caf80 "\240\260\f\020Z\177", length=1024, max_query_len=3000) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/sql_class.cc:540
|
#6 0x00007f5a18141cf4 in innobase_mysql_print_thd (f=0x7f5ba7906950, thd=Unhandled dwarf expression opcode 0xf3
|
#7 0x00007f5a181846be in DeadlockChecker::print (trx=0x7f59823329c0, max_query_len=3000) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/lock/lock0lock.cc:7238
|
#8 0x00007f5a18185b7f in DeadlockChecker::notify (this=0x7f5a100cb460, lock=0x7f13e4025b28) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/lock/lock0lock.cc:7384
|
#9 0x00007f5a18186815 in DeadlockChecker::search (this=0x7f5a100cb460) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/lock/lock0lock.cc:7500
|
#10 0x00007f5a18188a35 in DeadlockChecker::check_and_resolve (lock=0x7f13e4025c80, trx=0x7f59823356d0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/lock/lock0lock.cc:7635
|
#11 0x00007f5a1818a535 in lock_rec_enqueue_waiting (c_lock=0x7f5a1a3de938, type_mode=2563, block=Unhandled dwarf expression opcode 0xf3
|
#12 0x00007f5a1818aca7 in lock_rec_insert_check_and_lock (flags=Unhandled dwarf expression opcode 0xf3
|
#13 0x00007f5a182b5de0 in btr_cur_ins_lock_and_undo (flags=0, cursor=0x7f5a100cbb60, entry=0x7f11501973e0, thr=0x7f04587d12f0, mtr=Unhandled dwarf expression opcode 0xf3
|
#14 0x00007f5a182b8844 in btr_cur_optimistic_insert (flags=0, cursor=0x7f5a100cbb60, offsets=0x7f5a100cbb28, heap=0x7f5a100cbac0, entry=0x7f11501973e0, rec=0x7f5a100cbb20, big_rec=0x7f5a100cbab0, n_ext=0, thr=0x7f04587d12f0, mtr=0x7f5a100cc660) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/btr/btr0cur.cc:3031
|
#15 0x00007f5a181fb3e3 in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x7f1090a8e740, n_uniq=Unhandled dwarf expression opcode 0xf3
|
#16 0x00007f5a181fcfde in row_ins_clust_index_entry (index=0x7f1090a8e740, entry=0x7f11501973e0, thr=0x7f04587d12f0, n_ext=0, dup_chk_only=Unhandled dwarf expression opcode 0xf3
|
#17 0x00007f5a181ff38a in row_ins_index_entry (thr=Unhandled dwarf expression opcode 0xf3
|
#18 row_ins_index_entry_step (thr=Unhandled dwarf expression opcode 0xf3
|
#19 row_ins (thr=Unhandled dwarf expression opcode 0xf3
|
#20 row_ins_step (thr=Unhandled dwarf expression opcode 0xf3
|
#21 0x00007f5a1820e0de in row_insert_for_mysql (mysql_rec=0x7f1091cdb150 "0\220\375\221\020\177", prebuilt=0x7f04587c3cf0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/row/row0mysql.cc:1404
|
#22 0x00007f5a1814fb4f in ha_innobase::write_row (this=0x7f045ac412f0, record=0x7f045ac450e0 "\016") at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/storage/innobase/handler/ha_innodb.cc:8295
|
#23 0x00007f5a17fab8bf in handler::ha_write_row (this=0x7f045ac412f0, buf=0x7f045ac450e0 "\016") at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/handler.cc:5971
|
#24 0x00007f5a184a650a in ha_partition::write_row (this=0x7f045ac3a7f0, buf=0x7f045ac450e0 "\016") at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/ha_partition.cc:4189
|
#25 0x00007f5a17fab8bf in handler::ha_write_row (this=0x7f045ac3a7f0, buf=0x7f045ac450e0 "\016") at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/handler.cc:5971
|
#26 0x00007f5a17e07aa0 in write_record (thd=0x7f14080009a8, table=0x7f045ac3d958, info=0x7f5a100cdcc0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/sql_insert.cc:1654
|
#27 0x00007f5a17e0db7c in mysql_insert (thd=0x7f14080009a8, table_list=Unhandled dwarf expression opcode 0xf3
|
#28 0x00007f5a17e21e39 in mysql_execute_command (thd=0x7f14080009a8) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/sql_parse.cc:4430
|
#29 0x00007f5a17e277ca in mysql_parse (thd=0x7f14080009a8, rawbuf=Unhandled dwarf expression opcode 0xf3
|
#30 0x00007f5a18076734 in Query_log_event::do_apply_event (this=0x7f13dc9ee968, rgi=0x7f14202019a0, query_arg=0x7f14221178c0 "INSERT INTO app_12289_archive.rollup_hourly (month, hrl_hour, hrl_hash, hrl_tracker, hrl_network, hrl_site, hrl_creative, hrl_geo_country, hrl_campaign, hrl_install_count, hrl_install_matched_to_imp_"..., q_len_arg=Unhandled dwarf expression opcode 0xf3
|
#31 0x00007f5a17db89a3 in Log_event::apply_event (this=0x7f13dc9ee968, rgi=0x7f14202019a0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/log_event.h:1452
|
#32 0x00007f5a17dabc83 in apply_event_and_update_pos_apply (ev=0x7f13dc9ee968, thd=0x7f14080009a8, rgi=0x7f14202019a0, reason=Unhandled dwarf expression opcode 0xf3
|
#33 0x00007f5a17f2834e in rpt_handle_event (qev=0x7f1421dd4da8, rpt=Unhandled dwarf expression opcode 0xfa
|
#34 0x00007f5a17f2bb5c in handle_rpl_parallel_thread (arg=0x7f1420007eb0) at /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.14/sql/rpl_parallel.cc:1300
|
#35 0x00007f5a174baaa1 in start_thread () from /lib64/libpthread.so.0
|
#36 0x00007f5a15bd2bcd in clone () from /lib64/libc.so.6
|
This should've been fixed since 10.3.3 by
commit c2118a08b144c95cd4d88a080eaa70abd49f3740
|
Author: Monty <monty@mariadb.org>
|
Date: Thu Dec 7 21:28:00 2017 +0200
|
|
|
Move all kill mutex protection to LOCK_thd_kill
|
|
|
LOCK_thd_data was used to protect both THD data and
|
ensure that the THD is not deleted while it was in use
|
|
|
This patch moves the THD delete protection to LOCK_thd_kill,
|
which already protects the THD for kill.
|
|
|
The benefits are:
|
- More well defined what LOCK_thd_data protects
|
- LOCK_thd_data usage is now much simpler and easier to verify
|
- Less chance of deadlocks in SHOW PROCESS LIST as there is less
|
chance of interactions between mutexes
|
- Remove not needed LOCK_thread_count from
|
thd_get_error_context_description()
|
- Fewer mutex taken for thd->awake()
|
|
|
Other things:
|
- Don't take mysys->var mutex in show processlist to check if thread
|
is kill marked
|
- thd->awake() now automatically takes the LOCK_thd_kill mutex
|
(Simplifies code)
|
- Apc uses LOCK_thd_kill instead of LOCK_thd_data
|
Specifically by "- Remove not needed LOCK_thread_count from thd_get_error_context_description()"
10.2 is missing this fix, but it can be easily backported.
Unfortunately there's not enough data to analyze 10.3 deadlock. Dump of all threads callstacks is missing.
@Marko Mäkelä, this could be the case
We tried observing what was wrong by using gdb and although we couldn't see much we saw that it was hung between multiple drop commands
This was because of a script that drops and recreates the databases, since then we changed the timing of these scripts which fixed the issue for some time but this morning it crashed again after two weeks but we can't keep gdb running since this eventually also causes the server to crash
The original report was something specific to 10.3.7.
The backport of the cleanup from 10.3.3 to 10.1.41, 10.2.25 effectively reverted the attempted fix of
MDEV-11896, which caused the hang in 10.0.32, 10.1.26, 10.2.8, 10.3.1. A deeper analysis of this is inMDEV-13983.