Skip to content
Dynamic Telemetry is a PROPOSAL : please provide feedback! :-)

Dynamic Telemetry is not an implementation, it's a request for collaboration, that will lead to an shared understanding, and hopefully one or more implementations.

Your feedback and suggestions on this document are highly encouraged!

Please:

  1. Join us, by providing comments or feedback, in our Discussions page

  2. Submit a PR with changes to this file ( docs/Demos.0.DynamicID.md)

Direct Sharing URL

http://microsoft.github.io/DynamicTelemetry/docs/Demos.0.DynamicID/

Demo 0 - Durable ID's Explanation

Using DurableID in OpenTelemetry, to locate the source of the the expense

This demonstration will showcase and contrast two logging messages in OpenTelemetry. One will use a Durable Identifier, and the other will not. It's expected that not all software using OpenTelemetry will utilize a durable identifier, even though, in Dynamic Telemetry, the use of the DurableID is considered a best practice. A durable identifier functions like a GPS or homing beacon, mapping any row of telemetry to a specific line of code.

In Microsoft .net platform, a durable identifier is created automatically at compile time for OpenTelemetry user using ILogger - when the author of the software follows best practices.

Contrasting C# that makes use of Durable ID's, with C# that does not

Let's examine code that makes use of a durable identifier versus one that doesn't. We'll inspect both in the Application Insights Log database, to spot the difference.

Seeing the DurableID in Azures Application Insights

Lets start with the recommended way to log in .NET; using ILogger, with a compiler generated Durable ID.

private void LogWithDurableID()
{
    //
    // Log a message with a DurableID; 'behind the scenes' the dotnet compiler will
    //     generate two ID's - one numerical, and one a string
    //
    // Behind the scenes, the compiler uses this syntax to create identifiers that are included
    //     into the telemetry row, that can be used visually, and in automation, to map
    //     from row of telemetry, to line of code - very useful when extending the capabilities
    //     of your telemetry assets
    //
    // NOTE: adding the _instanceID is to showcase how, we can more easily locate this line
    //     of code, as compared with the earlier 'flattened' version.  The compiler will attach
    //     an 'EventName' property with the value of our function name "LogLaunch".  We can use this
    //     instead of regular expressions to locate and aggregate
    //
    LogLaunch(_logger, _version, _instanceID);
}

[LoggerMessage(Level = LogLevel.Information, Message = "Launch, ver={version}, instantion={instantionID}")]
static partial void LogLaunch(ILogger logger, string version, Guid instantionID);

private void LogWithoutDurableID()
{
    //
    // Log a message without a DurableID;  while simple, this log will provide struggles later
    //    because while we receive a property bag of the variables (_version), we will not know
    //    which line of code emitted the telemetry - as our only identtifer will be the
    //    'flattened' payload string
    //
    // NOTE: adding the _instanceID is to showcase how, once 'flattened' this unrecommendable
    //    method of logging makes for tricky (and expensive) backend searching
    //
    _logger.LogInformation($"Launch, ver={_version}, instantion={_instanceID}");
}

Full Example Code

using Microsoft.AspNetCore.Mvc.RazorPages;
using System.Diagnostics.Metrics;

namespace DynamicTelemetry_Demo_DurableIds.Pages
{
    public partial class IndexModel : PageModel
    {
        private readonly ILogger<IndexModel> _logger;
        private static string _version = "0.0.4";
        private Guid _instanceID = Guid.NewGuid();

        public IndexModel(ILogger<IndexModel> logger, IMeterFactory meterFactory)
        {
            _logger = logger;

            //var meter = meterFactory.Create("DynamicTelemetry.Metric.Conversion");
            //_getCounter = meter.CreateCounter<int>("LogLaunch");

            // On Launch emit two logs - seemingly identical, one has a DurableID
            //_getCounter.Add(1);
            LogWithDurableID();
            LogWithoutDurableID();


            // START : LoopRandomGUID
            // Generate some data that will be tough to aggregate
            for (int i = 0; i < 1000; i++)
            {
                _logger.LogInformation($"Loop, random ID={Guid.NewGuid()}");
                LogRandomGuid(_logger, Guid.NewGuid());
            }
            // END : LoopRandomGUID
        }

