Getting out of “a variable nightmare” – or how I learnt to let go and embrace conventions

I’ve recently been doing some work automating the release of our integration projects to our various clients, I was reviewing the work that had been done last week and noticed that there were a lot of variables being defined. If we continued on this course as we added new clients we would end up adding between 3-5 new variables, multiple that by say 100 new clients and soon we would have an incredible amount of variables to deal with.

In our project we use Octopus environments to represent our different clients; you can see from the image below that we were defining a lot of different variables for each of our clients.

variables-before

As you can see above with only a handful of clients it’s already getting out of control – there has to be a better way!

Embrace convention, simplify your life

Consistency by convention

It struck me that we had inadvertently created a few conventions in the way we were defining different variables.

For example we had the following variables defined for each of our environments:

  • Client Staging DB, which represents the name of a database used by an ETL process these all took the form Client_[client name]
  • Client Staging User ID which took the form Staging_[client name].

These two variables (along with Client Staging Password) are used in the Client – National Conn String variable.

It dawned on me that with a very simple convention I could get rid of most of these repeated variables.

So instead of continuing on creating scoped variables for each of our clients (environments) I embraced the Octopus Environment Name variable. Now all of these existing variables that were scoped to each environment have been deleted and now there is a single variable shared by all environments.

Client – National Conn String has been replaced with

Data Source=xyz;User Id=Client_#{Octopus.Environment.Name};Password=#{Client Staging Password};Initial Catalog=Staging_#{Octopus.Environment.Name};Provider=SQLNCLI11.1;

This means longer having to define the Client Staging DB and Client Staging User ID variables.

There were a bunch of other variables that I went through and updated to use the same convention. After making this change I went from having 38 variables, down to 22.

variables-after

We now have an opinionated deployment process, which comes with some some big advantages:

  • The process is easier to reason about
  • Everything is consistent
  • Less setup work when on-boarding new clients

But it’s good to be flexible

There is still room for exceptions, take the Client – Local Conn String variable, I was able to standardize this for all of our clients except for the one where we run our database on their cluster. For them I have a variable scoped just to their environment.

Octopus Deploy makes it easy to be flexible with variable scoping.

Variable sets reduce noise

The other trick that I’ve used is putting groups of related variables into their own variable sets. They are great for sharing variables between projects, but I’ve used them to remove noise from the project variables listing.

No pain no gain

It’s worth mentioning there was a little bit of pain, not all of the environments were configured consistently, not all of the SQL users were named according to the convention. Which meant a bit of manual work fixing things up; but in the long run it’ll pay off.

Advertisements

Distributed multi-tenanted releases with Octopus Deploy

TL;DR; read the Octopus guidance, adopt the “environment per tenant” approach, try to make your process consistent across tenants and use scoped variables to make steps re-usable, keep complexity out.

In my last couple of posts I’ve written about the various aspects involved with automating the release of our client integration projects. I’ve shown how to get TeamCity to build Integration Services projects and then how to deploy them into SQL Server SSIS Catalog with Octopus Deploy.

In this post I’m going to explain how we setup Octopus Deploy for distributed multi-tenanted deployments.

octopus-dashboard

What is a distributed multi-tenanted deployment?

A tenant in the context of DrDoctor it is a hospital. As mentioned in a previous post, when DrDoctor starts working with a new hospital we do some bespoke integration work to integrate their PAS system with our system. This ETL process is made up of a couple of staging databases and some SSIS packages which orchestrate the ETL process.

For each hospital that we work with, we are given a virtual machine within their network to which we deploy a database and a set of SSIS packages. We then have a schedule job that:

  • Performs an ETL process on the client machine to transform the data from their PAS system into our schema
  • Transfers the transformed data from the client site to our central database running in our data center.

So in our context we have a mixed deployment topology, some components go to a virtual machine running in a remote data center and some components go to our servers running in another data center.

Setting up Octopus Deploy

Octopus Deploy already has some very helpful guidance around different ways that it can be set up to support multi-tenanted deployments. There are broadly speaking two approaches: environment per tenant or project per tenant.

The process which I opted for was environment per tenant, in this approach there is a single project which contains all the different steps and variables, and multiple environments which represent the various tenants.

The reason I opted for environment per tenant is that our release process is the same for each of our clients, this keep the overhead of maintenance low and the process of setting up a new client easy.

setting up the environments

As per the Octopus guidance (linked to above) I created an environment for each of the hospitals DrDoctor currently works with. At this time they are all configured with an offline package drop deployment target while we work with the various IT departments to get their firewalls to allow the Octopus tentacles to communicate with our Octopus server.

