MySQL Bugs: #12071: Windows hang: 'Opening tables' or 'Waiting for table' lockup

Bug #12071	Windows hang: 'Opening tables' or 'Waiting for table' lockup
Submitted:	20 Jul 2005 20:50	Modified:	17 Jun 2010 22:57
Reporter:	Dima Mihaylov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S1 (Critical)
Version:	4.1.12a/4.1.15-GA/5.0.16-GA	OS:	Windows (Windows 2003 std SP1/ Windows 2003 Std)
Assigned to:		CPU Architecture:	Any

Description:
We are hosting providers, server is running 200+ used databases.
After installing SP1 on Windows 2003 Server we've run into this bug:

After some attempt to loop for SHOW DATABASES / SHOW TABLES server deadlocks with 'Waiting For Table' for some random table. It happens every night when our tools run the loops.
We were running version 4.1.7 at that moment, only myISAM tables.

We've upgraded to 4.1.12a urgently - problem stays.

1) we can run any 100 of 200 bases into the loop - problem persists.
2) we can reproduce the error with some probability if we take ANY database with lots of tables (100 to 300) and query SHOW TABLE STATUS or any similiar metadata queries that involves all the tables.

We have table_cache at 500 (set up interactively after server startup, confirmed).

How to repeat:
Unfortunately we cannot suggest scenario, as it definitely happens when server has more than 10000+ files to handle in more than 200 db's, but the load is not needed.
I may suggest to create with some environment with 500 db's with 100 tables in each with sliglthly random structures, and run the loop. We are not sure, but personally I will give 50% that this scenario will hit this bug.

It seems that SP1 for 2003 Server did the trick.

Suggested fix:
Anyway, it is annoying to see 'Waiting for tables' with
a) no activity, zero
b) no connections (all killed)
c) good myISAM files, no repair artifacts of whatever

The lock object/initiator should be visible or alive, but it is not visible so we can not release the lock.
Something leaves it and goes for good.

I should add that the sever stays FULLY functional, it can even select from table under lock. Everything unrelated to lock works just fine.
Tables are not damaged -we were trying to repair everything both online and offline, every table is fine, and, to add, the table in subject is random each time.

Additional notes:

1. Sometimes status is not Waiting for table, but Opening table(s?).

2. I've found now that besides SP1 there was another change - by the acident (the same SP1 auto-tuning) Data Execution Prevention/Protection was enabled for all services including mySQL.
It was disabled previousely.

May be this broke some locking mechanics in the server. We've seen bad behaviour under DEP enabled for other programs.
I'll return later if problem goes away without DEP.

Could you please show for us the output of show variables
and show status when the issue reported happens.
You can use use the display option for to be private
to the MySQL developers if it is convenient for you.

Thanks in advance

I have the dump, wanted to post it when I get to work. So now I am posting;

'Aborted_clients', '9942'
'Aborted_connects', '54'
'Binlog_cache_disk_use', '0'
'Binlog_cache_use', '0'
'Bytes_received', '1226208037'
'Bytes_sent', '2672346559'
'Com_admin_commands', '11113'
'Com_alter_db', '0'
'Com_alter_table', '2'
'Com_analyze', '0'
'Com_backup_table', '0'
'Com_begin', '249'
'Com_change_db', '962754'
'Com_change_master', '0'
'Com_check', '0'
'Com_checksum', '0'
'Com_commit', '285'
'Com_create_db', '1'
'Com_create_function', '0'
'Com_create_index', '0'
'Com_create_table', '4904'
'Com_dealloc_sql', '0'
'Com_delete', '28284'
'Com_delete_multi', '0'
'Com_do', '0'
'Com_drop_db', '0'
'Com_drop_function', '0'
'Com_drop_index', '0'
'Com_drop_table', '2692'
'Com_drop_user', '0'
'Com_execute_sql', '0'
'Com_flush', '1'
'Com_grant', '1'
'Com_ha_close', '0'
'Com_ha_open', '0'
'Com_ha_read', '0'
'Com_help', '0'
'Com_insert', '337383'
'Com_insert_select', '623'
'Com_kill', '0'
'Com_load', '0'
'Com_load_master_data', '0'
'Com_load_master_table', '0'
'Com_lock_tables', '3'
'Com_optimize', '12'
'Com_preload_keys', '0'
'Com_prepare_sql', '0'
'Com_purge', '0'
'Com_purge_before_date', '0'
'Com_rename_table', '0'
'Com_repair', '5309'
'Com_replace', '744'
'Com_replace_select', '0'
'Com_reset', '0'
'Com_restore_table', '0'
'Com_revoke', '0'
'Com_revoke_all', '0'
'Com_rollback', '37'
'Com_savepoint', '0'
'Com_select', '3950076'
'Com_set_option', '151539'
'Com_show_binlog_events', '0'
'Com_show_binlogs', '5'
'Com_show_charsets', '38'
'Com_show_collations', '50'
'Com_show_column_types', '0'
'Com_show_create_db', '4'
'Com_show_create_table', '119'
'Com_show_databases', '3047'
'Com_show_errors', '0'
'Com_show_fields', '519665'
'Com_show_grants', '5'
'Com_show_innodb_status', '0'
'Com_show_keys', '135'
'Com_show_logs', '0'
'Com_show_master_status', '0'
'Com_show_new_master', '0'
'Com_show_open_tables', '0'
'Com_show_privileges', '0'
'Com_show_processlist', '639'
'Com_show_slave_hosts', '0'
'Com_show_slave_status', '0'
'Com_show_status', '2'
'Com_show_storage_engines', '0'
'Com_show_tables', '257'
'Com_show_variables', '90'
'Com_show_warnings', '0'
'Com_slave_start', '0'
'Com_slave_stop', '0'
'Com_truncate', '486'
'Com_unlock_tables', '3'
'Com_update', '259679'
'Com_update_multi', '0'
'Connections', '216002'
'Created_tmp_disk_tables', '16390'
'Created_tmp_files', '32'
'Created_tmp_tables', '43856'
'Delayed_errors', '0'
'Delayed_insert_threads', '3'
'Delayed_writes', '15239'
'Flush_commands', '1'
'Handler_commit', '3'
'Handler_delete', '23439'
'Handler_discover', '0'
'Handler_read_first', '105188'
'Handler_read_key', '157880640'
'Handler_read_next', '259222151'
'Handler_read_prev', '426048'
'Handler_read_rnd', '17741082'
'Handler_read_rnd_next', '481036143'
'Handler_rollback', '740'
'Handler_update', '26130649'
'Handler_write', '8436986'
'Key_blocks_not_flushed', '0'
'Key_blocks_unused', '1049'
'Key_blocks_used', '28694'
'Key_read_requests', '239625524'
'Key_reads', '428115'
'Key_write_requests', '985994'
'Key_writes', '233069'
'Max_used_connections', '193'
'Not_flushed_delayed_rows', '0'
'Open_files', '948'
'Open_streams', '0'
'Open_tables', '500'
'Opened_tables', '37329'
'Qcache_free_blocks', '4348'
'Qcache_free_memory', '12663632'
'Qcache_hits', '4370295'
'Qcache_inserts', '3868490'
'Qcache_lowmem_prunes', '3324149'
'Qcache_not_cached', '81077'
'Qcache_queries_in_cache', '11968'
'Qcache_total_blocks', '29802'
'Questions', '10812983'
'Rpl_status', 'NULL'
'Select_full_join', '5411'
'Select_full_range_join', '14'
'Select_range', '37311'
'Select_range_check', '0'
'Select_scan', '223018'
'Slave_open_temp_tables', '0'
'Slave_running', 'OFF'
'Slave_retried_transactions', '0'
'Slow_launch_threads', '0'
'Slow_queries', '51'
'Sort_merge_passes', '0'
'Sort_range', '3138423'
'Sort_rows', '25088222'
'Sort_scan', '98773'
'Table_locks_immediate', '5095897'
'Table_locks_waited', '2091'
'Threads_cached', '27'
'Threads_connected', '34'
'Threads_created', '995'
'Threads_running', '1'
'Uptime', '39310'

