elastic / elastic/beats

[x-pack][metricbeat][iis] Investigate metrics leaking to a wrong process (application pools)

Open
#48,792 0 comments 2 reactions 0 assignees View on GitHub
Team:Obs-InfraObs
Dominant language
Go
Stars
12.7k
Forks
5k
Avg merge
2d 2h
Merged PRs (30d)
364

Description

It seems that when you run multiple application pools and one of them gets stopped/restarted metricbeat reports its metrics (for example `# Gen 0 Collections`) as metrics of a different app pool (that is still running).

### Preliminary analysis
It seems this behavior is connected to how PDH counters behave.
In order to try and investigate this a little further I've used this powershell script:
```
$results = foreach ($proc in Get-CimInstance Win32_Process -Filter "Name = 'w3wp.exe'") {
$WorkerPID = $proc.ProcessId
$appPoolName = $proc.CommandLine.Split('"')[1]

# Find the instance name (w3wp, w3wp#1, etc)
$processCategory = New-Object System.Diagnostics.PerformanceCounterCategory("Process")
$instances = $processCategory.GetInstanceNames() | Where-Object { $_ -match "^w3wp(#\d+)?$" }

foreach ($inst in $instances) {
$idCounter = New-Object System.Diagnostics.PerformanceCounter("Process", "ID Process", $inst, $true)

# Check if this instance belongs to our current loop's PID
if ($idCounter.RawValue -eq $WorkerPID) {
try {
# Create the Gen 0 counter
$gen0 = New-Object System.Diagnostics.PerformanceCounter(".NET CLR Memory", "# Gen 0 Collections", $inst, $true)

# First call to NextValue() often returns 0, we need the RawValue or a second call
$val = $gen0.RawValue

[PSCustomObject]@{
AppPool = $appPoolName
PID = $WorkerPID
Instance = $inst
Gen0Cols = $val
}
} catch {
# This w3wp isn't running .NET Framework (could be .NET Core or No Managed Code)
}
break # Found the instance for this PID, move to next process
}
}
}

$results | Format-Table -AutoSize
```

This script produced a table like this:
```
AppPool PID Instance Gen0Cols
------- --- -------- --------
DefaultAppPool 1404 w3wp 3
zRmAoVOT 12932 w3wp#1 3
.Ney_2 7296 w3wp#2 3
EtQKqWjM 624 w3wp#3 3
lQzBAMHP 5364 w3wp#4 11
ytYuhpwr 11660 w3wp#5 3
zOXGgNtn 2044 w3wp#6 4
lgArfpvj 6972 w3wp#7 3
cFiwlXuz 11236 w3wp#8 3
BwFRIWmh 10244 w3wp#9 3
qixghmay 12536 w3wp#10 3
mxIgZapB 5288 w3wp#11 4
bklVLKgi 10576 w3wp#12 4
uQlBwkFb 3108 w3wp#13 3
rJYpZcHu 8196 w3wp#14 3
qRIByVab 3300 w3wp#15 3
yFTULeYC 4780 w3wp#16 4
DkYZNoMP 11232 w3wp#17 4
PbrEIdkD 12144 w3wp#18 3
AjrdVzqD 9616 w3wp#19 4
tzJjKvsN 8948 w3wp#20 0
HbniZJXy 7912 w3wp#21 18
Classic .NET AppPool 8664 w3wp#22
```
After that I've stopped `lQzBAMHP` app pool(Instance `w3wp#4`, Gen0Cols: 11) and ran the script again and got following result:
```
AppPool PID Instance Gen0Cols
------- --- -------- --------
DefaultAppPool 1404 w3wp 3
zRmAoVOT 12932 w3wp#1 3
.Ney_2 7296 w3wp#2 3
EtQKqWjM 624 w3wp#3 3
ytYuhpwr 11660 w3wp#4 11
zOXGgNtn 2044 w3wp#5 3
lgArfpvj 6972 w3wp#6 4
cFiwlXuz 11236 w3wp#7 3
BwFRIWmh 10244 w3wp#8 3
qixghmay 12536 w3wp#9 3
mxIgZapB 5288 w3wp#10 3
bklVLKgi 10576 w3wp#11 4
uQlBwkFb 3108 w3wp#12 4
rJYpZcHu 8196 w3wp#13 3
qRIByVab 3300 w3wp#14 3
yFTULeYC 4780 w3wp#15 3
DkYZNoMP 11232 w3wp#16 4
PbrEIdkD 12144 w3wp#17 4
AjrdVzqD 9616 w3wp#18 5
tzJjKvsN 8948 w3wp#19 0
HbniZJXy 7912 w3wp#20 18
Classic .NET AppPool 8664 w3wp#21
```
Notice that with instance w3wp#4 and Gen0Cols of 11 now a different app pool is reported (`ytYuhpwr`). And metricbeat has exactly same behavior.

This gh issue is meant for:
1. Investigation of why exactly this behavior happens (likely it's something about how courters work but it has be confirmed).
2. Find a solution for metricbeat to make metrics reporting correct in an event of app pool being stopped/restarted.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.