
The Google Feed code that is run on a 60-second timer by Global.asax appears to be leaking an SQL connection sometimes. I will file a bug report via the Feedback button (referring to this post), but I wanted to post here in case someone else runs into the same problem I did. Here is what I went through that led me to blame the Google Feed code.
I was working on my Dev site, and decided to increase the Idle Time-out setting for the Application Pool in IIS to 360 minutes (IIS Manager: choose server on left side, expand tree, select Application Pools, select appropriate pool, click Advanced Settings.. on the right, set Idle Time-out (minutes) to 360, click OK, choose server on left side again, click Restart on the right). I did this because the default is only 20 minutes, and I got tired of waiting for it to load again if I was interrupted by other tasks while working on customizing the site.
After I did this, I started getting these errors on an irregular basis:
I say irregularly because it wasn't every day, sometimes it would be a couple days before it would happen. Once it started though, the same set of 4 messages was repeatedly added to the error log many times per hour. Also, once the error started occurring, I would get similar errors trying to open the site in the browser.2014-03-14 08:08:56,232 WARN ADOExceptionReporter NHibernate.ADOException: While preparing SELECT this_.StoreId as StoreId107_0_, this_.Name as Name107_0_, this_.ApplicationName as Applicat3_107_0_, this_.LoweredApplicationName as LoweredA4_107_0_, this_.LicenseKey as LicenseKey107_0_, this_.DefaultWarehouseId as DefaultW6_107_0_, this_.NextOrderId as NextOrde7_107_0_, this_.OrderIdIncrement as OrderIdI8_107_0_, this_.WeightUnitId as WeightUn9_107_0_, this_.MeasurementUnitId as Measure10_107_0_ FROM ac_Stores this_ an error occurred ---> System.InvalidOperationException: Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.
at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)
at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
at System.Data.SqlClient.SqlConnection.Open()
at NHibernate.Connection.DriverConnectionProvider.GetConnection()
at NHibernate.AdoNet.ConnectionManager.GetConnection()
at NHibernate.AdoNet.AbstractBatcher.Prepare(IDbCommand cmd)
--- End of inner exception stack trace ---
at NHibernate.AdoNet.AbstractBatcher.Prepare(IDbCommand cmd)
at NHibernate.AdoNet.AbstractBatcher.ExecuteReader(IDbCommand cmd)
at NHibernate.Loader.Loader.GetResultSet(IDbCommand st, Boolean autoDiscoverTypes, Boolean callable, RowSelection selection, ISessionImplementor session)
2014-03-14 08:08:56,232 ERROR ADOExceptionReporter While preparing SELECT this_.StoreId as StoreId107_0_, this_.Name as Name107_0_, this_.ApplicationName as Applicat3_107_0_, this_.LoweredApplicationName as LoweredA4_107_0_, this_.LicenseKey as LicenseKey107_0_, this_.DefaultWarehouseId as DefaultW6_107_0_, this_.NextOrderId as NextOrde7_107_0_, this_.OrderIdIncrement as OrderIdI8_107_0_, this_.WeightUnitId as WeightUn9_107_0_, this_.MeasurementUnitId as Measure10_107_0_ FROM ac_Stores this_ an error occurred
2014-03-14 08:08:56,232 WARN ADOExceptionReporter System.InvalidOperationException: Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.
at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)
at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)
at System.Data.SqlClient.SqlConnection.Open()
at NHibernate.Connection.DriverConnectionProvider.GetConnection()
at NHibernate.AdoNet.ConnectionManager.GetConnection()
at NHibernate.AdoNet.AbstractBatcher.Prepare(IDbCommand cmd)
2014-03-14 08:08:56,232 ERROR ADOExceptionReporter Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.
Recycling the Application Pool or restarting the web site or IIS would resolve the issue.
I searched the forums (via ablecommerce.net) for "The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached". The last post in this thread viewtopic.php?f=42&t=16035 gave me the hint that it had to do with the SQL connection pool, not the IIS Application Pool. After some Googling and reading, the common culprit seemed to be "leaked" or "orphaned" SQL connections (i.e., some code somewhere was opening an SQL connection, but not closing it when it was done). I decided to look at the SQL connections to the AbleCommerce database using the following query:
Code: Select all
declare @who2table as table
(
SPID int,
Status nvarchar(20),
Login nvarchar(50),
HostName nvarchar(50),
BlkBy nvarchar(50),
DBName nvarchar(500),
Command nvarchar(50),
CPUTime bigint,
DiskIO bigint,
LastBatch nvarchar(50),
ProgramName nvarchar(500),
SPID2 int,
REQUESTID int
);
INSERT INTO @who2table
EXEC ('sp_who2');
select * from @who2table where DBName = 'AbleCommerce' order by LastBatch;
delete @who2table;
I restarted IIS, logged into the web site and logged back out, then started running the query every so often again. After 5 minutes, connections started showing up again, sometimes 1 minute apart, sometimes 2 or more minutes apart. If I refreshed the query just right, I could see that a connection was added to the query results every minute, but only some of the connections were returned with subsequent queries; the rest would be gone after subsequent queries. For example, after about an hour there were still 31 connections showing (the site was not used at all during this time). For example:
Code: Select all
SPID Status Login HostName BlkBy DBName Command CPUTime DiskIO LastBatch ProgramName SPID2 REQUESTID
87 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:49:32 .Net SqlClient Data Provider 87 0
77 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:51:32 .Net SqlClient Data Provider 77 0
74 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:52:32 .Net SqlClient Data Provider 74 0
70 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:54:32 .Net SqlClient Data Provider 70 0
119 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:55:32 .Net SqlClient Data Provider 119 0
76 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:57:32 .Net SqlClient Data Provider 76 0
84 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 12:59:32 .Net SqlClient Data Provider 84 0
91 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:02:32 .Net SqlClient Data Provider 91 0
123 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:03:32 .Net SqlClient Data Provider 123 0
137 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:04:32 .Net SqlClient Data Provider 137 0
67 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:08:32 .Net SqlClient Data Provider 67 0
75 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:12:33 .Net SqlClient Data Provider 75 0
97 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:13:33 .Net SqlClient Data Provider 97 0
112 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:18:33 .Net SqlClient Data Provider 112 0
107 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:19:33 .Net SqlClient Data Provider 107 0
115 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:20:33 .Net SqlClient Data Provider 115 0
117 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:23:33 .Net SqlClient Data Provider 117 0
122 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:24:33 .Net SqlClient Data Provider 122 0
88 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:26:33 .Net SqlClient Data Provider 88 0
81 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:28:33 .Net SqlClient Data Provider 81 0
69 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:29:33 .Net SqlClient Data Provider 69 0
140 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:31:33 .Net SqlClient Data Provider 140 0
146 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:35:33 .Net SqlClient Data Provider 146 0
150 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:36:33 .Net SqlClient Data Provider 150 0
104 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:37:33 .Net SqlClient Data Provider 104 0
127 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:38:33 .Net SqlClient Data Provider 127 0
126 sleeping [login] [dbname] . AbleCommerce AWAITING COMMAND 0 0 3/14/14 13:39:33 .Net SqlClient Data Provider 126 0
Code: Select all
_timer = new System.Threading.Timer(new System.Threading.TimerCallback(AbleCommerce.Code.GoogleFeed.FeedTimerTask), null, 300000, 60000);
I commented that line in Global.asax and restarted IIS, and now the connection list doesn't grow any more.
Obviously, there are a lot of things interacting here, so I don't know exactly where the root cause is. It could be AbleCommerce code, .Net libraries, NHibernate libraries, ASP.Net, IIS, or SQL Server. For my Dev site, IIS is on a different server than SQL Server (both are virtual, not sure if they are on the same physical hardware) and SQL Server is handling other databases as well. I did a brief test with IIS and SQL Server on the same virtual server, and the same symptoms occurred, but much slower, maybe 3 or 4 connections added per hour.
I have heavily modified our site, but as far as I know I haven't changed any of the tables or changed anything having to do with the Google Feed code, the CommerceBuilder.Stores.Store object, or the CommerceBuilder.Configuration.ApplicationSettings object (these are referenced in CreateFeed).
Having said all that, I have not tested a fresh, clean, unmodified install of AC Gold to see if I get the same symptoms. Perhaps someone from AC can check this out. Also, I'm not sure how or how often the site maintenance runs (although I know it is much less frequenly), or if it is causing similar leaked SQL connections. Even if it is, it probably isn't noticeable because the default setting for recycling the Application Pools is every 24 hours, and that effectively closes all the leaked connections.
To summarize, if you start getting "The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached." errors, try commenting out the line in Global.asax that runs the Google Feed timer and see if that helps.