'Aborted_clients', '9942'
'Aborted_connects', '54'
'Binlog_cache_disk_use', '0'
'Binlog_cache_use', '0'
'Bytes_received', '1226208037'
'Bytes_sent', '2672346559'
'Com_admin_commands', '11113'
'Com_alter_db', '0'
'Com_alter_table', '2'
'Com_analyze', '0'
'Com_backup_table', '0'
'Com_begin', '249'
'Com_change_db', '962754'
'Com_change_master', '0'
'Com_check', '0'
'Com_checksum', '0'
'Com_commit', '285'
'Com_create_db', '1'
'Com_create_function', '0'
'Com_create_index', '0'
'Com_create_table', '4904'
'Com_dealloc_sql', '0'
'Com_delete', '28284'
'Com_delete_multi', '0'
'Com_do', '0'
'Com_drop_db', '0'
'Com_drop_function', '0'
'Com_drop_index', '0'
'Com_drop_table', '2692'
'Com_drop_user', '0'
'Com_execute_sql', '0'
'Com_flush', '1'
'Com_grant', '1'
'Com_ha_close', '0'
'Com_ha_open', '0'
'Com_ha_read', '0'
'Com_help', '0'
'Com_insert', '337383'
'Com_insert_select', '623'
'Com_kill', '0'
'Com_load', '0'
'Com_load_master_data', '0'
'Com_load_master_table', '0'
'Com_lock_tables', '3'
'Com_optimize', '12'
'Com_preload_keys', '0'
'Com_prepare_sql', '0'
'Com_purge', '0'
'Com_purge_before_date', '0'
'Com_rename_table', '0'
'Com_repair', '5309'
'Com_replace', '744'
'Com_replace_select', '0'
'Com_reset', '0'
'Com_restore_table', '0'
'Com_revoke', '0'
'Com_revoke_all', '0'
'Com_rollback', '37'
'Com_savepoint', '0'
'Com_select', '3950076'
'Com_set_option', '151539'
'Com_show_binlog_events', '0'
'Com_show_binlogs', '5'
'Com_show_charsets', '38'
'Com_show_collations', '50'
'Com_show_column_types', '0'
'Com_show_create_db', '4'
'Com_show_create_table', '119'
'Com_show_databases', '3047'
'Com_show_errors', '0'
'Com_show_fields', '519665'
'Com_show_grants', '5'
'Com_show_innodb_status', '0'
'Com_show_keys', '135'
'Com_show_logs', '0'
'Com_show_master_status', '0'
'Com_show_new_master', '0'
'Com_show_open_tables', '0'
'Com_show_privileges', '0'
'Com_show_processlist', '639'
'Com_show_slave_hosts', '0'
'Com_show_slave_status', '0'
'Com_show_status', '2'
'Com_show_storage_engines', '0'
'Com_show_tables', '257'
'Com_show_variables', '90'
'Com_show_warnings', '0'
'Com_slave_start', '0'
'Com_slave_stop', '0'
'Com_truncate', '486'
'Com_unlock_tables', '3'
'Com_update', '259679'
'Com_update_multi', '0'
'Connections', '216002'
'Created_tmp_disk_tables', '16390'
'Created_tmp_files', '32'
'Created_tmp_tables', '43856'
'Delayed_errors', '0'
'Delayed_insert_threads', '3'
'Delayed_writes', '15239'
'Flush_commands', '1'
'Handler_commit', '3'
'Handler_delete', '23439'
'Handler_discover', '0'
'Handler_read_first', '105188'
'Handler_read_key', '157880640'
'Handler_read_next', '259222151'
'Handler_read_prev', '426048'
'Handler_read_rnd', '17741082'
'Handler_read_rnd_next', '481036143'
'Handler_rollback', '740'
'Handler_update', '26130649'
'Handler_write', '8436986'
'Key_blocks_not_flushed', '0'
'Key_blocks_unused', '1049'
'Key_blocks_used', '28694'
'Key_read_requests', '239625524'
'Key_reads', '428115'
'Key_write_requests', '985994'
'Key_writes', '233069'
'Max_used_connections', '193'
'Not_flushed_delayed_rows', '0'
'Open_files', '948'
'Open_streams', '0'
'Open_tables', '500'
'Opened_tables', '37329'
'Qcache_free_blocks', '4348'
'Qcache_free_memory', '12663632'
'Qcache_hits', '4370295'
'Qcache_inserts', '3868490'
'Qcache_lowmem_prunes', '3324149'
'Qcache_not_cached', '81077'
'Qcache_queries_in_cache', '11968'
'Qcache_total_blocks', '29802'
'Questions', '10812983'
'Rpl_status', 'NULL'
'Select_full_join', '5411'
'Select_full_range_join', '14'
'Select_range', '37311'
'Select_range_check', '0'
'Select_scan', '223018'
'Slave_open_temp_tables', '0'
'Slave_running', 'OFF'
'Slave_retried_transactions', '0'
'Slow_launch_threads', '0'
'Slow_queries', '51'
'Sort_merge_passes', '0'
'Sort_range', '3138423'
'Sort_rows', '25088222'
'Sort_scan', '98773'
'Table_locks_immediate', '5095897'
'Table_locks_waited', '2091'
'Threads_cached', '27'
'Threads_connected', '34'
'Threads_created', '995'
'Threads_running', '1'
'Uptime', '39310'

What kind of engine do you use for tables ? MyISAM ? InnoDB ?

Only myISAM.

I feel that DEP was causing this bug. I cannot recreate it easily with DEP disabled.

Can we put this to suspended state and I'll reopen this bug if I find that DEP is not the cause?

DEP? I dont know any mysql parts that could  be target for DEP. But, of course it requires testing. 

OK, if it's a DEP, it's not a mysql bug. So, I set preliminary status as 'not a bug', if you find other cause of that behaviour, pls don't hesitate to reopen this bug report.

We really do not experiencing any hangups after DEP disabled. But we are trying to avoid load patterns that caused hangs as well, because we are running production system. My impression is that with probability of something like 90% DEP is the cause.
We have no free system to do testing; I feel that one should take 2003 Server SP1, enable DEP for all applications, create 10 db's with 500 tables in each, and run loop of SHOW DATABASES with SHOW TABLES for each db.

We've seen DEP causing altered floating point behaviour and lock behaviour in some application; DEP _may_ also change some tight timing nuances of code that boost probability for some not-quite-well done locking code. It is known that some locking patterns are not completely, but only practically completely safe.
If such pattern is used somewhere by acident, DEP may change practical behaviour. We' ve seen this proven issues of this case in other applications already. For example, new unexpected page fault inserted each time between some two lines of code that are expected to run without interruption by scenario, and so on..
(just thinking without clear meaning)

Sorry, hit this bug again with DEP disabled.

I'll try to make independent test environment with fresh install. It seems there is no other way to get the bug fixed.

I have no luck with recreating this bug in the sandbox.
I have new observations, however.

When server hangs this way, I have not only 'opening tables' processes hang, but also 'closing tables. In fact maybe just I simply run out of table_cache, because 'closing tables' cannot happen.

I have two questions:

1) what can prevent 'closing tables' task from ending? It is there for 30 - 60 - 90 seconds and so on.
2) what if table_cache is really low for the system? I have 500 (that is maximum I can permit becuse of handles limit).
Maybe in previous version it was handled differently? I.e. when I was out of the tables limit in previous versions of mySQL, I've seen slowdown, queue of queries waiting, that is all understandable. But that was not static hang.
Now in 4.1.* I see static hang when I run out of tables. Let us suppose I set this to 50 - it _hangs_ (deadlocks) immediately with the same sympthoms. Should it deadlock or not? Maybe, for example, to close the table it should open some another table, but there is a limit reached already, or something this way?
If it should or even may deadlock, then it is clear that it can rarely hit this state even with table_cache of 500.

Please comment these considerations.
We are hitting this bug at least once a week on all our production servers and it is really critical for us.

Thank you.

It looks like this when it hangs:
http://dmih.1gb.ru/lock_demo.htm

Another addition to this bug:

http://dmih.1gb.ru/lock_demo2.html

Server was running OK (little load).

Then I issued "SHOW TABLE STATUS FROM `1gb_profimages` ". It started to go into the deadlock as described above.
I've tried to kill the query (you see the status) - nothing happend.
That is, we are locked. You can see the picture.

Now I actually see, that I can hang the server with 
'SHOW TABLE STATUS FROM `<any base with more than about 100 tables>`'.
All tables are checked and ok.

