Category Archives: General

Handling times for an EV charger

This morning (October 30th 2022), the clocks went back in the UK – the time that would have been 2am fell back to 1am. This is just the regular “fall back” transition – there’s nothing special about it.

As it happens, I’d driven my electric car for quite a long journey yesterday, so I had it plugged in to charge overnight… and that’s where things get interesting.

My electricity tariff is called Octopus Go, which is designed for electric vehicle owners. Any electricity I use between 12:30am and 4:30am is significantly cheaper than at other times. I use a PodPoint charger, which allows me to control when the car will charge via an app. For each day of the week, there’s a start time and an end time – the charger turns on at the start time, and off at the end time. (If the car isn’t plugged in while it’s “on”, that’s fine. Likewise if the car finishes charging, it will stop drawing power.) Unsurprisingly, I have my schedule set for 12:30am to 4:30am every day. (If I know I need more charge than 4 hours provides, I tweak the schedule and then set it back.) The app looks like this:

PodPoint scheduling

Normally, that schedule will get me 4 hours of charging. But this morning was special due to the clocks going back… and I didn’t know what would happen. If the charger handled the schedule as “if the local time is between 12:30am and 4:30am, then the charger should be on” then it should charge for 5 hours:

  • It would charge for 1 1/2 hours between 12:30am and 2am
  • Local time would fall back to 1am
  • It would charge for 3 1/2 hours between 1am (the second occurrence of 1am!) and 4:30am

Assuming that happened, what rate would Octopus charge me for these 5 hours? The same logic should mean the whole charging period is on the cheap tariff… but would something go wrong?

I was geekily excited by all this and tweeted as much:

Exciting experiment tonight! I have my electric car charger set to charge between 00:30 and 04:30, as that’s when I get cheap electricity. The clocks go back (2:00 to 1:00) tonight. So: a) will I get 5 hours of charging? b) will all of it be at the cheap rate? Enquiring minds etc

What actually happened?

The car definitely charged for 5 hours. The PodPoint app shows each charging session, as shown in the screenshot below. (The session only ends when I remove the cable from the car, but the charging duration is measured separately.)

PodPoint charging session

The price there is only what PodPoint thinks I’ll be charged. Octopus makes data available the day after, but I’ll be checking three things when they do:

  • How today is represented in the CSV file you can download from them
  • How today is represented in the web graphs of usage
  • How much the electricity actually cost me

(I’m fairly convinced it will all be cheap, but it’ll be good to check.)

What should the code for an EV charger look like?

I had various responses to my tweet, including at least a few people informing me that the industry standard approach to time zone handling is to convert everything to UTC internally and only convert to local time for display purposes. Those responses are the reason for this blog post… because in my view, that’s absolutely the wrong way to treat this situation.

If you haven’t previously read my post on why storing UTC is not a silver bullet you may wish to do so, and my objections this time aren’t entirely unrelated, but it’s not quite the same thing. In particular, the problems with using a conversion to UTC have nothing to do with time zone rules changing in the future.

Let’s consider the information we have here:

  • The charging schedule is expressed in local start/end times on a per-day-of-week basis, e.g. “Monday: 00:30 to 04:30”. Note that there are no dates here; just days of the week and local times.
  • The charger needs to know the current local date and time. Typically (but not necessarily) that will mean:
    • The charger knows the current instant in time (i.e. it has a system clock)
    • The charger knows the “target” time zone for which the schedule should be applied (e.g. Europe/London)
    • The charger knows the rules for that time zone

My immediate question to the proposal of “the charger should convert everything to UTC” is to ask what that even means, given the information above. Knowing that the time zone is Europe/London, how does one convert a schedule entry of “Monday: 00:30 to 04:30” to UTC? A conversion to UTC is normally for a local date and time in a particular time zone to an instant in time. Here we don’t have a local date and time; we have a day of the week and a time. In Europe/London, “Monday” will sometimes have a UTC offset of +00, and sometimes have an offset of +01. (And “Sunday” can vary over the course of the day – as it would today, starting off with a UTC offset of +01 and ending with a UTC offset of +00.)

The next question would involve dealing with ambiguity and skipped times. Suppose my schedule for Sunday was Start=01:15, End=01:45. Assuming the conversion code was pinned to a specific date, how would those be converted into UTC today, when each of those times occurs twice? What about on March 27th 2022, when those times didn’t occur at all due to a “spring forward” from 1am to 2am?

Finally, I would ask where the requirement to convert to UTC came from. Is this thinking through the requirements, or just applying received wisdom of “always convert everything to UTC”?

Slightly generalizing my earlier statement, I would probably write the requirement as:

The charger status (on or off) is determined by the charging schedule, applied to the current local date and time. The charger should be “on” if the current local time is between the start and end time in the schedule for the current local day-of-week.

That doesn’t require any conversion to UTC. It doesn’t even require that the system is aware of the current instant in time at all – it only needs to know the current local date and time, because that’s the context in which the requirements are expressed.

So how do we know when to turn the charger on or off? If we cared about turning on and off at exactly the right time, we’d probably want to work out the duration between now and the next change – and that probably would involve conversions to UTC. But that’s unecessary. The way I’d write this would be to just have an infinite loop, checking whether the charger should be on or not, then sleeping for a bit. (That could be sleeping for 1 second, 10 seconds, a minute or even 5 minutes.)

