Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. Enterprise Library

Question

My ASP.NET 4.0 production application is experiencing re-occurring issues that cause the site to become unresponsive due to timeout errors.

Here is a brief overview of the application. The application resides across 3 servers; a web server, an app server and a DB server running SQL Server 2008. All servers are running on Windows Server 2008. The web server resides in the public domain. The app server resides in a DMZ with open communication between the Web server over ports 80 and 443 via WCF. The DB server resides in a private domain with open communication to the app server over port 1433. The application has been in production for some time now and only experiencing these issues frequently as of last week. There were no code changes and the hosting provider says there were no changes to the server made recently.

On the web server, the application experiences the error posted below (Error 1). The quick fix solution is to restart the app server IIS process, however, this is a reoccurring problem now and causing major interruptions to the business owners.

The application’s DAL uses Enterprise Library v4.1 to open connections to the database. I've included 2 snippets of code that is responsible for initiating the calls (Code 1 and Code 2). This method is repeated in various other methods. Is it possible that the ExecuteReader method is not properly closing the connection? There is no override of the method that allows me to specify ConnectionBehavior to close the connection.

We performed a SQL Profile analysis and determined there are no lingering open connections to the DB.

While researching the problem, someone suggested that Enterprise Library might have a bug where connections are not properly disposed of, however this was not verified on the post. How can I determine the cause of the problem? Or what would be the appropriate course of action to remedy the problem? I could increase the pool size, however that seems like it would just be a temporary solution.

Error 1:

***System.ServiceModel.FaultException: 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 Microsoft.Practices.EnterpriseLibrary.Data.Database.GetNewOpenConnection() at Microsoft.Practices.EnterpriseLibrary.Data.Database.GetOpenConnection(Boolean disposeInnerConnection) at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteReader(DbCommand command) at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteReader(String storedProcedureName, Object[] parameterValues) at CityStoreDAL.NavigationProvider.GetNavigator(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreDAL\NavigationProvider.cs:line 41 at CityStoreBLL.Navigation.GetNavigator(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreBLL\Navigation.cs:line 15 at CityStoreService.CityStoreService.GetNavigator(Int32 navigato rID) in c:\TFS\CityStore\DEV\SRC\CityStoreService\Navigation.cs:line 21 at SyncInvokeGetNavigator(Object , Object[] , Object[] ) at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs) at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc) at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc) at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)***
Generated: Wed, 12 Nov 2014 19:40:22 GMT