I repeat that I cannot reproduce this bug in my home environment (we are running loaded productional system).

What help may I provide, given that I cannot reproduce the bug in the test system?

Hello Mr Dima,

The only way I am thinking for to reproduce this issue on our side
if you can provide for us a db snapshot which create the issue
reported, also with your my.ini/my.cnf file. I will try to reproduce
it on my Windows 2003 Server std Edition.

If you are able for to do the above you can upload the zip file at

ftp://ftp.mysql.com/pub/mysql/upload/

with a name identifying this bug number report.

Thanks in advance.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Dima,

So, what about my.ini file content Miguel asked you about a month ago? Does your silence mean you solved the problem or this situation not happened any more?

Have you tried to work with a newer 4.1.14-nt?

Valeriy,

I still hit it from time to time in 4.1.13a. I did not upgrate to 14 because I see nothing related to this area in changelog.

We have rather complex DB server here, something about 20Gb of data in more than 20 000 MyISAM tables. And that is production system that have to run. 
It seems that any decimation of data involved decreases probability of hang dramatically, and so it dissapears. I have no success in creating test set. I've spent about 20 hours on it, and sill I cannot recreate this bug in the test system with limited number of bases.
I think that there is no point to give you my.ini and bases with no chances for you to recreate the bug. That will only be a waste of your time. I'll post my.ini anyway below this letter. It is short.

If some day I'll figure out what exactly causes this bug, I'll reopen this ticket.

------------
[mysqld]
default-collation = latin1_bin
basedir=D:/Web/mysql
datadir=D:/Web/mysql/data
innodb_data_home_dir = 
innodb_data_file_path = D:/Web/mysql/data-innoDB/ibdata1:100M:autoextend
innodb_log_group_home_dir = D:/Web/mysql/data-innoDB

;log
;log-long-format
log-slow-queries

old-passwords
skip-name-resolve 

set-variable = long_query_time=10

set-variable = back_log=1024
set-variable = max_connect_errors=10000000
set-variable = max_connections=640000
set-variable = connect_timeout=20
set-variable = wait_timeout=600
set-variable = interactive_timeout=600

set-variable = table_cache=500
set-variable = thread_cache_size=16
set-variable = max_tmp_tables=8192
set-variable = max_heap_table_size=64M
set-variable = tmp_table_size=32M

set-variable = key_buffer_size=512M
set-variable = read_buffer_size=128K
set-variable = read_rnd_buffer_size=64K
set-variable = sort_buffer=16M
set-variable = join_buffer_size=16M
set-variable = net_buffer_length=64K

set-variable = query_cache_type=1
set-variable = query_cache_size=32M

[client]
character-sets-dir=d:/web/mysql_aux2/share/charsets
default-character-set = cp1251

OK. So, I change status to Need Feedback and will wait for the additional information about possible repeatable test case. Reopen this bug as soon as you have something new to add.

