ASP.NET Core

Scalable and Performant ASP.NET Core Web APIs: SQL Server Isolation Level

This is another post in a series of posts on creating performant and scalable web APIs using ASP.NET core 2.0. In this post we’ll have a little look at isolation levels in SQL Server which is something that is often not thought about … until we hit performance issues …

By default, SQL Server uses the “Read Committed” isolation level and by default this blocks reads whilst updates take place. This can lead to scalability issues if we have lots of users reading data in addition to users writing data – particularly when the writes are heavy.

Let’s look at a simple example of simulating some users updating a contact record whilst other users get contact records.

We’ll start of with getting a benchmark for users just getting contact records. Here’s our Dapper data access code to get a contact record:

Here’s a snipet of results from our load test on the API endpoint:

GET benchmark

On to our data access code for updating a contact record … We’ve simulated a long database write by using a Thread.Sleep resulting in the updating taking > 1 sec.

Ok, lets load test some users updating a contact record whilst other users are getting the contact record:

GET requests blocked

We see that the GET requests take far longer than they were previously because they are being blocked by the PUT requests.

So, what can we do? How can we resolve this? It is tempting to use the “Read Uncommitted” isolation level. This appears to resolve the problem ….

… but what if the SQL did more database writes after the UPDATE on the Contact table and in the process errored and rolled back? We’d be potentially reading and returning incorrect data!

There is a much simpler solution … We can change the “Read Committed” isolation level behaviour to not block and instead read the current committed data. We change this on the database using the following SQL command:

So, no code changes – sweet!

If we now do the same load test again, the GET requests are much faster because they are not being blocked by the the PUT requests:
GET requests faster

In summary, having READ_COMMITTED_SNAPSHOT ON can generally lead to better performance without losing any accuracy in the data.

Don’t forget to subscribe to the rest of this series in the footer of this page!

Scalable and Performant ASP.NET Core Web APIs: ORM Choice

This is another post in a series of posts on creating performant and scalable web APIs using ASP.NET Core. In this post we’ll start to focus on data access within our API which is the often the cause of performance bottlenecks. We’ll start off with chosing our object relationship mapping framework / library (ORM)

Be careful with EF Core

Entity Framework Core nicely encapsulates the database details from developers. However this approach does carry some performance overheads and gotchas.

Let’s look at an example. Here’s our database model:

Database Model

We have a controller action method /contacts/{contactId} that returns a contact record.

Here’s the SQL Profiler trace:

EF Core SQL Profile - Example 1

Where’s the WHERE clause!? EF Core has fetched all the data in the Contact table too early because of the .ToList(). If we remove the .ToList(). EF Core behaves a little more as we expect:

EF Core SQL Profile - Example 2

Let’s add some more requirements for our action method … We now want to include the primary address, primary email address and primary phone number in /contacts/{contactId}.

The implementation is below. We’ve been good EF Core developers and used .AsNoTracking() so that no unnecessary change tracking occurs. We’ve also been specific about what fields we want to retreive so that EF Core doesn’t fetch more data than we need.

Here’s the SQL Profiler trace:

EF Core SQL Profile - Example 3

We have 4 calls to the database when a single SQL statement could have done the job.

So, with EF core, we need to know what we are doing and be really careful if we are implementing an API on top of a decent sized database. There are also cases when EF Core is going to generate inefficient SQL or round trip to the database multiple times – that’s just how it works!

Here’s a great post on other performance gothas in Entity Framework. It’s not specifically about EF Core but many of the points do apply.

Dapper helps build performant data access code

Dapper is a micro ORM that doesn’t abstract the SQL from us. In Dapper, we use regular SQL to access the database. Dapper simply maps the data to our c# objects.

Here’s the data access code using Dapper for the example above.

Here’s the SQL Profiler trace confirming only 1 hit on the database:
Dapper SQL Trace

So, our ORM choice for the rest of this series on creating performant and scalable web APIs using ASP.NET core 2.0 is Dapper. We’ll continue looking at data access in our next post – this time focusing on isolation levels and the impact on performance.

Don’t forget to subscribe to the rest of this series in the footer of this page!

Scalable and Performant ASP.NET Core Web APIs: Load Testing

Load Testing

