Trace Process Monitor

9 février 2018

Commentaires fermés

Chiffres à l’appui (métriques applicatives), un client me remonte une baisse générale de performance sur un serveur hébergeant une instance SQL Server. Elle se produit tous les jours de 11h00 à 11h06. Après vérification via une trace Perfmon, les ressources matérielles CPU, mémoire, disques ne montrent aucun signe de faiblesse. Du côté de SQL Server, RAS non plus : pas de requête de nature à entraîner une baisse significative de performance. La solution retenue est Process Monitor pour détecter la source de cette anomalie, l’objectif étant d’enregistrer une l’activité détaillée des process sur le serveur.

Pour mes besoins, Process Monitor est encapsulé dans un script Powershell mais rien ne vous empêche de l’exécuter en ligne de commande DOS. Le script Powershell est disponible sur Github :

https://github.com/concatskills/ProcessMonitor

La solution Powershell contient les éléments suivant :
– ProcessMonitor.ps1 : Script Powershell principal prenant en paramètre la durée en seconde d’enregistrement de la trace
– Dossier exe : contient le binaire de Process Monitor (procmon.exe)
– Dossier out : créé à la volée, stocke les traces au format d’origine pml (Processus Moniteur Format) et converties par la suite au format CSV

Le script principal ProcessMonitor.ps1 contient deux étapes principales :
– Enregistrement de la trace : Premier Start-Process
– Conversion de la trace au format CSV : Second Start-Process

<#
.SYNOPSIS
    Process Monitor
.DESCRIPTION
    Record trace to monitor process
.NOTES
    File Name      : ProcessMonitor.ps1
    Author         : Sarah BESSARD (sarah.bessard@concatskills.com)
    Prerequisite   : PowerShell V5 over Vista and upper.
    Copyright 2018 - Sarah BESSARD / CONCAT SKILLS
.LINK
    Script posted over:
    https://www.concatskills.com/2018/02/09/trace-process-monitor
    https://github.com/concatskills/ProcessMonitor
.EXAMPLE
    .\ProcessMonitor.ps1 -DurationInSec 30
#>

param(
    [Parameter(Mandatory=$True)] [int]$DurationInSec
    )

clear-host

$ScriptDirectory = Split-Path $MyInvocation.MyCommand.Path
$ScriptDirectoryExe = "$($ScriptDirectory)\exe"
$ScriptDirectoryOut = "$($ScriptDirectory)\out"

Push-Location $ScriptDirectory

$ProcMonExe = "$($ScriptDirectoryExe)\Procmon.exe"
$CapturePml = "$($ScriptDirectoryOut)\capture.pml"
$CaptureCsv = "$($ScriptDirectoryOut)\capture.csv"

$DurationInSec = [System.Math]::Abs($DurationInSec)

If(!(test-path $ScriptDirectoryOut)) { New-Item -ItemType Directory -Force -Path $ScriptDirectoryOut } else { Get-ChildItem -Path $ScriptDirectoryOut -Include *.* -Recurse  | remove-Item -Recurse -Force }
 
$argstart = "/Quiet /AcceptEula /Minimized /Backingfile $CapturePml /Runtime $DurationInSec"
$argstop = "/Openlog $CapturePml /SaveAs $CaptureCsv" 

# Warning UAC & run as admin
Start-Process -FilePath $ProcMonExe -ArgumentList $argstart -wait -Verb RunAs
Start-Process -FilePath $ProcMonExe -ArgumentList $argstop -wait -Verb RunAs

.SYNOPSIS

Process Monitor

.DESCRIPTION

Record trace to monitor process

.NOTES

File Name : ProcessMonitor.ps1

Author : Sarah BESSARD (sarah.bessard@concatskills.com)

Prerequisite : PowerShell V5 over Vista and upper.

.LINK

Script posted over:

https://www.concatskills.com/2018/02/09/trace-process-monitor

https://github.com/concatskills/ProcessMonitor

.EXAMPLE

.\ProcessMonitor.ps1 -DurationInSec 30

param(

[Parameter(Mandatory=$True)] [int]$DurationInSec

)

clear-host

$ScriptDirectory = Split-Path $MyInvocation.MyCommand.Path

$ScriptDirectoryExe = "$($ScriptDirectory)\exe"

$ScriptDirectoryOut = "$($ScriptDirectory)\out"

Push-Location $ScriptDirectory

$ProcMonExe = "$($ScriptDirectoryExe)\Procmon.exe"

$CapturePml = "$($ScriptDirectoryOut)\capture.pml"

$CaptureCsv = "$($ScriptDirectoryOut)\capture.csv"

$DurationInSec = [System.Math]::Abs($DurationInSec)

If(!(test-path $ScriptDirectoryOut)) { New-Item -ItemType Directory -Force -Path $ScriptDirectoryOut } else { Get-ChildItem -Path $ScriptDirectoryOut -Include *.* -Recurse | remove-Item -Recurse -Force }

$argstart = "/Quiet /AcceptEula /Minimized /Backingfile $CapturePml /Runtime $DurationInSec"

$argstop = "/Openlog $CapturePml /SaveAs $CaptureCsv"