There is a similar bug report (http://bugs.mysql.com/bug.php?id=13034). I'll inform you in case of any useful information provided for it.

I'm having something similar for two months now. When the server hangs, my processlist looks like this:

+---------+--------------+---------------------------------+--------------+---------+-------+----------------+------------------------------------------------------------------------------------------------------+
| Id      | User         | Host                            | db           | Command | Time  | State          | Info                                                                                                 |
+---------+--------------+---------------------------------+--------------+---------+-------+----------------+------------------------------------------------------------------------------------------------------+
| 1301119 | pill         | host:1273 			   | NULL         | Query   | 16932 | NULL           | SHOW TABLE STATUS FROM `manbo`                                                                       |
| 1301710 | apkapk       | SRVSRVSR:3443                   | db2          | Query   | 16930 | Opening tables | SELECT COUNT(*) from galeria_pictures WHERE aid='10'  AND approved='YES'                             |
| 1301712 | apkapk       | SRVSRVSR:3533                   | db2  	  | Query   | 16925 | Opening tables | DELETE FROM galeria_banned WHERE expiry < '2005-09-30 18:19:42'                                      |
| 1301713 | apkapk       | SRVSRVSR:3568                   | db2 	  | Query   | 16923 | Opening tables | DELETE FROM galeria_banned WHERE expiry < '2005-09-30 18:19:44'                                      |
| 1301714 | apkapk       | SRVSRVSR:3584                   | db2          | Query   | 16922 | Opening tables | DELETE FROM galeria_banned WHERE expiry < '2005-09-30 18:19:45'                                      |
| 1301715 | apkapk       | SRVSRVSR:3629                   | db2          | Query   | 16920 | Opening tables | DELETE FROM galeria_banned WHERE expiry < '2005-09-30 18:19:47'                                      |
| 1301716 | apkapk       | SRVSRVSR:3648                   | db2          | Query   | 16919 | Opening tables | DELETE FROM galeria_banned WHERE expiry < '2005-09-30 18:19:48'                                      |

Or, in a more descritive way, if someone executes SHOW TABLE STATUS FROM, the server is very likelly to crash.

After the SHOW TABLE STATUS is executed, no query is returned by the server.

Is this some kind or misconfiguration or is really a bug?

Maybe its better noted here (I first added comment at bug #13034):

We can also reproduce this bug. We first saw it selecting two databases in two
phpmyadmin windows. But it can also be reproduced with two open mysql command
line clients, each submitting a "SHOW TABLE STATUS FROM ´foo´" at the same
time. After that no querys that refer to tables are answered, but the server is
not completly locked up - I can still view the running processes. One of the two
processes and all new processes remain int 'Opening table' state.

The server is running on windows 2003 SERVER, SP 1, MySQL 4.1.14. Tables in
first database (server) had 68 tables - all tables are InnoDB except one MyISAM.
Same for the second database (old_server) with 38 tables.

SHOW VARIABLES, SHOW STATUS, PROCESSLIST http://www.uo-mittelerde.ch/mysqlbug.txt

You got it Gabriel.

As soon as we noticed that the server where crashing by SHOW TABLE STATUS FROM sent by phpMyAdmin, we shut it down.

It's been this way for two months now. We simply lost all credibility on MySQL due to simple, easy to find, bugs like this. But we need to offer reliable database to our users.

Any sugestions?

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

This has now been verified internally.

Marko,

please find out if it is hanging on some MySQL semaphore in the creation of a temp file.

Regards,

Heikki

Hmm... Dima's original report is from an all-MyISAM database. Maybe this is not an InnoDB bug at all.

Regards,

Heikki

I can confirm that on source server InnoDB is forbidden:

[mysqld]
....
skip-innodb
...

However after your notes I carried some investigations and I can confirm that InnoDB servers hang much frequently.
Thus there may be 2 different problems.

Hi!

Since InnoDB calculates statistics for each table (with 8 dives into each B-tree) in SHOW TABLE STATUS, that command for InnoDB tables runs much slower than MyISAM. Maybe the deadlock bug is dependent on the speed of the command.

I believe the bug is the same for MyISAM and InnoDB tables, and it is some race condition in SHOW TABLE STATUS that causes the MySQL table cache mutex to get locked for ever.

But Marko should also investigate the temp file creation, which is another potential source of deadlocks.

Regards,

Heikki

Hi!

By the way, SHOW TABLE STATUS looks at the listing of .frm files in a directory. What if some files change during the command? Has that been covered properly in the Windows version of MySQL? The behavior of these system calls is probably different in Unix and Windows, and that could explain why only the Windows version hangs.

Regards,

Heikki

I am not sure about windows.

I'll quote man above, he first opened separate ticket for the same bug:
http://bugs.mysql.com/bug.php?id=13034

His ticket OS was Debian.

We have the same Bug.

We use Win 2003 Server + SP1 , too. (MySQL 4.0.23)

We use a Database with 500 + Tables,
but we can't reproduce the error yet, but i don't try it with 
"show table status"

The same Server with nearly the same MySQL envirement
runs without problems on a Windows 2000 Server before.

The problems starts after porting to  Win 2003 Server + SP1 and new Hardware.

regards, 

Richard

Hi!

I change the category back to 'MySQL Server' and remove the assignment to Marko. Since the bug appears with all-MyISAM databases, this cannot be an InnoDB bug.

But Marko should still check what semaphores, if any, does the temp file creation acquire inside MySQL. And Marko should add diagnostics to 5.0 so that we can diagnose a hang in temp file creation.

A MySQL engineer is now able to reproduce the hang on a Windows computer. It is a matter of days now that this bug will be found and fixed.

Regards,

Heikki

The temp file creation in InnoDB calls two MySQL functions: create_temp_file() in mysys/mf_tempfile.c and my_close() in mysys/my_open.c. Both acquire THR_LOCK_open. In my_close(), THR_LOCK_open is being held across a loop that tries to close the file. This might very well cause the hang.

In MySQL 4.1, my_close() attempts close() only once, while 5.0 keeps trying until it succeeds or an error other than EINTR occurs. This probably enlarges the window of opportunity of the deadlock.

Mark,

in the next 2 hours I will try to repeat this in the Visual C++ debugger in my Windows XP computer.

Thank you,

Heikki

Updated version to include 5.0.16-GA

Mark, all,

I ran about 20 minutes ibtest4, 9, 9a, 9t, and two Perl programs that constantly perform SHOW TABLE STATUS. But no hang on my Win XP Professional, AMD Athlon 1800.

Since you can easily repeat the hang on Win 2003, please compile debug-Win32 configuration from source and run inside the Visual C++ debugger to determine where the hang is.

If you are not able to run inside the debugger, then just put some printfs to the MySQL functions that create and close a temporary file. Our best guess is that the hang happens in those functions.

Regards,

Heikki

Forgot to mention that I used a self-compiled debug-Win32 5.0.13 build.

Hi!

http://www.uo-mittelerde.ch/mysqlbug.txt

In that other bug report, when processing SHOW TABLE STATUS, trx->op_info == "returning table comment".

This is even more evidence that the thread is hung inside innobase_mysql_tmpfile(), in the call my_close(fd, MYF(MY_WME)) where the LOCK_open mutex of MySQL is being held.

Maybe there is some bug in Windows Server 2003 SP1 that breaks temporary file operations. Or some bug in innobase_mysql_tmpfile() or /mysys/mf_tempfile.c that only surfaces on that particular OS version.

Regards,

Heikki

Hi!

Dima observed this bug when he upgraded to SP1 of Win 2003. That strongly suggests that Dima's bug is the same bug that happens with InnoDB tables on Win 2003 SP1. But in Dima's case it is a MyISAM-only database.

An explanation could be that when Dima runs SHOW TABLE STATUS, MySQL has to open and close several files. If there is a hang in Windows' _close() function, that will cause the hang where THR_LOCK_open becomes locked for ever.

If the tables are InnoDB type, then in SHOW TABLE STATUS for every table in the database, InnoDB creates and closes a temporary file. That may provoke the Windows bug more easily.

If this hypothesis holds, there is a bug in Windows 2003 SP1 that causes hangs with both MyISAM and InnoDB tables, and with InnoDB tables more easily.

I have now studied the MySQL code and Windows' online manuals, but I cannot find any error in MySQL's calls to _open() and _close(). Thus, it might be a real OS bug.

Regards,

Heikki

If even it is the OS bug, if you may find some invalidely blocking call and avoid it. It seems that anyway it is the same debug process - to debug for blocking on some application sync or for blocking on some unexpected plain thunction, you will at some moment find the point and resolve it either way.
Good luck for you.

Marko,

I am assigning the bug back to you.

You can create one temp file at the startup of InnoDB, protect it with a mutex, and use that one file in all places where you now create a temp file. You already use this method for the foreign key error temp file, etc.

The bug is probably provoked by rapid creation/opening and closing of files.

The bug should be fixed in 4.1 and 5.0, maybe also in 4.0.

Unfortunately, this will not fix Dima's bug, since Dima's bug appears with an all-MyISAM database. If some of the users has a Microsoft support contract, he could report the problem to Microsoft after we have verified that the hang indeed happens inside a _close() call.

Regards,

Heikki

Heikki, 

I have tried to reproduce this in the same manner running with VC++ debug, but can not get the hang to occur when running in debug. We have tried this on two seperate machines now with the same results, hanging when not in debug but running successfully when in a debug mode. 

I did note that the SHOW commands were hanging in an "Opening tables" state slightly longer when running in debug, but they did not totally lock up the server as before. 

Glad to see you may be getting closer however, if you need us to test anything specific please let me know

Regards

Mark

Mark and Shane,

please add printfs in my_create(), my_close(), my_register_filename() to determine if a thread gets hung there WHILE holding the THR_LOCK_open mutex.

Also add printfs to that suspected call in my_base.cc.

Of course, all threads after the hang end up waiting for the LOCK_open mutex. The question is who is holding the mutex!

There might be a bug in pthread_mutex_lock() itself, but why would it only show up in SHOW commands? It is called millions of times in normal processing.

Regards,

Heikki

I've prepared a patch that is waiting for Heikki's approval.

But first I would like to be sure that the hang really is where I believe it is.
--Heikki

Stack traces of each thread when mysqld.exe is in hung state

Attachment: stacks_5.0.17-bk_2005-11-30.txt (text/plain), 30.98 KiB.

Marko, Heikki,

Do you want dumps of any of the variables of each thread when in this state ? Which ones ?

-Shane

Marko,

find out why a SELECT calls ha_innobase::update_table_comment().

That can eat up considerable CPU and makes little sense.

Regards,

Heikki

 	mysqld.exe!innobase_mysql_tmpfile()  Line 738 + 0x6	C++
 	mysqld.exe!_os_file_create_tmpfile()  + 0x9	C
 	mysqld.exe!ha_innobase::update_table_comment(const char * comment=0x04a03dd8)  Line 5755 + 0x5	C++
 	mysqld.exe!get_schema_tables_record(THD * thd=0x02fc27f0, st_table_list * tables=0x02ece228, st_table * table=0x031c1018, int res=0x00000000, const char * base_name=0x02ead888, const char * file_name=0x02ece218)  Line 2466 + 0x16	C++
 	mysqld.exe!get_all_tables(THD * thd=0x02fc27f0, st_table_list * tables=0x02fbaae0, Item * cond=0x00000000)  Line 2205	C++
 	mysqld.exe!get_schema_tables_result(JOIN * join=0x00000000)  Line 3836 + 0xc	C++
 	mysqld.exe!JOIN::exec()  Line 1293 + 0x30	C++
 	mysqld.exe!mysql_select(THD * thd=0x02fc27f0, Item * * * rref_pointer_array=0x02fc2bd0, st_table_list * tables=0x02fbaae0

Shane,

please show also the variables.

We are especially interested if Windows system calls get correct flags.

The hang looks like an OS hang in the creation of a temp file, or creation of a file, or creation of a file descriptor (the dup() call).

Marko's patch will solve most of the problem, but probably not all. Also MyISAM creates temp files.

Regards,

Heikki

Heikki,

> find out why a SELECT calls ha_innobase::update_table_comment().
> That can eat up considerable CPU and makes little sense.

It looks like in MySQL 5.0 file sql_show.cc, the MySQL 4.1 function mysqld_extend_show_tables() was replaced by the function get_schema_tables_record(). I believe that this change is related to the information_schema feature. I remember that about half a year ago, someone complained about the table comment being modified by ha_innobase::update_table_comment(). The data (information about free space and foreign keys) sure would better be made available somewhere else, perhaps in a more structured format, but where? Is there any suitable interface for that?

Marko,

find out how OFTEN get_schema_tables... is called. If it is only called now and then, then the CPU usage is tolerable. But if it is called in every SELECT, that is a bad thing.

The interface is MySQL developers' task to get right.

Regards,

Heikki

Marko,

ok, that get_schema_ ... is called in SHOW TABLE STATUS, not in a SELECT. No problem then with the CPU usage.

Looking at the stack traces of Shane, the immediate reason for the mysqld server hanging is that open_table() in the stack trace below is holding the THR_LOCK_open mutex, and it hangs in the call _open_osfhandle() in file my_open.c. Windows hangs there trying to obtain some lock.

The next step is to study from the Windows manuals if the function in my_open.c calls Windows system calls in a legal way.

http://msdn.microsoft.com/library/default.asp?url=/library/en-us/vclib/html/_crt__open_osf...

This looks like a Windows 2003 SP1 bug that can cause a hang or a deadlock inside the Windows file open routines, and the bug is provoked by rapid (temporary) file operations.

Regards,

Heikki

Thread 2900: SHOW TABLE STATUS (id 7432 in processlist)
------------

 	ntdll.dll!KiFastSystemCallRet() 	
 	ntdll.dll!NtWaitForSingleObject()  + 0xc	
 	ntdll.dll!RtlAddressInSectionTable()  + 0xda	
>	mysqld.exe!_lock(int locknum=11)  Line 319 + 0x8	C
 	mysqld.exe!_alloc_osfhnd()  Line 59 + 0x7	C
 	mysqld.exe!_open_osfhandle(int osfhandle=17440, int flags=0)  Line 375 + 0x5	C
 	mysqld.exe!my_sopen(const char * path=0x057dde78, int oflag=32768, int shflag=64, int pmode=384)  Line 349 + 0x11	C
 	mysqld.exe!my_open(const char * FileName=0x057dde78, int Flags=4096, int MyFlags=0)  Line 77	C
 	mysqld.exe!openfrm(THD * thd=0x02de9f58, const char * name=0x057de310, const char * alias=0x02ee13a8, unsigned int db_stat=8231, unsigned int prgflag=44, unsigned int ha_open_flags=0, st_table * outparam=0x03077020)  Line 106 + 0x6b	C++
 	mysqld.exe!open_unireg_entry(THD * thd=0x00004444, st_table * entry=0x00000000, const char * db=0x00000004, const char * name=0x00000000, const char * alias=0x00000003, st_table_list * table_desc=0x007f9108, st_mem_root * mem_root=0x00000004)  Line 1768 + 0x24	C++
 	mysqld.exe!open_table(THD * thd=0x02de9f58, st_table_list * table_list=0x02ee13b8, st_mem_root * mem_root=0x057deda8, int * refresh=0x057deda4, unsigned int flags=2)  Line 1307 + 0x25	C++
 	mysqld.exe!open_tables(THD * thd=0x00000000, st_table_list * * start=0x057dedec, unsigned int * counter=0x057dede0, unsigned int flags=2)  Line 2025 + 0x1b	C++
 	mysqld.exe!open_normal_and_derived_tables(THD * thd=0x02de9f58, st_table_list * tables=0x02ee13b8, unsigned int flags=2)  Line 2362 + 0x1a	C++
 	mysqld.exe!get_all_tables(THD * thd=0x02de9f58, st_table_list * tables=0x02df0b78, Item * cond=0x00000000)  Line 2204	C++
 	mysqld.exe!get_schema_tables_result(JOIN * join=0x00000000)  Line 3836 + 0xc	C++
 	mysqld.exe!JOIN::exec()  Line 1293 + 0x30	C++
 	mysqld.exe!mysql_select(THD * thd=0x02de9f58, Item * * * rref_pointer_array=0x02dea338, st_table_list * tables=0x02df0b78, unsigned int wild_num=0, List<Item> & fields={...}, Item * conds=0x00000000, unsigned int og_num=0, st_order * order=0x00000000, st_order * group=0x00000000, Item * having=0x00000000, st_order * proc_param=0x00000000, unsigned long select_options=2693024256, select_result * result=0x02df1b28, st_select_lex_unit * unit=0x02de9fb0, st_select_lex * select_lex=0x02dea210)  Line 1852	C++
 	mysqld.exe!handle_select(THD * thd=0x02de9f58, st_lex * lex=0x02de9f98, select_result * result=0x02df1b28, unsigned long setup_tables_done_option=0)  Line 250 + 0x68	C++
 	mysqld.exe!mysql_execute_command(THD * thd=0x00000000)  Line 2492	C++

Hi!

With some Googling I found the source of osfinfo.c, a Win32 support routine file.

Thread 1128 below is holding _mlock(_OSFHND_LOCK), and many other threads are waiting for that semaphore in _alloc_osfhnd(). Thread 1128 in turn is probably waiting for:

EnterCriticalSection( &(pio->lock) );

Maybe a race condition in Windows.

Regards,

Heikki

Thread 1128: 
------------

 	ntdll.dll!KiFastSystemCallRet() 	
 	ntdll.dll!NtWaitForSingleObject()  + 0xc	
 	ntdll.dll!RtlAddressInSectionTable()  + 0xda	
>	mysqld.exe!_alloc_osfhnd()  Line 112	C
 	mysqld.exe!_open_osfhandle(int osfhandle=17904, int flags=0)  Line 375 + 0x5	C
 	mysqld.exe!my_sopen(const char * path=0x050de98c, int oflag=38754, int shflag=64, int pmode=384)  Line 349 + 0x11	C
 	mysqld.exe!my_create(const char * FileName=0x050de98c, int CreateFlags=0, int access_flags=38754, int MyFlags=16)  Line 65	C
 	mysqld.exe!create_temp_file(char * to=0x007fca30, const char * dir=0xffffffff, const char * prefix=0x3c02d13a, int mode=4295179, int MyFlags=84797836)  Line 73 + 0x1e	C
 	mysqld.exe!my_tmpdir(st_my_tmpdir * tmpdir=0x00390000)  Line 71 + 0xa	C
 	ntdll.dll!RtlFindActivationContextSectionGuid()  + 0x2d5	
 	ntdll.dll!vDbgPrintEx()  + 0x5f	
 	050deb04()	
 	ntdll.dll!RtlAllocateHeap()  + 0x6c9	
 	ntdll.dll!RtlFreeHeap()  + 0x142	
 	ffffffff()

Heikki,

You're correct, it's hung on EnterCriticalSection( &(pio->lock)) ;
Here's the variables from that:

-	pio	0x00392090 {osfhnd=17892 osfile=1 '?' pipech=10 '?' ...}	ioinfo *
	osfhnd	17892	int
	osfile	1 '?'	char
	pipech	10 '?'	char
	lockinitflag	1	int
+	lock	{DebugInfo=0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c {DebugInfo=0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c ...} LockCount=-6 RecursionCount=1 ...} ...} LockCount=-6 RecursionCount=1 ...}	_RTL_CRITICAL_SECTION
-	pio->lock	{DebugInfo=0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c {DebugInfo=0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c ...} LockCount=-6 RecursionCount=1 ...} ...} LockCount=-6 RecursionCount=1 ...}	_RTL_CRITICAL_SECTION
+	DebugInfo	0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c {DebugInfo=0x0014b5f0 {Type=0 CreatorBackTraceIndex=0 CriticalSection=0x0039209c {DebugInfo=0x0014b5f0 LockCount=-6 RecursionCount=1 ...} ...} LockCount=-6 RecursionCount=1 ...} ...}	_RTL_CRITICAL_SECTION_DEBUG *
	LockCount	-6	long
	RecursionCount	1	long
	OwningThread	0x000008b0	void *
	LockSemaphore	0x0000444c	void *
	SpinCount	4000	unsigned long
	pio->osfile	1 '?'	char

