Bug #45252 MySQL stops responding after writing certain amount of data
Submitted: 1 Jun 2009 23:21 Modified: 11 Sep 2012 19:32
Reporter: Insfin Australia Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:6.0.10-alpha-community OS:Microsoft Windows (XP Professional with SP2)
Assigned to:
Tags: events, handles leak, memory leak

[1 Jun 2009 23:21] Insfin Australia
Description:
As part of our application stress tests, we are writing data into two 
MySQL databases. The stress test application, written in Delphi, and 
using MicroOLAP Direct Access components, is on a separate computer
to the database, connecting over a local 100M bit network.

We have observed that after a certain amount of data is written, the 
MySQL service stops responding to requests, while the actual MySQL 
service itself is still running.

Our setup is as follows:

MySQL Version: 6.0.10-alpha-community

Database Server OS: Windows XP Professional with SP2. Two databases, 
  DB1 and DB2, using the InnoDB engine.

Client OS: Microsoft Windows 2000 Server with SP4

The stress testing consists of two Windows applications: CLIENT1 and CLIENT2.
CLIENT1 has 4 threads, CLIENT2 also has 4 threads. 

Each of CLIENT1's thread, on execution:

  Writes 1 record of about 178 bytes into DB1.trx
  Writes 2 record of about 100 KB and 166 bytes respectively into DB1.trx_data
  Writes 1 record of about 65 bytes into DB1.trx_status
  Writes 1 record of about 114 bytes into DB1.trx_notes
  
Each of CLIENT2's thread, on execution:

  Reads 1 record of about 290 bytes from DB1.usr
  Writes 1 record of about 24 bytes to DB2.queue  

Each thread is selected to run randomly, with a frequency of approximately 
30 secs.

We started off with DB1 of about 700 MB in size. Now it is around 56 GB and 
growing. 

We found that after about 35,000 to 37,000 records have been written into
DB1.trx, requests to MySQL fail, while the actual service is still running.

Attempting to use the MySQL Query Browser on the database server also fails 
to connect once this occurs, eliminating any issue with our clients. 

We can stop the service gracefully, and start it again very gracefully.

Please note that with 37,000 records written into DB1.trx:

  (37,000 * 2) records written into DB1.trx_data
  37,000 records written into DB1.trx_status
  37,000 records written into DB1.trx_notes
  
And round 50,000 to 60,000 records written into DB2.queue.

At the point where MySQL stops responding, Windows Tasks Manager shows its
memory usage of 850,000 KB.

* There are also a significiant number of handles created by MySQL -- at some
  points, this number can be as high as 500,000 handles.
  
* Once MySQL stops responding, attempt to run any other program fails, we cannot
  even start Task Manager.

  Running command such as "netstat -a -b -p tcp" will result in the following 
  error:
  
    The application failed to initialize properly (0xc0000142)
    
  Starting MySQL Query Browser, or MySQL Administrator will also produce the
  above message.
  
* Trying to connect to MySQL (from another client machine) produces the error:

    MySQL Error Code: (2004) Can't create TCP/IP socket (10055)
    
It seems that MySQL somehow uses up all available memory and system resources
without releasing them.

And also please note that, this problem occurs with and without replication 
enabled.

Do you have any suggestions for this problem? We would appreciate it very much.

Best regards.

How to repeat:
Keep writing data into several tables in a database over several hours or
days.

Suggested fix:
None.
[2 Jun 2009 5:32] Sveta Smirnova
Thank you for the report.

>   Running command such as "netstat -a -b -p tcp" will result in the following 
  error:
>  
>    The application failed to initialize properly (0xc0000142)
    
This looks like you used all resources needed to create a connection, so this is not MySQL bug. Please either change your stress application, so it does not create so many connections or increase OS limits and value of max_connections for mysqld.
[4 Jun 2009 1:45] Insfin Australia
Hi Sveta,

Thank you for the reply. We would like to follow that up.

1. We observe that MySQL server does not release handles.

   a. The total number of handles was a bit more than 2,000,000 (2 millions) as 
      reported by Windows Task Manager. We stopped all applications that were 
      connecting to MySQL server. We waited for about 10 minutes. The total number
      of handles did not come down.
      
   b. We reset MySQL server. The total number of handles are about 135,000.
   
      We then started MySQL Query Browser, this is the only client that connected to
      MySQL server. We repeatedly submitted two queries. Each returned about 20K of data.
      
      Each time, the total number of handles jumped up between 3 and 6. And never came
      down.
      
      We shut down MySQL Query Browser, no client connection. The total number of handles
      stayed static.
      
    This might the cause of system running out resources? 