This is another post in a series of articles on creating performant and scalable web APIs using ASP.NET core 2.0. In this post we’ll focus on tools that can help us load test our API to ensure it’s going to perform and scale when it goes into production. Performance and scalability issues are much easier and quicker to resolve before our API has gone into production, so, it’s worth testing our API under simulated demand before it gets there.

WebSurge

WebSurge is a load testing tool for APIs behind the firewall or in the cloud that is really simple and quick to use.

During development, when we think our API is nearly complete, we can use WebSurge to determine how many requests per second our API can handle. So, this is not testing specific user scenarios under load, this is just testing a single API end point under load to see how many requests per second it can handle.

WebSurge

This video gives a great overview on WebSurge.

We’ll use WebSurge frequently during this series of blogs to determine the improvement we can make by doing different things.

Visual Studio Load Testing

If we are lucky enough to have the Enterprise version of Visual Studio, we can use the load testing tool within Visual Studio. It is more flexible than WebSurge but it is more time consuming to write the tests. This is perhaps a good choice if we are writing tests that simulate specific user scenarios under load.

In order to create tests, we first add a “Web Performance and Load Test” project to our solution.

When producing the actual tests we could record the test using a IE plugin that integrates with Visual Studio’s load testing tool. This is great for load testing traditional server driven web applications. However, for testing web APIs, creating a c# unit test is much simpler and gives us a lot of flexibility.

Unit Test

Now that we have a test, we can put this under load. We do this by right clicking on the project and clicking “Add > Load Test …”. A wizard will help us create the load test. We will see that we can use a cloud based load or a load generated from our PC (and potentially other PCs in our infrastructure). The wizard lets us configure lots of stuff such as the test duration, the think times (if we are trying to simulate realistic workloads), the number of users and obviously the tests to run and how they are mixed up during the load. After we have completed the wizard, we can run the load test by clicking the “Run Load Test” icon.

Run Load Test

After the load test has finished running, we get a summary of the results. The statistic that I’m most interested in is “Tests / Sec” which is similar to “Requests / Sec” in WebSurge.

Load Test Results

BenchmarkDotNet

BenchmarkDotNet is a low level tool to help us understand how our code will run at scale. It’s particularly good at comparing different pieces of code that give the same result to determine which one is the most efficient.

To do this we need to put our code in a .NET Core console app and bring in the BenchmarkDotNet nuget package.

As an example, let’s test the fastest method of iterating through a list to find an item. We’ll compare a classic for loop, a foreach loop and a FirstOrDefault() LINQ statement.

The functions to be tested need to have the [Benchmark] attribute. We simply call BenchmarkRunner.Run() in Main to invoke the test.

To simulate what would happen in production, we should build the console app in “release” mode and call it from the command line:

Here’s the results:

… the classic way is always best!

So, now we’ve got the tools we need to test and profile our ASP.NET Core Web API. In the next post we’ll get into the actual code, starting with our data access code.

Don’t forget to subscribe to the rest of this series in the footer of this page!

Scalable and Performant ASP.NET Core Web APIs: Profiling and Monitoring

Monitoring

This is the 2nd post in a series of articles on creating performant and scalable web APIs using ASP.NET Core 2.0. In this post we’ll focus on tools that can help us profile and monitor our API so that we can spot any performance and scalability issues before our customers do.

Often, like most bugs, the earlier in the development cycle we find a performance or scalability problem, the quicker and easier it is to fix. So, it is important to make use of these tools from the start of the development cycle as well as when the API is in production.

During our dev cycles, as well as checking we get the right status code, response body, … we should check the duration of the call and the size of the response. We’ll then hopefully spot if the API is slowing down during the development phase.

Below is the popular Postman tool, giving us the duration and size of the response.

Postman

Development Profiling Tools

Apart from keeping an eye on the duration and size of the API calls, what else can we do? What other tools are there in the development phase to give us confidence that the API is going to perform and scale well?

Stackify Prefix

Stackify Prefix is a great free profiling tool that can be used during the development of an ASP.NET Core Web API. It tracks web requests and database queries and we can even wire it up to Serilog. It’s really useful to have this on a 2nd screen as we build out our API.

To get started with Prefix and profile our API, first download Prefix and then bring in the following nuget package:

We then need to add the Stackify middleware before the MVC middleware. It also needs to come before any exception logging middleware as well so that the exceptions appear in Prefix:

If we want to include the Serilog logs in Prefix, we need to bring in the following nuget package:

… and add the following bits in appSettings.json:

To run prefix, we need to click on the icon in the task bar, enable it and then open it in a browser:

Run Prefix

If we then run our ASP.NET Core Web API in Visual Studio, Prefix will start to profile our API. We will see the requests, database queries and other information we’ve written to Serilog:

Prefix

Nice!

Application Insights in Visual Studio

Application Insights is Mircosoft’s fully fledged Application Performance Monitoring (APM) tool (we’ll come on to APMs later in this post). We can run this locally in Visual Studio 2017 to profile the API during development as an alternative to Stackify Prefix. It’s convenient because we are already likely using Visual Studio to develop the API.

To add this to a Visual Studio project, we right click on project in Solution Explorer and click “Add > Application Insights Telementry …”. We then click the “Start Free” button and then click “Or just add the SDK to try local only mode” at the bottom of the screen. The Application Insights SDK will then be added to the solution.

Application Insights, will automatically track our web requests – we don’t need to add any middleware. Unlike, Prefix, it doesn’t track database queries – we’d need to track these in our logger and wire Application Insights up to our logger (it is automatically wired up to the standard ILogger).

After we’ve added Application Insights to our solution in Visual Studio, we can view the trace information by going to “View > Other Windows > Application Insights Search”. If we enter a date and time in the “From” and “To” inputs and click the search icon, we will hopefully see trace information for the API calls in the bottom half of the screen. The actual individual trace items are in the middle column. If we click on a trace item, we get additional details of the item to the right of it. The element that I find really useful in the “Track Operation” section on the bottom right of the screen. This gives us an overview of the API call and we can quickly see what bits are slow and need further investigation.

Application Insights

“Application Insights Trends” is great for giving us an overview of the trace information. We can access this in Visual Studio via View > Other Windows > Application Insights Trends.

Personally, I prefer the UX of Prefix, but Application Insights is worth a look.

SQL Server Profiler

As the name suggests, SQL Server Profiler traces the SQL statements executed on a SQL Server database. This is a tool that comes with SQL Server and obviously is only useful if our API uses SQL Server for its storage! If we are using a different database then there is likely to be an equivalent profiler.

We can use this tool if our higher level profiling tool (like Prefix or an APM) has pointed to a problem in the data access code. This gives us a clear understanding of what SQL is being executed along with the associated costs.

This tool can also give us all the activity from the SQL Server – it may not be our API that is problematic – it may be some other process that is hogging the resources.

As well as the duration of each SQL statement, we can get other useful performance related information like the amount of CPU in milliseconds used by the statement, the number of page read I/Os caused by the statement and the number of page write I/Os caused by the statement.

SQL Profiler

Visual Studio Memory Profiler

Visual Studio has a set of low level profiling tools. The one that I find most useful is the memory profiler which lets us take snapshots of the managed and native memory heap and drill in to the differences between the snapshots. This can help us find memory leaks or just inefficient use of memory in our code.

We can switch the memory profiler on by clicking “Debug / Windows / Show Diagnostic Tools”.

Visual Studio Memory Profiler

We won’t be using this every day – just when our higher level profiling tool points to a problem in a specific area of code that we want to profile a little deeper.

Application Performance Monitoring (APM) Tools

APMs are primarily used to profile our code in production with regards to performance. However, these tools are also useful in the QA environment – particularly if we are running a load test and want to measure how different parts of the API perform.

Stackify Retrace

Stackify Retrace is a service that allows us to track the same as Stackify Prefix tracks, but it tracks it in production. It also tracks other metrics on the server such as CPU usage. Retrace can also notify us when certain events happen – e.g. when CPU usage > 90%.

In addition to adding the same middleware to our API code as we did for Prefix, we need to register with Stackify and download and install an agent. The agent will send the profile information to Stackify for us to view in their portal.

As with most APMs, this is a paid service which starts from $10 per month at the moment.

Application Insights

As mentioned before, Application Insights is Microsoft’s fully fledged APM tool. As well as wiring up locally, we can wire this up to the Azure Application Insights service. This allows us to view the information in the Azure Portal.