environments

I also added to each environment a listening tentacle deployment target for the tentacle inside our data center, this the same tentacle but with multiple environments applied to it.

shared-tentacle

I also created a new release life cycle for this project, which treats all the environments as equals.

etl-lifecycle

The release process

This is the release process at time of writing.

release-processSteps 2-4 and 6 I covered in my previous post about deploying SSIS projects with PowerShell and Octopus Deploy. All of these steps make use of environment specific variables so they will work uniformly across all of our clients.

The step that is interesting is actually step 5. As I noted above, we have to do bespoke integration work for each of our clients, this involves writing custom transforms (stored procedures) and having a different set of database tables to which we import data from and to.

In Visual Studio we have a SQL database project for each of our clients (Local.ClientX), with all the common objects in a referenced database project. The client specific database project contains the transform stored procedures, import tables and client specific data mappings.

database-projects

Each of these database projects are built by TeamCity and turned into NuGet packages for Octopus Deploy.

database-projects-in-teamcity

In step 5 there is a step for each of our different clients, with each step being scoped to a specific environment. The actual work being done in each of the sub-steps are identical with the exception of the NuGet package which is being deployed.

Configuring step 5 was the only point where I felt that the functionality of Octopus Deploy was lacking elegance. It would be much nicer to have a single step which dynamically picked the correct NuGet package based on the environment variable.

That wasn’t possible as far as I could see, hence why step 5 has lots of duplication.

Roles

There are two roles:

  1. client role – this is for all steps that should be run on the client integration machine
  2. mayden role – this is for the steps that should be run on our central server

Using roles allow us to control where each of the steps are run.

Introducing Offline package drop

At time of writing we haven’t yet negotiated with the various IT departments to allow the tentacles to get through their firewalls. However, with the release of Octopus Deploy 3.x this is no longer a deal breaker thanks to a new feature called offline package drop.

This is one of a number of new deployment targets that have been added in version 3.x. When you deploy a release to an offline package drop the Octopus server will create a local directory for that release/environment and bundle up all the release artifacts (NuGet packages, PowerShell scripts etc) and create a handy script which can be run to deploy the release. This is the perfect feature where you can’t have either a listening or polling tentacle.

So the release process now becomes:

  • Create a new release in Octopus
  • Deploy the release to one or more environments
  • Zip the deployment folder and copy to the client machine
  • Execute the deployment script

Assuming everything worked the client is now on the latest release.

Multiple deployment targets

One of the great features about Octopus Deploy is how the environments can be configured. As I showed above, in our environments we two deployment targets each scoped to specific roles. This becomes really handy when trying to coordinate different steps across different machines.

In our scenario, the way it has been configured is to have all the client specific steps go to the offline package target, and the step for our central server will go to the listening tentacle and therefore be executed without any manual work by the person doing the deployment.

The other nice thing is that once our clients start opening their firewall we can swap out the offline package drop with a listening or polling tentacle and the release process will just work as is.

Thoughts and advice

One of the biggest problems I was trying to address with all this automation was fear or more specifically releasing is really hard…so I’ll avoid it as much as I can. Before we automated the process we would often over point user stories that involved making changes to our ETL process because releasing was so hard.

One of the consequences I believe that has come out of this is that we will as time goes in build confidence in releasing changes, and therefore more easily make changes. There are loads of things we would like to do to our ETL process to make the actually process more efficient, or refactor some of the data structures. My hope is that all those little things we’ll start doing because it’ll no longer be a big scary release.

The main advice I would give to someone looking to use Octopus Deploy for multi-tenanted releases is this: adopt the environment per tenant and only one project approach. This might mean a little bit of pain making everything uniform, but it will reduce your overhead and give you a much simpler process to reason about.

The more I use Octopus the more it shows itself to be extremely flexible and suited to many different scenarios, but at the same time it doesn’t have to be complicated, you could very easily have a simple project up and running in an afternoon.

Go forth and automate.

Deploying SSIS projects with Octopus Deploy

In my previous blog post I outlined how to configure TeamCity to build SQL Server Integration Services projects and then package the ispac file into a NuGet package.

In this post I’m going to show how I set up Octopus Deploy to deploy the ispac to SQL Server 2012 and configure SSIS DB projects and environments.

Deployment Overview

Here is an overview of the process as is currently defined in Octopus Deploy.

1-process-overview

