Code for https://honestillusion.com/2021/12/14/simple-timings.html

TimeThis.cs

// Copyright (c) 2019-2020 James M. Curran/Novel Theory LLC.  All rights reserved.
// Licensed under the Apache License, Version 2.0. 
// See License.txt in the project root for license information.

using System;
using System.Diagnostics;
using Microsoft.Extensions.Logging;

namespace NovelTheory.Common
{
	// 
	public class TimeThis : IDisposable
	{
		private string _msg;
		private Stopwatch _sw;
		private ILogger _logger;

		public TimeThis(ILogger logger, string msg= null)
		{
			_msg = msg ?? "";
			_logger = logger;
			_logger.LogInformation("Start:" + msg);
			_sw = new Stopwatch();
			_sw.Start();
		}
		public void Dispose()
		{
			_sw.Stop();
			_logger.LogInformation($"Complete:{_msg}: Elapsed: {_sw.Elapsed}");
		}
	}


	public static class TimeThisExt
	{
		public static TimeThis TimeThis(this ILogger logger, string msg = null) 
			=> new TimeThis(logger, msg);
	}
}

Good idea! Thanks.

A suggestion: You can completely eliminate memory allocations and make it 3× faster:

• TimeThis does not have to be a class; make it a struct
• "Pre-define" logger methods to avoid allocations and time spent on parsing log message templates
• Use ValueStopwatch (which is a struct) instead of Stopwatch (a class)

// Copyright (c) 2019-2020 James M. Curran/Novel Theory LLC.  All rights reserved.
// Licensed under the Apache License, Version 2.0. 
// See License.txt in the project root for license information.

namespace NovelTheory.Common
{
    using System;
    using System.Diagnostics;
    using Microsoft.Extensions.Logging;

    public readonly struct TimeThis : IDisposable
    {
        private static readonly Action<ILogger, string?, Exception?> _started;
        private static readonly Action<ILogger, string?, TimeSpan, Exception?> _completed;

        private readonly string _msg;
        private readonly ValueStopwatch _sw;
        private readonly ILogger _logger;

        static TimeThis()
        {
            _started = LoggerMessage.Define<string?>(
                logLevel: LogLevel.Information,
                eventId: new EventId(1, "Start"),
                formatString: "Start: {Message}");

            _completed = LoggerMessage.Define<string?, TimeSpan>(
                logLevel: LogLevel.Information,
                eventId: new EventId(2, "Complete"),
                formatString: "Complete: {Message}; Elapsed: {Elapsed}");
        }

        public TimeThis(ILogger logger, string? msg = null)
        {
            _msg = msg ?? string.Empty;
            _logger = logger;
            _started(logger, msg, null);
            _sw = ValueStopwatch.StartNew();
        }

        public void Dispose()
        {
            _completed(_logger, _msg, _sw.Elapsed, null);
        }

        /// <summary>
        /// Value-type replacement for <see cref="Stopwatch"/> which avoids allocations.
        /// </summary>
        /// <remarks>
        /// Based on <seealso href="https://github.com/dotnet/extensions/blob/master/src/Shared/src/ValueStopwatch/ValueStopwatch.cs"/>.
        /// </remarks>
        private readonly struct ValueStopwatch
        {
            private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency;
            private readonly long _startTimestamp;

            private ValueStopwatch(long startTimestamp)
            {
                _startTimestamp = startTimestamp;
            }

            /// <summary>
            /// Creates a new <see cref="ValueStopwatch"/> that is ready to be used.
            /// </summary>
            public static ValueStopwatch StartNew() => new(Stopwatch.GetTimestamp());

            public bool IsActive => _startTimestamp != 0;

            /// <summary>
            /// Gets the time elapsed since the stopwatch was created with <see cref="StartNew"/>.
            /// </summary>
            public TimeSpan Elapsed
            {
                get
                {
                    // Start timestamp can't be zero in an initialized ValueStopwatch.
                    // It would have to be literally the first thing executed when the machine boots to be 0.
                    // So it being 0 is a clear indication of default(ValueStopwatch):
                    if (!IsActive)
                    {
                        throw new InvalidOperationException(
                            "An uninitialized, or 'default', ValueStopwatch cannot be used to get elapsed time.");
                    }

                    long end = Stopwatch.GetTimestamp();
                    long timestampDelta = end - _startTimestamp;
                    long ticks = (long)(TimestampToTicks * timestampDelta);

                    return new TimeSpan(ticks);
                }
            }
        }
    }

    public static class TimeThisExt
    {
        public static TimeThis TimeThis(this ILogger logger, string? msg = null)
            => new(logger, msg);
    }
}

Benchmark results:

| Method |      Mean |    Error |   StdDev | Ratio |  Gen 0 | Allocated |
|------- |----------:|---------:|---------:|------:|-------:|----------:|
|  Class | 173.39 ns | 8.868 ns | 0.486 ns |  1.00 | 0.0386 |     162 B |
| Struct |  57.83 ns | 0.618 ns | 0.034 ns |  0.33 |      - |         - |