Negative CPU values on Server Details

[SergeyKanzhelev]

Moved from https://github.com/Microsoft/ApplicationInsights-Home/issues/212

Reported by @rstirling

My application is presenting negative CPU values at Server>Server Details panel. This behavior is normal?

The application is deployed on development machine. The default language is English. It's a Java application running on Tomcat Server using version 2.0.2 AI agent/libs.

[littleaj]

-1 is the default value when CPU% cannot be computed for some reason. If it's due to some JMX error, it should show up in the SDK logs.

@rstirling, do you see any errors in the SDK logs enabled?
If you haven't done that before, add this to your ApplicationInsights.xml:

<SDKLogger type="CONSOLE">
	<Level>TRACE</Level>
</SDKLogger>

This will print our SDK logs to the application server's log file.
See the config file documentation if you'd rather output SDK logs to a separate file (bottom of page).

Once you have those, search for getProcessCPUUsage. There should be a TRACE message with the stack trace after that.

[rstirling]

Hi @littleaj .

I got the log but there are no exceptions on it:

AI: INFO 20-04-2018 12:18, 192(ActiveTransmissionNetworkOutput_1-6): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 118(ActiveTransmissionNetworkOutput_1-0): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 153(ActiveTransmissionNetworkOutput_1-1): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 165(ActiveTransmissionNetworkOutput_1-2): Backoff has been reset.
AI: TRACE 20-04-2018 12:18, 104(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '0.0'
AI: TRACE 20-04-2018 12:18, 104(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '0.0'
AI: TRACE 20-04-2018 12:18, 104(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '8.173039616E9'
AI: TRACE 20-04-2018 12:18, 104(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.101265024E9
AI: TRACE 20-04-2018 12:18, 104(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: -1.0
AI: INFO 20-04-2018 12:18, 178(ActiveTransmissionNetworkOutput_1-3): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 188(ActiveTransmissionNetworkOutput_1-4): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 190(ActiveTransmissionNetworkOutput_1-5): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 192(ActiveTransmissionNetworkOutput_1-6): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 118(ActiveTransmissionNetworkOutput_1-0): Backoff has been reset.
AI: INFO 20-04-2018 12:18, 153(ActiveTransmissionNetworkOutput_1-1): Backoff has been reset.
AI: INFO 20-04-2018 12:19, 165(ActiveTransmissionNetworkOutput_1-2): Backoff has been reset.
AI: INFO 20-04-2018 12:19, 178(ActiveTransmissionNetworkOutput_1-3): Backoff has been reset.
AI: INFO 20-04-2018 12:19, 188(ActiveTransmissionNetworkOutput_1-4): Backoff has been reset.
AI: INFO 20-04-2018 12:19, 190(ActiveTransmissionNetworkOutput_1-5): Backoff has been reset.
AI: TRACE 20-04-2018 12:19, 104(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '331555.21875'
AI: TRACE 20-04-2018 12:19, 104(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '10.705238342285156'
AI: TRACE 20-04-2018 12:19, 104(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '8.162217984E9'
AI: TRACE 20-04-2018 12:19, 104(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.239013248E9
AI: TRACE 20-04-2018 12:19, 104(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.44966843724250793
AI: INFO 20-04-2018 12:19, 192(ActiveTransmissionNetworkOutput_1-6): Backoff has been reset.

[littleaj]

Thanks for the follow up @rstirling. It's interesting that there are no exceptions. We can at least rule out JMX as the cause.

Now, the first datapoint for CPU% will always be -1. Is this what you are seeing? or do you see -1 as a value after that?

[rstirling]

Hey @littleaj ,

Yes, it is. I let my app running for a couple minutes today morning. I'll let it run for a longer period to have a better test scenario and I'll share the results here. Thanks.

[littleaj]

Ok, cool. At the very least, we can file an issue to remove the -1 datapoint from being reported. It does look a bit strange in the charts.

And yes, do let me know if -1 shows up later in the logs. That would be a separate issue.