Azure Insights

The nice thing about this APM is that there is a free usage tier for up to 1GB worth of data. Worth a look – particularly if our API is hosted in Azure.

So, there we have a range of high level and low level profiling tools that work well with ASP.NET Core 2.0. In the next post we’ll look at load testing tools …

Don’t forget to subscribe to the rest of this series in the footer of this page!

Scalable and Performant ASP.NET Core Web APIs: Introduction

Performant and scalable web APIs

Over the next month or so I’ll be posting a series of posts on creating performant and scalable web APIs using ASP.NET Core 2.0.

Performance is how fast our API can deal with a single request and make a response. Scalability is the amount of concurrent requests our API can deal with before it slows down significantly.

ASP.NET core itself is very focused on performance, which makes it a great choice for building APIs that perform well. v2.0 of .NET Core gave us general performance improvements on commonly used areas such as many of the collection classes, LINQ, compression and text processing. You can read more about the improvements here. In order for us to create APIs that scale well as more users use the API, we’ll need to architect our API well with usage growth in mind.

The series will start with how to profile and load test our API from a performance point of view. This is really important if we want to know we have a performance problem well before our customers tell us!

We’ll then move on to data access. ORMs are very popular these days but they can be the cause of performance issues …

We’ll look at paging, filtering and searching which improve the consumers experience of our API as well as hopefully having a positive performance impact.

We’ll have a good look at caching … allowing the client to cache responses as well as having a gateway cache on our server.

We’ll move on to allowing our API to work asynchronously to see how that effects performance and scalability.

We’ll look at a Microservices architecture and how that can help scalability.

We’ll end up on the topic of large volume imports – a common requirement in line of business applications that store lots of data.

Ensure you don’t miss any of these posts by subscribing to this blog in the footer of this page!

Controlling our ASP.NET Core Serilog Log

In a previous post we built up a Serilog log full of useful information. In this post we’re going to see if we can control exactly what is logged, without a software deployment. By default, we want our logs to be fairly light and have the ability to increase the amount of logging when we are diagnosing a problem.

So, we have an ASP.NET Core Web API in production, hosted in IIS. We also have the middleware running from this post that gives us additional properties in our log like “RequestPath” and “UserName”. Here’s our appSettings.json:

If we GET /api/contacts/f7d10f53-4c11-44f4-8dce-d0e0e22cb6ab we get:

Default log

If we increase the level to “Error”, we no longer get the “Information” entries. We will only get exceptions logged in our log. We don’t need to restart the app pool in IIS – the change kicks in as soon as we save appSettings.json. Nice!

If we decrease the level to “Debug”, we get a lot more log entries.

Debug Log

So, switching to the “Debug” level is going to be valuable when we are diagnosing a problem. However, that’s a lot of log entries from all over our web API – can we be more specific on what we want to log? That’s where filter expressions come in …

In order to use filter expressions, we need to reference the following nuget:

Having changed the MinimumLevel to “Debug”, let’s try to add a filter so that we only get “Debug” entries on GET api/contacts/{contactId} whilst still getting errors logged. Let’s change appSettings.json to:

Unfortunately for the filter to kick in, we do need to restart the app pool in IIS. After doing this, we do get all the log entries for that particular path:

Filtered Log

The filter expression uses a powerful SQL like syntax. The filter expression docs give the full details.

Another example of using a filter expression to control our logs is if a particular user is having a problem. The following appSettings.json will give all the log entries for “Carl” as well as any other errors.

Cool stuff!

Instrumenting Dapper Queries in ASP.NET Core

In my last post we touched on what we get from EF Core in our Serilog log entries. But what if we are using dapper? How can we trace the SQL and get query execution times?

We already have our Seriog outputting to SQL Server and our middleware from the last post.

Unfortunately, we don’t get any logging out of the box for dapper like we do with EF Core – so, we need to do a bit of work.

We’ll create a class that wraps the dapper methods we use and we’ll instrument those methods. We turn stats on for the connection and get them after the query has finished, passing them to a central method that does the logging.

The LogInfo() method logs the SQL, parameters and useful stats to Serilog. We could have just logged all the stats by doing .ForContext("Stats", stats, destructureObjects: true) but the log output wouldn’t have been as neat.