We are doing multi-tenanted releases for this project, which is why the Client DB (Step 4) is repeated multiple times. In a future post I’m going to cover off details about how we are doing multi-tenanted releases.

Setting up SSIS DB

The first step in the release process is to ensure that the SSIS DB is up to date for use with our SSIS projects, within this step we ensure that:

  • A project folder exists within SSIS DB for our ispac to be deployed into
  • An environment exists
  • Environment variables are up to date

All of this is achieved with a little bit of PowerShell

$folderName = $OctopusParameters['SSISDB FolderName']
$environmentName = $OctopusParameters['SSISDB EnvironmentName']

$loadStatus = [Reflection.Assembly]::Load("Microsoft.SqlServer.Management.IntegrationServices, Version=11.0.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91")

# Store the IntegrationServices Assembly namespace to avoid typing it every time            
$ISNamespace = "Microsoft.SqlServer.Management.IntegrationServices"            
            
Write-Host "Connecting to server ..."            
            
# Create a connection to the server            
$constr = "Data Source=localhost;Initial Catalog=master;Integrated Security=SSPI;"            

$con = New-Object System.Data.SqlClient.SqlConnection $constr

# Create the Integration Services object            
$ssis = New-Object $ISNamespace".IntegrationServices" $con

if ($ssis.Catalogs.Count -eq 0)
{
    Write-Error "SSISDB doesn't exist"
    throw "SSISDB doesn't exist"
}

$cat = $ssis.Catalogs["SSISDB"]

if ($cat.Folders[$folderName] -eq $null)
{
    Write-Host "Creating new folder" $folderName
    $newfolder = New-Object $ISNamespace".CatalogFolder" ($cat, $folderName, "Description")     
    $newfolder.Create()
}

$folder = $cat.Folders[$folderName]

if ($folder.Environments[$environmentName] -eq $null)
{
    Write-Host "Creating environment" $environmentName
    $newEnv = New-Object $ISNamespace".EnvironmentInfo" ($folder, $environmentName, "Descriptoin")
    $newEnv.Create()
}

$env = $folder.Environments[$environmentName]

Write-Host "creating variables"

if ($env.Variables["Local"] -eq $null)
{
    $env.Variables.Add("Local", [System.TypeCode]::String, $OctopusParameters['Client - Local Conn String'], $false, "Our local client db")
}
else
{
    $env.Variables["Local"].Value = $OctopusParameters['Client - Local Conn String']
}

# create other environment variables here...

#save changes to environment
$env.Alter()

(NB: This script and the subsequent one for deploying the ispac are based off this example by Matt Masson)

I’ve tried to write this script to be idempotent so that it can be run multiple times without causing any problems.

Here is what you will see in SQL Management Studio after this step has run:

2-ssisdb-with-folder

Deploying SSIS Projects

The next step is to actually deploy the Integration Services project into the SSIS DB. In this step we use a PowerShell script to:

  • Deploy the ispac into the project folder that was created in the previous step
  • Ensure that the project has a reference to the environment that was created in the previous step
### Static Variables

$localToLocalETLFullPath = ".\DrDoctorClientETL.ispac"
$folderName = $OctopusParameters['SSISDB FolderName']
$environmentName = $OctopusParameters['SSISDB EnvironmentName']
#the projectName needs to match the output name that has been specified on the project, you can see this in the properties in SQL Server Data Tools
$projectName = "DrDoctor Client ETL"

###

$loadStatus = [Reflection.Assembly]::Load("Microsoft.SqlServer.Management.IntegrationServices, Version=11.0.0.0, Culture=neutral, PublicKeyToken=89845dcd8080cc91")

# Store the IntegrationServices Assembly namespace to avoid typing it every time            
$ISNamespace = "Microsoft.SqlServer.Management.IntegrationServices"            
            
Write-Host "Connecting to server ..."            
            
# Create a connection to the server            
$constr = "Data Source=localhost;Initial Catalog=master;Integrated Security=SSPI;"            
            
$con = New-Object System.Data.SqlClient.SqlConnection $constr      
# Create the Integration Services object            
$ssis = New-Object $ISNamespace".IntegrationServices" $con
$cat = $ssis.Catalogs["SSISDB"]
$folder = $cat.Folders[$folderName]

Write-Host "Deploying project ..."            
[byte[]] $projectFile = [System.IO.File]::ReadAllBytes($localToLocalETLFullPath)            
$folder.DeployProject($projectName, $projectFile)

#####

Write-Host "adding reference to environment"

