HOWTO: Find NAV user running long SQL queries

I was recently tasked with determining why a NAV 2018 installation was occasionally performing poorly.  I suspected that one or more users were running particular queries or functions but I needed to find a way to prove that.  The catch was I am not a SQL DBA and I know even less about NAV.  But that’s how it is sometimes.  It falls on you when no one else can figure it out.

I did a lot of Googling but the consensus seems to be that it’s not possible to find the specific NAV user running any given SQL query because from the perspective of SQL every query is run as the NAV service account.  I found posts that explain how to enable SQL/NAV debugging to try and capture the user name in real time but this puts a lot of extra load on an already poorly performing system and we didn’t know exactly when the issue would occur.

I decided to build a NAV 2018 lab environment with multiple users to see if I can find a way to determine which user was running which queries.  I came up with something that seems to work and wanted to share it in case it benefits others.

In the screenshot below, I have 2 users called ADMIN-RV and JSMITH.  I used the NAV Client to perform various NAV functions with each user.  The report below shows how long each query took to execute, the full SQL query (not limited to just 4,000 characters) and most importantly of all, the actual NAV user account that executed the query.  The rows that do not include a username are internal system queries and are not associated with any end user.  The report below shows all queries for testing but in production we would limit it to queries that ran for longer durations.

Important: I discovered that this process only works with NAV 2018 Cumulative Update 20 as there appears to be a bug in earlier versions.  I confirmed this behavior by building a new server and installing NAV 2018 CU5 (our current production environment) and running my script.  It did not return any users.  I then performed an in-place upgrade from CU5 to CU20 in my lab and found that the report then worked as expected. 

How this Script Works

– We know from the many pages of Google search results that trying to determine the user executing a query from the SQL server side of things is almost impossible as SQL receives the query from the NAV service account

– We know that the NAV server itself must know which user executes a query.  We also know that NAV has a built in facility to automatically write to the event log any SQL query that exceeds a given execution threshold.  This is defined in the NAV Admin console here:

– That event log entry looks like this (found in Microsoft-DynamicsNAV-Common/Admin)  It tells us the specify query but it doesn’t tell us who executed it.  There is a field called ServerSessionUniqueID but that field is all zeros in the current CU5 production environment as shown below:

– By contrast, here is the same event entry in my lab environment, only this time running cumulative update 20.  You’ll notice that the ServerSessionUniqueID is now populated:

– If we now run the PowerShell command Get-NAVServerSession we see that it returns a SessionUniqueID field for each logged in user that it turns out maps 1 to 1 to the ServerSessionUniqueID in the event log message

– That’s the magic link we needed to make the required association.  I was then able to write a PowerShell script that combines that data from Event Viewer and the cmdlet above.  That script is included below

– One thing to note is that the Event log in question (Microsoft-DynamicsNAV-Common/Admin) by default only stores a rolling 1MB of data.  This is eaten up very quickly and so it’s recommended to increase this so you have a larger timespan of data to work with

# From a NAV 2018 CU20 or newer server, find all long running queries and produce a report showing which user ran those queries
# NAV; Dynamics; Report; User

# Import the NAV Admin module so we can use the Get-NAVServerSession cmdlet
Import-Module "C:\Program Files\Microsoft Dynamics NAV\110\Service\NavAdminTool.ps1" | Out-Null

Function Get-EventLogData
{
    param(
    [Parameter(Mandatory=$true)][String]$Logname,
    [Parameter(Mandatory=$false)][Int]$EventID,
    [Parameter(Mandatory=$false)][String]$ComputerName)

    $AllEvents = @()
    $EventDataHash = @{}

    try {$Events = Get-WinEvent -FilterHashtable @{logname="$LogName"; id=$EventID} -ComputerName $ComputerName -ErrorAction Stop }
    catch { Write-warning "Unable to get any events. $_" ; break }
    
    ForEach($Event in $Events)
    {
        $EventXML = [xml]$Event.ToXml()
        
        ForEach($One in $EventXML.Event.EventData.Data)
        { 
            $EventDataHash.($One.Name) = $One."#Text"
            $EventObject = New-Object PSObject -Property $EventDataHash
            $Event | Add-Member -MemberType NoteProperty -Name EventData -Value $EventObject -Force      
        }

        $AllEvents += $Event
    }

    Write-Output $AllEvents
}

# Define the name of the NAV instance that you wish to report on
$NAVInstanceName = 'DynamicsNAV110'

# Define all of the NAV servers in your pool so we can pull the event logs off of each one
$NAVServers = @'
NAV2
'@ -split "`r`n"

# This will get all of the users connected to the NAV server at the time of execution and get their SessionUniqueID which we can later use to correlate it with the EventLog
$ActiveUsers = Get-NAVServerSession $NAVInstanceName | select UserID, SessionUniqueID

$Output = @()

ForEach($NAVServer in $NAVServers)
{
    write-host "Processing $NAVServer" -ForegroundColor Green
    
    $SQLEvents = Get-EventLogData Microsoft-DynamicsNAV-Common/Admin -EventID 705 -ComputerName $NAVServer | where {$_.message -match 'took longer than the given threshold'}

    ForEach($Event in $SQLEvents)
    {
        $str = $Event.message -split "`r`n"
        $ServerSessionUniqueID = ((($str | where {$_ -match 'ServerSessionUniqueID:'}) -split ":")[1]).trim()

        $Output += [pscustomobject]@{
            NAVServer = $NAVServer
            TimeCreated = $Event.timecreated
            ExecutionTime = ((($str | where {$_ -match 'Execution TIme:'}) -split ":")[1]).trim()
            Instance = ((($str | where {$_ -match 'Server instance:'}) -split ":")[1]).trim()
            UserName = ($ActiveUsers | where {$_.SessionUniqueID -eq $ServerSessionUniqueID}).userid
            SQLQuery = $Str[13] #| select-string "message:" -context 0,1
            ServerSessionUniqueID = $ServerSessionUniqueID
            #ClientSessionID = ((($str | where {$_ -match 'ClientSessionID:'}) -split ":")[1]).trim() - Not used for this process
            #ClientActivityID = ((($str | where {$_ -match 'ClientActivityID:'}) -split ":")[1]).trim() - Not used for this process
        }
    }
}

# Filter out all of the entries where the serversessionuniquieid is blank as they appear to be system level queries that we don't care about
$Output | where {$_.serversessionuniqueid -ne '{00000000-0000-0000-0000-000000000000}'} | select * -ExcludeProperty Serversessionuniqueid | Out-GridView -Title "NAV SQL Queries by User"