The AddAdditionalInfoToException() method makes sure we have the full SQL and parameters in the exception that has occurred ensuring that they are together in our log.

Now, to use our DapperWrap class, we need to register it in Startup.

We can then inject DapperWrap where we need it. I’ve used it in a simple controller below:

We then get the following in our serilog log:

Dapper log

… with the following properties:

For an exception we get:

Dapper exception

… which includes the full SQL and parameter in the properties:

Nice!

Adding Useful Information to ASP.NET Core Web API Serilog Logs

In my last post, we setup structured logging leveraging Serilog and SQL Server. In this post, we’ll look closely at the log entries themselves for a web API – what comes out of the box, what’s missing and how we can fill the gaps …

A good log saves debugging time – particularly in production, by quickly helping us to pin point the root of a problem. A log containing a wealth of relevant information, reduces the amount of “I can’t reproduce” issues.

What we get out of the box

Let’s look at what we get out of the box then. We’ve already enabled Serilog with SQL Server as the destination. Let’s now tell Serilog to log as much as it can in appSettings.json:

We have a super simple controller for a contact resource in our web API that sits on top of an EF core data context. We only have methods for getting a record and inserting a record. This will be fine for allowing us to have close look at the log entries that are generated.

We also have an even more simplistic authentication controller that signs us in as “Carl” if we POST api/auth

After signing in and calling GET api/contacts/{contactId} we get:
Out of box log

That’s quite a bit of information, but let’s drill in more …

These are the properties we get from the request:

Notice that the request headers and body are missing. There is no information about the signed in user.

These are the properties we get from the response:

Notice that the response headers and body are missing. Again there is no information about the signed in user.

These are the properties we get from an EF core query execution:

Notice that the parameter value is missing – we just get “?”.

Let’s create an exception by adding a field in our data model class that doesn’t exist in the database:

Here’s what we get when GET api/contacts/{contactId}:

EF core exception

If we drill into the 2 highlighted entries, we have the following properties:

… and …

So, it’s great that we have the call stack and SQL but the parameter value for the SQL would have been nice.

What’s missing and why?

So, the key information that is missing is:

  • The request headers
  • The request body
  • The response headers
  • The response body
  • The EF core query parameter values
  • The user name

I don’t know for sure why the above are missing but I’m guessing it’s a combination of security and performance.

In terms of security, we need to secure the logs. Irregardless of adding more sensitive data, they already contain sensitive information about the internals of our app. We’ve taken a great first step by putting them in SQL Server because a person will need a valid SQL logon in order to be able to access the log directly. If we expose the log via a web page, we need to make sure that page is authenticated and also protected by an appropriate authorisation rule. So, if we secure the log properly I think we are good to add the missing information.

In terms of performance, let’s do a bench mark performance test now and do the same again after we’ve added the missing information to determine the impact. We’re going to use Rick Strahl’s excellent Web Surge tool for the test.

Here’s the results of the bench mark test where we repeatedly GET api/contacts/{contactId} for 10 seconds.

So, the average request time is 3.2ms when the app is running in IIS.

Before we go on and add this stuff, why do we need these bits of information? The information will help us pin problems down. The request headers and body are particularly important for web APIs – it’s much easier to reproduce a problem with a request, if we have all the information to replay it. If the problem is receiving unexpected data rather than an unexpected exception then the response headers and body give us all the information we need to work back through the request to determine what happened. In terms of the EF core queries, we can’t replay an exact query without the parameter values – e.g. a performance issue may be dependent on specific parameter values. Finally some problems are user specific, so capturing the user, allows us to quickly get all the log entries for the problematic user.

Adding EF core parameter values

This is a quick one. All we need to do is switch on “EnableSensitiveDataLogging” when the data context is configured.

This now includes the parameter value in the log entry:

Adding missing request and response information

This is a little more work. We’re going to use middleware so that we only have to write the code once (rather than add code to each controller and action method).

We’re going to call our middleware, SerilogRequestLogger. So, let’s register this when the app starts up. It is important that this is just after we add authentication in the middleware pipeline or we won’t have access to the user information.

Now on to the implementation of the middleware. We add the user name to all the log entries by using LogContext.PushProperty. You can see capturing the request and response body is a little tricky because they are streams.