System.Web.HttpUnhandledException: Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.ServiceModel.FaultException: 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 Microsoft.Practices.EnterpriseLibrary.Data.Database.GetNewOpenConnection()
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.GetOpenConnection(Boolean disposeInnerConnection)
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteReader(DbCommand command)
   at Microsoft.Practices.EnterpriseLibrary.Data.Database.ExecuteReader(String storedProcedureName, Object[] parameterValues)
   at CityStoreDAL.NavigationProvider.GetNavigator(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreDAL\NavigationProvider.cs:line 41
   at CityStoreBLL.Navigation.GetNavigator(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreBLL\Navigation.cs:line 15
   at CityStoreService.CityStoreService.GetNavigator(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreService\Navigation.cs:line 21
   at SyncInvokeGetNavigator(Object , Object[] , Object[] )
   at System.ServiceModel.Dispatcher.SyncMethodInvoker.Invoke(Object instance, Object[] inputs, Object[]& outputs)
   at System.ServiceModel.Dispatcher.DispatchOperationRuntime.InvokeBegin(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.ImmutableDispatchRuntime.ProcessMessage5(MessageRpc& rpc)
   at System.ServiceModel.Dispatcher.MessageRpc.Process(Boolean isOperationContextSet)

Server stack trace: 
   at System.ServiceModel.Channels.ServiceChannel.HandleReply(ProxyOperationRuntime operation, ProxyRpc& rpc)
   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
   at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
   at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)

Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
   at CityStoreWeb.CityStoreServiceReference.INavigation.GetNavigator(Int32 navigatorID)
   at CityStoreWeb.Product.<>c__DisplayClass1.<BindCategoryMenuAndInfo>b__0(INavigation proxy) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Product.aspx.cs:line 73
   at CityStoreWeb.Common.Service'1.Use(UseServiceDelegate'1 codeBlock) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Common\Utils.cs:line 243
   at CityStoreWeb.Product.BindCategoryMenuAndInfo(Int32 navigatorID) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Product.aspx.cs:line 71
   at CityStoreWeb.Product.SetupPage(Int32 navigatorID, Int32 categoryID, Int32 productID) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Product.aspx.cs:line 64
   at CityStoreWeb.Product.Page_Load(Object sender, EventArgs e) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Product.aspx.cs:line 37
   at System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr fp, Object o, Object t, EventArgs e)
   at System.Web.Util.CalliEventHandlerDelegateProxy.Callback(Object sender, EventArgs e)
   at System.Web.UI.Control.OnLoad(EventArgs e)
   at CityStoreWeb.Common.BasePage.OnLoad(EventArgs e) in c:\TFS\CityStore\DEV\SRC\CityStoreWeb\Common\BasePage.cs:line 26
   at System.Web.UI.Control.LoadRecursive()
   at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
   --- End of inner exception stack trace ---
   at System.Web.UI.Page.HandleError(Exception e)
   at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
   at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
   at System.Web.UI.Page.ProcessRequest()
   at System.Web.UI.Page.ProcessRequest(HttpContext context)
   at ASP.product_aspx.ProcessRequest(HttpContext context)
   at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Code 1:

public static NavigatorEntity GetNavigator(int navigatorID)
{
        Database db = DatabaseFactory.CreateDatabase();
        object[] spParams;
        spParams = new object[1];
        spParams[0] = navigatorID;
        using (IDataReader reader = db.ExecuteReader("GetNavigator", spParams))
        {
            if (reader == null)k
            {
                throw new ArgumentNullException("reader");
            }
            NavigatorEntity myNav = null;
            if (reader.Read())
            {
                myNav = GetNavigatorEntityFromReader(reader);
            }

            if (myNav != null)
            {
                reader.NextResult();
                myNav.Categories = GetCategoriesCollectionFromReader(reader);

                reader.NextResult();
                myNav.RecommendedProducts = 
                    ProductProvider.GetRecommendedProductCollectionFromReader(reader, false);
            }

            return myNav;
        }
    }

Code 2:

public static List<NavigatorEntity> GetNavigatorsAll()
{
    Database db = DatabaseFactory.CreateDatabase();

    using (IDataReader myReader = db.ExecuteReader("GetNavigatorsAll"))
    {
        return GetNavigatorCollectionFromReader(myReader);
    }
}

private static List<NavigatorEntity> GetNavigatorCollectionFromReader(IDataReader reader)
{
    List<NavigatorEntity> navigators = new List<NavigatorEntity>();
    while (reader.Read())
    {
        navigators.Add(GetNavigatorEntityFromReader(reader));
    }
    return navigators;
}

UPDATE:

Apparently, the problem was not with any of the methods that were referenced in the ASP.NET errors. They threw an exception because by the time they were reached, the problem (exhausted connection pool) had already occurred and the exception would be thrown on any proceeding method that opens a new connection.

After analyzing all the code in the Data Access Layer, I identified a few rouge methods that were not utilizing the using statement appropriately, thereby leaving open connections in the pool to accumulate. After isolating the methods and using performance monitors to observe the NumberOfPooledConnections, I confirmed these methods were to blame.

The fix was to wrap the rouge methods in the appropriate using statements.

One of the methods causing the problem:

public static List<TaxCodeEntity> CMSGetTaxCodes()
{
    Database db = DatabaseFactory.CreateDatabase();
    return GetTaxCodeCollectionFromReader(db.ExecuteReader("CMS_GetTaxCodes"));            
}

Fix:

public static List<TaxCodeEntity> CMSGetTaxCodes()
{
    Database db = DatabaseFactory.CreateDatabase();
    using (DbCommand dbCmd = db.GetStoredProcCommand("CMS_GetTaxCodes"))
    {
        using (IDataReader myReader = db.ExecuteReader(dbCmd))
        {
            return GetTaxCodeCollectionFromReader(myReader);
        }    
    }
}

Answer 1

I can see many actions happening once Reader is open. If any exceptions raised on dependent function like : myNav.Categories = GetCategoriesCollectionFromReader(reader); can keep the reader open. Safe side exclusively close the reader. like this:

    public static NavigatorEntity GetNavigator(int navigatorID)
    {
        Database db = DatabaseFactory.CreateDatabase();
        object[] spParams;
        spParams = new object[1];
        spParams[0] = navigatorID;
        using (IDataReader reader = db.ExecuteReader("GetNavigator", spParams))
        {
            try
            {
                if (reader == null)
                {
                    throw new ArgumentNullException("reader");
                }
                NavigatorEntity myNav = null;
                if (reader.Read())
                {
                    myNav = GetNavigatorEntityFromReader(reader);
                }

                if (myNav != null)
                {
                    reader.NextResult();
                    myNav.Categories = GetCategoriesCollectionFromReader(reader);

                    reader.NextResult();
                    myNav.RecommendedProducts = 
                        ProductProvider.GetRecommendedProductCollectionFromReader(reader, false);
                }

                return myNav;
            }
            catch
            {
            }
            finally
            {
                reader.Close();
            }
        }
    }

---

Also keep an eye on your sql server:

SELECT DB_NAME(dbid), COUNT(dbid), loginame from sys.sysprocesses where dbid > 0 GROUP BY dbid, loginame

Answer 2

One way to debug is to add performance counters to trace / log / exception handling. NumberOfActiveConnectionPoolGroups, NumberOfActiveConnectionPools and NumberOfPooledConnections are probably the counter values you need to debug the problem. MSDN Link