$project = $folder.Projects[$projectName]
$env = $folder.Environments[$environmentName]

if ($project.References.Count -eq 0)
{
    $project.References.Add($env.Name, $folderName)
}
else
{
    Write-Host "assuming that the correct environment has been configured"
}

####

Write-Host "applying environment variables to project"

$targetVar = $env.Variables["Local"]
$sourceVar = $env.Variables["Source"]

Write-Host "Updating Extract package parameters"

$extractPackage = $project.Packages["Extract.dtsx"]

$extractPackage.Parameters["CM.Target.ConnectionString"].Set([Microsoft.SqlServer.Management.IntegrationServices.ParameterInfo+ParameterValueType]::Referenced, $targetVar.Name)
$extractPackage.Parameters["CM.Source.ConnectionString"].Set([Microsoft.SqlServer.Management.IntegrationServices.ParameterInfo+ParameterValueType]::Referenced, $sourceVar.Name)

$project.Alter()

After this step has run the Projects folder will contain the first of our SSIS projects:

3-ssisdb-with-project

Deploying a database project

In a previous blog post I showed how you can fiddle with the dtproj and add a reference to the Octopack NuGet package to have TeamCity turn your database project into a NuGet package for you.

However, since discovering how to use NuSpec files in TeamCity I’d now recommend against changing your dtproj file and instead moving to using a NuSpec to define the package.

Here is a sample NuSpec file that I started using this week

<?xml version="1.0" encoding="utf-8"?>
<package xmlns="http://schemas.microsoft.com/packaging/2010/07/nuspec.xsd">
  <metadata>
    <id>ClientDB</id>
    <version>1.0.0</version>
    <authors>DrDoctor</authors>
    <requireLicenseAcceptance>false</requireLicenseAcceptance>
    <description>Client database</description>
  </metadata>
  <files>
    <file src="bin\Release\ClientDB.dacpac" target="ClientDB.dacpac" /> 
    <file src="bin\Release\Reference.dacpac" target="Reference.dacpac" /> 
  </files> 
</package> 

(You can adapt this as you need for your requirements)

As shown in my previous post on building SSIS projects in TeamCity you will need to add this NuSpec file the list of packages to build within the NuGet Packaging step to have TeamCity build the NuGet package.

Once TeamCity is building the NuGet package, we can add a new Deploy NuGet Package step in our Octopus Deploy project, with the follow PowerShell script as a custom deployment script.

Here is the PowerShell script which will generate an upgrade script using SqlPackage.exe

$dbName = $OctopusParameters['Client Staging DB']
$server = $OctopusParameters['National DB Server']

$releaseNumber = $OctopusParameters['Octopus.Release.Number']

& 'C:\Program Files (x86)\Microsoft SQL Server\110\DAC\bin\SqlPackage.exe' /Action:Script /OutputPath:Upgrade.$dbName.$releaseNumber.sql /SourceFile:DrDoctor_STG.dacpac /TargetServerName:$server /TargetDatabaseName:$dbName /p:IncludeCompositeObjects=true

New-OctopusArtifact -Path "Upgrade.$dbName.$releaseNumber.sql"

This will compare the dacpac to the database, if the database doesn’t exist then the upgrade script will create it, otherwise the upgrade script will contain a bunch of sql commands to upgrade the database to match the dacpac.

The New-Artifact command is a useful Octopus Deploy function that tells the tentecle to grab the file and make it part of the release, so it’s then available from within the Octopus Deploy web ui.

release-artifacts

Alternatively, if you’re game you could configure SqlPackage to automatically upgrade the database by using Action:Publish instead.

In the next blog post I’ll be covering multi-tenanted releases with Octopus Deploy and using the Offline Package Drop feature which was new in 3.0.

Disclaimer: the PowerShell could definitely do with some tidying up, don’t hold that against me 🙂

Building and packaging SQL Server Integration Services projects in TeamCity

At DrDoctor we’ve been using Octopus Deploy for about a year and half now, and in that time we have developed a very robust way of releasing the core of our system. That is, two IIS websites and a bunch of windows services. Release automation has vastly increased the frequency at which we release software into production and in turn the speed at which the business can operate.

The missing part in all of this are the integration projects, when DrDoctor begins working with a new hospital we do a bunch of work integrating their PAS system into our system. This takes the form of a couple of staging databases and a couple of SQL Server Integration Services (SSIS) projects.

Whenever we are discussing changes that need to be made we always screw up our faces at the thought of doing the release. We also have no idea which clients have which version, or when we last did a release.