Shane, Marko,

if I understand the printout right, thread 2224 holds pio->lock and thread 1128 is waiting for it. But 2224 cannot proceed because it waits for _mlock(_OSFHND_LOCK) that is held by 1128! Thus, this is a deadlock of threads in Windows, maybe provoked by a race condition.

The code in osfinfo.c, in _alloc_osfhnd() looks suspicious. AFTER doing

EnterCriticalSection( &(pio->lock) );

it checks if pio is 'reserved' by some other thread! But the function returns with the calling thread holding pio->lock! How can then another thread do the above call? Very suspicious code.

Note that the _dup() call is the reason why thread 2224 goes back to call _alloc_osfhnd().

Marko's patch removes all calls of dup() in InnoDB after InnoDB has started up. But what can cause MyISAM to hang? I did not find any calls of dup() from MySQL code. Hmm... actually, in MyISAM's case the hang might happen through MySQL's THR_LOCK_open. The thread holding pio->lock may end up waiting for MySQL's THR_LOCK_open while the thread holding THR_LOCK_open will end up waiting for pio->lock. The hang is possible with almost any program that uses multiple threads and opens files.

We should report this bug to Microsoft if we we do not find any error from my_open.c. They should check the suspicious code in _alloc_osfhnd().

Regards,

Heikki

Thread 2224: SHOW TABLE STATUS (id 7262 in processlist)
------------

 	ntdll.dll!KiFastSystemCallRet() 	
 	ntdll.dll!NtWaitForSingleObject()  + 0xc	
 	ntdll.dll!RtlAddressInSectionTable()  + 0xda	