I’ve created “somewhat pseudo-code” (it’s valid C#, it compiles, and would work – but there’s no application hooked up to use the library) for this in my GitHub demo repo, but the most important aspects are discussed below. I should note that there are no tests, and it isn’t designed to handle:

  • Changes to the time zone database
  • Changes to the target time zone
  • Changes to the schedule
  • Shutdown requests
  • Handling schedules where Start is later than End (e.g. to have a schedule of “11pm to 2am”)
  • Handling an end time of “midnight” in a schedule

None of these would be hard to handle (and the first three would be much harder to handle in any system that started from a position of “convert everything to UTC) but would be distractions from the main business of “how should the conversions work”.

The main loop is in EvChargerController, which is reproduced in its entirety below (other than comments; see the full code for the comments):

using Microsoft.Extensions.Logging;
using NodaTime;
using NodaTime.Text;

namespace EvChargerTiming;

public class EvChargerController
{
    private readonly DateTimeZone zone;
    private readonly IClock clock;
    private readonly ChargingSchedule schedule;
    private readonly EvCharger charger;
    private readonly ILogger logger;

    public EvChargerController(EvCharger charger, ChargingSchedule schedule, DateTimeZone zone, IClock clock, ILogger logger)
    {
        this.charger = charger;
        this.schedule = schedule;
        this.zone = zone;
        this.clock = clock;
        this.logger = logger;
    }

    public void MainLoop(TimeSpan pollingInterval)
    {
        while (true)
        {
            Instant now = clock.GetCurrentInstant();
            ZonedDateTime nowInTimeZone = now.InZone(zone);

            bool shouldBeOn = schedule.IsChargingEnabled(nowInTimeZone.LocalDateTime);
            if (charger.On != shouldBeOn)
            {
                logger.LogInformation("At {now} ({local} local), changing state to {state}",
                    InstantPattern.ExtendedIso.Format(now),
                    ZonedDateTimePattern.GeneralFormatOnlyIso.Format(nowInTimeZone),
                    shouldBeOn);

                charger.ChangeState(shouldBeOn);
            }

            Thread.Sleep(pollingInterval);
        }
    }
}

The only conversion involved is from the current instant in time to the local time in the target time zone. That’s much easier than converting from a local time into an instant, because there’s no scope for ambiguity or skipped values. The result of the conversion is used immediately rather than stored, which means we don’t need to worry about what data going stale if the time zone rules change.

I do use the instant when logging – in reality, I’d expect the logging infrastructure to log the instant at which the log entry is created, but I thought I’d demonstrate that it’s potentially useful to specify the instant and the result of the conversion. (As it happens, ZonedDateTimePattern.GeneralFormatOnlyIso includes the the UTC offset anyway, so the instant could be inferred from that, but hey.)

The ChargingSchedule type used by EvChargerController is even simpler. Again, I’ve cut the comments out – the full code has comments.

using NodaTime;

namespace EvChargerTiming;

public record ChargingScheduleDay(IsoDayOfWeek DayOfWeek, LocalTime Start, LocalTime End)
{
    public bool Contains(LocalTime now) =>
        Start <= now && now < End;
}

public class ChargingSchedule
{
    private readonly List<ChargingScheduleDay> days;

    public ChargingSchedule(List<ChargingScheduleDay> days)
    {
        this.days = days;
    }

    public bool IsChargingEnabled(LocalDateTime dateTime)
    {
        var day = days.Single(candidate => candidate.DayOfWeek == dateTime.DayOfWeek);
        return day.Contains(dateTime.TimeOfDay);
    }
}

The key part here is the signature of the sole method within ChargingSchedule:

public bool IsChargingEnabled(LocalDateTime dateTime)

From the perspective of turning the charger on and off, all we need to know is whether or not it should be on at a particular local date and time – which maps precisely onto the requirements.

Everything else derives from that requirement – and as you can see, the implementation is really trivial. There are basically three lines of “real code”, and they’re very easily testable.

Conclusion

When working with a date/time challenge, the first response should be “I need specific and clear requirements” rather than “we should use UTC”. Let the requirements drive the code. In this particular case, all the data is inherently “local”, and we never want to store any instants in time, so the conventional wisdom of converting to UTC really doesn’t help.

I’d also note that it’s a lot easier to spot that only the local date/time is relevant when using Noda Time than it would have been with the .NET built-in types – a signature of IsChargingEnabled(DateTime dateTime) would have needed more careful documentation to explain its intention.

Finally, remember that conversions from an instant in time to a local date/time are generally simpler than the other way round, as they’re always unambiguous. The solution above never needs to convert in the other direction, so we never need to make any decisions of how to handle ambiguous or skipped values.

None of this is intended to imply that you should never use UTC. When storing current/past timestamps (rather than user data) I’d almost always use UTC. But user data itself is rarely expressed in UTC, and sometimes (as here) we never need to do a conversion to UTC in order to process the data – if you don’t need to convert it, why would you do so?

Posting to wordpress.com in code

History

I started blogging back in 2005, shortly before attending the only MVP summit I’ve managed to go to. I hosted the blog on msmvps.com, back when that was a thing.

In 2014 I migrated to wordpress.com, in the hope that this would make everything nice and simple: it’s a managed service, dedicated to blogging, so I shouldn’t have to worry about anything but the writing. It’s not been quite that simple.

I don’t know when I started writing blog posts in Markdown instead of using Windows Live Writer to create the HTML for me, but it’s definitely my preferred way of writing. It’s the format I use all over the place, it makes posting code easy… it’s just “the right format” (for me).

Almost all my problems with wordpress.com have fallen into one of two categories:

  • Markdown on WordPress (via JetPack, I believe) not quite working as I expect it to.
  • The editor on wordpress.com being actively hostile to Markdown users

In the first category, there are two problems. First, there’s my general annoyance at line breaks being relevant outside code. I like writing paragraphs including line breaks, so that the text is nicely in roughly 80-100 character lines. Unfortunately both WordPress and GitHub decide to format such paragraphs as multiple short lines, instead of flowing a single paragraph. I don’t know why the decision was made to format things this way, and I can see some situations in which it’s beneficial (e.g. a diff of “adding a single word” showing as just that diff rather than all the lines in the paragraph changing) but I mostly dislike it.

The second annoyance is that angle brackets in code (either code fences or just in backticks) behave unpredictably in WordPress, in a way that I don’t remember seeing anywhere else. The most common cause of having to update a post is to fix some generics in C# code, mangling to Markdown to escape the angle brackets. One of these days I may try to document this so that I can get it right in future posts, but it’s certainly a frustration.

I don’t expect to be able to do anything about either of these aspects. I could potentially run posts through some sort of preprocessor, but I suspect tha unwrapping paragraphs but not code blocks could get fiddly pretty fast. I can live with it.

The second category of annoyance – editing on wordpress.com – is what this post is mostly about.

I strongly suspect that most bloggers want a reasonably-WYSIWYG experience, and they definitely don’t want to see their post in its raw, unformatted version (usually HTML, but Markdown for me). For as long as I can remember, there have been two modes in the wordpress.com editor: visual and text. In some cases just going into the visual editor would cause the Markdown to be converted into HTML which would then show up in the text editor… it’s been fiddly to keep it as text. My habit is to keep a copy of the post as text (originally just in StackEdit but now in GitHub) and copy the whole thing into WordPress any time I wanted to edit anything. That way I don’t really care what WordPress does with it.

However, wordpress.com have now made even that workflow even harder – they’ve moved to a “blocks” editor in the easy-to-get-to UI, and you can only get to the text editor via the admin UI.

I figured enough was enough. If I’ve got the posts as text locally (then stored on GitHub), there’s no need to go to the wordpress.com UI for anything other than comments. Time to crack open the API.

What no .NET package?

WordPress is a pretty common blogging platform, let’s face it. I was entirely unsurprised to find out that there’s a REST API for it, allowing you to post to it. (The fact that I’d been using StackEdit to post for ages was further evidence of that.) It also wasn’t surprising that it used OAuth2 for authentication, given OAuth’s prevalance.

What was surprising was my inability to find any .NET packages to let me write a C# console application to call the API with really minimal code. I couldn’t even find any simple “do the OAuth dance for me” libraries that would work in a console application rather than in a web app. RestSharp looked promising, as the home page says “Basic, OAuth 1, OAuth 2, JWT, NTLM are supported” – but the authentication docs could do with some love, and looking at the source code suggested there was nothing that would start a local web server just to receive the OAuth code that could then be exchanged for a full auth token. (I know very little about OAuth2, but just enough to be aware of what’s missing when I browse through some library code.) WordPressPCL also looked promising – but requires JWT authentication, which is available via a plugin. I don’t want to upgrade from a personal wordpress.com account to a business account just for the sake of installing a single plugin. (I’m aware it could have other benefits, but…)

So, I have a few options:

  • Upgrade to a business account, install the JWT plugin, and try to use WordPressPCL
  • Move off wordpress.com entirely, run WordPress myself (or find another site like wordpress.com, I suppose) and make the JWT plugin available, and again use WordPressPCL
  • Implement the OAuth2 dance myself

Self-hosting WordPress

I did toy with the idea of running WordPress myself. I have a Google Kubernetes Engine cluster already, that I use to host nodatime.org and some other sites. I figured that by now, installing WordPress on a Kubernetes cluster would be pretty simple. It turns out there’s a Bitnami Helm chart for it, so I decided to give that a go.

First I had to install Helm – I’ve heard of it, but never used it before. My first attempt to use it, via a shell script, failed… but with Chocolatey, it installed okay.

Installing WordPress was a breeze – until it didn’t actually work, because my Kubernetes cluster doesn’t have enough spare resources. It is a small cluster, certainly – it’s not doing anything commercial, and I’m paying for it out of my own pocket, so I try to keep the budget relatively low. Apparently too low.

I investigated how much it might cost to increase the capacity of my cluster so I could run WordPress myself, and when it ended up being more expensive than the business account on wordpress.com (even before the time cost of maintaining the site), I figured I’d stop going down that particular rabbit hole.

Implementing OAuth2

In the end, I really shouldn’t have been so scared of implementing the OAuth2 dance myself. It’s not too bad, particularly when I’m happy to do a few manual steps each time I need a new token, rather than automating everything.

First I had to create an “application” on wordpress.com. That’s really just a registration for a client_secret and client_id, along with approved redirect URIs for the OAuth dance. I knew I’d be running a server locally for the browser to redirect to, so I allowed http://127.0.0.1:8080/auth as a redirect URI, and created the app appropriately.

The basic flow is:

  • Start a local web server to receive a redirect response from the WordPress server
  • Visit a carefully-constructed URL on WordPress in the browser
  • Authorize the request in the browser
  • The WordPress response indicates a redirect to the local server, that includes a code
  • The local server then exchanges that code for a token by making another HTTP request to the WordPress server
  • The local server displays the access token so I can copy and paste it for use elsewhere

In a normal application the user never needs to see the access token of course – all of this happens behind the scenes. However, doing that within my eventual “console application which calls the WordPress API to create or update posts” would be rather more hassle than copy/paste and hard-coding the access token. Is this code secure, if it ever gets stolen? Absolutely not. Am I okay with the level of risk here? Yup.

So, what’s the simplest way of starting an HTTP server in a standalone app? (I don’t need this to integrate with anything else.) You could obviously create a new empty ASP.NET Core application and find the right place to handle the request… but personally I reached for the .NET Functions Framework. I’m clearly biased as the author of the framework, but I was thrilled to see how easy it was to use for a real task. The solution is literally a single C# file and a project file, created with dotnet new gcf-http. The C# file contains a single class (Function) with a single method (HandleAsync). The C# file is 50 lines of code in total.

Mind you, it still took over an hour to get a working token that was able to create a WordPress post. Was this due to intricacies of URL encoding in forms? No, despite my investigations taking me in that direction. Was it due to needing to base64 encode the token when making a request? No, despite many attempts along those lines too.

I made two mistakes:

  • In my exchange-code-for-token server, I populated the redirect_uri field in the exchange request with "http://127.0.0.1/auth" instead of "http://127.0.0.1:8080/auth"
  • In the test-the-token application, I specified a scheme of "Basic" instead of "Bearer" in AuthenticationHeaderValue

So just typos, basically. Incredibly frustrating, but I got there.

As an intriguing thought, now I’ve got a function that can do the OAuth dance, there’s nothing to stop me deploying that as a real Google Cloud Function so I could get an OAuth access token at any time just by visiting a URL without running anything locally. I’d just need a bit of configuration – which ASP.NET Core makes easy, of course. No need to do that just yet.

Posting to WordPress

At this point, I have a test application that can create a WordPress post (as Markdown, importantly). It can update the post as well.

The next step is to work out what I want my blogging flow to be in the future. Given that I’m storing the blog content in GitHub, I could potentially trigger the code from a GitHub action – but I’m not sure that’s a particularly useful flow. For now, I’m going to go with “explicitly running an app when I want to create/update a post”.

Now updating a post requires knowing the post ID – which I can get within the WordPress UI, but I also get when creating the post in the first place. But I’d need somewhere to store it. I could create a separate file with metadata for posts, but this is all starting to sound pretty complex.

Instead, my current solution is to have a little metadata “header” before the main post. The application can read that, and process it appropriately. It can also update it with the post ID when it first creates the post on wordpress.com. That also avoids me having to specify things like a title on the command line. At the time of writing this, this post has a header like this:

title: Posting to wordpress.com in code
categories: C#, General
---

After running my application for the first time, I expect it to be something like this:

postId: 12345
title: Posting to wordpress.com in code
categories: C#, General
---

The presence of the postId field will trigger the app to use “update” instead of “create” next time I ask it to process this file.

Will it work? I’ll find out in just a few minutes. This code hasn’t been run at all yet. Yes, I could write some tests for it. No, I’m not actually going to write the tests. I think it’ll be just as quick to iterate on it by trial and error. (It’s not terribly complicated code.)

Conclusion

If you can see this post, I have a new process for posting to my blog. I will absolutely not create this post manually – if the code never works, you’ll never see this text.

Is this a process that other people would want to use? Maybe, maybe not. I’m not expecting to open source it. But it’s a useful example of how it really doesn’t take that much effort to automate away some annoyance… and I was able to enjoy using my own Functions Framework for realsies, which is a bonus :)

Time to post!

Travis logs and .NET Core console output

This is a blog post rather than a bug report, partly because I really don’t know what’s at fault. Others with more knowledge of how the console works in .NET Core, or exactly what the Travis log does, might be able to dig deeper.

TL;DR: If you’re running jobs using .NET Core 3.1 on Travis and you care about the console output, you might want to set the TERM environment variable to avoid information being swallowed.

Much of my time is spent in the Google Cloud Libraries for .NET repository. That single repository hosts a lot of libraries, and many of the pull requests are from autogenerated code where the impact on the public API surface may not be immediately obvious. (It would be easy to miss one breaking change within dozens of comment changes, for example.) Our Travis build includes a job to work out the public API changes, which is fantastically useful. (Example)

