Getting started with Redis on Windows and a look at performance for logging

There’s a few scenarios in a few different projects where I need a fast dumping ground for data. In my deployments I need somewhere quick to pump logging messages to. These messages do not need to be written to disk or read out immediately so can be processed shortly after the fact out of process. I have the same requirements when rendering machine performance on a UI; I need a fast and non-intrusive way to collect the data from different machines and processes which can be read quickly later.

Redis is something which has been coming up frequently when talking linux and much has been said about its performance, so I wanted to take a quick look at performance in the context of logging. But first let’s get it up and running. I’ll be using PowerShell, chocolately and npm, so get those set up first.

Let’s begin by using chocolately to install redis.

cinst redis

The package should have installed a windows service running redis, let’s double check using powershell.

C:\> get-service *redis*

Status   Name               DisplayName
------   ----               -----------
Running  redis              Redis Server

Great, now time to get a UI to make using redis a little easier, this time the package is on npm.

C:\> npm install –g redis-commander;
C:\> redis-commander
No config found.
Using default configuration.
path.existsSync is now called `fs.existsSync`.
listening on  8081
Redis Connection 127.0.0.1:6379 Using Redis DB #0

The manager runs on port 8081 by default, let's take a look in a browser (use another shell as redis-commander will block your current one).

start http://localhost:8081

If you can see the UI then you are all set up and its time to push some data in and run some performance tests. Our build and deployment framework logs to the filesystem. This worked great for builds and simple deployments, but for scaled out environments and production which runs on many machines this is problematic. To avoid deadlocks and waits we manage a log file per machine and cat the tail into the main log when we can. We could aggregate these files post-deployment but its time to rethink how we do our logging. For now I just want to check raw speed and basic features of a few different technologies, today its redis.

We’ll use measure-command to find out how quickly we can log a bunch of messages to a file and then to redis. Using our framework to deploy to an environment for performance testing generates around 100K lines of logs across 123 log files and 27 machines. These get aggregated onto the deployment server for convenience but its still a lot of logs which are written during the deployment.

measure-command { 1..100000 | %{ Add-Content -Path C:\log1.txt -Value $_ } }
TotalSeconds : 319.9256509

This command is analgous to what we do in our PowerShell framework, since we do not keep a handle open on any one file we have to open it before writing every time. It takes 5 minutes to write that many lines of logs to the file system using Add-Content. This is a long time to spend logging and as we only write numbers in the benchmark involves less IO then deployment messages. We will benchmark redis for comparison and use the PowerRedis module.

We will make a single connection to redis as cmdlet takes care of the global state of the connection.

Connect-RedisServer

And the benchmark:

measure-command {1..100000 | %{ Add-RedisListItem -Name "deployment:log" -ListItem $_ } }
TotalSeconds      : 14.0009325

A fantastic improvement and the ability to log from multiple machines at the same time makes it a good option to consider. I can't help but wonder how fast we can log to a file if we did it more responsibly though.

C:\> $writer = New-Object System.IO.StreamWriter C:\log3.log
C:\> measure-command { 1..100000 | %{ $writer.WriteLine($_); } }
TotalSeconds      : 2.5816333
C:\> $writer.close()

So there are a few lessons to learn here. Avoid add-content if you’re writing more than a few messages. Do always measure your code so you do not waste minutes(!) logging to files. Redis is certainly fast enough for logging.

Catching the PowerShell error stream

One of the challenges with PowerShell is the merging of concepts into a single DSL. In regards to error messaging, we have $LASTEXITCODE, PowerShell / .NET (throw) and the error stream (Write-Error). I tend to avoid using Write-Error and prefer to use throw instead, however I do use powershell modules which use Write-Error and I want to be able to handle these when it makes sense.

The following code:

Write-Host "Standard catch:" -ForegroundColor Cyan
try {
    Write-Error "writing to the error stream"
}
catch{
    Write-Host "I've been caught" 
}

Produces the following output:

Standard catch:C:\users\naeemk\desktop\error_stream.ps1 : writing to the error stream
At line:1 char:1
+ .\error_stream.ps1
+ ~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Write-Error], WriteErrorException
    + FullyQualifiedErrorId : Microsoft.PowerShell.Commands.WriteErrorException,error_stream.ps1

This behaviour was unexpected when I first encountered it. Today I stumbled upon a tidy way to handle the error: by Stopping and Catching. If we set an ErrorAction of Stop to the problem call, we are able to catch the error stream properly.

Write-Host "Stop and Catch:" -ForegroundColor Cyan
try {
    Write-Error "writing to the error stream" -ErrorAction Stop
}
catch{
    Write-Host ("I've been caught: {0}" -f $_)
}

Which produces the expected output:

Stop and Catch:
I've been caught: writing to the error stream

In our case we were running this code inside a parallel runspace and the unhandled call to the error stream was crashing the runspace and giving us the wrong stacktrace. With this we can raise a PowerShell exception and marshall over the correct stacktrace to help with debugging.

Passing just an array to ArgumentList in Powershell

What is the expected output from this command?

invoke-command -ScriptBlock { param($list) $list | %{ write-host $_ } } -ArgumentList @(@(1,2,3))

I would have expected:

> 1
> 2
> 3

But it seems to be:

> 1

After some experimenting and trying various ways to get this working as expected, I finally resorted to google and found a post on StackOverflow. So the way to do this is by putting a comma in the array to satisfy the parser:

invoke-command -ScriptBlock { param($list) $list | %{ write-host $_ } } -ArgumentList @(,@(1,2,3))

And now I get the output:

> 1
> 2
> 3

I don't think this is intuitive and I hope this will be addressed in the future. At least for now there is a way to do it.

Getting the msdeploy.exe install path using powershell

 

I’ve been playing around with msdeploy and powershell lately, and one of the things I needed to find out is where the msdeploy.exe was located. After building a web deploy package, the associated batch file created by msdeploy uses a registry key to get the executables location.

Accessing the registry in powershell is super easy, so we may as well do the same thing. The key in question is: "HKLM:\SOFTWARE\Microsoft\IIS Extensions\MSDeploy" which we can access using a standard Get-ChildItem or gci for short.

image

I have both MSDeploy v1 and v2 installed, and it’s the latter one I want to get at so we can use a Select –Last 1 to choose it. We also want just the InstallPath property which is accessible via GetValue on the RegistryKey object.

image

Great! We can easily put this into a function and load it into our path using:

function Get-MSWebDeployInstallPath(){
     return (get-childitem "HKLM:\SOFTWARE\Microsoft\IIS Extensions\MSDeploy" | Select -last 1).GetValue("InstallPath")
}

function Load-Configuration
{
    $webDeploy = Get-MSWebDeployInstallPath
    $env:Path += (";" + $webDeploy)
}

You should be able to access msdeploy from your powershell script now…

Older Posts