>	mysqld.exe!_lock(int locknum=11)  Line 319 + 0x8	C
 	mysqld.exe!_alloc_osfhnd()  Line 59 + 0x7	C
 	mysqld.exe!_dup_lk(int fh=10)  Line 104 + 0x5	C
 	mysqld.exe!_dup(int fh=10)  Line 74 + 0x6	C
 	mysqld.exe!innobase_mysql_tmpfile()  Line 738 + 0x6	C++
 	mysqld.exe!os_file_create_tmpfile()  Line 554 + 0x5	C
 	mysqld.exe!ha_innobase::update_table_comment(const char * comment=0x049ed640)  Line 5755 + 0x5	C++
 	mysqld.exe!get_schema_tables_record(THD * thd=0x02eb00d0, st_table_list * tables=0x02fd71f0, st_table * table=0x05b5d018, int res=0, const char * base_name=0x042f3f68, const char * file_name=0x02fd71e8)  Line 2466 + 0x16	C++
 	mysqld.exe!get_all_tables(THD * thd=0x02eb00d0, st_table_list * tables=0x02ebb008, Item * cond=0x00000000)  Line 2205	C++
 	mysqld.exe!get_schema_tables_result(JOIN * join=0x00000000)  Line 3836 + 0xc	C++
 	mysqld.exe!JOIN::exec()  Line 1293 + 0x30	C++

Now that I have a solid testcase, I'm de-installing SP1 from my Win2003 box and will try repeat a lockup.  Will post the results tonight.

I repeated a hang after uninstalling SP1.  Needed to run my previous testcase twice in parallel, and left it running much longer than before.   A hangup still occurred.  I'll post the stack traces + some variables later nonight to confirm it's the same issue or not.

Shane,

very interesting. Maybe we have caught the 'Windows Bug of the Year'.

Regards,

Heikki

Yep..classic race condition...this bugs been around in the C Run-time for ever (7+ years), based on code for MS VC 6 and before.

Here's the program flow:

Thread 1128 calls _open_osfhandle() which calls _alloc_osfhnd()
Thread 1128 gets the _OSFHND_LOCK lock
Thread 1128 finds an available entry in the pio table and is just about to call EnterCriticalSection( &(pio->lock) ); on this empty entry
Thread 1128 gets timesliced out
Thread 2224 opens a file thereby filling the entry that thread 1128 thinks is empty
Thread 2224 calls dup() which gets the lock on the pio entry in lock_fh/lock_fhandle
Thread 2224 then calls alloc_osfhnd() from dup_lk()
Thread 2224 blocks on the wait for the _OSFHND_LOCK which is held by thread 1128
Thread 1128 then wakes up and blocks on the pio lock being held by Thread 2224.

Hilarity ensues...

Notes:
- this bug isn't in the O/S kernel per se but rather in the C runtime library
- this code is older than the hills and hasn't changed significantly in years (based on my browsing old MS VC++ C runtime source)
- this bug is not specific to any O/S version, Service Pack or anything else...
- this bug is more related to timing, multi-core CPUs, load, timeslices and all the other fun stuff that typical race conditions are sensitive to

Couple of simple fixes:
- use TryEnterCriticalSection() in alloc_osfhnd()...if you get the lock, great...if not, move on...at least you don't block.  This call wasn't added until NTv4 and since this code is older than NT v4, the call couldn't have been used back then.  Since it looks like mysql.exe is linked statically to the C-runtime (as opposed to MSVCRT??.DLL), a recompile of the CRT module and a relink with the fix may at least confirm the fix is good.
- put a sleep of some sort after the open call and before the dup() call to allow the other thread time to notice that the file has been opened... a real hack, though.
- avoid the use of all these calls altogether and re-write the code calling dup/osf*.  Go directly to the Win32 APIs (ReadFile(), CreateFile(), etc..) which will increase your speed, avoid limitations in the C runtime (i.e. sizes of internal file tables), make it easier to scale (4GB+ file sizes, etc..) and avoid unnecessary code layers.  Long term, moving to a real good implementation of these layers on Win32 instead of porting over from *nix is the right way to go for several reasons.

If you are talking globally, please accept my 2 cents: while using C++ runtime you are limited to 2048 opened files. There is no possibility to extend this limit of MSVC runtime.
That limits table cache to 500 - 700 (more than 500 is already at risk, more than 700 is at high risk).
If you switch to win32 API, you will discard this, and it will make ISP usage VERY VERY better.

For example, now I end up with no effective index cache because tables are closed, opened, closed, opened... I would be happy to have table cache at something about 2000 - 4000, but I cannot.

Yes, exactly my point.  

The Win32 API is the best, most scalable solution.  Anything else is a compromise and will not be as functional, as fast or as stable.

I am not involved in maintaining this code ... I'm just a Windows guy helping out at the request of a co-worker...

David and Dima,

thank you for this information!

David, have you reported this to Microsoft? I tried some Googling, but I could not find this bug from the web. Maybe this bug is not well-known after all?

It is not just the _dup() call that can cause the deadlock. Also other calls that call _alloc_osfhnd() can end up waiting for _mlock(_OSFHND_LOCK).

Hmm... could the C runtime of Developer Studio 2005 contain a bug-free implementation?

We in InnoDB are using the Posix call of the C runtime library to create and open the temp file because then fprintf() and other standard C calls can write to the file. For other files InnoDB does use the Win32 CreateFile() to open the file. MySQL, on the other hand, uses always Posix calls to create and open files.

We can remove the InnoDB problem with Marko's upcoming patch: create the temp file at the server startup. Removing the MySQL problem is harder. And I do not know if the Microsoft license allows us to modify their C runtime library code.

Thank you,

Heikki
Oracle/Innobase

1) I've never seen this issue before and can't find a bug for it in the MS KB...probably not known.

2) Correct...any call going through the osf* functions will have issues.

3) VS 2005 still has the same problem...I just checked the C runtime source.

4) MS doesn't allow modifications of the redistributable files themselves.  Probably the same applies to recompiled versions of their source that you link in directly.

5) Yes, changing from Posix calls to Win32 calls does indeed create alot of work to fully remove the limitations.  It's a matter of work vs. reward as with everything.  For things that need to be fast, scalable...go Win32.  For debug, tracing, log files, etc... then Posix is OK as long as the limitations are understood and won't impact the scalability, capability or performance of the product.  On 16-way 64-bit boxes with 32GB of RAM, I can tell you from experience that Posix-like APIs on Windows won't cut it for a fully scaled system.

From my unpretentious opinion I add again that even on moderate ISP level we cannot fully load single 2 Xeon machine on Windows because of definite IO limitation.
I run 2, 3, 4 instances of mySQL server per machine to load it fully, just to compensate unability to work with lots of tables at once. I know that MyISAM is a bit obsolete, but still, let us suppose InnoDB: at ISP level I have to run it file-per-table (for multiple reasons). I'll end up with something similiar to MyISAM, OK, twice larger table cache...
Also I noticed that because of no file hints I may suppose inefficient disk caching/buffering. That is really a big issue because when you retrieve index pages or individual records it can be _really_ much more effective if you give proper hints to Win32 subsystem. For example, you have internal buffers / index caches. Let Windows to avoid buffering the same thing in global system (file) cache.
Facing this conflict I found that mostly efficient configuration is when MySQL buffers are as low as 128Mb even on systems with 4 to 8 GB of RAM.

Sorry to bother you here in this duscussion, that is just my ill subject.

David,

thank you again. We have to figure out the best channel to file the bug report to Microsoft.

Fixing the bug in their C library is probably much easier than changing the code in all multithreaded Posix applications.

Nice to see a fellow Oracle employee at bugs.mysql.com :).

Regards,

Heikki

Dima,

InnoDB does use native Windows calls to manage .ibd files. Thus, there is no practical limit on how many .ibd files you can have open at one time.

The my.cnf option:

innodb_open_files

has a default value of 300. You could test a much larger value.

Note also that InnoDB only needs one open file descriptor to an .ibd file. All connections use the same file descriptor. If several connection may query the same table at the same time, then MyISAM needs one open descriptor to both the .MYI file and the .MYD file for every concurrent query to the table.

Regards,

Heikki

I have now reported this bug to Oracle's support contact at Microsoft Corp.

