dotnet-counters does not produce metrics when GC was running?

Question

dotnet-counters does not produce metrics when GC was running?

wangjia184 opened this issue 7 months ago · 1 comments

Description

We are running the following command on our production server to watch a process and write the metrics into CSV file

dotnet-counters collect --name OurApplication --output csv

As you can see from the log below, there is a gap between 8:52:57 and 8:53:03.
And the entries at 8:53:03 are doubled, and seems our application was doing a GC then.

Is that normal from dotnet-counters's perspective? timeline was interrupted, and entries are doubled at 8:53:03

Configuration

OS : Windows Server 2019 (Virtual machine)
The process being watched is .NET Core 6 Self-Host application

Other information

dotnet-counters --version
8.0.452401+966acd12b91675a4d06a7572ff47c587f827beaf

Timestamp,Provider,Counter Name,Counter Type,Mean/Increment
2023-11-14 8:52:55 AM,System.Runtime,CPU Usage (%),Metric,8
2023-11-14 8:52:55 AM,System.Runtime,Working Set (MB),Metric,19810
2023-11-14 8:52:55 AM,System.Runtime,GC Heap Size (MB),Metric,17007
2023-11-14 8:52:55 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:55 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:55 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:55 AM,System.Runtime,ThreadPool Thread Count,Metric,106
2023-11-14 8:52:55 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,18
2023-11-14 8:52:55 AM,System.Runtime,ThreadPool Queue Length,Metric,0
2023-11-14 8:52:55 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,2475
2023-11-14 8:52:55 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,43436272
2023-11-14 8:52:55 AM,System.Runtime,Number of Active Timers,Metric,625
2023-11-14 8:52:55 AM,System.Runtime,GC Fragmentation (%),Metric,18.255573520395323
2023-11-14 8:52:55 AM,System.Runtime,GC Committed Bytes (MB),Metric,21250
2023-11-14 8:52:55 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,10
2023-11-14 8:52:55 AM,System.Runtime,% Time in GC since last GC (%),Metric,2
2023-11-14 8:52:55 AM,System.Runtime,Gen 0 Size (B),Metric,122853376
2023-11-14 8:52:55 AM,System.Runtime,Gen 1 Size (B),Metric,131809232
2023-11-14 8:52:55 AM,System.Runtime,Gen 2 Size (B),Metric,14770898224
2023-11-14 8:52:55 AM,System.Runtime,LOH Size (B),Metric,5690637112
2023-11-14 8:52:55 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:52:55 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:52:55 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:52:55 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:52:55 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:52:56 AM,System.Runtime,CPU Usage (%),Metric,16
2023-11-14 8:52:56 AM,System.Runtime,Working Set (MB),Metric,19810
2023-11-14 8:52:56 AM,System.Runtime,GC Heap Size (MB),Metric,17079
2023-11-14 8:52:56 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:56 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:56 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:56 AM,System.Runtime,ThreadPool Thread Count,Metric,106
2023-11-14 8:52:56 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,16
2023-11-14 8:52:56 AM,System.Runtime,ThreadPool Queue Length,Metric,0
2023-11-14 8:52:56 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,1766
2023-11-14 8:52:56 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,71785088
2023-11-14 8:52:56 AM,System.Runtime,Number of Active Timers,Metric,626
2023-11-14 8:52:56 AM,System.Runtime,GC Fragmentation (%),Metric,18.255573520395323
2023-11-14 8:52:56 AM,System.Runtime,GC Committed Bytes (MB),Metric,21250
2023-11-14 8:52:56 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,6
2023-11-14 8:52:56 AM,System.Runtime,% Time in GC since last GC (%),Metric,2
2023-11-14 8:52:56 AM,System.Runtime,Gen 0 Size (B),Metric,122853376
2023-11-14 8:52:56 AM,System.Runtime,Gen 1 Size (B),Metric,131809232
2023-11-14 8:52:56 AM,System.Runtime,Gen 2 Size (B),Metric,14770898224
2023-11-14 8:52:56 AM,System.Runtime,LOH Size (B),Metric,5690637112
2023-11-14 8:52:56 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:52:56 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:52:56 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:52:56 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:52:56 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:52:57 AM,System.Runtime,CPU Usage (%),Metric,15
2023-11-14 8:52:57 AM,System.Runtime,Working Set (MB),Metric,19810
2023-11-14 8:52:57 AM,System.Runtime,GC Heap Size (MB),Metric,17144
2023-11-14 8:52:57 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:57 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:57 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:52:57 AM,System.Runtime,ThreadPool Thread Count,Metric,106
2023-11-14 8:52:57 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,22
2023-11-14 8:52:57 AM,System.Runtime,ThreadPool Queue Length,Metric,0
2023-11-14 8:52:57 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,2609
2023-11-14 8:52:57 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,64031888
2023-11-14 8:52:57 AM,System.Runtime,Number of Active Timers,Metric,632
2023-11-14 8:52:57 AM,System.Runtime,GC Fragmentation (%),Metric,18.255573520395323
2023-11-14 8:52:57 AM,System.Runtime,GC Committed Bytes (MB),Metric,21250
2023-11-14 8:52:57 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,5
2023-11-14 8:52:57 AM,System.Runtime,% Time in GC since last GC (%),Metric,2
2023-11-14 8:52:57 AM,System.Runtime,Gen 0 Size (B),Metric,122853376
2023-11-14 8:52:57 AM,System.Runtime,Gen 1 Size (B),Metric,131809232
2023-11-14 8:52:57 AM,System.Runtime,Gen 2 Size (B),Metric,14770898224
2023-11-14 8:52:57 AM,System.Runtime,LOH Size (B),Metric,5690637112
2023-11-14 8:52:57 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:52:57 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:52:57 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:52:57 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:52:57 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:53:03 AM,System.Runtime,CPU Usage (%),Metric,77
2023-11-14 8:53:03 AM,System.Runtime,Working Set (MB),Metric,19506
2023-11-14 8:53:03 AM,System.Runtime,GC Heap Size (MB),Metric,11999
2023-11-14 8:53:03 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:03 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:03 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Thread Count,Metric,106
2023-11-14 8:53:03 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,13
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Queue Length,Metric,1312
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,2272
2023-11-14 8:53:03 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,29606136
2023-11-14 8:53:03 AM,System.Runtime,Number of Active Timers,Metric,625
2023-11-14 8:53:03 AM,System.Runtime,GC Fragmentation (%),Metric,32.56508813651016
2023-11-14 8:53:03 AM,System.Runtime,GC Committed Bytes (MB),Metric,21065
2023-11-14 8:53:03 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,4
2023-11-14 8:53:03 AM,System.Runtime,% Time in GC since last GC (%),Metric,55
2023-11-14 8:53:03 AM,System.Runtime,Gen 0 Size (B),Metric,2034723376
2023-11-14 8:53:03 AM,System.Runtime,Gen 1 Size (B),Metric,35228048
2023-11-14 8:53:03 AM,System.Runtime,Gen 2 Size (B),Metric,10207516184
2023-11-14 8:53:03 AM,System.Runtime,LOH Size (B),Metric,5506087120
2023-11-14 8:53:03 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:53:03 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:53:03 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:53:03 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:53:03 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:53:03 AM,System.Runtime,CPU Usage (%),Metric,81
2023-11-14 8:53:03 AM,System.Runtime,Working Set (MB),Metric,19471
2023-11-14 8:53:03 AM,System.Runtime,GC Heap Size (MB),Metric,12028
2023-11-14 8:53:03 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:03 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:53:03 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Thread Count,Metric,119
2023-11-14 8:53:03 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,140
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Queue Length,Metric,41
2023-11-14 8:53:03 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,3810
2023-11-14 8:53:03 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,240251496
2023-11-14 8:53:03 AM,System.Runtime,Number of Active Timers,Metric,631
2023-11-14 8:53:03 AM,System.Runtime,GC Fragmentation (%),Metric,32.45798763243202
2023-11-14 8:53:03 AM,System.Runtime,GC Committed Bytes (MB),Metric,21024
2023-11-14 8:53:03 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,15
2023-11-14 8:53:03 AM,System.Runtime,% Time in GC since last GC (%),Metric,49
2023-11-14 8:53:03 AM,System.Runtime,Gen 0 Size (B),Metric,2020448648
2023-11-14 8:53:03 AM,System.Runtime,Gen 1 Size (B),Metric,66087528
2023-11-14 8:53:03 AM,System.Runtime,Gen 2 Size (B),Metric,10207516184
2023-11-14 8:53:03 AM,System.Runtime,LOH Size (B),Metric,5506087120
2023-11-14 8:53:03 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:53:03 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:53:03 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:53:03 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:53:03 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:53:04 AM,System.Runtime,CPU Usage (%),Metric,25
2023-11-14 8:53:04 AM,System.Runtime,Working Set (MB),Metric,19436
2023-11-14 8:53:04 AM,System.Runtime,GC Heap Size (MB),Metric,12032
2023-11-14 8:53:04 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,2
2023-11-14 8:53:04 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:04 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:53:04 AM,System.Runtime,ThreadPool Thread Count,Metric,119
2023-11-14 8:53:04 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,16
2023-11-14 8:53:04 AM,System.Runtime,ThreadPool Queue Length,Metric,12
2023-11-14 8:53:04 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,2042
2023-11-14 8:53:04 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,477115192
2023-11-14 8:53:04 AM,System.Runtime,Number of Active Timers,Metric,625
2023-11-14 8:53:04 AM,System.Runtime,GC Fragmentation (%),Metric,32.34115202488967
2023-11-14 8:53:04 AM,System.Runtime,GC Committed Bytes (MB),Metric,20943
2023-11-14 8:53:04 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,5
2023-11-14 8:53:04 AM,System.Runtime,% Time in GC since last GC (%),Metric,15
2023-11-14 8:53:04 AM,System.Runtime,Gen 0 Size (B),Metric,2053599224
2023-11-14 8:53:04 AM,System.Runtime,Gen 1 Size (B),Metric,6553504
2023-11-14 8:53:04 AM,System.Runtime,Gen 2 Size (B),Metric,10207603520
2023-11-14 8:53:04 AM,System.Runtime,LOH Size (B),Metric,5506087120
2023-11-14 8:53:04 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:53:04 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:53:04 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:53:04 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:53:04 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0
2023-11-14 8:53:05 AM,System.Runtime,CPU Usage (%),Metric,21
2023-11-14 8:53:05 AM,System.Runtime,Working Set (MB),Metric,19331
2023-11-14 8:53:05 AM,System.Runtime,GC Heap Size (MB),Metric,12096
2023-11-14 8:53:05 AM,System.Runtime,Gen 0 GC Count (Count / 1 sec),Rate,3
2023-11-14 8:53:05 AM,System.Runtime,Gen 1 GC Count (Count / 1 sec),Rate,1
2023-11-14 8:53:05 AM,System.Runtime,Gen 2 GC Count (Count / 1 sec),Rate,0
2023-11-14 8:53:05 AM,System.Runtime,ThreadPool Thread Count,Metric,119
2023-11-14 8:53:05 AM,System.Runtime,Monitor Lock Contention Count (Count / 1 sec),Rate,19
2023-11-14 8:53:05 AM,System.Runtime,ThreadPool Queue Length,Metric,1
2023-11-14 8:53:05 AM,System.Runtime,ThreadPool Completed Work Item Count (Count / 1 sec),Rate,2284
2023-11-14 8:53:05 AM,System.Runtime,Allocation Rate (B / 1 sec),Rate,571484344
2023-11-14 8:53:05 AM,System.Runtime,Number of Active Timers,Metric,626
2023-11-14 8:53:05 AM,System.Runtime,GC Fragmentation (%),Metric,32.27727329441327
2023-11-14 8:53:05 AM,System.Runtime,GC Committed Bytes (MB),Metric,20840
2023-11-14 8:53:05 AM,System.Runtime,Exception Count (Count / 1 sec),Rate,3
2023-11-14 8:53:05 AM,System.Runtime,% Time in GC since last GC (%),Metric,8
2023-11-14 8:53:05 AM,System.Runtime,Gen 0 Size (B),Metric,2048011728
2023-11-14 8:53:05 AM,System.Runtime,Gen 1 Size (B),Metric,12264968
2023-11-14 8:53:05 AM,System.Runtime,Gen 2 Size (B),Metric,10208735168
2023-11-14 8:53:05 AM,System.Runtime,LOH Size (B),Metric,5506087120
2023-11-14 8:53:05 AM,System.Runtime,POH (Pinned Object Heap) Size (B),Metric,8724512
2023-11-14 8:53:05 AM,System.Runtime,Number of Assemblies Loaded,Metric,421
2023-11-14 8:53:05 AM,System.Runtime,IL Bytes Jitted (B),Metric,4093040
2023-11-14 8:53:05 AM,System.Runtime,Number of Methods Jitted,Metric,44826
2023-11-14 8:53:05 AM,System.Runtime,Time spent in JIT (ms / 1 sec),Rate,0

Answer 1 · 2023-12-11T16:08:05.000Z

Is that normal from dotnet-counters's perspective?

Hi @wangjia184!

The implementation of counters uses an in-process thread that polls for values and then sends them over EventPipe to the dotnet-counters tool. The code that does this polling is located here: https://github.com/dotnet/runtime/blob/e42c683950b2c2c515a44f575942339555bd9cff/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/CounterGroup.cs#L268

timeline was interrupted

Since it is written in managed code the thread can theoretically be paused by the GC and therefore pause sending events. Collecting an ETW trace per https://learn.microsoft.com/dotnet/standard/garbage-collection/performance would help us to confirm.

entries are doubled at 8:53:03

The timestamp data added when it is injected into the eventpipe queue, for example here. If a pause occurred in the counter polling loop for any reason (for example a blocking GC), then I would expect the timestamp data to be skewed.

Hope this helps, and please let us know if this answers the question.