IDMS Performance Analysis Steps

IDMS Performance Analysis

Overview

To get detailed diagnostic information for IDMS, we analyze logs and metrics from the Windows Process Activation Service (WAS), IIS, Windows performance counters and SQL Server. Together, these sources show how requests flow through the system, where time is spent, and which resources are under strain:

Source	What it shows
Windows Process Activation Service (WAS)	The health of the IDMS application pool and worker process, including starts, stops, recycles and failures
IIS logs	Every request IDMS receives: which endpoint was called, by which client IP, its response status and how long it took
IIS HTTPERR logs	Requests that IIS rejected or abandoned before IDMS could process them, such as when the request queue is full
Performance counters	Server load over time: executing and queued requests, threads, handles, SQL connection pools, CPU and memory
SQL Server	Which database queries are the most expensive, and how IDMS configuration affects query load

The sections below give the commands for collecting each source. Run the PowerShell commands on the IDMS web server from an elevated (Run as Administrator) PowerShell window. Run the SQL queries in SQL Server Management Studio against the server that hosts the IdExchange database.

Windows Process Activation Service (WAS)

WAS is a core component of IIS that manages application pools and worker processes independently of HTTP. It lets IIS applications listen for and process requests over both HTTP and non-HTTP protocols. IDMS runs in an IIS application pool, so WAS must be running for IDMS to serve requests. WAS also records application pool events in the Windows System event log. Use these events to find out whether the IDMS worker process was recycled, stopped responding or failed during a period of slowness.

Start the WAS Service

Check the current status and startup type of WAS and the World Wide Web Publishing Service (W3SVC):

PowerShell

Get-Service WAS, W3SVC | Select-Object Name, Status, StartType

Set both services to start automatically and start them:

PowerShell

"WAS", "W3SVC" | ForEach-Object {
    Set-Service -Name $_ -StartupType Automatic
    Start-Service -Name $_
}

IIS Request Analysis

Find Slow Requests

Loads the most recent IIS log and lists the 50 slowest requests (5 seconds or longer). time-taken is in milliseconds.

Note: Update $logDir to match your site's log folder (W3SVC<siteId>). The $entries variable created here is reused by the concurrency commands below, so run this first.

PowerShell

$logDir = 'C:\inetpub\logs\LogFiles\W3SVC1'
$log = Get-ChildItem "$logDir\*.log" | Sort-Object LastWriteTime | Select-Object -Last 1
$fields = ((Select-String -Path $log.FullName -Pattern '^#Fields:' | Select-Object -Last 1).Line -replace '^#Fields: ', '') -split ' '

$entries = Get-Content $log.FullName | Where-Object { $_ -notlike '#*' } | ConvertFrom-Csv -Delimiter ' ' -Header $fields

$entries | Where-Object { [int]$_.'time-taken' -ge 5000 } | Sort-Object { [int]$_.'time-taken' } -Descending | Select-Object -First 50 date, time, c-ip, cs-uri-stem, cs-uri-query, sc-status, time-taken | Format-Table -AutoSize

View Requests That Are Executing Right Now

Lists requests that have been running longer than 5 seconds, then the total count of executing requests:

PowerShell

& "$env:windir\system32\inetsrv\appcmd.exe" list requests /elapsed:5000
(& "$env:windir\system32\inetsrv\appcmd.exe" list requests).Count

Request Concurrency

1. Group Requests by Minute and Client IP

PowerShell

$entries | Group-Object -Property @{ e = { $_.time.Substring(0, 5) } }, 'c-ip' | Sort-Object Count -Descending | Select-Object -First 30 Count, Name | Format-Table -AutoSize

2. Total Requests per Minute (All Clients)

PowerShell

$entries | Group-Object { $_.time.Substring(0, 5) } | Select-Object @{n='Minute(UTC)'; e={$_.Name}}, Count | Sort-Object 'Minute(UTC)' | Format-Table -AutoSize

Requests Being Rejected

Counts IIS-level rejections in the HTTPERR logs:

PowerShell

Select-String -Path "$env:windir\System32\LogFiles\HTTPERR\*.log" -SimpleMatch -Pattern 'QueueFull', 'AppOffline', 'Connection_Abandoned_By_ReqQueue', 'Connection_Abandoned_By_AppPool', 'Timer_ConnectionIdle' | Group-Object Pattern | Select-Object Count, Name | Format-Table -AutoSize

Pattern	Meaning
`QueueFull`	Requests rejected with HTTP 503 because the application pool queue was full
`AppOffline`	The application pool was stopped or unavailable
`Connection_Abandoned_By_ReqQueue`	The worker process stopped responding to queued requests
`Connection_Abandoned_By_AppPool`	The application pool stopped responding to requests in progress
`Timer_ConnectionIdle`	Normal cleanup of idle client connections

Record the Application Pool Settings

PowerShell

& "$env:windir\system32\inetsrv\appcmd.exe" list apppool "IDMS" /text:*

Performance Counters

Start the Performance Counter Collection

Samples every 15 seconds and writes a CSV file to C:\\PerfLogs:

PowerShell

New-Item -ItemType Directory -Path 'C:\PerfLogs' -Force | Out-Null
$counters = @(
    '\ASP.NET Applications(__Total__)\Requests Executing',
    '\ASP.NET Applications(__Total__)\Requests In Application Queue',
    '\ASP.NET\Requests Queued',
    '\ASP.NET\Requests Rejected',
    '\ASP.NET\Requests Current',
    '\ASP.NET\Request Wait Time',
    '\Process(w3wp*)\Thread Count',
    '\Process(w3wp*)\Handle Count',
    '\Process(w3wp*)\% Processor Time',
    '\Process(w3wp*)\Private Bytes',
    '\.NET Data Provider for SqlServer(*)\NumberOfPooledConnections',
    '\.NET Data Provider for SqlServer(*)\NumberOfActiveConnectionPools',
    '\TCPv4\Connections Established',
    '\Processor(_Total)\% Processor Time',
    '\Memory\Available MBytes'
)
logman create counter IDMS_Slowness -c $counters -si 00:00:15 -f csv -o 'C:\PerfLogs\IDMS_Slowness' -max 500
logman start IDMS_Slowness

Stop the Performance Counter Collection

PowerShell

logman stop IDMS_Slowness
logman delete IDMS_Slowness

SQL Analysis

User Attribute Query

Identifies credential policies whose print attributes are pulled from the directory (Active Directory):

SQL

USE [IdExchange];
SELECT UserCredentialKey, CustomPrintDataAttributes
FROM IdExchange.UserCredentialType
WHERE CustomPrintDataAttributes LIKE '%adattribute%';

Determine the Most Expensive Queries

Top 20 queries by total elapsed time since SQL Server last started:

SQL

SELECT TOP 20
       qs.execution_count,
       qs.total_elapsed_time / 1000                        AS total_ms,
       qs.total_elapsed_time / qs.execution_count / 1000   AS avg_ms,
       qs.max_elapsed_time / 1000                          AS max_ms,
       qs.total_logical_reads / qs.execution_count         AS avg_reads,
       SUBSTRING(t.text, 1, 400)                           AS query_text
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) t
WHERE t.dbid = DB_ID('IdExchange') OR t.dbid IS NULL
ORDER BY qs.total_elapsed_time DESC;