In this and a few subsequent posts I’m going to outline the various steps that I took to automate our deployments, so we can get on doing the interesting work and let the computers handle the boring deployment work.

Building SSIS Projects in TeamCity

The first step required is to have TeamCity build our Integration Services (SSIS) projects in TeamCity. In reality all it’s really doing is taking all the .dtsx packages that are part of the project and turning them into an ispac file.

The ispac is basically a zip file that contains all the packages and some other metadata which is used when deploying into SQL Server SSISDB.

There are two methods that come up from a Google search on getting TeamCity building SSIS projects, the first involves using a community MSBuild extension and a bunch of other bits, you can read more about it here or here, you can find the MSBuild extension on CodePlex. I tried this method, but didn’t have immediate success.

The second option is to use Visual Studio (SQL Server Data Tools) devenv.exe to build your project, this was already installed on our build server as it is required when building database projects.

To do this in the TeamCity project’s build configuration I added a new build step, which was a Command Line runner:

1-building-ssis-devenv

In the custom script I put in the full path to devenv.exe, our SSIS projects are built in SSDT BI 2012 (Visual Studio 2012 shell) so I’m using that version of devenv.exe on the build server.

Packaging SSIS Projects for deployment

Now that TeamCity is building the project it time to setup TeamCity to package the ispac file into a NuGet package. As mentioned in the intro, we use Octopus Deploy as our deployment system, it in turn uses the NuGet package format as the container for application files (more details).

Setting up TeamCity to automate the creation of NuGet packages turns out to be really easy.

Creating a NuSpec file

The first step is to create a NuSpec file, this is the manifest file that TeamCity will use when building the NuGet package (it tells TeamCity which files to include in the package).

To set this up I added a new file called Local_ETL.nuspec into my project folder with the following content

<?xml version="1.0" encoding="utf-8"?>
<package xmlns="http://schemas.microsoft.com/packaging/2010/07/nuspec.xsd">
  <metadata>
    <id>SSIS.Local_ETL</id>
    <version>1.0.0</version>
    <authors>DrDoctor</authors>
    <requireLicenseAcceptance>false</requireLicenseAcceptance>
    <description>Sync client to local</description>
  </metadata>
  <files>
    <file src="bin\Development\DrDoctor Client ETL.ispac" target="DrDoctorClientETL.ispac" />
  </files>
</package>

This as you can specifies a NuGet package ID, a version and a bunch of files that should be included.

Add build step in TeamCity

The next and final step is to configureTeamCity to create the NuGet package using the NuSpec file.

In TeamCity go into the Build Steps of your project, and click Add build step. From the runner type select NuGet Pack and configure the step with the following:

1-teamcity-nuget-packaging

Make sure that you have ticked “Publish created packages to build artifacts”. This will ensure that the packages are available through the built-in NuGet repository.

In the next post I’ll show how I setup my deployment project in Octopus Deploy to deploy the SSIS ispac to SQL Server SSISDB.

Stay tuned.

Applying custom settings with Octopus Deploy

If you’re a .Net developer and not currently doing automated deployments then you really should be. If you’d like some help getting started send me a message in the comments and I’ll drop you an email.

The core of any deployment is the ability to easily manage and apply configuration values, across environments and across your different apps/web apps.

Octopus Deploy has first class support for managing variables, including setting different scopes or environments and steps in your deployment process. It also has first class support for substituting variables into your <appSettings> and <connectionStrings>. In this case, all you need to do is create a variable with the same name as the appSetting and Octopus Deploy will swap in this value during deployment. Easy.

So what’s the problem?

The trouble comes when you start using custom settings in your app.config and web.config files. For example, you might have a web.config file that looks like this:

<configuration>
  <configSections>
    <section name="SomeCrazySettings" type="SomeAssembly.SomeCrazySettings, SomeAssembly" />
  </configSections>
  <appSettings>
    <!-- omitted -->
  </appSettings>
  <SomeCrazySettings>
    <CustomThing key1="foo" key2="bar" />
  </SomeCrazySettings>
</configuration>

Octopus Deploy does have a built in way of dealing with this problem, but the downside is that you have to hard-code the values in the Octopus Deploy convention, e.g.

<SomeCrazySettings>
  <CustomThing key1="#{Crazy Key1}" key2="#{Crazy Key2}" /> 
</SomeCrazySettings>