        // StartExample:NoDurableId
        private void LogWithoutDurableID()
        {
            //
            // Log a message without a DurableID;  while simple, this log will provide struggles later
            //    because while we receive a property bag of the variables (_version), we will not know
            //    which line of code emitted the telemetry - as our only identtifer will be the
            //    'flattened' payload string
            //
            // NOTE: adding the _instanceID is to showcase how, once 'flattened' this unrecommendable
            //    method of logging makes for tricky (and expensive) backend searching
            //
            _logger.LogInformation($"Launch, ver={_version}, instantion={_instanceID}");
        }
        // EndExample:NoDurableId


        // StartExample:DurableId
        private void LogWithDurableID()
        {
            //
            // Log a message with a DurableID; 'behind the scenes' the dotnet compiler will
            //     generate two ID's - one numerical, and one a string
            //
            // Behind the scenes, the compiler uses this syntax to create identifiers that are included
            //     into the telemetry row, that can be used visually, and in automation, to map
            //     from row of telemetry, to line of code - very useful when extending the capabilities
            //     of your telemetry assets
            //
            // NOTE: adding the _instanceID is to showcase how, we can more easily locate this line
            //     of code, as compared with the earlier 'flattened' version.  The compiler will attach
            //     an 'EventName' property with the value of our function name "LogLaunch".  We can use this
            //     instead of regular expressions to locate and aggregate
            //
            LogLaunch(_logger, _version, _instanceID);
        }

        [LoggerMessage(Level = LogLevel.Information, Message = "Launch, ver={version}, instantion={instantionID}")]
        static partial void LogLaunch(ILogger logger, string version, Guid instantionID);
        // EndExample:DurableId


        // START_DEFINE : LogRandomGuid
        [LoggerMessage(Level = LogLevel.Information, Message = "Loop, random ID={guid}")]
        static partial void LogRandomGuid(ILogger logger, Guid guid);
        // END_DEFINE : LogRandomGuid
    }
}

Spotting the difference in your database

While both of these logging methods result in the same printf() ('flatted') log, the one with the Durable ID offers many extra goodies.

Please recall the source snippets above; when these two lines of code manifest in our database, they look as follows.

Upon examining each of these rows in the telemetry data, you will notice that one contains an entry in the custom definitions while the other does not.

This customDimension column is generated by the compiler, and includes a string based EventName as well as a numerical EventId.

You can see an expanded version of these fields below.

Trying to reason over lots of Logs

Scenarios that require performant study and aggregation of clusters of Logs, really struggle with 'flattened' logs. This is discussed more in the Position Paper on Durable ID's, but in short, due to the addition of a GUID, each row of telemetry is different from another.

You can see this quickly, with a quick dcount (distinct count) of each message.

Notice in this screenshot, that the number of distinct messages is similar to the number of absolute messages - without a Durable Identifier, spotting the differences can be difficult. This in turn complicates cost reductions, as well as any number of the Dynamic Telemetry scenarios.

Use Azure Monitor and KQL language to locate an expensive OpenTelemetry log

Lets go back to the original code; and use the compiler generated Durable ID to quickly count the ILogger log, that followed recommended guidance.

// Generate some data that will be tough to aggregate
for (int i = 0; i < 1000; i++)
{
    _logger.LogInformation($"Loop, random ID={Guid.NewGuid()}");
    LogRandomGuid(_logger, Guid.NewGuid());
}

[LoggerMessage(Level = LogLevel.Information, Message = "Loop, random ID={guid}")]
static partial void LogRandomGuid(ILogger logger, Guid guid);

This time, instead of trying to deduplicate with the message (where the GUID all bug guarantees each row is unique), we will deduplicate with the extracted EventName field.

You'll notice "LogRandomGuid" quickly stands out, with a tidy dcount(), whereas the other similar log is still unclear.

With the event name in hand, we can quickly do all sorts of quick study and aggregation across our logs. With a little dreaming, it's easy to appreciate the value of the investment. What was once multiple pages of rows has now been streamlined into only five rows.