Hello Heikki,
just a correction of your previous post regarding MyISAM: as
http://dev.mysql.com/doc/refman/5.0/en/open-tables.html
says: "With MyISAM tables, one extra file descriptor is required for the data file for each client that has the table open. (By contrast, *the index file descriptor is shared between all threads*.)".

Heikki && All,

Please see: 

http://blogs.msdn.com/larryosterman/archive/2005/03/02/383685.aspx

"In addition, for Windows 2003, SP1, the EnterCriticalSection API has a subtle change ...."

However I was unable for to find in the SP1 documentation something related for.

Hi!

I have now checked the code from a version of osfinfo.c found from the web. Looks like _open_osfhandle() does use _alloc_osfhnd() correctly. It unlocks the critical section with a call _unlock_fh(fh) when it has set the F_OPEN flag in the pio. The code was hard to read because _pioinfo(fh) is really a macro that calculates the correct pio and the unlocks pio->lock.

The next question is if _dup_lk() uses _alloc_osfhnd() correctly: does it unlock the critical section? I cannot find the source of dup.c from the web and do not have MSVC at home. I cannot check it right away.

If it is a MySQL problem that causes the deadlock, at least two come to my mind:
1) badly built mysqld.exe - maybe we have linked both multithreaded and non-multithreaded libraries to the .exe,
2) memory corruption that makes the _alloc_osfhnd() calls behave erratically.

Shane's printout suggested that pio->lock was still owned by thread 2224 when that thread had already returned back from a file call. Could _dup_lk() forget to unlock the critical section in some case?

Hi!

I am looking at a version of dup.c that Shane has in a 2003 version 7 of MS Developer Studio.

The function _dup (int fh) first locks pio->lock with a call _lock_fh(fh). Then, if if ( _osfile(fh) & FOPEN, it calls _dup_lk(fh).

The deadlock can happen this way:

a) Thread 1 calls _open_osfhandle(). In _alloc_osfhnd(), it gets a pio, does _munlock(_OSFHND_LOCK), and gets pre-empted BEFORE it sets the flag FOPEN in pio. Thread 1 is still holding pio->lock.

b) Thread 2 calls _open_osfhandle(). It calls _alloc_osfhnd(), acquires _mlock(_OSFHND_LOCK), sees the pio WITHOUT the FOPEN flag set, and gets pre-empted.

c) Thread 1 runs again, releases pio->lock and returns from _open_osfhandle(). Then Thread 1 calls _dup(), which acquires pio->lock, and then calls _dup_lk() which in turn calls _alloc_osfhnd(). Since Thread 2 is holding the _mlock(_OSFHND_LOCK), Thread 1 has to wait.

d) Thread 2 runs again. It attempts to acquire pio->lock. But pio->lock is held by Thread 1.

=> DEADLOCK.

---

Analysis of the bug:

To avoid a deadlock in multithreaded programs, we should assign a numeric 'rank' to each semaphore. To avoid deadlocks, semaphores should be acquired so that the ranks are in a descending order. Since _mlock(_OSFHND_LOCK) is acquired before pio->lock, _mlock(_OSFHND_LOCK) must have a higher 'rank'.

We can give ranks to pio->locks in the pio array in this way: the later a pio is in the array, the lower rank it has.

The code in dup.c breaks the rank order in two ways: it acquires pio->lock before _mlock(_OSFHND_LOCK) though pio->lock has a lower rank. Also, in the call _alloc_osfhnd() it acquires ANOTHER pio2->lock though that other pio2->lock may also have a higher rank than pio->lock!

A comment in dup.c says:

"
*       Multi-thread: Be sure not to hold two file handle locks
*       at the same time!
"

but the function itself breaks this rule.

Fix: create a new state field to pio:
      bool pio_is_free;

Let _mlock(_OSFHND_LOCK) protect THAT field. Then there is no need to peek the flag F_OPEN in pio.

Question: are there similar rank order bugs elsewhere in the C runtime?

Regards,

Heikki

Dima, all,

I have now approved Marko's patch that makes InnoDB to create all temp files at the server startup. Then there probably is no danger of the dup() deadlock with InnoDB.

I have not yet studied what could cause the pure MyISAM deadlock reported by Dima. MyISAM does not call dup(), as far as I know.

Dima, if you happen to have Visual C++, could you compile the Win32 Debug configuration of mysqld under it, run in the debugger, and find out the stack traces in the pure MyISAM deadlock?

Regards,

Heikki

Yes, I have, and I'll try, but can you please describe method to hang at least InnoDB? I was unable to do it in debug.

Dima,

SHOW TABLE STATUS;

should hang InnoDB quite easily, since it calls dup() for each table.

I do not know what can hang MyISAM. In one of your outputs, there was SHOW TABLE STATUS running at the time of the hang.

Regards,

Heikki

Hi,

our company a support contract with MS, if someone give me a decription, we can open a Ticket.

We have the freezebug in our company ,too.

What can we do now except avoidung to use "show table status"?

Is there a  patch for 4.0.x?

regards, 

Richard

Hi,

our company a support contract with MS, if someone give me a decription, we can open a Ticket.

We have the freezebug in our company ,too.

What can we do now except avoidung to use "show table status"?

Is there a  patch for 4.0.x?

regards, 

Richard

Richard,

I have reported the bug to the Oracle support contract at Microsoft.

Marko's patch that I approved yesterday will remove most freezes. The rest of the freezes may require help from Microsoft.

I am reassigning this bug to Elliot Murphy, who can find out which future 4.0.xx, 4.1.xx, and 5.0.xx releases will contain the fixes.

You can work around this bug by avoiding SHOW CREATE TABLE and SHOW TABLE STATUS when the mysqld server is under load.

Regards,

Heikki

Richard,
the bug has already been reported to Microsoft. See Heikki's comments on this bug report at [5 Dec 12:15] and [7 Dec 12:52].

The bug is also triggered by MySQL 4.0 since version 4.0.19 (May 2004). It should be possible to apply my patch for MySQL 4.1 to 4.0, but I do not know if there will be any new releases of MySQL 4.0.

Note that my patch only reduces the probability of the bug (in the Windows C runtime library) to occur. One hang has been reported for a MyISAM-only setup. The bug could be worked around by using native Windows I/O calls. InnoDB already uses them, but MyISAM uses the POSIX compatibility functions open(), close() et al.

updated synopsis.

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/77

Marko, all

I cannot repeat the hang using today's 4.1-bk pull which includes the patch http://lists.mysql.com/commits/77

After running three instances of my original testcase in parallel for 3 hours, no hang occurred.  So, for InnoDB it looks much less likely to see such a hang, but I haven't tested MyISAM yet.

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/124

Hi,

I have been unable to reproduce the hang using InnoDB tables on todays 5.0-bk build.  Sure enough, running >25 threads at a time querying status does use up more CPU, but none of them get hung up forever..

Good work on that patch!

Fixed in 4.1.17, 5.0.18.

Noted in 4.1.17, 5.0.18 changelogs.

Reopening this bug report because Dima originally reported it from a pure MyISAM database, and the patch only works around in the InnoDB case.

Hello Dima,

On your initial report you mentioned that only MyISAM tables are involved
and your suggestion how to repeat was:

"I may suggest to create with some environment with 500 db's with 100 tables in
each with sliglthly random structures, and run the loop. We are not sure, but
personally I will give 50% that this scenario will hit this bug."

I would like to know if the loop is done walking sequentially the databases for
one client application or you used a threaded client.

Thanks in advance.

Hi there,

we could no longer reproduce the bug. Thanks for your help!

Gabriel

Sorry for beeing away, still holidays.
Exactly this code was causing initial bug (PHP pseudocode):

$q = mysql_query ("SHOW DATABASES");
while ($r = mysql_fetch_array($q))
{
	$q3 = @mysql_query ("SHOW TABLES FROM `$r[0]`");
	if ($q3)
	{
		while ($r2 = mysql_fetch_array ($q3)) 
		{
			//...
		}

		$q4 = mysql_query ("SHOW TABLE STATUS FROM `$r[0]`");
		while ($r4 = mysql_fetch_array ($q4))
		{
			//...
		}
	}
}

