App Insights traces are out-of-order (Azure Functions app)

Question

I send my Azure Functions TraceWriter output to Application Insights, via the App Insights integration. When I look for the traces, they don't appear in order. For example, I can run a query like

traces | where operation_Id == "<guid>" | order by timestamp asc

and get back 19 trace records from this invocation. But between them they only have 5 unique timestamps and so the records do not come back in perfect order.

Is there any other way to sort the traces?

---

This query confirms that the timing sent to App Insights is millisecond resolution - if that. (micros and nanos are always =0).

traces | project timestamp, datetime_part('microsecond', timestamp)

Answer 1

I'm waiting for an official answer from the App Insights team to see if there's a way we can provide greater precision, but we may be at the mercy of DateTime.Now

---

[Update]: It looks like App Insights will be improving this. They filed two issues to track:

• https://github.com/Microsoft/ApplicationInsights-Home/issues/189
• https://github.com/Microsoft/ApplicationInsights-Home/issues/190

The workaround still applies until these are fixed.

---

However, you can add your own measurements using a Stopwatch and even have it be sortable in App Insights. You do this with the structured logging capabilities in ILogger.

A quick example:

using System.Net;
using System.Diagnostics;

public static HttpResponseMessage Run(HttpRequestMessage req, ILogger logger)
{
    // offset the Stopwatch with the current ticks so multiple runs don't overlap.
    var startTicks = DateTime.UtcNow.Ticks;
    Stopwatch sw = Stopwatch.StartNew();
    logger.LogInformation("[{PreciseTimeStamp}] Log 1", (startTicks + sw.ElapsedTicks).ToString());
    logger.LogInformation("[{PreciseTimeStamp}] Log 2", (startTicks + sw.ElapsedTicks).ToString());
    logger.LogInformation("[{PreciseTimeStamp}] Log 3", (startTicks + sw.ElapsedTicks).ToString());
    logger.LogInformation("[{PreciseTimeStamp}] Log 4", (startTicks + sw.ElapsedTicks).ToString()); 
    logger.LogInformation("[{PreciseTimeStamp}] Log 5", (startTicks + sw.ElapsedTicks).ToString());
    sw.Stop();

    return req.CreateResponse(HttpStatusCode.OK);
}

This will output something like:

2018-03-06T19:46:32.278 [Info] [636559623922781779] Log 1
2018-03-06T19:46:32.278 [Info] [636559623922783356] Log 2
2018-03-06T19:46:32.278 [Info] [636559623922784381] Log 3
2018-03-06T19:46:32.278 [Info] [636559623922785325] Log 4
2018-03-06T19:46:32.278 [Info] [636559623922786254] Log 5

And in App Insights, you can sort with order by tolong(customDimensions.prop__PreciseTimeStamp) asc. But since the timestamp is in the message, you could sort by that as well.

If you want to get fancier, you can add the new column to your trace without it showing up in your message with a logging helper like this:

public static void LogWithPrecision(ILogger logger, string message, long ticks)
{
    var state = new Dictionary<string, object>
    {
        ["PreciseTimeStamp"] = ticks.ToString()
    };

    logger.Log(LogLevel.Information, 0, state, null, (s, e) => message);
}

You can sort the same way as above but without the ticks showing up in the message.

Answer 2

I'm looking for traces for a specific Azure Function invocation, and they don't appear in order

Actually, there are always three message status for the same operation. As you know, their timestamps are the same.You could filter operation_Id and message status to get specific Azure Function invocation.

Is there any other way to sort the traces?

As you mentioned that you don't believe timestamp field,so you could store the datetime to custom traces. Then you could know the order of records. Such as this article.

// Track a Metric
var metric = new MetricTelemetry("Test Metric", DateTime.Now.Millisecond);
UpdateTelemetryContext(metric.Context, context, name);
telemetryClient.TrackMetric(metric);