2. We leave max_connections at the default value which is 100

   [mysqld]
   max_connections=100
   
   Our stress test applications do not connect directly to MySQL, they connect to
   a middle server, and this middle server maintains only two connection to MySQL
   server.
   
   Each stress test's thread talks to the middle server, once finishes, it closes
   the socket.   
   
   At its peak, the middle server has about 23 active threads.
   
   There is no TCP socket or MySQL connection leaks on our applications.

Would you please have a look into this?

Thank you and best regards.
[4 Jun 2009 5:55] Sveta Smirnova
Thank you for the feedback.

Which storage engine do you use? Do you have query cache enabled? Please also check bug #21487 in case if your case is similar.
[9 Jun 2009 5:22] Insfin Australia
Hi Sveta,

Thank for looking into it.

1. We use InnoDB storage engine in all our databases.

2. We did have query cache enabled by default. These were the settings:

     query_cache_limit = 1048576
     query_cache_min_res_unit = 4096
     query_cache_size = 75497472
     query_cache_type = ON
     query_cache_wlock_invalidate = OFF
     
   We pulled out those values by running this query:
   
     show variables where variable_name like 'query_cache%';
     
3. Disabling query cache does not help.

     query_cache_limit = 1048576
     query_cache_min_res_unit = 4096
     query_cache_size = 0
     query_cache_type = ON
     query_cache_wlock_invalidate = OFF

   (query_cache_size = is set to 0.)
   
   It stopped responding at the appropriately the same point:
   
     MySQL memory usage: 845,376 KB
     MySQL total handles: 4,975,383

4. Bug #21487 is similar to this one. And it has not been resolved.

5. My supervisor points out that, regardless of how we config the query cache,
   and write the client applications, MySQL should not just stop responding. It 
   should be able to correctly manage memory and system resources.
   
Would you please have a look into this?

Thank you and best regards.

Be Hai Nguyen.
[9 Jun 2009 8:50] Sveta Smirnova
Thank you for the feedback.

Could you please try Handle programm from http://technet.microsoft.com/en-us/sysinternals/bb896655.aspx to see what is really allocated to mysqld? Also, please, provide full mysqld error log file. Worth checking OS logs.

Please also try current version 6.0.11, because 6.0 is alpha, so even minor versions can have huge improvements.
[1 Jul 2009 23:33] Insfin Australia
Hi Sveta,

Thank you for replying.

A few days after the 9/June/2009, we tried download 6.0.11, but has been removed
ever since. The page we tried was:

   http://dev.mysql.com/downloads/mysql/6.0.html
   
Does that means 6.0.11 is not available for downloading anymore? What other version would you suggest we try?

Thank you and best regards.

Be Hai Nguyen.
[2 Jul 2009 9:31] Sveta Smirnova
Thank you for the feedback.

Version 6.0 was partially replaced with version 5.4 and partially exists as development version 6.0 which can be found at Launchpad. Older 6.0 releases moved to "Archive" section located at http://downloads.mysql.com/archives.php?p=mysql-6.0, but latest version there is 6.0.9 

Anyway please try to get output of Handle program to find what is really used.
[3 Jul 2009 4:35] Insfin Australia
Hi Sveta,

Thank you for replying.

We are still on 6.0.10 -- and we have just run another test.

1. There is nothing out of the ordinary in MySQL error log or
   OS log (Windows Event Viewer.)
   
2. We did run handle as you recommended:

      C:\>....\handle.exe -a > c:\handles.txt
    
   We have got 4.odd millions entries for mysql.exe in c:\handles.txt.
   
   Most are event handles. And this matches up with the number reported by
   Windows Task Manager.
   
   
   "c:\handles.txt" is more than 100 MB. Zipped down to 11 MB. So we did
   not attached it in this post.
   
Would you be able to advise on what we should try next? Or are any other
info that you would like to request?
   
Thank you and best regards.

Be Hai Nguyen.
[4 Aug 2009 5:52] Sveta Smirnova
Thank you for the feedback.

> Most are event handles.

This looks similar to bug #21487. Do you have query cache enabled? Do  you have large  innodb_buffer_pool_size? Please try to decrease it and check if it solves the problem.
[4 Sep 2009 23:00] Bugs System
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".
[20 Jun 2011 11:44] Shane Bester
Folks who get this error message need to check if this applies to them:
http://support.microsoft.com/kb/917114

Also make sure enough memory and non-paged pool is available on the
system.
[20 Jun 2011 11:45] Shane Bester
btw, it is expected that mysqld.exe uses this many handles.  that is not a bug.
[4 Nov 2011 8:56] Jason Garrett
I can also add my issue to this BUG.

Windows Server 2003 Enterprise - SP2 (32 bit)
IBM x3650
18 GB Memory

