This is part eight of the Building a Voice-Driven TV Remote series:

1. Getting The Data
2. Adding Search
3. The Device API
4. Some Basic Alexa Commands
5. Adding a Listings Search Command
6. Starting to Migrate from HTTP to MQTT
7. Finishing the Migration from HTTP to MQTT
8. Tracking Performance with Application Insights

In the last part I vastly improved the performance of the app by switching from HTTP to MQTT. With that in place, the next step I wanted to take was seeing where the remaining time was being spent. How quick are calls to the search service or the database? How long are the nightly downloads and imports taking? To answer these questions I set out to add Application Insights to the app to really get some visibility.

Initial Setup

The basic setup for Application Insights is as easy as it gets. After you create a new Insights app and get the instrumentation key from it, all you need to do is add an app setting to your function app named APPINSIGHTS_INSTRUMENTATIONKEY and you'll start getting metrics reporting to Insights automatically. With that in place, for example, I can easily see the execution history for the DownloadLineup function:

Each morning that is taking around 6-8s seconds to run, which is perfectly fine to me.

Tracking Sub-Operations

The main thing I wanted to get insight into is where the RemoteSkill function was spending its time, to figure out how I can make that as fast as possible. I could already see the overall function durations using the same method as above, but that doesn't help me see how it spends its time during that duration.

To add this in, I pulled in the Microsoft.ApplicationInsights NuGet package, which allows me to interact with Application Insights programmatically. First, I added a new file named telemetry.fsx to the function:

module Telemetry

open System
open Microsoft.ApplicationInsights
open Microsoft.ApplicationInsights.Extensibility
open Microsoft.ApplicationInsights.DataContracts

let private instrumentationKey = Environment.GetEnvironmentVariable("APPINSIGHTS_INSTRUMENTATIONKEY")
let private telemetryClient = TelemetryClient(InstrumentationKey = instrumentationKey)

let setOperationId operationId =
    telemetryClient.Context.Operation.Id <- operationId

let startOperation (name:string) = 
    telemetryClient.StartOperation<DependencyTelemetry>(name)

Here I create a TelemetryClient and expose a couple utility methods: one to set the overall operation ID so that all sub-operations will be tracked within the overall request operation, and another to start a new sub-operation. The operation is an IDisposable, so the duration for it lasts from when it's created until it's disposed.

With that in place, all I needed to do was start sprinkling calls to it all around the function implementation. For example, to track the calls to search service in search.fsx:

let private searchShows request =
    use operation = Telemetry.startOperation "ShowSearch"
    search "shows" request |> ShowSearchResults.Parse

let private searchChannels request =
    use operation = Telemetry.startOperation "ChannelSearch"
    search "channels" request |> ChannelSearchResults.Parse

Or to track executing a command in commands.fsx:

let executeCommand commandSlug = 
    use operation = Telemetry.startOperation "ExecuteCommand"
    ...

With a bunch of these in place I started executing commands and searches via Alexa to see how it looked. Here's an example of how one request stacked up:

The vertical order can get a little mixed up when operations start really close together, but you can still get a good idea of the flow here. In this case the whole request took 1385ms, 1024ms of which was spent executing the commands to change the channel. This is somewhat expected, since I had added a 250ms sleep in between each command execution to avoid overloading my cable box.

One obvious performance improvement here in terms of the function itself would be to allow for sending multiple commands at once via IoT Hub, and do the pauses on the Raspberry Pi instead of in the function. This would also be a nice cost optimization since with Azure Functions you pay for the time your function is spent running, and most of the time here is actually spent sleeping.

The calls to the search service are also a little bit slower than I was expecting so I'll also be looking into how to tweak that as well.