The problem that I have with the above is when I want to hard-code the values for local development. One of the applications I work on has a config item called BaseUri and when I’m working locally I like to have it set to my local machine e.g. http://localhost:44301. So the syntax above doesn’t work unless I’m happy with constantly changing the values.

In this blog post I’m going to show how with a little bit of PowerShell we can update the custom settings shown above.

Deployment Script

PowerShell makes your deployments awesome, especially in the context of Octopus Deploy. Anything that isn’t baked in can easily be implement with a little bit of PowerShell.

$Path = $OctopusParameters["OctopusOriginalPackageDirectoryPath"]

$Config = Get-ChildItem "$Path\*" -Include *.exe.config | Select-Object -First 1
[xml]$ConfigXml = Get-Content $Config

$configNodes = $ConfigXml.SelectNodes("//SomeCrazySettings");

if ($configNodes.Count -eq 1)
{
    $ConfigXml.configuration.SomeCrazySettings.key1=$OctopusParameters['Key1']
    $ConfigXml.configuration.SomeCrazySettings.key2=$OctopusParameters['Key2']

    $ConfigXml.Save($Config)
}

This script does the following:

  • Line 1-4: Finds the config file and then loads it as an XML object
  • Line 6: Using XPath looks for the node with the custom configuration
  • Line 8-14: If the node was found, updates the values of the custom keys, and then saves the file.

Go forth and automate.

Improving .Net Performance

Over the past couple of weeks we’ve noticed that our Reporting service is terribly slow.

splunk-dblogger

The above chart is part of our APM (Application Performance Monitoring) solution built on top of MiniProfiler and Splunk (see this blog post for more details). Our reporting service works by processing messages which are queued up by various other services onto a queue in RabbitMQ. What this chart is showing is that the reporting service is working at a very constant and slow pace. It will eventually get through the backlog of messages, but it takes it a few hours each morning while the CPU sits at around 100%.

Instead of the chart above, what I’d rather see is a big spike in activity that is sustained for a (much) shorter period of time!

In this post I’m going to show how I used the built-in tooling in Visual Studio 2013 to find and diagnose the bottlenecks in our code and then visualize the improvement in performance using Splunk and MiniProfiler.

Finding and fixing performance bottlenecks

I’ve known for a long time that Visual studio has built-in performance sampling tools, but have rarely used them. I found Sasha Goldshtein’s (blog|Twitter) Pluralsight course on Measuring .Net Performance an excellent overview of how to get started with them.

To measure the performance I first queued up a significant number of messages for the reporting service to process then started the Visual Studio Profiler.

Profiling CPU Usage

I started by setting the project I wanted to profile as the “Startup project”. Then from the Analyze menu, selected Performance and Diagnostics, which brings up the following window

1-performance-and-diagnostics

I then selected Performance Wizard under Available Tools and then clicked the Start button. This brings up a dialog where you can select a few options, I selected CPU sampling as the profiling method, then the Reporting Service project as the profiling target, then clicked finished. The Reporting service then started and Visual Studio started profiling, after about 5 minutes I stopped the profiling.

Viewing Profiler Reports and fixing bottlenecks

This is what the first profiling report looked like

2-first-perf-report

As you can see from the Hot Path, the Infrastructure.PubSub.EzNQ.BusItemTypeNameSerializer.DeSerialize method gets called lot and is potentially very slow! The good news here is that this is our code, which means I can click on this row and visual studio will take me to this method, and even highlight the expensive code.

3-first-hot-path

The class in question is an implementation of an interface which is part of EasyNetQ (a very nice .Net API for RabbitMQ which all of our services use). The interface ITypeNameSerializer let’s us customize our queue names and tells EasyNetQ what type it should deserialize a message into.

As shown above there is a clear bottleneck in this code, the fix turned out to be pretty straightforward, I created the typesCache Dictionary at the class level, and then updated the DeSerialize method to:

public Type DeSerialize(string serializedName)
{
  var typeName = serializedName.Split('_')[1];

  if (typesCache.ContainsKey(typeName))
  {
    return typesCache[typeName];
  }
  else
  {
    var type = AppDomain.CurrentDomain.GetAssemblies()
                .SelectMany(a => a.GetTypes())
                .FirstOrDefault(t => t.Name == typeName);

    typesCache[typeName] = type;

    return type;
  }
}

After making these changes I ran the profiler again to see what difference that had made, here are the profile results for the second run through

4-second-hot-path

As you can see the Infrastructure.PubSub.EzNQ.BusItemTypeNameSerializer.DeSerialize method doesn’t get a mention, looks like the fix was successful. But now a call to DataAccess.SimpleDataHelper.GetDatabase in the DbReporter class is in the hot path.

Clicking onto the ReportingService.DbReporter.WriteReportToDb row brings up the code for that method

5-writereporttodbThis c# code probably has any DBA wriggling in their seat right about now (sorry!), this method is writing each message that it processes into a corresponding table in our database using the likes of c# dynamic and SimpleData. It’s pretty powerful and very neat as we don’t have to write lots of code to persist all the different reporting events to the database.

Sadly there isn’t much that can really be done about the .Insert call, however after reading through the SimpleData documentation I realized that I don’t need to continually make calls to .GetDatabase, but rather can do this once in the constructor and SimpleData will take care of opening and closing the connections as needed.

After making these two fixes the profiler results after a third run don’t indicate anything specific that can be “fixed”, so it was time to push it up to our testing environment and do some real testing.

Comparing Performance

As I mentioned above our custom APM solution is built on top of Splunk and MiniProfiler. There are a number of advantages that we get from this that we wouldn’t get from the likes of New Relic or Stackify. One advantage is that we can add our own meta data to all the performance data we generate.

We put a Version number into all the performance data that we generate, this comes from the NuGet version number generated by TeamCity as part of our build process. Because we put this Version number in it means comparing performance between versions becomes trivial.

In Splunk I created the following dashboard, which allows me or any of my fellow developers at DrDoctor to select an Application and Transaction and then a baseline and comparison version.

comparing-performance

Judging by the results shown above, it’s working at roughly twice the speed, I’d have hoped for it to be a bit faster than that, but still I’m not complaining!

Unexpected consequences

Our Reporting service does two things it writes all IReportItem messages which it processes to their respective table in the database and the second thing is write all events into a log file for Splunk to index.

While doing some local testing I noticed that even writing to a log file was slow! The maximum speed I saw was ~50messages/second just to write to a log file! After making the fixes above the processing speed went up to 5,000 messages/second! Not insignificant that’s for sure.

6-queue speed

Send logs to Splunk with log4net UdpAppender

Last week I deployed a new Api hosted as an Azure WebApp, we wanted some reporting events to come out of it into our Splunk instance so we could keep an eye on whether it is working as expected. I started off by using the Splunk C# SDK as it looked nice and easy to add into our app.

A very trivial example of using the Splunk SDK would look like this:

public class SplunkLogger
{
	private readonly Splunk.Service service;
	private readonly Splunk.Receiver receiver;

	public SplunkLogger()
	{
		this.service = new Splunk.Service("myawesomesplunkinstance", 8089, "https");
		this.service.Login("", "");
		this.receiver = new Splunk.Receiver(service);
	}

	public void Log(string msg)
	{
		var args = new Splunk.ReceiverSubmitArgs
		{
			Source = "mysource",
			SourceType = "mysource-event",
			Index = "myindex"
		};

		receiver.Submit(args, msg);
	}
}

The Splunk SDK should have worked, but since there was A LOT of traffic at different times throughout the day the vast majority of the HTTP requests to the Splunk API just timed out.


System.Net.WebException: The operation has timed out
  at System.Net.HttpWebRequest.GetRequestStream(TransportContext& context)
  at System.Net.HttpWebRequest.GetRequestStream()
  at Splunk.HttpService.Send(String path, RequestMessage request)
  at Splunk.Service.Send(String path, RequestMessage request)
  at Splunk.Receiver.Submit(String indexName, Args args, String data)
  at Splunk.Receiver.Submit(Args args, String data)
  at Splunk.Receiver.Submit(ReceiverSubmitArgs args, String data)

After I discovered that it constantly just timed out I started to look around for an alternative to using the Splunk REST Api endpoint.

I’ve always noticed that Splunk lets you send events data to it via TCP/UDP but have never had cause or reason to use it. However given that our API was hosted as an Azure Web App and logging to the file system wasn’t an option I thought this would be the perfect time to try it out. As it turns out I was not disappointed.

 Setting up Splunk

The first thing you will need to do is configure your Splunk instance to listen out for events from a Udp port.

  1. From the Splunk settings, select Data Inputs1-data-inputs
  2. Click “Add new” UDP input2-add-new-udp
  3. This will bring up the Add Data wizard, enter the port you want Splunk to listen on (this will also need to go into your log4net config)3-add-data-wizard
  4. The next page “Input Settings” let you (optionally) specify various things about the data you are going to be sending. There are two particularly useful settings here, the sourcetype and index4-input-settings
  5. Click Review and then Submit

