Posts by Nicholas Blumhardt

C# 6 string interpolation and Serilog

It’s easy to spot the similarity between Serilog message templates:

// Serilog
var loggedInUserId = "nblumhardt";
Log.Information("Logged in {UserId}", loggedInUserId);

and C# 6 interpolated strings:

// C# 6
Log.Information($"Logged in {loggedInUserId}");

This is naturally because of their shared common ancestor, the .NET format string. Under the hood, interpolated strings in C# are converted by the compiler into a struct with the classic format string and argument values, logically along the lines of:

// C# 6 desugared
Log.Information(new FormattableString
  {
    Format = "Logged in {0}",
    Args = new object[] { loggedInUserId }
  });

The similarity has led a few of us, since seeing the new C# feature, to wonder whether a few keystrokes might be shaved off of the Serilog API if only the C# compiler would preserve the names of the “holes” in the interpolated string, i.e. loggedInUserId in this example.

There was initially mention of Serilog on the design thread for the feature, and more recently Andrey Shchekin most graciously raised a ticket on the Roslyn issue tracker as a prompt for some support in C# 7.

I’ve had some time to think about this feature now, and while the concision is appealing, I’m no longer convinced string interpolation (name preservation or not) is a good fit for Serilog.

1. A good variable name is not necessarily a good property name

Let’s take the example above; in our hypothetical C# 6 example the complete snippet would look like:

var loggedInUserId = "nblumhardt";
Log.Information($"Logged in {loggedInUserId}");

The variable name loggedInUserId obviously reflects what this value is being used for by the program. But, if that name was carried through to the log event, e.g.:

{ { "Properties": { "loggedInUserId": "nblumhardt",

This would lead us to query the log with filters like:

loggedInUserId == "nblumhardt"

Fine if we only want to find events where the user was logged in, but in the context of a larger and more complex application, we’ll often want to find as many events as possible that are related to a specific user (who might be having some technical trouble!).

In that case, a more general property name is a better fit:

Log.Information("Logged in {UserId}", loggedInUserId);

// Elsewhere
Log.Information("Password for {UserId} successfully changed", loggedInUserId);

This small change allows us to query UserId == "nblumhardt" and find both matching events.

Log event property names are important enough for diagnostics that they deserve their own identity, separate from the variable names around them.

2. Holes don’t always have obvious names

What does the property name for this statement look like?

Log.Information($"Enabling categories {new[]{1, 2, 3}}");

Here the hole is filled with an expression that’s not a simple name, so some kind of munging would be necessary in order to turn it into a valid log event property name (a JSON identifier or similar).

Going down this path would definitely reduce the overall quality of log events, and elevating log events to first-class status is what Serilog’s all about.

So what’s the relationship between Serilog and C# 6, then?

String interpolation is a great feature, one I’ve looked forward to in C# for a long time. The idea of providing direct support for Serilog is a very interesting one and worth exploring, but I’m increasingly convinced it’s unnecessary.

Interpolation is nice when it keeps code DRY, cutting out the redundant clutter of {0} and {1} and preventing parameter mismatches.

In the case of Serilog, I think it’s incorrect to consider the property names like {UserId} as redundant; in a well-implemented logging strategy they’re an incredibly important part of the picture that deserve their own consideration. You wouldn’t let variable names determine the table and column names in a relational database – it’s exactly the same trade-off being considered here.

What do you think? I’d love to be convinced there’s more synergy to be found here, but I’m not seeing it at present.

Tagging log events for effective correlation

Correlation, at least when we’re talking diagnostic logs, is the process of finding events that are related to each other in some way. It’s typical to correlate events raised during a transaction, on a specific thread, on a machine or from steps in some kind of process.

Correlation is king in the world of operating complex, distributed and asynchronous apps: it’s how the signal is picked out of the noise – the wheat from the irrelevant chaff – the diamonds that will help you solve a critical issue from the mud of day-to-day happenings.

I gave a presentation a few weeks back at DDD Brisbane on building better apps by taking an active approach to logging. The last post should give you an idea of the flavor of it. After the talk some nice folks approached me and said I’d filled in a missing link for them – it made me realize I’ve been using a little strategy for correlation without really thinking about it, and you might find this useful too.

Contextual correlation

For a long time, diagnostic logs have incorporated contextual information into events. Context tells you what was happening when an event was raised, or where the event was raised from. In its earliest form it might be the thread ID you sometimes see formatted into text logs:

2015-01-22 10:55:05.776 INFO [22] Serving catalog index
2015-01-22 10:55:05.902 WARN [8] Query took 109 ms
2015-01-22 10:55:05.902 INFO [22] Responding with OK

The thread ID in this case is included in each log message between brackets after the level. It tells us that the warning on the second line was raised on thread 8, which isn’t the same thread as was concurrently serving the product catalog (thread 22), so the source of the warning was elsewhere.

Searching a simple text log like this we could grep for /[8]/ to see what else was happening on thread 8 and hopefully narrow down on the source of the slow query.

Serilog does contextual correlation in a few different ways.

Enrichers can be used to attach different contextual properties to events:

var log = new LoggerConfiguration()
  .Enrich.With<ThreadIdEnricher>()
   // Other config here, then…
  .CreateLogger();

Enrichers work well when the context of an event can be determined statically – i.e. it’s something ambient like the thread id, machine name, the logged-in user, and so-on.

For context that’s more localized, there’s a special enricher that can be added to enable the Log Context:

  .Enrich.FromLogContext()

Once the log context is enabled, a block of related messages can be tagged using the methods on the LogContext class:

using (LogContext.PushProperty("MessageId", GetCurrentMessageId()))
{
  Log.Information("Processing {OrderId}", message.Order.Id);

  // Later
  Log.Information("Order processing complete");
}

If we look at these logs in Seq, we’ll see an MessageId property attached to each event within the using block:

1-MessageId

This can be used as a filter, e.g. MessageId == 12345, to view the events raised when processing the message.

Contextual correlation is bread-and-butter stuff. If your application processes work asynchronously, you need to be able to filter down to a single task, and properties tagging events from a context make this as painless as possible.

It’s worth noting that contexts overlap – an event can belong to a thread as well as to a message. (This is one of the arguments for structured logs – it’s much easier to work with events with real, named properties than it is to devise readable, unambiguous ways to embed all of these into the format of a text log message.)

Setting up and using the log context does add some noise to application code, so it’s something to be used judiciously. To tag events for correlation without additional machinery, another technique is useful.

Lateral correlation

If you think about all the contexts in your running application, you might come up with a mental picture like this:

Contextual

The green lines show sequences of events tagged with the same RequestId property, while blue shows a MessageId property that might be added to events during back-end processing. There’s some simplification here, given the way contexts overlap, but essentially each context is a temporal sequence of correlated events.

When it comes time to use these logs however, scenarios frequently cross these little islands of navigability, so something else is needed.

Let’s say we’ve received an issue report tagged with an exception message. We find the exception using the text:

2-InvOrder

And then follow the MessageId contextual property to see what happened in the message handler that failed.

3-Mid

Now, we know somehow we were sent an order without any items – where did it come from? This is where a lateral correlation identifier comes in handy. The second event in the three above implements this:

Log.Information("Processing {OrderId}", message.Order.Id);

OrderId is a business-domain identifier included in the message itself that links the event across lines of causality to others related to the same order.

Once we jump across contexts using the OrderId:

4-Find

We can now see an event from the HTTP request that initiated the order.

5-Req

(A keen-eyed reader might note here that searching on ItemCount == 0 would have narrowed things down a little faster – but identifying this opportunity still requires some navigation through the logs from the point of failure too.)

Correlating by HTTP request Id we get all of the events from the request and should (on a real event stream) be able to get to the bottom of the issue:

6-Final

Patching this into our mental model, OrderId let us navigate laterally between the two sequences of events.

Lateral

Logging in two dimensions

Armed with a tool like structured logging that can easily be overused and create clutter, the last thing anyone wants to do is bung every possible property onto every event in an attempt ease diagnostics later on.

Keeping a clear distinction between the contextual and lateral correlation links makes it possible to navigate effectively through events raised by the app with a minimum of syntactic noise.

It turns out that in most situations I’ve encountered, architectural and infrastructural concerns dominate the notion of context. HTTP request id, thread id, message id – these are all mechanical concerns that get buried into plumbing and attached using enrichers or the log context. This is pretty convenient – the noisier APIs for adding contextual properties are best kept in infrastructural code when possible.

Identifiers from the business domain provide lateral navigation through logs – customer ids, order ids and the like – letting you skip between the various contexts in which an entity was referenced. Using structured logging these links can be created without much fanfare – just logging an event with the identifier in its message text is enough to make the connection.

It’s a simple perspective that helps me use structured logs more effectively, and it can be a nice foundation for guidelines shared with a team. If you use this strategy already, or another similar one, I’d love to hear more about your experiences!

Using Serilog with F# Discriminated Unions

Serilog

This week GitHub user vlaci called us out on awful F# support in Serilog. In their issue report they show how a nice clean discriminated union type like “Option” is represented hideously in structured data:

type Shape =
    | Circle of Radius : double
    | Rectangle of Width : double *  Height : double
    | Arc // ...
let shape = Circle 5.
Log.Information("Drawing a {@Shape}", shape)

Prints:

2015-01-14 16:52:06 [Information] Drawing a Circle { Radius: 5, Tag: 0, IsCircle:
   True, IsRectangle: False, IsArc: False }

The verbosity gets worse for types with more values.

I took this as a chance to crank up Visual Studio and get reacquainted with F#, using the example from @vlaci as a starting point. Using Serilog.Extras.FSharp you can now enjoy your discriminated unions encoded pleasantly like:

2015-01-14 16:58:31 [Information] Drawing a Circle { Radius: 5 }

Depending on the log storage you use you’ll be able to query on the tag as well as the fields (like Radius) from the union.

You can enable this by installing the package and adding Destructure.FSharpTypes() to your logger configuration:

open Serilog

[<EntryPoint>]
let main argv =

    Log.Logger <- LoggerConfiguration()
        .Destructure.FSharpTypes()
        .WriteTo.ColoredConsole()
        .CreateLogger()

    Log.Information("Drawing a {@Shape}", Circle 5.)

    0

Thanks again to vlaci for kicking this off. I was especially keen to see this in because I’m sure someone with better F# skills than mine can add a lot to the Serilog/F# experience. If you have ideas we’d love to hear from you on the project site!

Give your instrumentation some love in 2015!

This is the year for better instrumentation.

  • On premises, applications are more integrated, distributed and asynchronous than ever
  • The move to the cloud is driving architectures with fine-grained modularity and scale-out across many remote machines

If you still treat logging as an afterthought, operating and debugging apps in 2015 is looking like a nightmare.

Thankfully, tools and practices are catching up. And, just as it was with requirements, builds, testing and deployment, many improvements are coming from an integrated approach to what was once “somebody else’s problem” or a siloed responsibility.

If your instrumentation isn’t all it could be, here are three suggestions to get you off to a new start this year.

1. Take another look at Structured Logs

First, a new generation of tooling has come online. Text logs from distributed apps are an ergonomic disaster, requiring complex, cumbersome tools to manipulate in all but the most trivial scenarios, so alternatives have been baking away for a long time and are finally hitting the mainstream.

In .NET, we’ve got SLAB from Microsoft Patterns and Practices, and more recently the open-source Serilog, that make structured logging as quick, easy and painless to implement as text logging (think log4net, NLog) but with miraculous advantages when it comes time to consume events for diagnostic purposes.

Unlike text logs, when you write a structured log all of the data associated with an event are kept in a structured format (think “JSON document”) that can be rendered out to a more traditional text message, but also sorted, searched and filtered just like documents in a NoSQL database might be.

What’s the difference between this (log4net):

log.Warn("Cache reached {0} items", cache.Count);

And this? (Serilog):

log.Warning ("Cache reached {CacheSize} items", cache.Count);

To write, very little – and when viewed at the console, not much either. But with appropriate storage, the structured version supports filtering with queries like:

CacheSize > 1000

… and not a regex in sight.

With structured logs you can use clean data types and familiar operators to quickly answer questions that would be time-consuming and awkward using plain text.

If you’re not using structured logs already, give this technique a try this year – it’ll change the way you look at logs for the better.

2. Use Logs to validate new Behavior

Automated tests are great – they verify that a chunk of code in isolation does what you expect. If you’re like me though, you spend a good amount of time smoke testing your work by hand, too – putting features through their paces the old fashioned way and trying to break them.

While you do this, logs are a great way to peer into the internals of an application. Sometimes, below the surface, all is not what it seems – that warning you added: "This code should only be called on even numbered years"? Well, how do you know it isn’t triggering right now? Watching each step in a process logged out clearly is a great way to understand your system better, and it really does improve the quality of the code you check in.

Think about it this way – unit tests validate your expectations, but logs will show you things you didn’t expect.

For this strategy to be effective, you need to have logs written to a log viewer on your development machine. Console terminals and text files are under-powered and quickly become a blur when things heat up. There are lots of great tools for this; our log server Seq is free for development use, or check some of the other options you can find with a quick web search. What tooling you use is a secondary consideration though – the important thing is to make feedback from logs a first-class part of your basic development process.

And, here’s the trick: while you’re using logs in this way, you’re implicitly shaping them to be useful for diagnosing issues in production. If your logs show you clearly what’s happening during development, there’s a good chance they’ll be useful later down the track too.

3. Match Issues with relevant Logs

Here’s another great strategy I’ve seen used to brilliant effect.

When features are formally tested, pipe logs from the test environment to a log server. Whenever someone raises an issue, ask them to include a link to relevant events from the log. (This will quickly validate the quality of your error messages!)

For example, if the user is raising purchase order #12345, they can search the log from the test environment for “purchase order 12345” and should get relevant results that they can link to from an issue.

Again, here’s the trick: how will the tester always find relevant events, you ask? Well – that’s a good question! When a real customer hits an issue raising a PO, you’ll need to do the same thing. This makes test-time issues a drill for the real thing – one that validates the quality of your instrumentation and improves your readiness for dealing with issues in production.

As a bonus, you’ll soon be able to link to logs for issues in the production environment, too, which is absolutely golden if you’re the developer in the hot seat.

Conclusion

That’s it for this post. Three things you can try to get your instrumentation kicked off in the right direction this year:

  • Write structured logs
  • Use them to validate behavior during development
  • Link relevant logs from your test team’s issue reports

Once we take instrumentation back into the realm of our responsibility as developers and stop just throwing it over the wall, there are lots more interesting things to consider about writing smarter, more effective logs in the first place. I’d love to hear what works for you.

Uncorking the Seq API

The web interface of Seq connects to the server via a simple API using JSON/HTTP. (I’d call it REST, but it’s not fully IEEE 1337.00 REST-1.1 compliant ;-))

Quite a few customers integrate with the API, either for querying events or for automating administrative tasks like adding users, creating/modifying queries and views, etc.

Though it’s possible to just jump right in using JSON, it’s a pain to figure out the dynamic structure of the entities that are sent and received and hand-code C# types that serialize appropriately using JSON.NET.

To fix this, we just published the entire set of Seq API types, as well as higher-level wrappers, to the new seq-api project on GitHub and published via NuGet:

Install-Package Seq.Api

You can use the package to connect and work with items from your Seq instance:

var connection = new SeqConnection("http://my-seq/prd");

var views = await connection.Views.ListAsync();
foreach (var view in views)
{
  Console.WriteLine(view.Title);
}

Things should be pretty self-explanatory – just dot your way through the properties on SeqConnection to find your way around.

As a brand new project we fully expect some rough edges in there, for example you may need to upgrade to Seq 1.6.7 in order for some features to work. You can already do some interesting things with it though!

The seq-tail.exe app that’s included as a sample in the repository implements something like the Unix tail for logs from your remote Seq server.

seq-tail

Syntax is:

seq-tail.exe <server> [--filter=<f>] [--apikey=<k>] [--window=<w>]

(Nerdy note – if you haven’t seen docopt.net in action before, check out how the command-line parsing in the example works.)

Now that the API is published I’m looking forward to actively improving it – it’s crying out for some Rx love, for starters. If you crank it up I’d love to hear about your experiences.

Viewing logs from C# mobile apps

I’ve recently been writing some code for Windows Phone, cross-compiled for iOS and Android using the Xamarin tools.

The app does quite a lot of background processing, but during development and testing it started to feel like a black box. A few lines of code got events posting from Serilog via HTTP to a Seq instance running on my development machine.

I liked the results so much tonight I decided make a quick experimental port of Serilog.Sinks.Seq to a portable class library:

Seq.Client.Portable

You can install it in your Windows Phone or Xamarin project directly from NuGet:

Install-Package Seq.Client.Portable

Configure the logger in portable code:

Log.Logger = new LoggerConfiguration()
  .WriteTo.SeqPortable("http://169.254.80.80:5341")
  .CreateLogger();

And write log messages from your mobile app straight back to Seq running on your development machine:

Log.Information("Hello, Seq!");

Single-user installs of Seq are free, so you can use this during development even if your team uses something else for production logging.

Emulator Networking

You’ll need to use the address of your development machine assigned by the emulator – don’t try connecting to Seq as localhost – this will loop back to the emulator itself. Windows Phone lets me get at my desktop via "http://169.254.80.80:5341" while Android works with "http://10.0.2.2:5341". (5341 is the default port Seq listens on.)

I haven’t tested this on iOS yet – it’s possible you’ll find issues there if you beat me to it.

Why ‘Experimental’?

It’s somewhat uncharted territory for me – Serilog is still working the last kinks out of iOS/Android support, and the Serilog features that the sink relies on aren’t all portable because of missing features like System.Threading.Timer. Eventually I hope the code here can be feed back into Serilog and improve this.

Where’s the code?

Here, on GitHub. Please send a PR if you find any improvements to make. Enjoy!

Dynamically changing the Serilog level

In the Serilog project we’re frequently asked how to adjust the logging level at runtime, and until recently we haven’t had a great answer.

Many larger/distributed apps need to run at a fairly restricted level of logging, say, Information (my preference) or Warning, and only turn up the instrumentation to Debug or Verbose when a problem has been detected and the overhead of collecting a bit more data is justified.

Setting the level to its minimum (Verbose) and dynamically filtering events has been our suggestion so far, and it does save on network or disk I/O bandwidth, but the overhead of generating the events in the first place is still a significant consideration.

In Serilog 1.4.11, there’s a new type, LoggingLevelSwitch that provides this feature with very minimal performance overhead.

Using LoggingLevelSwitch

If an app needs dynamic level switching, the first thing to create is an instance of this type:

var levelSwitch = new LoggingLevelSwitch();

You need to keep the switch around in an accessible place.

This object defaults the current minimum level to Information, so if you want to be more restricted, set its minimum level up-front:

levelSwitch.MinimumLevel = LogEventLevel.Warning;

Now, when configuring the logger, provide the switch using MinimumLevel.ControlledBy():

var log = new LoggerConfiguration()
  .MinimumLevel.ControlledBy(levelSwitch)
  .WriteTo.ColoredConsole()
  .CreateLogger();

Now, events written to the logger will be filtered according to the switch’s MinimumLevel property.

If you need to turn the level up or down at runtime, perhaps in response to a command sent over the network, it’s as easy as:

levelSwitch.MinimumLevel = LogEventLevel.Verbose;

log.Verbose("This will now be logged");

Querying collection properties in Seq 1.5

Seq implements a filtering syntax that’s loosely based on C#. The following expression matches the events you’d expect it to, if you’re used to working with C# or a similar language:

Tag == "seq"

Which is to say: “Match events where the Tag property has the value "seq". Sub-properties of objects can be accessed using the familiar dotted syntax (Property.Subproperty.Subproperty) and so-on.

Seq 1.5, currently a preview, steps into some new territory.

What about a collection of tags?

It’s not uncommon for Serilog events to carry properties that are collections. For example we might log events on a Q&A site like:

Log.Information("User {Username} posted a question tagged {Tags}", username, tags);

Resulting in events like:

Event with Collection Property

Instead of being marked with a single tag, each event carries a collection of zero-or-more.

Matt Hamilton asks:

This is where Seq 1.4 draws a blank. Translating this to the Q&A example, about the best we can manage is a text search for "seq" and requiring the existence of the Tags property using Has(Tags).

This is a bit of a shame – the promise of Seq and structured logging in general is to make querying log events precise – so why aren’t collections covered?

The C# way

Seq isn’t only about precise queries; the whole foundation of the app is the idea that it should also be easy and natural to query log data.

I’d thought about collection queries quite a lot when putting the original filtering syntax together. C#-style the query would look something like:

Any(Tags, tag => tag == "seq")

Seq doesn’t use extension method-style calls, but this is pretty close to the Enumerable.Any() call you’d write using Linq.

I don’t like it!

In a full-featured programming language this syntax makes sense, but it’s too noisy, complex, and easy to mistype to make a good filtering syntax for Seq. And so, that’s where things have sat for the last twelve months.

Pattern matching

With a bit more thought, Matt and I both ended up thinking the problem might be better suited to a pattern-matching syntax like:

Tags[?] == "seq"

So, this is what Seq 1.5 provides. The question mark wildcard ? matches any element in the collection, while an asterisk * wildcard only matches if all elements satisfy the condition.

Questions tagged seq

Wildcards work in any comparison where one side is a property path (including indexers and dotted sub-properties). Multiple wildcards along the path are supported.

You can write the following expression to find questions where all answers are "Yes!":

Answers[*].Content == "Yes!"

(Under the hood, Seq rewrites these expressions into the equivalent lambda-style syntax – much the same way as the C# compiler transforms Linq query comprehensions. Working through implementing this reminded me just how fantastic the C# compiler really is!)

Try it out!

You can download a preview build of Seq 1.5 here. It’s not ready for production use yet, but should be just fine for dev/non-mission-critical servers. We’d love to hear what you think!

How (not) to parameterize Serilog events

Writing an event with Serilog is just like formatting a string:

Log.Information("The time is {Time}", DateTime.Now);

There’s one subtle and important difference though. The first parameter to Information(), here given the value "The time is {Time}" isn’t just an arbitrary string – it’s a Serilog message template.

You might be tempted occasionally to write events like:

Log.Information("The time is " + DateTime.Now);

Don’t do this. While never particularly good logging practise (the string concatenation occurs regardless of whether logging is enabled or not, wasting RAM and CPU cycles), with Serilog this is strongly considered an anti-pattern.

Why an anti-pattern?

The first example, using Serilog correctly, creates events that are logically like:

{
  "MessageTemplate": "The time is {Time}",
  "Properties": { "Time": "2014-09-11T09:35.55.000" }
}

The second, incorrect example will yield:

{
  "MessageTemplate": "The time is 2014-09-11T09:35.55.000",
  "Properties": {}
}

While you might not notice the difference initially when logging to the console or a text file, the first event is much more useful than the second:

  • Time is stored as a queryable property
  • All events of this type share the same message template, making the events queryable by type as well

Serilog is also optimised for creating well-formed events like the first one; while the second example won’t blow up, since each event has a unique “template” it will not take advantage of message template caching, requiring the message to be parsed each time. The extra junk in the message template cache will eventually cause the cache to flush, reducing logging performance throughout the app.

Be on the lookout…

There are a few ways your code can fall into this trap. Here’s (a simplification of) one that got me recently:

catch (Exception ex)
{
  Log.Error(ex.Message);
}

It’s a bit harder to spot the logging of an arbitrary string here, but like the broken example above, this will generate a potentially-unique template for every message.

(In case you’re wondering, the recommended way to log an exception with Serilog is:

catch (Exception ex)
{
  Log.Error(ex, "Failed while trying to open the database");
}

The exception will be attached to the event as a first-class property, and fully-rendered in both text and JSON… Easy!)

Event = Template + Properties

Just remember, a Serilog event isn’t a string – it’s the combination of a message template and zero-or-more properties.

Thinking this way will help you get more value out of Serilog as your application grows and you start to consider more advanced storage/querying options. Happy logging!

Seq 1.5 preview

TL;DR: The next point release of Seq is a bit broader in scope than what we’ve shipped in previous point releases. Storage and caching changes in Seq 1.5 bring some noticeable improvements to performance, responsiveness and manageability.

Since Seq first arrived a year ago, its storage has been a simple b-tree based data file managed by ESENT. This had pros as well as cons: on the pro-side, we’ve been able to keep our efforts focused on making Seq quick to set up and easy to use while ESENT does its thing keeping data safe and accessible on disk.

This approach has taken us a long way, but coupled with the particular access patterns generated by log data, it does lead us to some cons, the biggest of which we’re addressing in Seq 1.5.

Query performance and cache efficiency

In Seq 1.4, we left caching decisions to ESENT – what to cache, when to expire it, and how much RAM to use in the process. For the most part this did a fine job, but it left a couple of important opportunities on the table.

Segmented caching

Log data has a very specific access pattern: recent events are always more interesting than historical ones. A couple of queries deep into history shouldn’t cause more recent events to be purged from cache. Recently-written events should get to the cache before needing queries to “warm them up” and so-on.

In 1.5, Seq keeps a time-ordered list of cached event segments. Each segment is a time slice – the preview uses 1-day slices as the unit of granularity. As RAM fills up, segments are dropped from the end of the list, preserving more recent events.

Cache

It’s a very simple strategy, but an effective one – response times on queries improve dramatically when all data is in cache, and most queries of interest are filled by recent events.

Naturally, response time drops as the query progresses into un-cached regions of storage. Our current “usability benchmark” is to consider a million 1 KB events generated per day. On a 16 GB server, around a week’s data will be cacheable, and response time on this will be within a few seconds. Most Seq installations carry a lot fewer events and so will run completely in RAM.

Past the cache bounds, “archival” data is available at a response time a couple of orders of magnitude below this. Optimally, a retention policy will thin out the events past this point, e.g. by deleting “debug” or tracing events, thus bringing response times back up within a similar range.

Optimal in-memory representation

Using the storage layer’s cache meant Seq still had quite a bit of work to do when scanning events to fulfil query results. This work not only added to response time – it also generated garbage that pushed the GC harder, reducing overall performance.

Since we’re now in control of our own caching destiny, in Seq 1.5 we’re free to choose an in-memory representation that’s much closer to our needs when querying. This eliminates all JSON processing and allocation on a per-event basis, and makes it possible to run practically all queries in compiled code.

Schema-sharing

The most exciting outcome of choosing our own in-memory representation is the opportunity we then have to extract common features from events.

When caching raw event data at the storage layer, each “blob” is unique – property names and so-on get stored for every event. If two events are created by the same line of code, thus having the same property names and message template, the storage layer will record two copies of this information.

In RAM, we’re free to share schema information and duplicated values between many events. While the following two events share nothing on disk:

{"Latitude": 25, "Longitude": 134}
{"Latitude": 12, "Longitude": 54}

In the Seq caching layer they’ll share a single schema object:

Schema

Over many events the savings brought by this approach are significant.

Manageability

Using a single, large data file brought with it a couple of major drawbacks.

Sheer size

First, storing everything in a single large file makes it hard to work with large Seq installations. One user ended up with a single 350 GB default.seq that was impossible to work with in any way. We don’t want to see that again!

In Seq 1.5, files on disk are split into 7-day extents:

Storage

The extents are completely self-contained, meaning they can be deleted, moved or backed-up individually.

Compaction time

ESENT data files can only be compacted (shrunk to remove free space) off-line. Coupled with creating a very large data file, this could mean considerable downtime while disk space was reclaimed, and having to use command-line tools to do it was inconvenient.

Compaction would also require enough free disk space to hold a complete copy of the data – a challenge and a waste when a lot of event data is stored.

Using a series of extents on disk means that segments can be compacted one at a time, ideally in the background on a running server, and only the storage for a single extent is required during the compaction process.

The 1.5.5-pre build still relies on a command-line seq compact facility, but storage requirements are lessened and the process is much more responsive. We’ll be working on background compaction for the next preview.

Installing Seq 1.5.5-pre

There are a few things to know before you upgrade to Seq 1.5.5-pre.

The migration process requires approximately the same disk space as is taken by the existing C:\ProgramData\Seq\Data folder. Seq will refuse to migrate or run without this available. After migration is run, the space will be freed and won’t be needed again except to store events.

Running the following commands prior to migration will free as much space as possible for the process:

seq stop
seq compact

Migration from a large Seq 1.4 database can also take considerable time – allowing 10 minutes per million events would give a safe margin; better hardware will move data much faster. If this makes migration prohibitive, and you can’t use retention policies to cut down on event volume beforehand, please email support for help.

After migration completes, it will take a little while for the cache to warm up. If you see an asterisk (*) after the Loading… indicator text, this means events are being scanned in un-cached storage regions. Give it a few more minutes :).

Finally, the new cache is designed for server use and thus consumes as much system memory as it can. If the system comes under memory pressure, it will release memory to compensate. This mightn’t be convenient on all systems – if you’re in this position we’d like to know a bit more about your setup: email us at the address above and we’ll let you know when configuration options are available to control this.

What else is to come from 1.5?

Already included in the current preview are some major improvements to start-up/shut-down time, and some long overdue features such as manual deletion of events. There are several other tickets planned for the full release, and I’ll post some details on those as they land.

How does 1.5.5-pre work for you?

We haven’t published any figures with this post; when Seq 1.5 is ready to ship I’ll make sure we share some 1.4 vs. 1.5 benchmarks, but for the time being we’re looking for real-world usage and feedback to validate the direction we’re taking and provide a qualitative measure of how the changes stack up.

If you’re able to try Seq 1.5, we’d love to hear your impressions. It’s not a production-ready release, but we’ll do our very best to support migration from the preview to RTW when that happens (we’ve migrated our own servers!) so with some small risk it should be fine to use on dev/non-mission-critical systems.

Download it now!

You can grab the installer here.