Slow performance on ASP.NET MVC application using EntityFramework + SQL Server

Used technologies and software:

  •  ASP.NET MVC 5
  • Entity Framework Code First 6.x
  • SQL Server 2014 Express
  • Windows Server 2012
  • IIS 8.0
  • Hyper-V Virtual Machine (SSD and 8GB RAM set dynamic with 4GB as start up value).
  • Visual Studio 2013

Problem:

Website in production is slow, takes several seconds (+30s) or even minutes to load a page. But this does not always happen.
In development everything works always fast.

Steps taken to figure out the problem:

  • Netword config, NIC, IP, DNS, … –> ok
  • Checking if connection string is set correctly. –> ok
    (tip: see https://teusje.wordpress.com/2012/02/21/how-to-test-an-sql-server-connection/ )
  • Adding caching to the ASP.NET MVC application. –> ok, but still too slow
  • SQL Server 2014 Profiler:
    Trying to figure out if it is the application or the SQL Server, so we ran the Profiler and copy several queries and executed them directly on the SQL Server without any problem.
  • Log files:
    Custom log file in the ASP.NET MVC application gave us a good hint:

    Exceptions:

     sqlexception: Timeout expired EntityCommandExecutionException
    
     SqlException: Timeout expired.  The timeout period elapsed prior to completion of the operation or the server is not responding.
     Stack:    at System.Data.SqlClient.SqlConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
        at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception, Boolean breakConnection, Action`1 wrapCloseInAction)
        at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj, Boolean callerHasConnectionLock, Boolean asyncClose)
        at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior, SqlCommand cmdHandler, SqlDataReader dataStream, BulkCopySimpleResultSet bulkCopyHandler, TdsParserStateObject stateObj, Boolean& dataReady)
        at System.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
        at System.Data.SqlClient.SqlDataReader.get_MetaData()
        at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds, RunBehavior runBehavior, String resetOptionsString)
        at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, Boolean async, Int32 timeout, Task& task, Boolean asyncWrite, SqlDataReader ds)
        at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method, TaskCompletionSource`1 completion, Int32 timeout, Task& task, Boolean asyncWrite)
        at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior, RunBehavior runBehavior, Boolean returnStream, String method)
        at System.Data.SqlClient.SqlCommand.ExecuteReader(CommandBehavior behavior, String method)
        at System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(CommandBehavior behavior)
        at System.Data.Common.DbCommand.ExecuteReader(CommandBehavior behavior)
        at Glimpse.Ado.AlternateType.GlimpseDbCommand.ExecuteDbDataReader(CommandBehavior behavior)
        at System.Data.Common.DbCommand.ExecuteReader(CommandBehavior behavior)
        at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.b__c(DbCommand t, DbCommandInterceptionContext`1 c)<
        at System.Data.Entity.Infrastructure.Interception.InternalDispatcher`1.Dispatch[TTarget,TInterceptionContext,TResult](TTarget target, Func`3 operation, TInterceptionContext interceptionContext, Action`3 executing, Action`3 executed)
        at System.Data.Entity.Infrastructure.Interception.DbCommandDispatcher.Reader(DbCommand command, DbCommandInterceptionContext interceptionContext)
        at System.Data.Entity.Internal.InterceptableDbCommand.ExecuteDbDataReader(CommandBehavior behavior)
        at System.Data.Common.DbCommand.ExecuteReader(CommandBehavior behavior)
        at System.Data.Entity.Core.EntityClient.Internal.EntityCommandDefinition.ExecuteStoreCommands(EntityCommand entityCommand, CommandBehavior behavior)

Start Microsoft SQL Server Management Studio and navigate to:
[Server Instance] –> [Management] –> [SQL Server Logs] –> double click [Current – …] there you select [Windows NT]

There we’ve seen the real problem several times in the logs:

"AppDomain 50 (master.sys[runtime].48) is marked for unload due to memory pressure."

sql server problem

Now we simply started Task Manager on the server and watched the ‘Memory’ in the ‘Performance’ tab.
The memory was constantly at 3.7GB or 3.8GB when we visited the website.

vm memory
Hooray! We found the problem. 🙂 Now we need to find a solution.

As you might remember from the beginning of this post, we’ve configured our Hyper-V Virtual Machine with the Dynamic Memory option.
This had a start up value of 4GB… and our server was constantly at 3.7GB or 3.8GB…

So why does our server not dynamically increase the RAM of the virtual machine?

It turns out that Hyper-V Dynamic Memory, introduced in Windows Server 2008 R2 SP1, is only supported in SQL Server Enterprise and Datacenter Editions!

Solution:

Don’t enable Hyper-V Dynamic Memory for your virtual machine but set it static with a value of e.g. 8GB RAM.

Voila:

vm memory fixed

🙂

Your Host Operating System needs to be at least Windows Server 2008 R2 SP1 or Microsoft Hyper-V Server 2008 R2 SP1 as your Hyper-V host.
The Guest Operating System edition (= your virtual machine) needs to be Web, Standard, Enterprise or Datacenter.
You need SQL Server Enterprise or Datacenter edition if you want that SQL Server automatically uses more RAM when needed using the Hyper-V Dynamic Memory feature.
In case you just have a Windows Server Standard and SQL Server Express and you have the same symptoms as described above just set your virtual machine RAM to a static value instead of using Hyper-V Dynamic Memory.

Extra information:

Advertisements

Windows Server: logging users logon and logoff via PowerShell

You are planning a migration and you want to track and monitor for a few weeks when your server is being used the most?

  1. Open Windows PowerShell ISE ( or notepad 😉 )
  2. Add this PowerShell line below and save the script as monitorlogon.ps1
  3. "logon {0} {1} {2:yyyy-MM-dd HH:mm:ss}" -f $env:username, $env:computername, (Get-Date) >> logon.log
  4. Create another script file, add the PowerShell line below and save it as monitorlogoff.ps1
  5.  "logff {0} {1} {2:yyyy-MM-dd HH:mm:ss}" -f $env:username, $env:computername, (Get-Date) >> logoff.log
  6. Start the Logal Group Policy Editor ([Windows]+[r] > gpedit.msc)
  7. Navigate to [User Configuration] > [Windows Settings] > [Scripts (Logon/Logoff)]
  8. Double click on the [Logon] name
  9. Navigate to the [PowerShell Scripts] tabpage
  10. Click the [Add] button and select your monitorlogon.ps1 script.
  11. Optionally you can select the execution order, default is set to “Not configured”.
  12. Repeat again from step 6. for the Logoff script.

You can change the >> filename.log part to >> \\MyShare\filename.log.

If you want to do this on a Windows Server 2003 where you can’t run your PowerShell you will need to save the file as an *.cmd:

  1. Create a new file and call it monitorlogon.cmd
  2. Enter the line below and save the script as monitorlogon.cmd:
  3. echo logon %username% %computername% %date% %time% >> C:\logon.log
  4. Repeat this for monitorlogoff.cmd and adjust the script line.
  5. Follow the steps from the PowerShell script.