Here’s an example of what we get in our request information log entry for a POST to api/contacts:

… and our EF call:

… and our response information:

Dealing with exceptions

So, far so good – we have added some extra useful information and this is included in exceptions as well (even though I’ve not shown it above). We can go a bit further though …

We can improve the experience of the consumer of the API by giving them an error reference that they can quote when raising a support ticket. We need to wrap an exception handler around line await _next(httpContext) in our middleware:

Here’s what the consumer gets when they hit a problem in our code:

Consumer exception

We can quickly get to that entry in our log by writing a SQL query to filter on the errorId property:

How much slower is our middleware?

To finish this post off, let’s see the performance impact of logging all this extra stuff. Let’s again repeatedly call GET api/contacts/{contactId} for 10 seconds.

Perf with middleware

The average request time was 3.6ms. So, roughly an addition of 0.4ms for this test.

Not that much slower!

Recommended reading for building great ASP.NET Web APIs:

ASP.NET Core Logging with Serilog and SQL Server

Serilog is a great 3rd party library for structured logging in our ASP.NET core apps. Structured logging is key to producing easily readable and filterable logs.

Using SQL Server as a log destination, allows us to leverage the power of SQL querying for log filtering. It can be a good choice if our app is already using SQL Server.

So, how do we implement a Serilog SQL log in ASP.NET Core 2.0 …

First we need to bring in the following nuget packages:

Next up, we need to change how logging is setup in Program.cs. The 3 lines at the start of Main() tells the program to use Serilog as the logger and to read the configuration from appsettings.json.

Serilog can then be configured to use SQL Server as a destination in appSettings.json, along with the minimum logging level. We need to specify the connection string for the logging database and the table name to log the data into.

We can get Serilog to create our Log table automatically but let’s do this outselves so that we have control of our schema. For example, we want the Properties column to be based on the xml data type so that we can query it (serilog creates this as nvarchar).

Below is TSQL script to create the Log table:

We can then write to the log in our code, logging structured objects using {@object} in the message template. Below is a web API action method for getting and returning a record (a contact in this case). We log when the contact is fetched from the cache / database and also when the contact is set in the cache.

Now that Serilog and SQL Server are setup, wired together and we have some logging code, we should get our logs output to our SQL Server table.

Get contact log

Note that if we have problems getting the log to write to SQL Server, we can use Serilog.Debugging.SelfLog.Enable() in Program.Main() to surface errors from Serilog.

The Properties column contains useful additional information, including what we specified in our structured log after the contact is added to the cache is:
Get contact log properties

We can extract specific data in the Properties column using XQuery syntax. We can even filter on values in the Properties column.

For example, if we wanted to find when a particular contact was added to the cache, we could use something like:

XQuery

Pretty useful!

Recommended reading for building great ASP.NET Web APIs:

Getting started with Redis

Recently, I’ve been looking into how to improve the performance and scalability of ASP.NET Core web APIs. One strategy for doing this is caching data in a Redis server. Redis is popular open source key-value store that is often used for caching.

In this post, we’ll briefly cover how to get started with redis on windows.

Installation

For the installer, head to the latest windows redis release, download and run the latest MSI.

I’d recommend ticking the box to add redis to the PATH variable to make interacting with redis from the command line easier:
Redis PATH

Also, take note of the port that redis will run on:
Redis Port

Let’s quickly check it’s installed and running ok by testing it in the CLI:
Redis Test

We can also install Redis Desktop Manager which is a GUI management tool for Redis.

After we have installed redis desktop manager, we can connect to our redis server.
Redis Deskop Manager Connection

We can then see the key and value we set earlier in the redis CLI:

We can edit the value:
Redis Deskop Manager Edit Value

As you would expect, you can add new key-values as well
Redis Deskop Manager New Value

Why redis?

  • Redis is super fast – according to the docs, it can potentially perform up to 120,000 requests per second
  • Redis is very simple – you can store data with just a single set command and retrieve the data using the get command. There’s no defining of any tables etc
  • Redis is durable – it can write the data to disk …
  • Redis works on multiple platforms and many languages – including windows and ASP.NET Core!

We’ll wire a redis cache up to an ASP.NET Core web API in a future post …

Recommended reading for redis: