MySQL Bugs: #68289: Mysql connection pool exhausted/connections not reused

Bug #68289	Mysql connection pool exhausted/connections not reused
Submitted:	6 Feb 2013 10:41	Modified:	14 Feb 2013 19:55
Reporter:	Velja Radenkovic	Email Updates:
Status:	Closed	Impact on me:	None
Category:	Connector / NET	Severity:	S1 (Critical)
Version:	6.4.4.0	OS:	Windows (2008 server / Web application context)
Assigned to:	Fernando Gonzalez.Sanchez	CPU Architecture:	Any
Tags:	.net Connector, asp.net, connection pool, exhausted pool, IIS, MySQL

Description:
Recently we moved one asp.net mvc application to windows 2008 server.
(We had same problem on windows 2003 server and we upgraded to 2008 following suggestion from senior ORACLE/MySql DBA)
Connection pool is exhausted and connections are not reused. Further more I wanted to get some time to resolve this by settings ConnectionLifeTime=45 hoping that connection will be dropped in 45 seconds. That setting clearly doesn't work.

It reuses connection only first 30 seconds to 1 minute of connection lifetime. After that as you can see they are in sleep status and connector always opens new one. After it exhaust the application pool it starts showing exception listed bellow.

Longest running query comeletes in 3.2 seconds.

Connection string:
Datasource=localhost;Database=XXXXX;uid=XXXX;pwd=XXXXX;ConnectionLifeTime=45;

Look at show process list output:
| 101 | root | localhost:49464 | somedbname | Sleep   | 28607 |       | NULL
              |
| 104 | root | localhost:49477 | somedbname | Sleep   | 28315 |       | NULL
              |
| 106 | root | localhost:49481 | somedbname | Sleep   | 28015 |       | NULL
              |
| 111 | root | localhost:49493 | somedbname | Sleep   | 27715 |       | NULL
              |
| 112 | root | localhost:49495 | somedbname | Sleep   | 27415 |       | NULL
              |
| 114 | root | localhost:49501 | somedbname | Sleep   | 27115 |       | NULL
              |
| 116 | root | localhost:49505 | somedbname | Sleep   | 26815 |       | NULL
              |
| 118 | root | localhost:49510 | somedbname | Sleep   | 26515 |       | NULL
              |
| 120 | root | localhost:49514 | somedbname | Sleep   | 26213 |       | NULL
              |
| 123 | root | localhost:49522 | somedbname | Sleep   | 25911 |       | NULL
              |
| 126 | root | localhost:49528 | somedbname | Sleep   | 25614 |       | NULL
              |
| 129 | root | localhost:49541 | somedbname | Sleep   | 25314 |       | NULL
              |
| 131 | root | localhost:49552 | somedbname | Sleep   | 25014 |       | NULL
              |
| 132 | root | localhost:49554 | somedbname | Sleep   | 24714 |       | NULL
              |
| 134 | root | localhost:49559 | somedbname | Sleep   | 24414 |       | NULL
              |
| 135 | root | localhost:49568 | somedbname | Sleep   | 24113 |       | NULL
              |
| 136 | root | localhost:49570 | somedbname | Sleep   | 23810 |       | NULL
              |
| 139 | root | localhost:49574 | somedbname | Sleep   | 23514 |       | NULL
              |
| 140 | root | localhost:49611 | somedbname | Sleep   | 23214 |       | NULL
              |
| 143 | root | localhost:49619 | somedbname | Sleep   | 22912 |       | NULL
              |
| 145 | root | localhost:49623 | somedbname | Sleep   | 22611 |       | NULL
              |
| 150 | root | localhost:49638 | somedbname | Sleep   | 22315 |       | NULL
              |
| 151 | root | localhost:49641 | somedbname | Sleep   | 22013 |       | NULL
              |
| 154 | root | localhost:49655 | somedbname | Sleep   | 21710 |       | NULL
              |
| 156 | root | localhost:49659 | somedbname | Sleep   | 21414 |       | NULL
              |
| 157 | root | localhost:49661 | somedbname | Sleep   | 21114 |       | NULL
              |
| 158 | root | localhost:49663 | somedbname | Sleep   | 20813 |       | NULL
              |
| 160 | root | localhost:49669 | somedbname | Sleep   | 20514 |       | NULL
              |
| 161 | root | localhost:49671 | somedbname | Sleep   | 20214 |       | NULL
              |
| 162 | root | localhost:49673 | somedbname | Sleep   | 19914 |       | NULL
              |
| 164 | root | localhost:49677 | somedbname | Sleep   | 19614 |       | NULL
              |
| 165 | root | localhost:49680 | somedbname | Sleep   | 19313 |       | NULL
              |
| 166 | root | localhost:49682 | somedbname | Sleep   | 19015 |       | NULL
              |
| 168 | root | localhost:49687 | somedbname | Sleep   | 18714 |       | NULL
              |
| 171 | root | localhost:49693 | somedbname | Sleep   | 18414 |       | NULL
              |
| 172 | root | localhost:49695 | somedbname | Sleep   | 18114 |       | NULL
              |
| 173 | root | localhost:49697 | somedbname | Sleep   | 17814 |       | NULL
              |
| 174 | root | localhost:49699 | somedbname | Sleep   | 17515 |       | NULL
              |
| 176 | root | localhost:49703 | somedbname | Sleep   | 17214 |       | NULL
              |
| 177 | root | localhost:49705 | somedbname | Sleep   | 16911 |       | NULL
              |
| 179 | root | localhost:49709 | somedbname | Sleep   | 16614 |       | NULL
              |
| 180 | root | localhost:49711 | somedbname | Sleep   | 16314 |       | NULL
              |
| 181 | root | localhost:49714 | somedbname | Sleep   | 16015 |       | NULL
              |
| 182 | root | localhost:49717 | somedbname | Sleep   | 15714 |       | NULL

Exception:
System.Configuration.ConfigurationErrorsException: Too many connections (D:\Web_Data\somedomain.com\web.config line 99) ---> MySql.Data.MySqlClient.MySqlException: Too many connections
   at MySql.Data.MySqlClient.MySqlStream.ReadPacket()
   at MySql.Data.MySqlClient.NativeDriver.Open()
   at MySql.Data.MySqlClient.Driver.Open()
   at MySql.Data.MySqlClient.Driver.Create(MySqlConnectionStringBuilder settings)
   at MySql.Data.MySqlClient.MySqlPool.CreateNewPooledConnection()
   at MySql.Data.MySqlClient.MySqlPool.GetPooledConnection()
   at MySql.Data.MySqlClient.MySqlPool.TryToGetDriver()
   at MySql.Data.MySqlClient.MySqlPool.GetConnection()
   at MySql.Data.MySqlClient.MySqlConnection.Open()
   at MySql.Web.Common.SchemaManager.GetSchemaVersion(String connectionString)
   at MySql.Web.Common.SchemaManager.CheckSchema(String connectionString, NameValueCollection config)
   at MySql.Web.Security.MySQLRoleProvider.Initialize(String name, NameValueCollection config)
   at System.Web.Configuration.ProvidersHelper.InstantiateProvider(ProviderSettings providerSettings, Type providerType)

How to repeat:
Just use providers (role, membership etc.) create a loop that opens connection/does some work/closes connection and leave more then minute between.

innodb status

Attachment: innodb.out (application/octet-stream, text), 18.32 KiB.

Process list

Attachment: processlist.out (application/octet-stream, text), 1.45 KiB.

I installed application/server clone on virtual machine. I limited conns to 10 and I can pretty much waste the server in 30 mins. I will continue debugging. 

Anyone knows what below means? Its from inno db status output.
---TRANSACTION 6531, not started
MySQL thread id 20, OS thread handle 0x910, query id 8019 localhost ::1 root cleaning up

I found bug in my code :|. Buggy function call was in filter so I wasn't aware of its execution. :| I will provide some more data but this is most probably not mysql nor mysql connector bug. I am testing again ATM. I apologize for being stupid.

Velja

Good to know, I was not able to repro.

However, we used to have a bug in pooling, see http://bugs.mysql.com/bug.php?id=63942
and the fixed was released in 6.4.5

Regards

I did upgrade to Version=6.6.5.0. I attached debugger to connector and pool was working all right but I still had same issue. That's how I found my reader that wasn't closed.

I added watch to private List<Driver> inUsePool; And saw that all stucked connections are in use there. Watching: inUsePool[0-10].reader.Command.CommandText
helped me identify part in code that wasnt closing reader/connection. All connections that were stuck were indeed occupied by my reader. All had same SQLCommand that is called only once in application.

Tomorrow I will have this new setup under live server load and I bet it will work fine.

I probably totally confused you by saying that Providers caused this. Sorry for that. Filter was executing before my test case and I was blind to spot that.