When we updated our .NET Core SDK to 3.1 – or at least around that time; it may have been coincidence – we noticed that some of the log lines in our Travis jobs seemed to be missing. They were actually missing from all the jobs, but it was particularly noticeable for that “change detection” job because the output can often be small, but should always contain a “Diff level” line. It’s really obvious when that line is missing.

I spent rather longer trying to diagnose what was going wrong than I should have done. A colleague noted that clicking on “Raw log” showed that we were getting all the output – it’s just that Travis was swallowing some of it, due to control characters being emitted. This blog post is a distillation of what I learned when trying to work out what was going on.

A simple set of Travis jobs

In my DemoCode repository I’ve created a Travis setup for the sake of this post.

Here are the various files involved:

.travis.yml:

dist: xenial  

language: csharp  
mono: none  
dotnet: 3.1.301  

jobs:  
  include:  
    - name: "Default terminal, no-op program"  
      script: TravisConsole/run-dotnet.sh 0  

    - name: "Default terminal, write two lines"  
      script: TravisConsole/run-dotnet.sh 2  

    - name: "Mystery terminal, no-op program"  
      env: TERM=mystery  
      script: TravisConsole/run-dotnet.sh 0  

    - name: "Mystery terminal, write two lines"  
      env: TERM=mystery  
      script: TravisConsole/run-dotnet.sh 2  

    - name: "Mystery terminal, write two lines, no logo"  
      env: TERM=mystery DOTNET_NOLOGO=true  
      script: TravisConsole/run-dotnet.sh 2

TravisConsole/run-dotnet.sh:

#!/bin/bash  

set -e  

cd $(readlink -f $(dirname ${BASH_SOURCE}))  

echo "Before dotnet run (first)"  
dotnet run -- $1  
echo "After dotnet run (first)"  

echo "Before dotnet run (second)"  
dotnet run -- $1  
echo "After dotnet run (second)"

TravisConsole/Program.cs:

using System;  

class Program  
{  
    static void Main(string[] args)  
    {  
        int count = int.Parse(args[0]);  
        for (int i = 1; i <= count; i++)  
        {  
             Console.WriteLine($"Line {i}");  
        }  
    }  
}

So each job runs the same .NET Core console application twice with the same command line argument – either 0 (in which case nothing is printed out) or 2 (in which case two it prints out “Line 1” then “Line 2”). The shell script also logs before and after executing the console application. The only other differences are in terms of the environment variables:

  • Some jobs use TERM=mystery instead of the default
  • The final job uses DOTNET_NOLOGO=true

I’ll come back to the final job right at the end – we’ll concentrate on the impact of the TERM environment variable first, as that’s the main point of the post. Next we’ll look at the output of the jobs – in each case showing it in the “pretty” log first, then in the “raw” log. The pretty log has colour, and I haven’t tried to reproduce that. I’ve also only shown the relevant bit – the call to run-dotnet.sh.

You can see all of the output shown here in the Travis UI, of course.

Job 1: Default terminal, no-op program

Pretty log

$ TravisConsole/run-dotnet.sh 0
Before dotnet run (first)
Welcome to .NET Core 3.1!
---------------------
SDK Version: 3.1.301
----------------
Explore documentation: https://aka.ms/dotnet-docs
Report issues and find source on GitHub: https://github.com/dotnet/core
Find out what's new: https://aka.ms/dotnet-whats-new
Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https
Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs
Write your first app: https://aka.ms/first-net-core-app
--------------------------------------------------------------------------------------
Before dotnet run (second)
The command "TravisConsole/run-dotnet.sh 0" exited with 0.

Note the lack of After dotnet run in each case.

Raw log