MySQL 5.1.48-community-log (yeah, yeah, working on the upgrade!)
46 Databases
InnoDB on most tables, with separate file per table
Largest Database = 158 tables, 91 GB
Largest Table File = 48 GB (i'm so proud, but dream of partitioning...)

MySQL runs for anywhere from 1 day to 2 weeks, before queries stop using indexes correctly, and take extraordinarily long to complete (ie. normally less than 10 seconds, and now longer than 10 minutes).
Stopping and starting MySQL resolves the issue.

Observing the mysqld.exe process, 466189 handles are held.
The handle.exe tool validates this high number:
Handle v3.46
Copyright (C) 1997-2011 Mark Russinovich
Sysinternals - www.sysinternals.com

Handle type summary:
  Desktop         : 120
  Directory       : 220
  Event           : 473623
  File            : 8555
  IoCompletion    : 1182
  Job             : 2
  Key             : 2493
  KeyedEvent      : 94
  Mutant          : 1490
  Port            : 902
  Process         : 414
  Section         : 756
  Semaphore       : 2435
  SymbolicLink    : 5
  Thread          : 2975
  Timer           : 65
  Token           : 173
  WaitablePort    : 3
  WindowStation   : 191
  WmiGuid         : 192
Total handles: 495890

Running handle.exe -a, the output verifies the mysqld.exe process holds all of these event handles.

Query Cache is not on:
mysql> show variables where variable_name like 'query%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_alloc_block_size       | 8192    |
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_type             | ON      |
| query_cache_wlock_invalidate | OFF     |
| query_prealloc_size          | 8192    |
+------------------------------+---------+

To verify:
mysql> show global status like 'qc%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Qcache_free_blocks      | 0     |
| Qcache_free_memory      | 0     |
| Qcache_hits             | 0     |
| Qcache_inserts          | 0     |
| Qcache_lowmem_prunes    | 0     |
| Qcache_not_cached       | 0     |
| Qcache_queries_in_cache | 0     |
| Qcache_total_blocks     | 0     |
+-------------------------+-------+

And for good measure:
mysql> show variables where variable_name like 'innodb%';
+-----------------------------------------+---------------------------+
| Variable_name                           | Value                     |
+-----------------------------------------+---------------------------+
| innodb_adaptive_hash_index              | ON                        |
| innodb_additional_mem_pool_size         | 26214400                  |
| innodb_autoextend_increment             | 8                         |
| innodb_autoinc_lock_mode                | 0                         |
| innodb_buffer_pool_size                 | 1258291200                |
| innodb_checksums                        | ON                        |
| innodb_commit_concurrency               | 0                         |
| innodb_concurrency_tickets              | 500                       |
| innodb_data_file_path                   | ibdata1:10M:autoextend    |
| innodb_data_home_dir                    | M:\MySQL Datafiles\       |
| innodb_doublewrite                      | ON                        |
| innodb_fast_shutdown                    | 1                         |
| innodb_file_io_threads                  | 4                         |
| innodb_file_per_table                   | ON                        |
| innodb_flush_log_at_trx_commit          | 2                         |
| innodb_flush_method                     |                           |
| innodb_force_recovery                   | 0                         |
| innodb_lock_wait_timeout                | 50                        |
| innodb_locks_unsafe_for_binlog          | OFF                       |
| innodb_log_buffer_size                  | 12582912                  |
| innodb_log_file_size                    | 268435456                 |
| innodb_log_files_in_group               | 2                         |
| innodb_log_group_home_dir               | N:\MySQL Datafiles\iblogs |
| innodb_max_dirty_pages_pct              | 90                        |
| innodb_max_purge_lag                    | 0                         |
| innodb_mirrored_log_groups              | 1                         |
| innodb_open_files                       | 300                       |
| innodb_rollback_on_timeout              | OFF                       |
| innodb_stats_on_metadata                | ON                        |
| innodb_support_xa                       | OFF                       |
| innodb_sync_spin_loops                  | 20                        |
| innodb_table_locks                      | ON                        |
| innodb_thread_concurrency               | 18                        |
| innodb_thread_sleep_delay               | 10000                     |
| innodb_use_legacy_cardinality_algorithm | ON                        |
+-----------------------------------------+---------------------------+

Have verified that Microsoft Article 917114 is applied, as server version of afd.sys file is 5.2.3790.4828.

My question is, if this is not a bug, have I allocated too much memory?
Can you give me a simple explanation as to why so many event handles are held?

Regards
Jason
BTW: MySQL, fantastic product, love your work...
[29 Nov 2011 16:57] Sveta Smirnova
Jason,

thank you for the feedback.

Regarding to memory usage you should check your OS: open Process Monitor and find out how much RAM is available for other applications. Please also note on 32-bit system a process can not take more than 4G of RAM (exact number is actually less than 4G).

Please also try smaller number of innodb_thread_concurrency.
[30 Dec 2011 7:00] Bugs System
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".