Bug #47525 MySQL crashed (Federated)
Submitted: 22 Sep 2009 16:09 Modified: 18 Dec 2009 15:00
Reporter: Zigmund Bulinsh Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Federated storage engine Severity:S2 (Serious)
Version:5.1.39 OS:Windows
Assigned to: Davi Arnaut CPU Architecture:Any
Tags: regression

[22 Sep 2009 16:09] Zigmund Bulinsh
Description:
090922 18:30:36  InnoDB: Started; log sequence number 6 2099158586
090922 18:30:37 [Note] Slave SQL thread initialized, starting replication in log 'datacenter_log.000032' at position 317, relay log '.\agora_relay_log.001665' position: 256
090922 18:30:37 [Note] Event Scheduler: Loaded 0 events
090922 18:30:37 [Note] D:\MySQL\bin\mysqld.exe: ready for connections.
Version: '5.1.39-community-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
090922 18:30:37 [Note] Event Scheduler: scheduler thread started with id 3
090922 18:30:37 [Note] Slave I/O thread: connected to master 'replication@127.0.0.1:3333',replication started in log 'datacenter_log.000032' at position 317
090922 19:00:36 - mysqld got exception 0xc0000005 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=396361728
read_buffer_size=16777216
max_used_connections=1
max_threads=100
threads_connected=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2435703 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
00422E26    mysqld.exe!slave_io_thread_detach_vio()[slave.cc:3757]
004DE9C7    mysqld.exe!end_server()[client.c:949]
004DEA49    mysqld.exe!mysql_close()[client.c:2756]
0059DCE9    mysqld.exe!ha_federated::close()[ha_federated.cc:1660]
004D694D    mysqld.exe!closefrm()[table.cc:1971]
00460A18    mysqld.exe!intern_close_table()[sql_base.cc:780]
00460A2B    mysqld.exe!free_cache_entry()[sql_base.cc:802]
00682720    mysqld.exe!my_hash_delete()[hash.c:551]
0045FC8F    mysqld.exe!flush_tables()[sql_base.cc:8387]
0043D107    mysqld.exe!handle_manager()[sql_manager.cc:110]
00679D2B    mysqld.exe!pthread_start()[my_winthread.c:85]
006592D3    mysqld.exe!_callthreadstart()[thread.c:293]
0065936C    mysqld.exe!_threadstart()[thread.c:275]
75EFD0E9    kernel32.dll!BaseThreadInitThunk()
770819BB    ntdll.dll!RtlInitializeExceptionChain()
7708198E    ntdll.dll!RtlInitializeExceptionChain()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

How to repeat:
Don't know yet.
[22 Sep 2009 16:12] Zigmund Bulinsh
Just thought that this can help you, if you changed code regarding some component or object (before I had never had such exception in versions from 5.1.31 to 5.1.38).
I haven;t redumbed database from 5.1.31, because I haven't seen that there were some changes in file formats and also redumping gigabytes' database is not so fun...
[22 Sep 2009 16:37] Zigmund Bulinsh
Happened again. And I see that it happens after 30 minutes of work...

InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
090922 19:04:47  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Last MySQL binlog file position 0 5910, file name .\agora_log.000341
090922 19:04:47  InnoDB: Started; log sequence number 6 2099162683
090922 19:04:47 [Note] Recovering after a crash using agora_log
090922 19:04:47 [Note] Starting crash recovery...
090922 19:04:47 [Note] Crash recovery finished.
090922 19:04:48 [Note] Slave SQL thread initialized, starting replication in log 'datacenter_log.000033' at position 1685, relay log '.\agora_relay_log.001668' position: 1835
090922 19:04:48 [Note] Event Scheduler: Loaded 0 events
090922 19:04:48 [Note] D:\MySQL\bin\mysqld.exe: ready for connections.
Version: '5.1.39-community-log'  socket: ''  port: 3306  MySQL Community Server (GPL)
090922 19:04:48 [Note] Event Scheduler: scheduler thread started with id 3
090922 19:04:48 [Note] Slave I/O thread: connected to master 'replication@127.0.0.1:3333',replication started in log 'datacenter_log.000033' at position 1685
090922 19:34:47 - mysqld got exception 0xc0000005 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=396361728
read_buffer_size=16777216
max_used_connections=5
max_threads=100
threads_connected=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2435703 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
00422E26    mysqld.exe!slave_io_thread_detach_vio()[slave.cc:3757]
004DE9C7    mysqld.exe!end_server()[client.c:949]
004DEA49    mysqld.exe!mysql_close()[client.c:2756]
0059DCE9    mysqld.exe!ha_federated::close()[ha_federated.cc:1660]
004D694D    mysqld.exe!closefrm()[table.cc:1971]
00460A18    mysqld.exe!intern_close_table()[sql_base.cc:780]
00460A2B    mysqld.exe!free_cache_entry()[sql_base.cc:802]
00682720    mysqld.exe!my_hash_delete()[hash.c:551]
0045FC8F    mysqld.exe!flush_tables()[sql_base.cc:8387]
0043D107    mysqld.exe!handle_manager()[sql_manager.cc:110]
00679D2B    mysqld.exe!pthread_start()[my_winthread.c:85]
006592D3    mysqld.exe!_callthreadstart()[thread.c:293]
0065936C    mysqld.exe!_threadstart()[thread.c:275]
75EFD0E9    kernel32.dll!BaseThreadInitThunk()
770819BB    ntdll.dll!RtlInitializeExceptionChain()
7708198E    ntdll.dll!RtlInitializeExceptionChain()
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
[22 Sep 2009 16:39] Zigmund Bulinsh
I have no any events created for 30 minutes.. But the time when server crashes is strictly 30 minutes with 1 second delay.
[22 Sep 2009 17:01] MySQL Verification Team
It is a slave server setup?. Thanks in advance.
[22 Sep 2009 17:49] Zigmund Bulinsh
Yes. It is. The master is located on the localhost as you see with the same version (5.1.39).