(I'll post more comments on 10, jan)

Up to now we only saw the bug on Windows Server 2003 with SP1. However we have not stumbled across a problem on a system without the Service Pack. It is a system for heavy load benchmarking of our application and showed messages like "Unable to close file xxx.frm" or "Invalid data in xxx.frm" which might be relatd to this problem, too. Some minutes after the messages had been written to the .err file, the MySQL service crashed according to the Windows Event Log.
Except for the "mysql" database we only use InnoDB tables.

I tested the latest Windows source 4.1.17 with 500 databases with 100 MyISAM
tables each and doing show tables from and I was unable to get the server hanging:

Microsoft Windows [Version 5.2.3790]
(C) Copyright 1985-2003 Microsoft Corp.

c:\>cd\mysql\bin

C:\mysql\bin>mysqld-nt --standalone --console --table_cache=500
060119 14:54:38  InnoDB: Started; log sequence number 0 43634
mysqld-nt: ready for connections.
Version: '4.1.17-nt'  socket: ''  port: 3306  Source distribution

Connected to the server: 4.1.17-nt
Databases found:  503
SHOW TABLE STATUS FROM db0 Tables: 101
SHOW TABLE STATUS FROM db1 Tables: 101
<cut>
SHOW TABLE STATUS FROM db500 Tables: 10
SHOW TABLE STATUS FROM db51 Tables: 101
SHOW TABLE STATUS FROM db52 Tables: 101
SHOW TABLE STATUS FROM db53 Tables: 101
SHOW TABLE STATUS FROM db54 Tables: 101
SHOW TABLE STATUS FROM db55 Tables: 101
SHOW TABLE STATUS FROM db56 Tables: 101
SHOW TABLE STATUS FROM db57 Tables: 101
SHOW TABLE STATUS FROM db58 Tables: 101
SHOW TABLE STATUS FROM db59 Tables: 101
SHOW TABLE STATUS FROM db6 Tables: 101
SHOW TABLE STATUS FROM db60 Tables: 101
SHOW TABLE STATUS FROM db61 Tables: 101
SHOW TABLE STATUS FROM db62 Tables: 101
SHOW TABLE STATUS FROM db63 Tables: 101
SHOW TABLE STATUS FROM db64 Tables: 101
SHOW TABLE STATUS FROM db65 Tables: 101
SHOW TABLE STATUS FROM db66 Tables: 101
SHOW TABLE STATUS FROM db67 Tables: 101
SHOW TABLE STATUS FROM db68 Tables: 101
<cut>

mysql> show processlist\G
*************************** 1. row ***************************
     Id: 1
   User: root
   Host: localhost:1027
     db: db123
Command: Query
   Time: 0
  State: NULL
   Info: show processlist
*************************** 2. row ***************************
     Id: 3
   User: root
   Host: localhost:1029
     db: test
Command: Query
   Time: 0
  State: Opening table
   Info: SHOW TABLE STATUS FROM db416
2 rows in set (0.00 sec)

Below the 2 application for to create the databases and tables and to query
the server:

#include <my_global.h>
#include <m_string.h>
#include "mysql.h"

#define DB_HOST			"localhost"
#define DB_USER			"root"
#define DB_PASSW		""
#define DB_NAME			"test"
#define DB_PORT			3306
#define DB_UNIX_SOCKET	NULL

void main( void )
{
  MYSQL mysql;
  char my_sub[255],my_query[255],my_query2[255];
 
  mysql_init(&mysql);
     
  if (!mysql_real_connect(&mysql,DB_HOST,DB_USER,DB_PASSW,DB_NAME,
						   DB_PORT,DB_UNIX_SOCKET,0))
  {
    printf("Error: %s\n",mysql_error(&mysql));
    return;
  }
  else
   printf( "Connected to the server: %s\n", mysql_get_server_info(&mysql));

  for (int y = 0; y <= 500; y++)
  {
	int10_to_str((int) y,strmov(my_sub, "Create Database if not exists db"), 10);
    
    if (mysql_query( &mysql, my_sub) )
	{
      printf("Error (query): %s\n", mysql_error( &mysql ));
      mysql_close( &mysql );
      return;
    }
	  
    int10_to_str((int) y,strmov(my_sub, "Use db"), 10);
    
    if (mysql_query( &mysql, my_sub) )
	{
      printf("Error (query): %s\n", mysql_error( &mysql ));
      mysql_close( &mysql );
      return;
	}

	for (int x = 0; x <= 100; x++)
    {
	 int10_to_str((int) x,strmov(my_sub, "Create Table if not exists tb"), 10);
     strxnmov(my_query,sizeof(my_query)-1,my_sub,
	          " (id int not null auto_increment primary key, idname varchar(200))engine=MyISAM",NullS);
	 	
      int10_to_str((int) x,strmov(my_sub, "Insert into tb"), 10);
      strxnmov(my_query2,sizeof(my_query2)-1,my_sub," set idname = repeat('A',200)",NullS);
	 
	 if (mysql_query( &mysql, my_query) )
	 {
       printf("Error (query): %s\n", mysql_error( &mysql ));
       mysql_close( &mysql );
       return;
	 }

     for ( int z =1; z <= 20; z++ )
     {
      if (mysql_query( &mysql, my_query2) )
	  {
        printf("Error (query): %s\n", mysql_error( &mysql ));
        mysql_close( &mysql );
        return;
	  }
     }
   }
  }
  mysql_close(&mysql);
}
---------------------------------------------------------------------------
#include <my_global.h>
#include <m_string.h>
#include "mysql.h"

#define DB_HOST			"localhost"
#define DB_USER			"root"
#define DB_PASSW		""
#define DB_NAME			"test"
#define DB_PORT			3306
#define DB_UNIX_SOCKET	NULL

void main( void )
{
  MYSQL mysql;
  MYSQL_RES	* res, *res2 ;
  MYSQL_ROW	row ;
  char my_query[255];
   
  mysql_init(&mysql);
    
  if (!mysql_real_connect(&mysql,DB_HOST,DB_USER,DB_PASSW,DB_NAME,
						   DB_PORT,DB_UNIX_SOCKET,0))
  {
    printf("Error: %s\n",mysql_error(&mysql));
    return;
  }
  else
	printf("Connected to the server: %s\n",mysql_get_server_info(&mysql));

  if (mysql_query( &mysql, "SHOW DATABASES") )
  {
    printf("Error (query): %s\n", mysql_error( &mysql ));
    mysql_close( &mysql );
    return;
  }
  else
  {
    res = mysql_store_result( &mysql ) ;
    int i = (int) mysql_num_rows( res ) ; 
    printf( "Databases found:  %ld\n", i ) ;

    while ( row = mysql_fetch_row( res ) )
    {
      int j = mysql_num_fields( res ) ;

      for ( int k = 0 ; k < j ; k++ )
      {
        strxnmov(my_query, sizeof(my_query)-1,"SHOW TABLE STATUS FROM ",row[k],NullS);
        if (mysql_query( &mysql, my_query ))
        {
          printf("Error (query): %s\n", mysql_error( &mysql ));
          mysql_close( &mysql );
          return;
        }
        else
        {
          res2 = mysql_store_result( &mysql ) ;
          int u  = (int) mysql_num_rows( res2 ) ;
          printf("%s Tables: %d\n",my_query, u);

        }

      }
    }
  }

  mysql_close(&mysql);
}

I will do one more test trying to force the create of temp files.

Hello There,
We are also a web host suffering from the same problem - where can we get hold of the 4.1.17 Windows build, I assume 4.1.17 is safe to use?

To add to my last comment, if only the source for 4.1.17 is available for download, can somebody please provide the binaries.

I would be most grateful.

Warren,

4.1.18 is currently available.

You'll probably want version 4.1.19 or 5.0.19 because of bug 15653 fixed in those versions. 5.0.19 is available now. For 4.1.19 I don't see a planned release looking at the schedule as far ahead as June.

I was unable to repeat with MyISAM tables.

I can't repeat the hang anymore with 200 threads, and thousands of myisam tables, 4.1.18.

I had such problem if there were not enough resources on server. Check df -h for mysql directory free space.

I imagine that problem was slightly different than this bug - the server locking up because of lack of disk space. 

This bug is actually Windows specific - so I can't imagine that it would be related (if you were using Linux, which I infer from "df -h").

Thanks for the comment though!

Mark

bug status is really closed due to the workaround made in innodb.

Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)