Splunk is now listening on that UDP port.

Important Note: Make sure that all firewall ports between your producer and Splunk are open to allow UDP traffic on the specified port! Otherwise it will silently fail.

Introducing the log4net UdpAppender

The first step of getting this working from your application is adding the log4net NuGet package to your project, next up open your log4net configuration and add the following <appender>

<appender name="SplunkAppender" type="log4net.Appender.UdpAppender">
  <remoteAddress value="<your-splunk-server>" />
  <remotePort value="<your-udp-port>" />
  <layout type="log4net.Layout.PatternLayout">
    <ConversionPattern value="%m%n" />
  </layout>
</appender>
<root>
  <level value="DEBUG"></level>
  <appender-ref ref="SplunkAppender"></appender-ref>
</root>

Now from your c# code you use log4net as you normally would:

var logger = log4net.LogManager.GetLogger("SplunkLogger");
logger.Info("logged to splunk!");

And you should start seeing your events in Splunk.

If you need to verify that log4net is sending events over UDP you can use Wireshark. Here I have set it up to capture packets from my wifi adapter and monitoring port 9977

5-wireshark

Log File Intelligence – log4net meets Splunk

At DrDoctor we are slowly adopting Splunk as our central reporting repository. We already have most of our application specific events going into it and we are already seeing some great benefits.

In this post I’m going to show the various steps I went through to get our log4net files being ingested in a useful format. Monitoring a file is easy, extracting useful fields is sometimes a challenge especially with log files.

Setting the format string

The first step was to change the format string in the log4net.config file. The main aim here was to make my life easier for when the log files are going into Splunk. By prefixing all the log4net tokens with a name means that I can write some simple, but very reliable regexes in Splunk to turn these into fields.


%utcdate{ISO8601} Release:'!release!' Version:'!version!' Thread:'[%thread]' Level:'%-5level' Logger:'%logger' Message:'%message'%newlineException:'%exception'

Those who are familiar with the log4net configuration options with notice that there are two tokens that don’t exist in the format string above. They are !release! and !version!, these are two very useful values to capture alongside our error messages as we can then start to track when new types of errors are discovered or introduced.

I’m using a custom PowerShell script in our deployment system, Octopus Deploy to set these values during the deployment phase, the release number reflects the Octopus Deploy release and the version number reflects the build number from TeamCity. Arguably we probably don’t need both, but I’m not entirely sure what I’m going to need yet so I’m going to stick with both for now.

Setting up Splunk

In our environment and most others I would assume, we are using the Splunk universal forwarder to send data to Splunk. The first step then is to add a new entry to the inputs.conf file to keep an eye on our logs directory.

[monitor://d:\logs\*.log]
sourcetype=log4net

Well that was easy, now that the Universal Forwarder is tracking the log files directory we should start seeing log entries appearing in Splunk.

This is a good start, but it would be more useful if we could start seeing the breakdown of the various entries. This is the point where we need to extract the various fields from the raw events.

To do this we need to make use of the Splunk field extractions. To extract more fields scroll down and click the link “Extract New Fields”

1-extract-new-fields

Then click “I prefer to enter the regex myself”

2-write-myown-regex

All the extractions follow a similar pattern, here is the regex to extract the log level:

Level:'(?P<Level>(([A-Za-z]*)))'

Enter that into the regex input, then click the Preview button, in the sample events you will see all the different logging levels highlighted, you will also notice a new tab called Level appear.

3-preview

Here is the complete list:

Release:'(?P<Release>(([0-9|.]*)))'
Version:'(?P<Version>(([0-9|.]*)))'
Level:'(?P<Level>(([a-zA-Z]*)))'
Message:'(?P<Message>((.+)))'

Go through the steps above for each one.

Log Intelligence

Now we can start doing some fancy queries.

Example one: number of errors by Release and host

index=logs sourcetype=log4net | stats count by Release, host

4-count-by-release-host

Example two: number of errors over time

index=logs sourcetype=log4net | timechart count

5-timechart

Example three: number of errors by application

index=logs sourcetype=log4net | rex field=source "Error\\\(?<app>(\w|\s|\d)*)" | stats count by Release, host, app | sort -Release, -count 

6-errors-by-application

Next steps

There are many possibilities, here are a couple of ideas:

  • Build a dashboard from the various queries above
  • Create some Splunk Alerts to trigger when a threshold of errors have been triggered