# Warning UAC & run as admin

Start-Process -FilePath $ProcMonExe -ArgumentList $argstart -wait -Verb RunAs

Start-Process -FilePath $ProcMonExe -ArgumentList $argstop -wait -Verb RunAs

Prérequis

Pour des raisons de sécurité, l’exécution de script PowerShell est bloquée par défaut, parce qu’il n’est pas signé et provient d’Internet comme dans le cas présent.

File … cannot be loaded. The file is not digitally signed. The script will not be executed on the system.

Pour remédier au problème, se placer dans le répertoire principal (ex : C:\Github\ProcessMonitor) hébergeant entre autres le script Powershell et lancer les commandes suivantes :

Set-ExecutionPolicy -ExecutionPolicy Unrestricted
CD C:\Github\ProcessMonitor
Unblock-File .\ProcessMonitor.ps1

Set-ExecutionPolicy -ExecutionPolicy Unrestricted

CD C:\Github\ProcessMonitor

Unblock-File .\ProcessMonitor.ps1

Enregistrement d’une trace

On pose la solution Powershell sur le serveur à auditer sur un disque où l’on dispose d’un espace suffisant pour enregistrer la trace et stocker en plus son homologue au format CSV. Il n’y a qu’un paramètre à renseigner en entrée du script principal, la durée de la trace en seconde :

.\ProcessMonitor.ps1 -DurationInSec 30

1	.\ProcessMonitor.ps1 -DurationInSec 30

L’exécution du script va entraîner l’ouverture du binaire procmon.exe (attention aux paramètres UAC, ils peuvent empêcher l’ouverture de l’exécutable) :

Une fois le temps de la trace écoulé, une fenêtre de progression de conversion de la trace capture.pml vers un CSV, capture.csv, apparaît :

Analyse de la trace

Une fois la trace convertie au format CSV, capture.csv, on l’importe dans SQL Server pour analyse et on exécute la requête suivante : on affiche le process ayant le plus grand nombre d’opérations par minute. J’ai pris la peine de normaliser le nom des colonnes mais surtout d’exclure quelques process système connus. Cela étant, la liste n’est pas exhaustive.

;  WITH Process  
AS (
	SELECT	ShortTimeOfDay = LEFT([TimeOfDay],5)
			, ProcessName
			, CountOperations = COUNT(*)
			, RankCountOperationsPerMinute = ROW_NUMBER()OVER( PARTITION BY LEFT([TimeOfDay],5) ORDER BY COUNT(*) DESC )

	FROM	[tempdb].[dbo].[TraceProcessMonitor]
	WHERE	1 = 1
	AND		ProcessName NOT IN ('Procmon64.exe', 'Explorer.EXE', 'DesktopInfo.exe', 'svchost.exe', 'System', 'wmiprvse.exe', 'services.exe')
	GROUP BY LEFT([TimeOfDay],5), ProcessName
)
SELECT	*
FROM	Process
WHERE	RankCountOperationsPerMinute <= 5
ORDER BY ShortTimeOfDay ASC, RankCountOperationsPerMinute

; WITH Process

AS (

SELECT ShortTimeOfDay = LEFT([TimeOfDay],5)

, ProcessName

, CountOperations = COUNT(*)

, RankCountOperationsPerMinute = ROW_NUMBER()OVER( PARTITION BY LEFT([TimeOfDay],5) ORDER BY COUNT(*) DESC )

FROM [tempdb].[dbo].[TraceProcessMonitor]

WHERE 1 = 1

AND ProcessName NOT IN ('Procmon64.exe', 'Explorer.EXE', 'DesktopInfo.exe', 'svchost.exe', 'System', 'wmiprvse.exe', 'services.exe')

GROUP BY LEFT([TimeOfDay],5), ProcessName

)

SELECT *

FROM Process

WHERE RankCountOperationsPerMinute <= 5

ORDER BY ShortTimeOfDay ASC, RankCountOperationsPerMinute

Le résultat de la requête exporté dans Excel est plutôt intéressant : il semblerait que l’antivirus Kapersky, kavfs.exe, ait une activité suspecte, bien qu’il ne verrouille aucun fichier SQL Server.

Concrètement on cherche un pyromane et on a intercepté kavfs.exe avec un briquet sur lui. Dans le doute, on demande à décaler son exécution, voir sa désactivation. Affaire à suivre…

Quelques semaines plus tard : Kapersky était bien le coupable.

Auteur

Sarah Béquet

Archietcte Data Microsoft, les maîtres mots sont : performance, industrialisation, méthodologie & bonne humeur.

Derniers articles

2019.12.02BI & Big Data Etude des contextes en DAX (4/4) : Transition de contexte
2019.11.25BI & Big Data Etude des contextes en DAX (3/4) : Contexte de requête
2019.11.17BI & Big Data Etude des contextes en DAX (2/4) : Contexte de filtre
2019.11.11BI & Big Data Etude des contextes en DAX (1/4) : Contexte de ligne

Articles liés

Scripter la création et suppression des contraintes (ex : FK)

XEvent : Processus bloqués et bloquant

XEvent : Requêtes longues

Scripter la création et suppression des index

Blog