Monitoring Upgrade performance with Application Insights

Dynamics 365 Business central sends upgrade signals that represent the application starting point of a single upgrade routine (AL0000EJ9 signal sent every time HasUpgradeTag in Codeunit 999 is called) and the ending point (AL0000EJA signal sent every time SetUpgradeTag in Coduenit 999 is called). See more here 

Extension Update Trace Telemetry – Business Central | Microsoft Docs

This means that calculating the interval between the 2 signals within the same upgrade tag, in the same Upgrade event, will provide the execution time of a specific upgrade routine.

Why are these signals so important?

Within SaaS there is a specific upgrade window set by default or – warmly recommended – set by partner or customer. This determines the max time constraint every single environment has to perform a minor or major upgrade.

In some circumstances, the data upgrade could be the part of the upgrade that is taking most of the time. This depends mainly on 3 factors:

1. The number of records per environment impacted by the upgrade routine
2. Goodness of the code written with an accent on performance

The number of records should not be considered per environment, as clearly written above, and not per single Company since the upgrade routines typically are running on a per Company basis.

The following KQL query will be able to catch every single upgrade tag duration per company given a specific AAD Tenant ID and environment name and a time window.

//Monitor long running data upgrades

let GetLongRunningUpgradeTags = (StartDateTime: datetime, EndDateTime: datetime, TenantID: string, EnvironmentName: string ){

union AppInsightsTraces

| where TIMESTAMP >= StartDateTime and TIMESTAMP = EndDateTime

| where customDimensions.aadTenantId == TenantID

| where customDimensions.environmentName == EnvironmentName

| where customDimensions.eventId == 'AL0000EJA'

| extend upgradeTenantID = tostring(customDimensions.aadTenantId)

| extend upgradeEnvironmentName = tostring(customDimensions.environmentName)

| extend upgradeTag = tostring(customDimensions.eventID)

| extend upgradeEventType = tostring( customDimensions.alUpgradeTag )

| extend upgradeCompanyName = tostring(customDimensions.alCompanyName)

| project TIMESTAMP, message, upgradeTag, customDimensions, session_Id, upgradeTenantID, upgradeEnvironmentName, upgradeEventType, upgradeCompanyName

| join kind=inner

(

union AppInsightsTraces

| where TIMESTAMP >= StartDateTime and TIMESTAMP = EndDateTime

| where customDimensions.aadTenantId == TenantID

| where customDimensions.environmentName == EnvironmentName

| where customDimensions.eventId == 'AL0000EJ9'

| extend upgradeTenantID = tostring(customDimensions.aadTenantId)

| extend upgradeEnvironmentName = tostring(customDimensions.environmentName)

| extend upgradeTag = tostring(customDimensions.eventID)

| extend upgradeEventType = tostring( customDimensions.alUpgradeTag )

| extend upgradeCompanyName = tostring(customDimensions.alCompanyName)

| project TIMESTAMP, message, upgradeTag, customDimensions, session_Id, upgradeTenantID, upgradeEnvironmentName, upgradeEventType, upgradeCompanyName

) on upgradeEnvironmentName, session_Id, upgradeCompanyName, upgradeEventType

| extend upgradeTagDuration = TIMESTAMP - TIMESTAMP1

| extend upgradeTagDurationInSec = round(upgradeTagDuration / 1s)

| project session_Id, TIMESTAMP, upgradeTagDuration, upgradeTagDurationInSec, upgradeCompanyName, upgradeEventType

};

GetLongRunningUpgradeTags(now(-24h), now(), "a11cccc1-1e11-11ec-c1c3-11e1f111b111", "Production")

| order by session_Id desc, TIMESTAMP desc //data upgrade tag timeline execution

//| order by session_Id desc, upgradeTagDuration desc //data upgrade tag longest execution

Ordering by session and TIMESTAMP will provide the timeline (execution order) of the upgrade while ordering by session and upgradeTagDuration sort the single upgrade routine per duration. This query is very good and practical in identify bottlenecks that were rolling back upgrades due to long running data upgrades.

Let’s make a practical example and a good tip about coding for a better performance during upgrade.

We detected few environments rolling back major upgrades due to long running data upgrade when moving from 18.5 to 19.0. Running that query resulted in determines that approx. 98% of the upgrade time it was related to the GENITEMPOSTINGROUPS tag.

See below a small snippet of the result considering an environment with a discrete number of companies and sorted by duration

We detected that a huge number of items per single company was there and, overall, some Per Tenant Extension (PTE) were interfering with the standard upgrade routine.

There is a very useful AL Statement that could be used to prevent some code interference during upgrades: GetExecutionContext()

This could be used in the typical Event Subscriber that holds the code that is interfering (such as e.g. OnBeforeModify or OnAfterModify) with a statement like the following

        if GetExecutionContext() = ExecutionContext::Upgrade then

            exit;

Bottom line. Worth also pointing the attention on this specific signal ingestion and cost management in relation of the upgrade signals. These signals are sent to the Application Insight resource every time Codeunit 9999 executes HasUpgradeTag and SetUpgradeTag function.

This means that if you have several hundred companies and the upgrade do have a discrete number of upgrade routine, you might end up in receiving several thousands of signals in your ingestion point.

Currently, it is not possible to opt out for specific signals and cost management has to be handled post-ingestion as reported in BCTech/FAQ.md at master · microsoft/BCTech (github.com)

This post was originally published on this site