OS = Windows Vista SP1.
[22 Sep 2009 17:52] MySQL Verification Team
looks like it's happening each 30 minutes because this is the default value for "flush_time" on windows. probably running "flush tables" will crash too..
[23 Sep 2009 6:59] Zigmund Bulinsh
Hm.. No. Flush tables work. It just crashes after 30 minutes. And it happens now on all production systems, so I rolled back to the 5.1.38.

And happens only if federated tables are connected to the local database on the other server port.
[23 Sep 2009 7:01] Zigmund Bulinsh
As it happens on all my DB instances which has a federated table connections to the replication master's tables.
[23 Sep 2009 7:04] Zigmund Bulinsh
Just checked now... It happens absolutely on all instances with federated tables (and also without any operations made on them). Just crashes...
[23 Sep 2009 7:10] Zigmund Bulinsh
The same stack trace for every instance.
[23 Sep 2009 8:25] Zigmund Bulinsh
I found when it happens. it happens only when you update data through the federated tables. After the update goes 30 minutes and then crashes. If I make flush files, then it works, but still crashes after minutes.
[23 Sep 2009 8:38] Valeriy Kravchuk
I've repeated this on 64-bit XP without any problem. Look:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3306 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 10
Server version: 5.0.81-community-nt MySQL Community Edition (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> show create table t1;
ERROR 1146 (42S02): Table 'test.t1' doesn't exist
mysql> create table t1(c1 int) engine=MyISAM;
Query OK, 0 rows affected (0.27 sec)

mysql> insert into t1 values(1), (2);
Query OK, 2 rows affected (0.19 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> exit
Bye

So, I've created some table on other MySQL server running on the same machine. Then:

C:\Program Files\MySQL\MySQL Server 5.0\bin>mysql -uroot -proot -P3307 test
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.1.39-community MySQL Community Server (GPL)

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create table tfed(c1 int) engine=federated
    -> connection='mysql://root:root@localhost:3306/test/t1';
Query OK, 0 rows affected (0.00 sec)

mysql> select * from tfed;
+------+
| c1   |
+------+
|    1 |
|    2 |
+------+
2 rows in set (1.06 sec)

Then I just waited for 30 minutes doing nothing and had got exactly the same crash:

090923 10:57:45  InnoDB: Started; log sequence number 0 183597
090923 10:57:45 [Note] Event Scheduler: Loaded 0 events
090923 10:57:45 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready
 for connections.
Version: '5.1.39-community'  socket: ''  port: 3307  MySQL Community Server (GPL
)
090923 11:27:46 - mysqld got exception 0xc0000005 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=8388608
read_buffer_size=65536
max_used_connections=2
max_threads=100
threads_connected=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 41085 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
000000014002A3A2    mysqld.exe!slave_io_thread_detach_vio()[slave.cc:3757]
00000001401175AF    mysqld.exe!end_server()[client.c:949]
0000000140117650    mysqld.exe!mysql_close()[client.c:2758]
0000000140200CA1    mysqld.exe!ha_federated::close()[ha_federated.cc:1660]
000000014010DEB9    mysqld.exe!closefrm()[table.cc:1971]
00000001400752F0    mysqld.exe!intern_close_table()[sql_base.cc:782]
000000014007530E    mysqld.exe!free_cache_entry()[sql_base.cc:803]
000000014031F9E1    mysqld.exe!my_hash_delete()[hash.c:551]
000000014007432F    mysqld.exe!flush_tables()[sql_base.cc:8387]
000000014004B8BF    mysqld.exe!handle_manager()[sql_manager.cc:110]
0000000140315B25    mysqld.exe!pthread_start()[my_winthread.c:85]
00000001402DFDA7    mysqld.exe!_callthreadstart()[thread.c:295]
00000001402DFE75    mysqld.exe!_threadstart()[thread.c:275]
0000000077D6B71A    kernel32.dll!BaseThreadStart()
[23 Sep 2009 9:30] MySQL Verification Team
is this a regression caused by fix to bug #45242 I wonder ?
[29 Sep 2009 15:34] Zigmund Bulinsh
This happens also without updating federated tables. It is enough to make a database dump (with mysqldump). And after 30 minutes it crashes again.
[30 Sep 2009 14:10] Davi Arnaut
Yes, regression caused by Bug#45242. The patch missed a condition that happens due to FLUSH TABLES.
[30 Sep 2009 19:01] Davi Arnaut
BTW, the crash after 30 minutes is probably due to the FLUSH_TIME variable which flushes tables at a given interval.
[30 Sep 2009 20:49] Davi Arnaut
Workaround: set flush_time to 0.
[30 Sep 2009 21:38] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/85275

2813 Davi Arnaut	2009-09-30
      Bug#47525: MySQL crashed (Federated)
      
      On Mac OS X or Windows, sending a SIGHUP to the server or a
      asynchronous flush (triggered by flush_time), would cause the
      server to crash.
      
      The problem was that a hook used to detach client API handles
      wasn't prepared to handle cases where the thread does not have
      a associated session.
      
      The solution is to verify whether the thread has a associated
      session before trying to detach a handle.
     @ mysql-test/r/federated_debug.result
        Add test case result for Bug#47525
     @ mysql-test/t/federated_debug-master.opt
        Debug point.
     @ mysql-test/t/federated_debug.test
        Add test case for Bug#47525
     @ sql/slave.cc
        Check whether a the thread has a associated session.
     @ sql/sql_parse.cc
        Add debug code to simulate a reload without thread session.
[30 Sep 2009 21:43] Davi Arnaut
Queued to 5.0-bugteam
[5 Oct 2009 17:09] Zigmund Bulinsh
Just wanted to inform that "set global flush_time = 0" does not solves the problem. Server still crashes.
[5 Oct 2009 19:41] Davi Arnaut
flush_time only takes effect on start up (cnf file) or after the current flush_time is expires (that is, if flush_time was previously set, it will run once).
[6 Oct 2009 8:57] Bugs System
Pushed into 5.0.87 (revid:joro@sun.com-20091006073202-rj21ggvo2gw032ks) (version source revid:davi.arnaut@sun.com-20090930213802-w029fmi6q1hd1ggp) (merge vers: 5.0.87) (pib:11)
[6 Oct 2009 9:01] Bugs System
Pushed into 5.1.40 (revid:joro@sun.com-20091006073316-lea2cpijh9r6on7c) (version source revid:ingo.struewing@sun.com-20091002112748-2xmjv846dk323nc3) (merge vers: 5.1.40) (pib:11)
[14 Oct 2009 15:34] Paul DuBois
Noted in 5.0.87, 5.1.40 changelogs.

On Mac OS X or Windows, sending a SIGHUP signal to the server or an
asynchronous flush (triggered by flush_time) caused the server to
crash.  

Setting report to NDI pending push into 5.5.x+.
[22 Oct 2009 6:33] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091022063126-l0qzirh9xyhp0bpc) (version source revid:alik@sun.com-20091019135554-s1pvptt6i750lfhv) (merge vers: 6.0.14-alpha) (pib:13)
[22 Oct 2009 7:06] Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091022060553-znkmxm0g0gm6ckvw) (version source revid:alik@sun.com-20091013094238-g67x6tgdm9a7uik0) (merge vers: 5.5.0-beta) (pib:13)
[22 Oct 2009 19:51] Paul DuBois
Noted in 5.5.0, 6.0.14 changelogs.
[18 Dec 2009 10:29] Bugs System
Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)
[18 Dec 2009 10:44] Bugs System
Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)
[18 Dec 2009 11:00] Bugs System
Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)
[18 Dec 2009 11:14] Bugs System
Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)
[18 Dec 2009 15:00] Tony Bedford
Also noted in the following changelogs:

5.1.41-ndb-7.1.0
5.1.41-ndb-6.2.19
5.1.41-ndb-6.3.31
5.1.41-ndb-7.0.11
[12 Sep 2018 20:20] Vincent Wansink
I can confirm that this is also happening on 5.5.61.  My server is extremely busy (thousands of transactions per second) and mysql crashes exactly 30 minutes after it was restarted all day every day.

This only started happening after I started using federated tables.
[13 Sep 2018 15:27] Vincent Wansink
I can also confirm that setting "flush_time = 0" in my.ini makes this problem go away.
[23 Feb 2021 9:36] Aldo Rizzardi
Happened to me also on 5.5.62 with federated tables, 30minutes exactly and seems solved with "flush_time = 0".
I had before version 5.5.60 without the issue.
Thanks Vincent Wansink for your update comment, I registered to add mine too.