[0K$ TravisConsole/run-dotnet.sh 0
Before dotnet run (first)

Welcome to .NET Core 3.1!

---------------------

SDK Version: 3.1.301

----------------

Explore documentation: https://aka.ms/dotnet-docs

Report issues and find source on GitHub: https://github.com/dotnet/core

Find out what's new: https://aka.ms/dotnet-whats-new

Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https

Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs

Write your first app: https://aka.ms/first-net-core-app

--------------------------------------------------------------------------------------
[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=After dotnet run (first)
Before dotnet run (second)
[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=After dotnet run (second)
travis_time:end:18aa556c:start=1595144448336834755,finish=1595144452475616837,duration=4138782082,event=script
[0K[32;1mThe command "TravisConsole/run-dotnet.sh 0" exited with 0.[0m

In the raw log, we can see that After dotnet run is present each time, but with [?1h=[?1h=[?1h=[?1h=[?1h=[?1h=[?1h= before it. Let’s see what happens when our console application actually writes to the console.

Job 2: Default terminal, write two lines

Pretty log

$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)
Welcome to .NET Core 3.1!
---------------------
SDK Version: 3.1.301
----------------
Explore documentation: https://aka.ms/dotnet-docs
Report issues and find source on GitHub: https://github.com/dotnet/core
Find out what's new: https://aka.ms/dotnet-whats-new
Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https
Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs
Write your first app: https://aka.ms/first-net-core-app
--------------------------------------------------------------------------------------
Line 2
Before dotnet run (second)
Line 2
The command "TravisConsole/run-dotnet.sh 2" exited with 0.

This time we don’t have After dotnet run – and we don’t have Line 1 either. As expected, they are present in the raw log, but with control characters before them:

[0K$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)

Welcome to .NET Core 3.1!

---------------------

SDK Version: 3.1.301

----------------

Explore documentation: https://aka.ms/dotnet-docs

Report issues and find source on GitHub: https://github.com/dotnet/core

Find out what's new: https://aka.ms/dotnet-whats-new

Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https

Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs

Write your first app: https://aka.ms/first-net-core-app

--------------------------------------------------------------------------------------
[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=Line 1
Line 2
[?1h=After dotnet run (first)
Before dotnet run (second)
[?1h=[?1h=[?1h=[?1h=[?1h=[?1h=Line 1
Line 2
[?1h=After dotnet run (second)
travis_time:end:00729828:start=1595144445905196926,finish=1595144450121508733,duration=4216311807,event=script
[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Now let’s try with the TERM environment variable set.

Job 3: Mystery terminal, no-op program

$ TravisConsole/run-dotnet.sh 0
Before dotnet run (first)
Welcome to .NET Core 3.1!
---------------------
SDK Version: 3.1.301
----------------
Explore documentation: https://aka.ms/dotnet-docs
Report issues and find source on GitHub: https://github.com/dotnet/core
Find out what's new: https://aka.ms/dotnet-whats-new
Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https
Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs
Write your first app: https://aka.ms/first-net-core-app
--------------------------------------------------------------------------------------
After dotnet run (first)
Before dotnet run (second)
After dotnet run (second)
The command "TravisConsole/run-dotnet.sh 0" exited with 0.

That’s more like it! This time the raw log doesn’t contain any characters within the script execution itself. (There are still blank lines in the “logo” part, admittedly. Not sure why, but we’ll get rid of that later anyway.)

[0K$ TravisConsole/run-dotnet.sh 0
Before dotnet run (first)

Welcome to .NET Core 3.1!

---------------------

SDK Version: 3.1.301

----------------

Explore documentation: https://aka.ms/dotnet-docs

Report issues and find source on GitHub: https://github.com/dotnet/core

Find out what's new: https://aka.ms/dotnet-whats-new

Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https

Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs

Write your first app: https://aka.ms/first-net-core-app

--------------------------------------------------------------------------------------
After dotnet run (first)
Before dotnet run (second)
After dotnet run (second)
travis_time:end:11222e41:start=1595144449188901003,finish=1595144453242229433,duration=4053328430,event=script
[0K[32;1mThe command "TravisConsole/run-dotnet.sh 0" exited with 0.[0m

Let’s just check that it still works with actual output:

Job 4: Mystery terminal, write two lines

Pretty log

4.45s$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)
Welcome to .NET Core 3.1!
---------------------
SDK Version: 3.1.301
----------------
Explore documentation: https://aka.ms/dotnet-docs
Report issues and find source on GitHub: https://github.com/dotnet/core
Find out what's new: https://aka.ms/dotnet-whats-new
Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https
Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs
Write your first app: https://aka.ms/first-net-core-app
--------------------------------------------------------------------------------------
Line 1
Line 2
After dotnet run (first)
Before dotnet run (second)
Line 1
Line 2
After dotnet run (second)
The command "TravisConsole/run-dotnet.sh 2" exited with 0.

Exactly what we’d expect from inspection. The raw log doesn’t hold any surprises either.

Raw log

[0K$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)

Welcome to .NET Core 3.1!

---------------------

SDK Version: 3.1.301

----------------

Explore documentation: https://aka.ms/dotnet-docs

Report issues and find source on GitHub: https://github.com/dotnet/core

Find out what's new: https://aka.ms/dotnet-whats-new

Learn about the installed HTTPS developer cert: https://aka.ms/aspnet-core-https

Use 'dotnet --help' to see available commands or visit: https://aka.ms/dotnet-cli-docs

Write your first app: https://aka.ms/first-net-core-app

--------------------------------------------------------------------------------------
Line 1
Line 2
After dotnet run (first)
Before dotnet run (second)
Line 1
Line 2
After dotnet run (second)
travis_time:end:0203f787:start=1595144444502091825,finish=1595144448950945977,duration=4448854152,event=script
[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Job 5: Mystery terminal, write two lines, no logo

While job 4 is almost exactly what we want, it’s still got the annoying “Welcome to .NET Core 3.1!” section. That’s a friendly welcome for users in an interactive context, but pointless for continuous integration. Fortunately it’s now easy to turn off by setting DOTNET_NOLOGO=true. We now have exactly the log we’d want:

Pretty log

$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)
Line 1
Line 2
After dotnet run (first)
Before dotnet run (second)
Line 1
Line 2
After dotnet run (second)
The command "TravisConsole/run-dotnet.sh 2" exited with 0.

Raw log

[0K$ TravisConsole/run-dotnet.sh 2
Before dotnet run (first)
Line 1
Line 2
After dotnet run (first)
Before dotnet run (second)
Line 1
Line 2
After dotnet run (second)
travis_time:end:0bb5a6d4:start=1595144448986411002,finish=1595144453476210113,duration=4489799111,event=script
[0K[32;1mThe command "TravisConsole/run-dotnet.sh 2" exited with 0.[0m

Conclusion

The use of mystery as the value of the TERM environment variable isn’t special, other than “not being a terminal that either Travis or .NET Core will have any fixed expectations about”. I expect that .NET Core is trying to be clever with its output based on the TERM environment variable, and that Travis isn’t handling the control characters in quite the way that .NET Core expects it to. Which one is right, and which one is wrong? It doesn’t really matter to me, so long as I can fix it.

This does potentially have a cost, of course. Anything which would actually produce prettier output based on the TERM environment variable is being hampered by this change. But so far we haven’t seen any problems. (It certainly isn’t stopping our Travis logs from using colour, for example.)

I discovered the DOTNET_NOLOGO environment variable – introduced in .NET Core 3.1.301, I think – incidentally while researching this problem. It’s not strictly related to the core problem, but it is related to the matter of “making CI logs readable” so I thought I’d include it here.

I was rather surprised not to see complaints about this all over the place. As you can see from the code above, it’s not like I’m doing anything particularly “special” – just writing lines out to the console. Are other developers not having the same problem, or just not noticing the problem? Either way, I hope this post helps either the .NET Core team to dive deeper, find out what’s going on and fix it (talking to the Travis team if appropriate), or at least raise awareness of the issue so that others can apply the same workaround.

Using “git bash” from AppVeyor

Update: I don’t know whether it was partially due to this blog post or not, but AppVeyor has fixed things so that you don’t (currently, 20th October 2019) need to use the fix in this post. You may want to include it anyway, for the sake of future-proofing.


TL;DR: If your AppVeyor build starts breaking because it’s started using WSL bash, change the path in your YAML file – see the end of the post for an example.

For years now, I’ve used bash scripts for all kinds of automation in Windows projects. The version of bash I use is the one that comes with Git for Windows – I believe its origins include Cygwin, MSYS2, and MinGW-w64. (I don’t know enough about the differences between those projects or which builds on which to say more. Fortunately, I don’t need to.) This version of bash is installed by default AppVeyor, the CI system I typically use for Windows builds, so I don’t need to do anything else.

Importantly, I don’t want to use Windows Subsystem for Linux (WSL) on Windows builds. The point of doing the build is to use the Windows tool chains. I use Travis for doing Linux builds.

On October 11th 2019, my Noda Time AppVeyor build failed with this error:

build/appveyor.sh: line 11: dotnet: command not found

It turns out this is because AppVeyor has started shipping WSL with its Visual Studio 2019 images. The bash from WSL is earlier in the path than the version of bash from git, so that one is used, and everything starts failing.

It took a little while to diagnose this, but the fix is pretty easy – you just need to put git bash earlier in your path. I chose to do this in the “install” part of appveyor.yml:

install:
  # Make sure we get the bash that comes with git, not WSL bash
  - ps: $env:Path = "C:\Program Files\Git\bin;$env:Path"

Using just that change, the build started working again. Hooray!

Storing UTC is not a silver bullet

Note: this is a pretty long post. If you’re not interested in the details, the conclusion at the bottom is intended to be read in a standalone fashion. There’s also a related blog post by Lau Taarnskov – if you find this one difficult to read for whatever reason, maybe give that a try.

When I read Stack Overflow questions involving time zones, there’s almost always someone giving the advice to only ever store UTC. Convert to UTC as soon as you can, and convert back to a target time zone as late as you can, for display purposes, and you’ll never have a time zone issue again, they say.

This blog post is intended to provide a counterpoint to that advice. I’m certainly not saying storing UTC is always the wrong thing to do, but it’s not always the right thing to do either.

Note on simplifications: this blog post does not go into supporting non-Gregorian calendar systems, or leap seconds. Hopefully developers writing applications which need to support either of those are already aware of their requirements.

Background: EU time zone rule changes

The timing of this blog post is due to recent European Parliament proceedings that look like they will probably end the clocks changing twice a year into “summer time” or “winter time” within EU member states. The precise details are yet to be finalized and are unimportant to the bigger point, but for the purpose of this blog post I’ll assume that each member state has to decide whether they will “spring forward” one last time on March 28th 2021, then staying in permanent “summer time”, or “fall back” one last time on October 31st 2021, then staying in permanent “winter time”. So from November 1st 2021 onwards, the UTC offset of each country will be fixed – but there may be countries which currently always have the same offset as each other, and will have different offsets from some point in 2021. (For example, France could use winter time and Germany could use summer time.)

The larger point is that time zone rules change, and that applications should expect that they will change. This isn’t a corner case, it’s the normal way things work. There are usually multiple sets of rule changes (as released by IANA) each year. At least in the European changes, we’re likely to have a long notice period. That often isn’t the case – sometimes we don’t find out about rule changes until a few days before they happen.

Application example

For the sake of making everything concrete, I’m going to imagine that we’re writing an application to help conference organizers. A conference organizer can create a conference within the application, specifying when and where it’s happening, and (amongst other things) the application will display a countdown timer of “the number of hours left before the start of the conference”. Obviously a real application would have a lot more going on than this, but that’s enough to examine the implementation options available.

To get even more concrete, we’ll assume that a conference organizer has registered a conference called “KindConf” and has said that it will start at 9am in Amsterdam, on July 10th 2022. They perform this registration on March 27th 2019, when the most recently published IANA time zone database is 2019a, which predicts that the offset observed in Amsterdam on July 10th 2022 will be UTC+2.

For the sake of this example, we’ll assume that the Netherlands decides to fall back on October 31st 2021 for one final time, leaving them on a permanent offset of UTC+1. Just to complete the picture, we’ll assume that this decision is taken on February 1st 2020, and that IANA publishes the changes on March 14th 2020, as part of release 2020c.

So, what can the application developer do? In all the options below, I have not gone into details of the database support for different date/time types. This is important, of course, but probably deserves a separate blog post in its own right, on a per-database basis. I’ll just assume we can represent the information we want to represent, somehow.

Interlude: requirements

Before we get to the implementations, I’ll just mention a topic that’s been brought up a few times in the comments and on Twitter. I’ve been assuming that the conference does still occur at 9am on July 10th 2022… in other words, that the “instant in time at which the conference starts” changes when the rules change.

It’s unlikely that this would ever show up in a requirements document. I don’t remember ever being in a meeting with a product manager where they’d done this type of contingency planning. If you’re lucky, someone would work out that there’s going to be a problem long before the rules actually change. At that point, you’d need to go through the requirements and do the implementation work. I’d argue that this isn’t a new requirement – it’s a sort of latent, undiscovered requirement you’ve always had, but you hadn’t known about before.

Now, back to the options…

Option 1: convert to UTC and just use that forever

The schema for the Conferences table in the database might look like this:

  • ID: auto-incremented integer
  • Name: string
  • Start: date/time in UTC
  • Address: string

The entry for KindConf would look like this:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T07:00:00Z
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands

That entry is then preserved forever, without change. So what happens to our countdown timer?

Result

The good news is that anyone observing the timer will see it smoothly count down towards 0, with no jumps. The bad news is that when it reaches 0, the conference won’t actually start – there’ll be another hour left. This is not good.

Option 2: convert to UTC immediately, but reconvert after rule changes

The schema for the Conferences table would preserve the time zone ID. (I’m using the IANA ID for simplicity, but it could be the Windows system time zone ID, if absolutely necessary.) Alternatively, the time zone ID could be derived each time it’s required – more on that later.

  • ID: auto-incremented integer
  • Name: string
  • Start: date/time in UTC
  • Address: string
  • Time zone ID: string

The initial entry for KindConf would look like this:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T07:00:00Z
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam

On March 14th 2020, when the new time zone database is released, that entry could be changed to make the start time accurate again:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T08:00:00Z
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam

But what does that “change” procedure look like? We need to convert the UTC value back to the local time, and then convert back to UTC using different rules. So which rules were in force when that entry was created? It looks like we actually need an extra field in the schema somewhere: TimeZoneRulesVersion. This could potentially be a database-wide value, although that’s only going to be reasonable if you can update all entries and that value atomically. Allowing a value per entry (even if you usually expect all entries to be updated at roughly the same time) is likely to make things simpler.

So our original entry was actually:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T07:00:00Z
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • TimeZoneRules: 2019a

And the modified entry is:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T08:00:00Z
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • TimeZoneRules: 2020c

Of course, the entry could have been updated many times over the course of time, for 2019b, 2019c, …, 2020a, 2020b. Or maybe we only actually update the entry if the start time changes. Either way works.

Result

Now, anyone refreshing the countdown timer for the event will see the counter increase by an hour when the entry is updated. That may look a little odd – but it means that when the countdown timer reaches 0, the conference is ready to start. I’m assuming this is the desired behaviour.

Implementation

Let’s look at roughly what would be needed to perform this update in C# code. I’ll assume the use of Noda Time to start with, but then we’ll consider what happens if you’re not using Noda Time.

public class Conference
{
    public int Id { get; set; }
    public string Name { get; set; }
    public string Address { get; set; }
    public Instant Start { get; set; }
    public string TimeZoneId { get; set; }
    public string TimeZoneRules { get; set; }
}

// In other code... some parameters might be fields in the class.
public void UpdateStartTime(
    Conference conference,
    Dictionary<string, IDateTimeZoneProvider> timeZoneProvidersByVersion,
    string latestRules)
{
    // Map the start instant into the time zone using the old rules
    IDateTimeZoneProvider oldProvider = timeZoneProvidersByVersion[conference.TimeZoneRules];
    DateTimeZone oldZone = oldProvider[conference.TimeZoneId];
    ZonedDateTime oldZonedStart = conference.Start.InZone(oldZone);   

    IDateTimeZoneProvider newProvider = timeZoneProvidersByVersion[latestRules];
    DateTimeZone newZone = newProvider[conference.TimeZoneId];
    // Preserve the local time, but with the new time zone rules
    ZonedDateTime newZonedStart = oldZonedStart.LocalDateTime.InZoneLeniently(newZone);

    // Update the conference entry with the new information
    conference.Start = newZonedStart.ToInstant();
    conference.TimeZoneRules = latestRules;
}

The InZoneLeniently call is going to be a common issue – we’ll look at that later (“Ambiguous and skipped times”).

This code would work, and Noda Time would make it reasonably straightforward to build that dictionary of time zone providers, as we publish all the “NZD files” we’ve ever created from 2013 onwards on the project web site. If the code is being updated with the latest stable version of the NodaTime NuGet package, the latestRules parameter wouldn’t be required – DateTimeZoneProviders.Tzdb could be used instead. (And IDateTimeZoneProvider.VersionId could obtain the current version.)

However, this approach has three important requirements:

  • The concept of “version of time zone rules” has to be available to you
  • You have to be able to load a specific version of the time zone rules
  • You have to be able to use multiple versions of the time zone rules in the same application

If you’re using C# but relying on TimeZoneInfo then… good luck with any of those three. (It’s no doubt feasible, but far from simple out of the box, and it may require an external service providing historical data.)

I can’t easily comment on other platforms in any useful way, but I suspect that dealing with multiple versions of time zone data is not something that most developers come across.

Option 3: preserve local time, using UTC as derived data to be recomputed

Spoiler alert: this is my preferred option.

In this approach, the information that the conference organizer supplied (“9am on July 10th 2022”) is preserved and never changed. There is additional information in the entry that is changed when the time zone database is updated: the converted UTC instant. We can also preserve the version of the time zone rules used for that computation, as a way of allowing the process of updating entries to be restarted after a failure without starting from scratch, but it’s not strictly required. (It’s also probably useful as diagnostic information, too.)

The UTC instant is only stored at all for convenience. Having a UTC representation makes it easier to provide total orderings of when things happen, and also to compute the time between “right now” and the given instant, for the countdown timer. Unless it’s actually useful to you, you could easily omit it entirely. (My Noda Time benchmarks suggest it’s unlikely that doing the conversion on every request wouldn’t cause a bottleneck. A single local-to-UTC conversion on my not-terribly-fast benchmark machine only takes ~150ns. In most environments that’s close to noise. But for cases where it’s relevant, it’s fine to store the UTC as described below.)

So the schema would have:

  • ID: auto-incremented integer
  • Name: string
  • Local start: date/time in the specified time zone
  • Address: string
  • Time zone ID: string
  • UTC start: derived field for convenience
  • Time zone rules version: for optimization purposes

So our original entry is:

  • ID: 1
  • Name: KindConf
  • LocalStart: 2022-07-10T09:00:00
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • UtcStart: 2022-07-10T07:00:00Z
  • TimeZoneRules: 2019a

On March 14th 2020, when the time zone database 2020c is released, this is modified to:

  • ID: 1
  • Name: KindConf
  • LocalStart: 2022-07-10T09:00:00
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • UtcStart: 2022-07-10T08:00:00Z
  • TimeZoneRules: 2020c

Result

This is the same as option 2: after the update, there’s a jump of an hour, but when it reaches 0, the conference starts.

Implementation

This time, we don’t need to convert our old UTC value back to a local value: the “old” time zone rules version and “old” UTC start time are irrelevant. That simplifies matter significantly:

public class Conference
{
    public int Id { get; set; }
    public string Name { get; set; }
    public string Address { get; set; }
    public LocalDateTime LocalStart { get; set; }
    public string TimeZoneId { get; set; }
    public Instant UtcStart { get; set; }
    public string TimeZoneRules { get; set; }
}

// In other code... some parameters might be fields in the class.
public void UpdateUtcStart(
    Conference conference,
    IDateTimeZoneProvider latestZoneProvider)
{
    DateTimeZone newZone = latestZoneProvider[conference.TimeZoneId];
    // Preserve the local time, but with the new time zone rules
    ZonedDateTime newZonedStart = conference.LocalStart.InZoneLeniently(newZone);

    // Update the conference entry with the new information
    conference.UtcStart = newZonedStart.ToInstant();
    conference.TimeZoneRules = latestZoneProvider.VersionId;
}

As the time zone rules version is now optional, this code could be ported to use TimeZoneInfo instead. Obviously from my biased perspective the code wouldn’t be as pleasant, but it would be at least reasonable. The same is probably true on other platforms.

So I prefer option 3, but is it really so different from option 2? We’re still storing the UTC value, right? That’s true, but I believe the difference is important because the UTC value is an optimization, effectively.

Principle of preserving supplied data

For me, the key difference between the options is that in option 3, we store and never change what the conference organizer entered. The organizer told us that the event would start at the given address in Amsterdam, at 9am on July 10th 2022. That’s what we stored, and that information never needs to change (unless the organizer wants to change it, of course). The UTC value is derived from that “golden” information, but can be re-derived if the context changes – such as when time zone rules change.

In option 2, we don’t store the original information – we only store derived information (the UTC instant). We need to store information to tell us all the context about how we derived it (the old time zone rules version) and when updating the entry, we need to get back to the original information before we can re-derive the UTC instant using the new rules.

If you’re going to need the original information anyway, why not just store that? The implementation ends up being simpler, and it means it doesn’t matter whether or not we even have the old time zone rules.

Representation vs information

It’s important to note that I’m only talking about preserving the core information that the organizer entered. For the purposes of this example at least, we don’t need to care about the representation they happened to use. Did they enter it as “July 10 2022 09:00” and we then parsed that? Did they use a calendar control that provided us with “2022-07-10T09:00”? I don’t think that’s important, as it’s not part of the core information.

It’s often a useful exercise to consider what aspects of the data you’re using are “core” and which are incidental. If you’re receiving data from another system as text for example, you probably don’t want to store the complete XML or JSON, as that choice between XML and JSON isn’t relevant – the same data could be represented by an XML file and a JSON file, and it’s unlikely that anything later will need to know or care.

A possible option 4?

I’ve omitted a fourth option which could be useful here, which is a mixture of 2 and 3. If you store a “date/time with UTC offset” then you’ve effectively got both the local start time and the UTC instant in a single field. To show the values again, you’d start off with:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T09:00:00+02:00
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • TimeZoneRules: 2019a

On March 14th 2020, when the time zone database 2020c is released, this is modified to:

  • ID: 1
  • Name: KindConf
  • Start: 2022-07-10T09:00:00+01:00
  • Address: Europaplein 24, 1078 GZ Amsterdam, Netherlands
  • TimeZoneId: Europe/Amsterdam
  • TimeZoneRules: 2020c

In systems that support “date/time with UTC offset” well in both the database and the languages using it, this might be an attractive solution. It’s important to note that the time zone ID is still required (unless you derive it from the address whenever you need it) – there’s a huge difference between knowing the time zone that’s applied, and knowing the UTC offset in one specific situation.

Personally I’m not sure I’m a big fan of this option, as it combines original and derived data in a single field – the local part is the original data, and the offset is derived. I like the separation between original and derived data in option 3.

With all those options presented, let’s look at a few of the corner cases I’ve mentioned in the course of the post.

Ambiguous and skipped times

In both of the implementations I’ve shown, I’ve used the InZoneLeniently method from Noda Time. While the mapping from UTC instant to local time is always completely unambiguous for a single time zone, the reverse mapping (from local time to UTC instant) is not always unambiguous.

As an example, let’s take the Europe/London time zone. On March 31st 2019, at 1am local time, we will “spring forward” to 2am, changing offset from UTC+0 to UTC+1. On October 27th 2019, at 2am local time, we will “fall back” to 1am, changing offset from UTC+1 to UTC+0. That means that 2019-03-31T01:30 does not happen at all in the Europe/London time zone, and 2019-10-27T01:30 occurs twice.

Now it’s reasonable to validate this when a conference organizer specifies the starting time of a conference, either prohibiting it if the given time is skipped, or asking for more information if the given time is ambiguous. I should point out that this is highly unlikely for a conference, as transitions are generally done in the middle of the night – but other scenarios (e.g. when to schedule an automated backup) may well fall into this.

That’s fine at the point of the first registration, but it’s also possible that a previously-unambiguous local time could become ambiguous under new time zone rules. InZoneLeniently handles that in a way documented in the Resolvers.LenientResolver. That may well not be the appropriate choice for any given application, and developers should consider it carefully, and write tests.

Recurrent events

The example I’ve given so far is for a single event. Recurrent events – such as weekly meetings – end up being trickier still, as a change to time zone rules can change the offsets for some instances but not others. Likewise meetings may well be attended by people from more than a single time zone – so it’s vital that the recurrence would have a single coordinating time zone, but offsets may need to be recomputed for every time zone involved, and for every occurrence. Application developers have to think about how this can be achieved within performance requirements.

Time zone boundary changes and splits

So far we’ve only considered time zone rules changing. In options 2-4, we stored a time zone ID within the entry. That assumes that the time zone associated with the event will not change over time. That assumption may not be valid.

As far as I’m aware, time zone rules change more often than changes to which time zone any given location is in – but it’s entirely possible for things to change over time. Suppose the conference wasn’t in Amsterdam itself, but Rotterdam. Currently Rotterdam uses the Europe/Amsterdam time zone, but what if the Netherlands splits into two countries between 2019 and 2022? It’s feasible that by the time the conference occurs, there could be a Europe/Rotterdam time zone, or something equivalent.

To that end, a truly diligent application developer might treat the time zone ID as derived data based on the address of the conference. As part of checking each entry when the time zone database is updated, they might want to find the time zone ID of the address of the conference, in case that’s changed. There are multiple services that provide this information, although it may need to be a multi-step process, first converting the address into a latitude/longitude position, and then finding the time zone for that latitude/longitude.

Past vs recent past

This post has all been about future date/time values. In Twitter threads discussing time zone rule changes, there’s been a general assertion that it’s safe to only store the UTC instant related to an event in the past. I would broadly agree with that, but with one big caveat: as I mentioned earlier, sometimes governments adopt time zone rule changes with almost no notice at all. Additionally, there can be a significant delay between the changes being published and them being available within applications. (That delay can vary massively based on your platform.)

This means that while a conversion to UTC for a value more than (say) a year ago will probably stay valid, if you’re recording a date and time of “yesterday”, it’s quite possible that you’re using incorrect rules without knowing it. (Even very old rules can change, but that’s rarer in my experience.)

Do you need to account for this? That depends on your application, like so many other things. I’d at least consider the principle described above – and unless it’s much harder for you to maintain the real source information for some reason, I’d default to doing that.

Conclusion

The general advice of “just convert all local date/time data to UTC and store that” is overly broad in my view. For future and near-past events, it doesn’t take into account that time zone rules change, making the initial conversion potentially inaccurate. Part of the point of writing this blog post is to raise awareness, so that even if people do still recommend storing UTC, they can add appropriate caveats rather than treating it as a universal silver bullet.

I should explicitly bring up timestamps at this point. Machine-generated timestamps are naturally instants in time, recording “the instant at which something occurred” in an unambiguous way. Storing those in UTC is entirely reasonable – potentially with an offset or time zone if the location at which the timestamp was generated is relevant. Note that in this case the source of the data isn’t “a local time to be converted”.

That’s the bigger point, that goes beyond dates and times and time zones: choosing what information to store, and how. Any time you discard information, that should be a conscious choice. Are you happy discarding the input format that was used to enter a date? Probably – but it’s still a decision to make. Defaulting to “convert to UTC” is a default to discarding information which in some cases is valid, but not all. Make it a conscious choice, and ensure you store all the information you think may be needed later. You might also want to consider whether and how you separate “source” information from “derived” information – this is particularly relevant when it comes to archiving, when you may want to discard all the derived data to save space. That’s much easier to do if you’re already very aware of which data is derived.

My experience is that developers either don’t think about date/time details nearly enough when coding, or are aware of some of the pitfalls but decide that means it’s just too hard to contemplate. Hopefully this worked example of real life complexity shows that it can be done: it takes a certain amount of conscious thought, but it’s not rocket science.

NuGet package statistics

For a while, I’ve been considering how useful nuget.org statistics are.

I know there have been issues in the past around accuracy, but that’s not what I’m thinking about. I’ve been
trying to work out what the numbers mean at all and whether that’s useful.

I’ve pretty sure an older version of the nuget.org gallery gave stats on a per-operation basis, but right now it looks like we can break down the downloads by package version, client name and client version. (NodaTime example)

In a way, the lack of NuGet “operation” at least makes it simpler to talk about: we only know about “downloads”. So, what counts as a download?

What’s a download?

Here are a few things that might increment that counter:

  • Manual download from the web page
  • Adding a new package in Visual Studio
  • Adding a new package in Visual Studio Code
  • nuget install from the command line
  • dotnet restore for a project locally
  • dotnet restore in a Continuous Integration system testing a PR
  • dotnet restore in a CI system testing a merged PR

All of them sound plausible, but it’s also possible that they wouldn’t increment the counter:

  • I might have a package in my NuGet cache locally
  • A CI system might have its own global package cache
  • A CI system might use a mirror service somehow

So what does the number really mean? Some set of coincidences in terms of developer behavior and project lifetime? One natural reaction to this is “The precise meaning of the number doesn’t matter, but bigger is better.” I’d suggest that’s overly complacent.

Suppose I’m right that some CI systems have a package cache, but others don’t. Suppose we look at packages X and Y which have download numbers of 1000 and 100,000 respectively. (Let’s ignore
which versions those are for, or how long those versions have been out.) Does that mean Y‘s usage is “better” than X‘s in some way? Not necessarily. Maybe it means there’s a single actively-developed
open source project using Y and a CI system that doesn’t have a NuGet cache (and configured to build each PR on each revision), whereas maybe there are a thousand entirely separate projects using
X, but all using a CI system that just serves up a single version from a cache for everything.

Of course, that’s an extreme position. It’s reasonable to suggest that on average, if package Y has larger download numbers than package X, then it’s likely to be more widely used… but can we
do better?

What are we trying to measure?

Imagine we had perfect information: a view into every machine on the planet, and every operation any of them performed. What number would we want to report? What does it mean for a package to be “popular” or “widely used”?

Maybe we should think in terms of “number of projects that use package X“. Let’s consider some situations:

  • A project created to investigate a problem, and then gets deleted. Never even committed to source control system.
  • A project which is created and committed to source control, but never used.
  • A project created and in production use, maintained by 1 person.
  • A project created and in production use, maintained by a team of
    100 people.
  • A project created by 1 person, but then forked by 10 people and
    never merged.
  • A project created on github by 1 person, and forked by 10 people on github, with them repeatedly creating branches and merging back into the original repo.
  • A project which doesn’t use package X directly, but uses package Y that depends on package X.

If those all happened for the same package, what number would you want each of those projects to contribute to the package usage?

One first-order approximation could be achieved with “take some hash of the name of the project and propagate it (even past caches) when installing a package”. That would allow us to be reasonably confident in some measure of “how many differently-named projects depend on package X” which might at least feel slightly more reasonable, although it’s unclear to me how throwaway projects would end up being represented. (Do people tend to use the same names as each other for throwaway projects? I bet Console1 and WindowsForms1 would be pretty popular…)

That isn’t a serious suggestion, by the way – it’s not clear to me that hashing alone provides sufficient privacy protection, for a start. There are multiple further issues in terms of cache-busting, too. It’s an interesting thought experiment.

What do I actually care about though?

That’s even assuming that “number of projects that use package X is a useful measure. It’s not clear to me that it is.

As an open source contributor, there are two aspects I care about:

  • How many people will I upset, and how badly, if I break something?
  • How many people will I delight, and to what extent, if I implement a particular new feature?

It’s not clear to me that any number is going to answer those questions for me.

So what do you care about? What would you want nuget.org to show if it could? What do you think would be reasonable for it to show in the real world with real world constraints?

Imposter Syndrome (part 2)

9 days ago, I posted Imposter Syndrome (part 1) and then immediately listened to Heather Downing‘s excellent NDC talk on the topic.

This is the “reflections afterwards” post I’d expected to write (although slightly more delayed than I’d hoped for). I’m not going to try to recap Heather’s talk, because that wouldn’t do justice to it. Please watch the video instead. This is my set of reflections after Heather’s talk – some of it directly responding to what she said, and other parts simply my own meandering thought process.

Responding to praise

This one’s simple. I’ve often responded to praise in ways that effectively negate the opinion of the other person – saying that I’m really not as smart as they think I am, etc. I suspect there’s some cultural influence there; it’s a fairly British thing to do. But I hadn’t considered the flip side of this not conveying humility on my part, but wrongness on their part.

So I’m going to start to just say “thank you” as far as I can. I think there will still be times where it would be important to try to correct a potentially harmful impression – if someone explains that they’re trying to win technical arguments by quoting me, for example – but most of the time I’ll try to bite my tongue, and just say thanks… and maybe try to shift the conversation onto what they’re doing. (If someone says they’re inspired by me, that’s great – so what have they been inspired to do? Does this give me an opportunity to encourage them further?)

Success and luck

There are two very slightly different nuances to being “lucky” – at least in the way I think about it. The first is a sort of “undeserved positive effects” aspect. “I’m lucky to be married to such a wonderful person” or “I’m lucky to have a natural aptitude for computing” for example. Things you can’t really control much. The second is a sort of “the same sequence of events could have unfolded very differently” aspect. “I’m lucky to have ended up in a job I love without making a career plan” for example.

I fear I’m not transferring the ideas from brain to screen very clearly, but there are two important points:

Firstly, I don’t want anyone to try to emulate me in areas where I’ve been genuinely lucky. I have no doubt that in other situations (with a different set of colleagues, for example) some of my actions could have led to very different results. I’ve always spent quite a lot of time learning by experimentation and community writing – whether that’s on newsgroups, Stack Overflow or blog posts. Some of this has been done on company time, and every company I’ve worked for has (quietly) acknowledged that it’s been a broadly positive thing – so long as it’s not been too excess, of course. Other software engineers – particularly those in jobs where every hour has to be accounted for – could see a very different result to the same actions.

On the other hand, I should probably accept the point Heather made that attributing repeated success to luck is foolish. I don’t think I’m lucky to receive upvotes on Stack Overflow: I make a conscious effort to communicate clearly, and that’s something I’ve put a lot of effort into over several years. Some of the further results could be called lucky: if Stack Overflow hadn’t come on the scene, I’m sure I’d still be writing on newsgroups with a vastly smaller potential audience for answers. The more immediate effect of “If I put effort into writing clearly and researching my subject matter, that effort is appreciated by those who read it” isn’t a matter of luck though.

Writing off success as just luck risks undervaluing processes and practices that are genuinely helpful – as well as potentially giving the impression that we won’t appreciate the hard work and diligence of others. (On the other hand, check your privilege before ascribing all your success to your own graft and/or brilliance.)

Dunning-Kruger harms everyone

Finally, the Dunning-Kruger effect is probably worth fighting against in both aspects.

Those who are overestimating their skills are doing themselves a disservice by appearing arrogant or compounding their ignorance by “meta-ignorance” of the scope of the subject matter. Unless they’re trying to represent a larger entity (a consultancy for example) the impact seems fairly localized.

I’m coming round to the idea that those who are underestimating their skills – and doing so publicly – might be discouraging everyone else. If someone I look up to as an expert in a topic were to only rate themselves as “8 out of 10” in knowledge in that topic, that could make me feel worse about my own understanding of the topic. While I suspect it’s hard for anyone in a culture that values humility to rate their knowledge as “9.5 out of 10” for something, I think it’s important that the real experts do so. Yes, they can still be aware of the areas they struggle in – but there must be some way of expressing that while acknowledging their overall expertise.

Beyond simple discouragement, there’s another aspect of underestimating your own prowess that can prove unhelpful, and that’s in terms of explanations. I’ve always found most (not quite all) security experts hard to understand. They’re so deeply immersed in their own domain that they may not appreciate how many assumptions of shared terminology and understanding they need to remove before they can communicate effectively with “lay” people.

I only give the example of security as one where I personally struggle to learn from people who undoubtedly have knowledge I could benefit from. My fear is that I do the same unwittingly when it comes to areas I’m confident in. I tend to make more conscious effort when discussing date/time issues as I’m aware of the common misunderstandings. What about C# though? When I use language specification terminology in blog posts and Stack Overflow answers, what proportion of readers just get lost quickly? I’m not quite sure what to do about this, beyond becoming more conscious of it as a possibility.

Conclusion

This is by no means an end to my thoughts on Imposter Syndrome or related self-evaluation traits, although it may well be my last blog post on it. No impressive final thoughts, no clever tying up of all the strands… this is only a conclusion in the sense that it’s concluding the post. The end.

Imposter syndrome (part 1)

Note: this is a purely personal post. It has no code in. It’s related to the coding side of my world more than the rest of who I am, so it’s in my coding blog, but if you’re looking for code, just move on.

As part of a Twitter exchange, I discovered that Heather Downing (blog, twitter) would be talking about Imposter Syndrome. This is a topic that interests me for reasons I’ll go into below. I figured it would be interesting to jot down some thoughts on it before Heather’s talk, and then again afterwards, comparing my ideas with hers. As such, I expect to publish this post pretty much as I’m sitting down for the talk, for maximum independence. (Ed: it’s not somewhat rushed. Back when I started it on Tuesday, it seemed like I had loads of time. It’s now Friday morning and I’m desperately trying to get it into some kind of coherent state in time to post…)

There are two ways I could write this post: one very abstract, about “people in general”, and one very concrete, about myself. The first approach would probably end in platitudes and ignorance – the second could well feel like a mixture of egocentricity, arrogance and humble-bragging. I’m going for the second approach anyway, so if you suspect you’ll get annoyed by reading about my thoughts about myself, I suggest moving along. (Read Heather’s blog, for example.)

Aspects of Imposter Syndrome

I think about Imposter Syndrome in three different ways. For some people they may be very similar, but in my case there are pretty radical differences. (For some reason I tend to be a corner case in all kinds of ways. Basically, I’m awkward.)

  • What do people say (and think) about your skills?
  • What skills are expected or required for what you do? (e.g. the job you’re in, success in the community, speaking etc)
  • What do you say about your skills?

I think of Imposter Syndrome as believing that your true set of skills or abilities is lower than the evaluations listed above. It’s possible that the third bullet really doesn’t belong there, but it’s sufficiently closely related that I want to talk about it anyway.

What do people say (and think) about my coding ability?

The Jon Skeet facts page is the first thing that comes to mind, followed by the Toggl “Rescue the Princess” comic. While both of those are clearly meant to be comedy rather than taken seriously, I suspect some of the hyperbole has rubbed off.

I get attention at conferences and on Twitter as if I really showed exceptional coding ability. There’s an assumption that I really can answer anything. People talk about being inspired by me. People still show up to my talks. People ask how I “get so much done” – when I see plenty of people achieving much more than I do. (I slump in front of the TV at night with Holly far more than the question would suggest…)

What skills are expected of me?

Back in 2012, I talked with Scott Hanselman about Imposter Syndrome and “being a phony”. Back then, I still felt like an imposter at Google – and knew that plenty of my colleagues felt the same way.

In my job, I’m expected to be a proficient coder and leader in the area that I’m working on. I was briefly a manager too, but I’m not any more – so my role is fairly purely technical… but that still includes so-called “soft skills” in terms of communication and persuasion. (I hate the term “soft skills” as it implies those skills are less important or difficult. They’re critical, and sadly underdeveloped!)

In the community, I’m expected to be prolific and accurate online, and interesting/engaging in person, particularly while presenting.

What do I say and think about myself?

I try to make the “say” and “think” match. For some definitions of Imposter Syndrome, I don’t think I actually suffer from it at all. In particular:

  • The hyperbole is clearly incorrect. It’s not just fake humility that suggests I’m not really the world’s top programmer… the idea that I could possibly believe that is laughable.
  • These days I’m pretty comfortable with what I do at work. I work hard, I’m working in an area where I feel I have expertise (C# API design) and I get things done. The work I do doesn’t involve the same degree of computer science brilliance as designing Spanner or implementing a self-driving car, but it’s far from trivial.
  • There are thing I’ve done that I’m genuinely proud of beyond my day job – in particular, Noda Time and C# in Depth. I take pride in my Stack Overflow answers too, but they’re slightly different in a way that’s hard to explain. I’m certainly pleased that they’re helpful.
  • I’m confident in my boundaries: I know that I know C# very well and Java pretty well. I know that I have more awareness of date/time issues than the vast majority of developers. I know that I can express ideas clearly, and that that’s important. I’m also well aware of my limitations: if you see any code I write outside Java and C# (e.g. Bash, Python, Javascript) then it’s horrible, and I make no claims otherwise.

Talking about being an “imposter” or “phony” suggests making a claim to competence which is untrue. I don’t think that’s the case here – and that applies to the vast majority of other “famous” developers I know. They’re generally well aware of their limitations too, and their presentations are always about the technology rather than about themselves. There are exceptions to this, and I know my “Abusing C#” talk has sometimes been seen as a self-promotion vehicle instead of the gleeful exploration of C# corner cases it’s intended to be… but in general, I haven’t interacted with many big egos in the tech space. (This may be a matter of the conferences I’ve chosen to go to. I’m aware there are plenty of big-ego jerks around, but I haven’t spoken with many of them…)

Conclusion

I still believe there is a disconnect between even people’s genuine expectations (as opposed to the hyperbole) and the reality of my competence, even though I don’t cultivate those expectations. As a mark of this, I believe my talks are more popular in anticipation than in experience – it’s often a full house, but in the green/yellow/red appraisal afterwards there’s usually a bunch of yellows and even some reds.

Obviously the disconnect gives an ego boost which I try to dampen, but it has genuinely positive aspects too: one of the things people say to or about me is that I inspire them. That’s fantastic. It really doesn’t matter whether they’re buying into a myth: if something they see in me inspires them to “do better” (whatever that may mean for them) then that’s a net benefit to the world, right?

I’m going to keep making it perfectly clear to people that a lot of what is said about me is massively overblown, while keeping confidence in myself as a really pretty decent developer. Am I over-recognized/over-hyped? Yes. Am I an imposter? I don’t think so.

Postscript

Since finishing the above conclusion, I’ve just watched Felienne‘s talk on “Programming is writing is programming” which was the best talk I’ve seen at any conference. Now I feel like an imposter…

Diversity and speaking engagements

Background

I’m in the privileged position of receiving more invitations to speak (at conferences, user groups and podcasts) than I can realistically agree to. I’ve decided to start applying some new criteria to how I pick which ones I go to1.

However, over the last couple of years as feminism has become an increasingly important part of my life I’ve found myself saddened by the lack of diversity at conferences, both in terms of speakers and attendees. It’s not uncommon for me to spend the first couple of minutes of a conference talk commenting on this, and asking the audience (broadly white men) to think about what they can do to improve this, understanding that it’s our problem to fix. I don’t know whether that’s had any impact, but I’m likely to keep doing it anyway. (Drip, drip, drip.)

I should point out that some conferences do pretty well. When I was invited to speak at NorDevCon for the second time, a large part of why I accepted was because of the diversity of both speakers and attendees. (It varies by year, of course.) When I recently spoke at Web Summit the attendee gender diversity was the best I’ve ever seen – along with a Women in Tech lounge that was certainly busy.

Anyway, to do my part in encouraging diversity, from now on when I’m invited to speak, I’m going to refer the organizers to this post.

My requirements for speaking engagements

  • Conferences must have a published Code of Conduct, including incident resolution steps. Where possible, this should be highlighted in opening remarks (typically before the keynote). It’s important that all speakers and attendees feel both safe and welcome – and members of under-represented groups are the most likely not to feel safe and welcome.
  • Organizers must take active steps to encourage speaker diversity. One common challenge to diversity initiatives is that they mean compromising on quality, but I disagree with the assumption behind the challenge. There are many high-quality presenters who are women, but it may mean making more effort to find them. (It’s all too easy to rely on the “regulars” in the tech speaking circles.) If an organizer publishes how they’re trying to encourage diversity, that’s definitely a bonus. I’d at least expect organizers to keep track of how they’re doing over time, and be willing to privately share how they’re trying to improve. It’s hard to give concrete limits here as I may need to make a decision before the rest of the speaker list is decided, but any time I find myself at a conference where 25% or less of the speakers are non-white-men, I’ll be vocally disappointed. Over time, I expect this number to get higher.
  • Ideally, publishing data on attendee diversity over time, with a public plan for improvements. This may not always be possible historically, as the data may not have been captured – but I doubt that it’s very hard to add it to future registration processes. (I’d encourage organizers to think beyond binary gender identification when adding this, too.)
  • I won’t personally speak in any white-male-only panels of three people or more. Ideally, I’d like to see efforts for there not to be any such panels.

If conferences and user groups don’t want to make any efforts to improve diversity, that’s their choice – but I hope that they’ll find it increasingly difficult to attract good speakers, and I’m going to be a tiny part of that scarcity.

How I’m happy to help organizers

On a positive side, I’m happy to:

  • Try to help organizers find diverse speakers. I don’t currently have much in the way of a contact list on this front yet, but that’s something for me to try to improve.
  • Help potential speakers tune their abstracts or presentations in private. I know that presenting for the first time can be daunting, particularly if you feel under-represented within the industry to start with. I don’t have any experience on this sort of coaching, but if I can be helpful at all, I’ll do my best.
  • Co-present with someone who might otherwise worry that they wouldn’t get much attendance, etc. In particular, I’d be very happy to be an on-stage guinea-pig, learning from another presenter in a field I’m not familiar with, and asking questions along the way in an active tutorial style. (I’d expect any partnership like this to be primarily about highlighting the other speaker’s knowledge – it mustn’t be tokenism just to get them on stage while I waffle about C# yet again. That would propagate negative stereotypes.)
  • Be very vocal about positive experiences in diversity.

Diversity matters. It’s good business and it’s important ethically. Improving the diversity of events is only a small part of improving the industry, and I’d encourage all readers to think about what they can do elsewhere in their own place of work or study.

Further reading:

For conference organizers:

For new speakers:


1 Previously, my criteria have been very loosely based on:

  • Preferring events where I won’t need to stay overnight
  • Preferring events where there are other talks I’ll be interested in
  • Preferring community over commercial organizers
  • Preferring events where the focus actually seems to intersect with my area of dubious expertise. (I’m unlikely to speak at any Agile, Testing or DevOps conferences – while I can appreciate them, that’s not my area.)
  • How many other things I have going on at the time

I’m expecting this post to change over time. I don’t generally like revisionism, but I want this post to stay “live” and relevant for as long as possible. As a compromise, here’s a revision history.

  • 2016-12-10: Initial post
  • 2016-12-16: Updated structure for clarity, fixed MVDP expansion (oops), rewording around not lowering quality

Tracking down a performance hit

I’ve been following the progress of .NET Core with a lot of interest, and trying to make the Noda Time master branch keep up with it. The aim is that when Noda Time 2.0 eventually ships (apologies for the delays…) it will be compatible with .NET Core from the start. (I’d expected to be able to support netstandard1.0, but that appears to have too much missing from it. It looks like netstandard1.3 will be the actual target.)

I’ve been particularly looking forward to being able to run the Noda Time benchmarks (now using BenchmarkDotNet) to compare .NET Core on Linux with the same code on Windows. In order to make that a fair comparison, I now have two Intel NUCs, both sporting an i5-5250U and 8GB of memory.

As it happens, I haven’t got as far as running the benchmarks under .NET Core – but I am now able to run all the unit tests on both Linux and Windows, using both the net451 TFM and netcoreapp1.0.

When I did that recently, I was pretty shocked to see that (depending on which tests I ran) the tests were 6-10 times slower on Linux than on Windows, using netcoreapp1.0 in both cases. This post is a brief log of what I did to track down the problem.

Step 1: Check that there’s really a problem

Thought: Is this actually just a matter of not running the tests in a release configuration, or something similar?

Verification: I ran the tests several times, specifying -c Release on the command line to use the release build of both NodaTime.Test.dll and NodaTime.dll. Running under a debugger definitely wasn’t an issue, as this was all just done from the shell.

Additionally, I ran the tests in two ways – firstly, running the whole test suite, and secondly running with --where=cat!=Slow to avoid the few tests I’ve got which are known to be really pretty slow. They’re typically tests which compare the answers the BCL gives with the answers Noda Time gives, across the whole of history for a particular calendar system or time zone. I’m pleased to report that the bottleneck in these tests is almost always the BCL, but that doesn’t help to speed them up. If only the “slow” tests had been much slower on Linux, that might have pointed to the problems being in BCL calendar or time zone code.

The ratios vary, but there was enough of a problem under both circumstances for it to be worth looking further.

Step 2: Find a problematic test

I didn’t have very strong expectations one way or another about whether this would come down to some general problem in the JIT on Linux, or whether there might be one piece of code causing problems in some tests but not others. Knowing that there are significant differences in handling of some culture and time zone code between the Linux and Windows implementations, I wanted to find a test which used the BCL as little as possible – but which was also slow enough for the differences in timing to be pronounced and not easily explicable by the problems of measuring small amounts of time.

Fortunately, NUnit produces a TestResult.xml file which is easy to parse with LINQ to XML, so I could easily transform the results from Windows and Linux into a list of tests, ordered by duration (descending), and spot the right kind of test.

I found my answer in UmAlQuraYearMonthDayCalculatorTest.GetYearMonthDay_DaysSinceEpoch, which effectively tests the Um Al Qura calendar for self consistency, by iterating over every day in the supported time period and checking that we can convert from “days since Unix epoch” to an expected “year, month day”. In particular, this test doesn’t rely on the Windows implementation of the calendar, nor does it use any time zones, cultures or anything similar. It’s nicely self-contained.

This test took 2051ms on Linux and 295ms on Windows. It’s possible that those figures were from a debug build, but I repeated the tests using a release build and confirmed that the difference was still similar.

Step 3: Find the bottleneck

At this point, my aim was to try to remove bits of the test at a time, until the difference went away. I expected to find something quite obscure causing the difference – something like different CPU cache behaviour. I knew that the next step would be to isolate the problem to a small piece of code, but I expected that it would involve a reasonable chunk of Noda Time – at least a few types.

I was really lucky here – the first and most obvious call to remove made a big difference: the equality assertion. Assertions are usually the first thing to remove in tests, because everything else typically builds something that you use in the assertions… if you’re making a call without either using the result later or asserting something about the result, presumably you’re only interested in side effects.

As soon as I removed the call to Assert.AreEqual(expected, actual), the execution time dropped massively on Linux, but hardly moved on Windows: they were effectively on a par.

I wondered whether the problem was with the fact that I was asserting equality between custom structs, and so tried replacing the real assertions with assertions of equality of strings, then of integers. No significant difference – they all showed the same discrepancy between Windows and Linux.

Step 4: Remove Noda Time

Once I’d identified the assertions as the cause of the problem, it was trivial to start a new test project with no dependency on Noda Time, consisting of a test like this:

[Test]
public void Foo()
{
    for (int i = 0; i < 1000000; i++)
    {
        var x = 10;
        var y = 10;
        Assert.AreEqual(x, y);
    }
}

This still demonstrated the problem consistently, and allowed simpler experimentation with different assertions.

Step 5: Dig into NUnit

For once in my life, I was glad that a lot of implementation details of a framework were exposed publicly. I was able to try lots of different “bits” of asserting equality, in order to pin down the problem. Things I tried:

  • Assert.AreEqual(x, y): slow
  • Assert.That(x, Is.EqualTo(y)): slow
  • Constructing an NUnitEqualityComparer: fast
  • Calling NUnitEqualityComparer.AreEqual: fast. (Here the construction occurred before the loop, and the comparisons were in the loop.)
  • Calling Is.EqualTo(y): slow

The last bullets two bullets were surprising. I’d been tipped off that NUnitEqualityComparer uses reflection, which could easily differ in performance between Windows and Linux… but checking for equality seemed to be fast, and just constructing the constraint was slow. In poking around the NUnit source code (thank goodness for Open Source!) it’s obvious why Assert.AreEqual(x, y) and Assert.That(y, Is.EqualTo(x)) behave the same way – the former just calls the latter.

So, why is Is.EqualTo(y) slow (on Linux)? The method itself is simple – it just creates an instance of EqualConstraint. The EqualConstraint constructor body doesn’t do much… so I proved that it’s not EqualConstraint causing the problem by deriving my own constraint with a no-op implementation of ApplyTo… sure enough, just constructing that is slow.

That leaves the constructor of the Constraint abstract base class:

protected Constraint(params object[] args)
{
    Arguments = args;

    DisplayName = this.GetType().Name;
    if (DisplayName.EndsWith("`1") || DisplayName.EndsWith("`2"))
        DisplayName = DisplayName.Substring(0, DisplayName.Length - 2);
    if (DisplayName.EndsWith("Constraint"))
            DisplayName = DisplayName.Substring(0, DisplayName.Length - 10);
}

That looks innocuous enough… but maybe calling GetType().Name is expensive on Linux. So test that… nope, it’s fast.

At this point I’m beginning to wonder whether we’ll ever get to the bottom of it, but let’s just try…

[Test]
public void EndsWith()
{
    string text = "abcdefg";
    for (int i = 0; i < Iterations; i++)
    {
        text.EndsWith("123");
    }
}

… and sure enough, it’s fast on Windows and slow on Linux. Wow. Looks like we have a culprit.

Step 6: Remove NUnit

At this point, it’s relatively plain sailing. We can reproduce the issue in a simple console app. I won’t list the code here, but it’s in the GitHub issue. It just times calling EndsWith once (to get it JIT compiled) and then a million times. Is it the most rigorous benchmark in the world? Absolutely not… but when the difference is between 5.3s on Linux and 0.16s on Windows, on the same hardware, I’m not worried about inaccuracy of a few milliseconds here or there.

Step 7: File a CoreCLR issue

So, as I’ve shown, I filed a bug on GitHub. I’d like to think it was a pretty good bug report:

  • Details of the environment
  • Short but complete console app ready to copy/paste/compile/run
  • Results

Exactly the kind of thing I’d have put into a Stack Overflow question – when I ask for a minimal, complete example on Stack Overflow, this is what I mean.

Anyway, about 20 minutes later (!!!), Stephen Toub has basically worked out the nub of it: it’s a culture issue. Initially, he couldn’t reproduce it – he saw the same results on Windows and Linux. But changing his culture to en-GB, he saw what I was seeing. I then confirmed the opposite – when I ran the code having set LANG=en-US, the problem went away for me. Stephen pulled Matt Ellis in, who gave more details as to what was going wrong behind the scenes.

Step 8: File an NUnit issue

Matt Ellis suggested filing an issue against NUnit, as there’s no reason this code should be culture-sensitive. By specifying the string comparison as Ordinal, we can go through an even faster path than using the US culture. So

if (DisplayName.EndsWith("Constraint"))

becomes

if (DisplayName.EndsWith("Constraint", StringComparison.Ordinal))

… and the equivalent for the other two calls.

I pointed out in the issue that it was also a little bit odd that this was being worked out in every Constraint constructor call, when of course it’s going to give the same result for every instance of the same type. When “every Constraint constructor call” becomes “every assertion in an entire test run”, it’s a pretty performance-critical piece of code. While unit tests aren’t important in terms of performance in the same way that production code is, anything which adds friction is bad news.

Hopefully the NUnit team will apply the simple improvement for the next release, and then the CoreCLR team can attack the tougher underlying problem over time.

Step 9: Blog about it

Open up Stack Edit, start typing: “I’ve been following the progress”… :)

Conclusion

None of the steps I’ve listed here is particularly tricky. Diagnosing problems is often more a matter of determination and being unwilling to admit defeat than cleverness. (I’m not denying that there’s a certain art to being able to find the right seam to split the problem in two, admittedly.)

I hope this has been useful as a “start to finish” example of what a diagnostic session can look and feel like. It wasn’t one physical session, of course – I found bits of time to investigate it over the course of a day or so – but it would have been the same steps either way.

Smug, satisfied smile…