CheckMK version 2.0.0P1 vs CheckMK version 2.0.0p16 (CRE): Agent takes nearly double time to answer

Troubleshooting
1

Hi

I’ve recently upgraded my setup from CheckMK v2.0.0p1 to v2.0.0p16 and I noticed quite a jump in agent responsiveness. You can clearly see before it was around 25 seconds before the agent got it’s message though and now it takes 40 or more seconds which leads to time-outs littering my dashboard.

image
image1159×572 56.1 KB

Anyone else noticed this behaviour or could explain it?

There are even worse examples:

image
image1160×578 97 KB

Reboot of the server has been done to try and solve this.

2

You are sure that all the settings are the same? I don’t think so.
In your first graph i see already (also with the old system) a wrong configured agent. Normal agent response time takes 0.1 to 1 second not longer.
To say more about this problem the exact host config is needed.
From p1 to p16 are already many changes and you are sure that nothing important was shown at update time?

3

Please tell me what is configured wrong @andreas-doehler and I’ll try to correct it for the agent.
What file can I post here to show the host config?
I haven’t seen anyting important at update time, but I could be wrong ofcourse.

4

Is that the systemd-timesyncd bug?

Check if ntp or chrony are running on your hosts for time syncing and really disable systemd-timesyncd:

systemctl disable --now systemd-timesyncd
systemctl mask systemd-timesyncd
5

Hey

These are both windows based systems, that I have showed in my examples.
They have always been synched with NTP since they have been set up. Nothing has changed about that.

How can I further troubleshoot this?

6

Check on the Windows hosts which agent plugins are installed and how they are executed.

Call the agent locally and see where it hangs while outputting its data.

7

Some small parts of my agent config on Windows looks like this.

global:
  async_script_execution: parallel

local:
  execution:
    - pattern: "*"
      async: yes

plugins:
  execution:
    - pattern     : "*"
      async       : yes

If needed you should configure single plugins as cached like this example for the Windows update status.

plugins:
  execution:
    - pattern     : '$BUILTIN_PLUGINS_PATH$\windows_updates.vbs'
      timeout     : 3600
      run         : yes
      async       : yes
      cache_age   : 90000
1 Like
8

Hey @r.sander

When I execute the windows agent on the windows server itself, it also takes 40+ seconds to execute.
Can I somehow narrow it down where it hangs, on which “subtask”?

9

First you have to fix your plugin config. If no plugins are activated it should not run longer than 1-2 seconds.

10

I solved the issue by rebooting the target server and removing the “windows_updates.vbs”.
@andreas-doehler : Can you explain where exactly, meaning in which files, I need to make those adjustments?
Is that in the “check_mk.yml” file? And if so: where do I add these lines? I have the default like listed below. Can I just paste it in between?

plugins:
    enabled: yes

    player: ''   # internal value, do not change this
11

The file you can manually edit is the “check_mk.user.yml” inside “C:\ProgramData\checkmk\agent”.
After some edit you should test your settings with “check_mk_agent.exe showconfig”.
My output looks like this.

plugins:
  enabled: true
  player: ""
  max_wait: 60
  async_start: yes
  folders: [$CUSTOM_PLUGINS_PATH$, $BUILTIN_PLUGINS_PATH$]
  execution:
    - pattern: $BUILTIN_PLUGINS_PATH$\windows_updates.vbs
      timeout: 3600
      run: yes
      async: yes
      cache_age: 90000

What path is used depends on your configuration. It is more the general configuration :wink:

12

Andreas, why don’t you mention what you have mentioned in another thread?

The VBS plugin is better to be replaced by the powershell script to determine pending windows updates. However, keep in mind that both of these checks actively poll either the windows update catalog servers or your local WSUS/SCCM (if configured). I find this somewhat contradictive to the common dogma that monitoring should only be looking, not actively doing things. This is a lesson taught by tribe29 staff and shouldn’t have changed to this day.

13

Hi Simon,

where can i find the mentioned powershell script?

14

Is there a better method to determine the current update status?

The APT and Zypper updates agent plugins for Linux also do an “apt update” or “zypper ref” to refresh the list of available packages to be able to determine the update status.

1 Like
15

I can do this but this is not the real problem here.

In this topic i posted a Powershell version of the update check script.

But also with this script you need to make the cache configuration.

What i do at the moment on some servers is not to check if there are updates available. I check what update was last installed and you can filter unwanted updates and so on.
This is better in environments where you cannot have a WSUS or internet connection.

This can be something what @simon-mueller wants instead of checking the WSUS.

16

There you go.

@r.sander :

To get the date of the search for updates and the date of the actual update done you can do something like this:
image

On the server/client you can’t list updates without searching for them (Hen/Egg Problem).
But if you have a WSUS Server in your environment you can do yourself a big favor and use powershell scripts to verify the update status against several clients and then piggybacking this information to your hosts.

17

Still one server keeps troubling me:
A Windows server 2012 R2 (updated till the lastest possible update)
No plugins installed
YML file changed to disable all checks except for ‘checkMK’ itself which I verified by ‘check_mk_agent.exe showconfig’ & afterwards running check_mk_agent.exe test which shows me only this:
image
When I execute the cmk -d SERVERNAME, it takes more then a minute before it shows output and the output it does eventually show, is still the full output without anything left out.

I tried the following aswell, but that didn’t solve it.
uninstalled agent
Restarted server
reinstalled agent
Server removed from CheckMK and added again

18

Output of the cmk -vv command as follows:
OMD[icasa]:~$ cmk -vv SERVERNAME
Checkmk version 2.0.0p16
Try license usage history update.
Trying to acquire lock on /omd/sites/icasa/var/check_mk/license_usage/next_run
Got lock on /omd/sites/icasa/var/check_mk/license_usage/next_run
Trying to acquire lock on /omd/sites/icasa/var/check_mk/license_usage/history.json
Got lock on /omd/sites/icasa/var/check_mk/license_usage/history.json
Next run time has not been reached yet. Abort.
Releasing lock on /omd/sites/icasa/var/check_mk/license_usage/history.json
Released lock on /omd/sites/icasa/var/check_mk/license_usage/history.json
Releasing lock on /omd/sites/icasa/var/check_mk/license_usage/next_run
Released lock on /omd/sites/icasa/var/check_mk/license_usage/next_run
Loading autochecks from /omd/sites/icasa/var/check_mk/autochecks/SERVERNAME.mk

  • FETCHING DATA
    Source: SourceType.HOST/FetcherType.TCP
    [cpu_tracking] Start [7f7465cbe6a0]
    Connecting via TCP to IP_ADDRESS:6556 (5.0s timeout)
    [TCPFetcher] Fetch with cache settings: DefaultAgentFileCache(base_path=PosixPath(’/omd/sites/icasa/tmp/check_mk/cache/SERVERNAME’), max_age=MaxAge(checking=0, discovery=120, inventory=120), disabled=False, use_outdated=False, simulation=False)
    Not using cache (Too old. Age is 44 sec, allowed is 0 sec)
    [TCPFetcher] Execute data source
    Reading data from agent
    Output is not encrypted
    Write data to cache file /omd/sites/icasa/tmp/check_mk/cache/SERVERNAME
    Trying to acquire lock on /omd/sites/icasa/tmp/check_mk/cache/SERVERNAME
    Got lock on /omd/sites/icasa/tmp/check_mk/cache/SERVERNAME
    Releasing lock on /omd/sites/icasa/tmp/check_mk/cache/SERVERNAME
    Released lock on /omd/sites/icasa/tmp/check_mk/cache/SERVERNAME
    Closing TCP connection to 172.23.0.150:6556
    [cpu_tracking] Stop [7f7465cbe6a0 - Snapshot(process=posix.times_result(user=0.0, system=0.0, children_user=0.0, children_system=0.0, elapsed=156.5600000023842))]
    [cpu_tracking] Start [7f7465b62040]
  • PARSE FETCHER RESULTS
    Source: SourceType.HOST/FetcherType.TCP
    No persisted sections loaded
    → Add sections: [‘check_mk’, ‘df’, ‘fileinfo’, ‘logwatch’, ‘mem’, ‘ps’, ‘services’, ‘systemtime’, ‘uptime’, ‘winperf_if’, ‘winperf_phydisk’, ‘winperf_processor’, ‘wmi_cpuload’]
    Received no piggyback data
    Loading item states
    Trying to acquire lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Got lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Releasing lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Released lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    CPU utilization Total CPU: 22.85%
    Disk IO SUMMARY PEND - Initializing counters
    Filesystem C:/ 81.86% used (122.51 of 149.66 GB), trend: +210.35 MB / 24 hours
    Interface 1 [Intel[R] 82574L Gigabit Network Connection], (Connected), Speed: 1 GBit/s, In: 15.1 kB/s (0.01%), Out: 36.9 kB/s (0.03%)
    Memory and pagefile RAM: 54.98% - 4.40 GB of 8.00 GB, Commit charge: 26.67% - 4.27 GB of 16.00 GB
    Service KAVFS Kaspersky Security Service: running (start type is auto)
    Service Summary Autostart services: 62, Stopped services: 2
    Service angara Kaspersky Sandbox Integration: running (start type is auto)
    Service kavfsslp Kaspersky Security Exploit Prevention Service: running (start type is auto)
    Service klnagent Kaspersky Security Center Network Agent: running (start type is auto)
    Service soyuz Kaspersky Endpoint Agent: running (start type is auto)
    Service vostok KATA Integration: running (start type is auto)
    System Time Offset: -592 ms
    Uptime Up since Dec 08 2021 09:05:13, Uptime: 2 hours 13 minutes
    Saving item states
    Trying to acquire lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Got lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Releasing lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    Released lock on /omd/sites/icasa/tmp/check_mk/counters/SERVERNAME
    [cpu_tracking] Stop [7f7465b62040 - Snapshot(process=posix.times_result(user=0.029999999999999805, system=0.0, children_user=0.0, children_system=0.0, elapsed=0.03999999910593033))]
    [agent] Version: 2.0.0p16, OS: windows, execution time 156.6 sec | execution_time=156.600 user_time=0.030 system_time=0.000 children_user_time=0.000 children_system_time=0.000 cmk_time_agent=156.560
19

On this machine you should take a look at the agent log file.
For this you should see at what point it needs the time.
A single call of the agent will start with a line like this.

2021-10-13 13:47:16.144 [srv 25960] Connected from '172....

The last line of such a communication would be something like this

2021-10-13 13:47:16.886 [srv 25960] perf: Answer is ready in [733] milliseconds
2021-10-13 13:47:16.886 [srv 25960] Send [71538] bytes of data
2021-10-13 13:47:16.948 [srv 25960] perf:  In [431] milliseconds process 'powershell.....

After the “send” it outputs the line for async plugin processing.
You see in my case here the complete agent processing took around 700 millieseconds.

20

2021-12-08 11:36:56.465 [srv 1396] Connected from ‘IP_ADDRESS’ ipv6:false ← queue
2021-12-08 11:36:56.465 [srv 1396] [Warn ] OHM file ‘C:\ProgramData\checkmk\agent\bin\OpenHardwareMonitorCLI.exe’ is not found
2021-12-08 11:36:56.466 [srv 1396] Allowed Extensions: [checkmk.py,py,exe,bat,vbs,cmd,ps1]
2021-12-08 11:36:56.467 [srv 1396] [Trace] Left [36] files to execute
2021-12-08 11:36:56.474 [srv 1396] [Trace] Left [0] files to execute in ‘plugins’
2021-12-08 11:36:56.475 [srv 1396] Generating answer number [1]
2021-12-08 11:36:56.475 [srv 1396] Id is [9139169048663]
2021-12-08 11:36:56.475 [srv 1396] [Trace] Provider ‘wmi_cpuload’ is direct called, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.478 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:01.479 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_PerfOS_System’ in 5002ms sends NO DATA
2021-12-08 11:37:01.479 [srv 1396] [Warn ] On timeout in sub section ‘system_perf’ try reuse cache
2021-12-08 11:37:01.480 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:01.503 [srv 1396] Object ‘Win32_ComputerSystem’ in 23ms sends [1260] bytes
2021-12-08 11:37:01.504 [srv 1396] [Trace] Sending data ‘wmi_cpuload’ id is [9139169048663] length [1317]
2021-12-08 11:37:01.505 [srv 1396] perf: Section ‘wmi_cpuload’ took [5028] milliseconds
2021-12-08 11:37:01.505 [srv 1396] [Trace] Provider ‘uptime’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.506 [srv 1396] Using file ‘C:\Program Files (x86)\checkmk\service\check_mk_agent.exe’ for winperf
2021-12-08 11:37:01.506 [srv 1396] [Trace] Sending data ‘uptime’ id is [9139169048663] length [17]
2021-12-08 11:37:01.507 [srv 1396] [Trace] Loaded [3] entries in LogWatch
2021-12-08 11:37:01.507 [srv 1396] Exec ‘C:\Program Files (x86)\checkmk\service\check_mk_agent.exe’ for ‘winperf’ to be started
2021-12-08 11:37:01.508 [srv 1396] [Trace] Provider ‘df’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.508 [srv 1396] [Trace] Provider ‘mem’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.509 [srv 1396] [Trace] Sending data ‘mem’ id is [9139169048663] length [229]
2021-12-08 11:37:01.509 [srv 1396] perf: Section ‘mem’ took [0] milliseconds
2021-12-08 11:37:01.510 [srv 1396] [Trace] Provider ‘fileinfo’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.510 [srv 1396] [Trace] Sending data ‘fileinfo’ id is [9139169048663] length [34]
2021-12-08 11:37:01.511 [srv 1396] perf: Section ‘fileinfo’ took [0] milliseconds
2021-12-08 11:37:01.511 [srv 1396] [Trace] Provider ‘logwatch’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.512 [srv 1396] Allowed Extensions: [checkmk.py,py,exe,bat,vbs,cmd,ps1]
2021-12-08 11:37:01.519 [srv 1396] [Trace] Left [36] files to execute
2021-12-08 11:37:01.528 [srv 1396] Processed [1] drives
2021-12-08 11:37:01.529 [srv 1396] [Trace] Sending data ‘df’ id is [9139169048663] length [61]
2021-12-08 11:37:01.529 [srv 1396] Received [1445] bytes from ‘wmi_cpuload’
2021-12-08 11:37:01.530 [srv 1396] [Trace] Provider ‘ps’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.608 [srv 1396] async RunStdCmd: “C:\Program Files (x86)\checkmk\service\check_mk_agent.exe” -runonce winperf mail:\.\mailslot\Global\WinAgent_0 id:9139169048663 timeout:10 ip:IP_ADDRESS 234:phydisk 510:if 238:processor
2021-12-08 11:37:01.620 [srv 1396] [Trace] Provider ‘services’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.627 [srv 1396] perf: Section ‘uptime’ took [1] milliseconds
2021-12-08 11:37:01.628 [srv 1396] perf: Section ‘df’ took [21] milliseconds
2021-12-08 11:37:01.629 [srv 1396] [Trace] Left [0] files to execute in ‘plugins’
2021-12-08 11:37:01.652 [srv 1396] [Trace] To start [0] sync plugins
2021-12-08 11:37:01.667 [srv 1396] [Trace] Provider ‘plugins’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.679 [srv 1396] [Trace] Sending data ‘services’ id is [9139169048663] length [8550]
2021-12-08 11:37:01.681 [srv 1396] perf: Section ‘services’ took [54] milliseconds
2021-12-08 11:37:01.730 [srv 1396] Received [145] bytes from ‘uptime’
2021-12-08 11:37:01.733 [srv 1396] [Trace] Sending data ‘plugins’ id is [9139169048663] length [13]
2021-12-08 11:37:01.734 [srv 1396] perf: Section ‘plugins’ took [55] milliseconds
2021-12-08 11:37:01.734 [srv 1396] Allowed Extensions: [checkmk.py,py,exe,bat,vbs,cmd,ps1]
2021-12-08 11:37:01.735 [srv 1396] [Trace] Left [0] files to execute
2021-12-08 11:37:01.735 [srv 1396] [Trace] Left [0] files to execute in ‘local’
2021-12-08 11:37:01.735 [srv 1396] [Trace] To start [0] sync plugins
2021-12-08 11:37:01.736 [srv 1396] [Trace] Provider ‘local’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.737 [srv 1396] [Trace] Provider ‘dotnet_clrmemory’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.737 [srv 1396] [Trace] Provider ‘wmi_webservices’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.739 [srv 1396] [Trace] Provider ‘msexch’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.741 [srv 1396] [Trace] Absent/Empty node mrpe.config type is 1
2021-12-08 11:37:01.742 [srv 1396] [Warn ] Section ‘local’ cannot provide data
2021-12-08 11:37:01.742 [srv 1396] [Trace] Sending data ‘local’ id is [9139169048663] length [0]
2021-12-08 11:37:01.743 [srv 1396] perf: Section ‘local’ took [6] milliseconds
2021-12-08 11:37:01.743 [srv 1396] [Trace] Skipping ‘openhardwaremonitor’ by time
2021-12-08 11:37:01.744 [srv 1396] [Trace] Provider ‘skype’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.744 [srv 1396] [Trace] Provider ‘spool’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.745 [srv 1396] [Warn ] Section ‘spool’ cannot provide data
2021-12-08 11:37:01.745 [srv 1396] [Trace] Sending data ‘spool’ id is [9139169048663] length [0]
2021-12-08 11:37:01.745 [srv 1396] perf: Section ‘spool’ took [0] milliseconds
2021-12-08 11:37:01.746 [srv 1396] [Trace] Provider ‘mrpe’ is about to be started, id ‘9139169048663’ port [mail:\.\mailslot\Global\WinAgent_0]
2021-12-08 11:37:01.747 [srv 1396] [Warn ] Section ‘mrpe’ cannot provide data
2021-12-08 11:37:01.747 [srv 1396] [Trace] Sending data ‘mrpe’ id is [9139169048663] length [0]
2021-12-08 11:37:01.748 [srv 1396] perf: Section ‘mrpe’ took [1] milliseconds
2021-12-08 11:37:01.748 [srv 1396] [Trace] Sending data ‘ps’ id is [9139169048663] length [8293]
2021-12-08 11:37:01.749 [srv 1396] perf: Section ‘ps’ took [140] milliseconds
2021-12-08 11:37:01.750 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Address Book Web Query’
2021-12-08 11:37:01.754 [srv 1396] Received [357] bytes from ‘mem’
2021-12-08 11:37:01.754 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Address Book File Download’
2021-12-08 11:37:01.760 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Location Information Service’
2021-12-08 11:37:01.763 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Distribution List Expansion’
2021-12-08 11:37:01.769 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - UCWA’
2021-12-08 11:37:01.774 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Mobile Communication Service’
2021-12-08 11:37:01.775 [srv 1396] Received [162] bytes from ‘fileinfo’
2021-12-08 11:37:01.779 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Throttling and Authentication’
2021-12-08 11:37:01.785 [srv 1396] [Trace] Key value cannot be processed ‘LS:WEB - Auth Provider related calls’
2021-12-08 11:37:01.790 [srv 1396] [Trace] Key value cannot be processed ‘LS:SIP - Protocol’
2021-12-08 11:37:01.796 [srv 1396] Received [189] bytes from ‘df’
2021-12-08 11:37:01.796 [srv 1396] [Trace] Key value cannot be processed ‘LS:SIP - Responses’
2021-12-08 11:37:01.801 [srv 1396] [Trace] Key value cannot be processed ‘LS:SIP - Peers’
2021-12-08 11:37:01.807 [srv 1396] [Trace] Key value cannot be processed ‘LS:SIP - Load Management’
2021-12-08 11:37:01.812 [srv 1396] [Trace] Key value cannot be processed ‘LS:SIP - Authentication’
2021-12-08 11:37:01.817 [srv 1396] Received [8678] bytes from ‘services’
2021-12-08 11:37:01.818 [srv 1396] [Trace] Key value cannot be processed ‘LS:CAA - Operations’
2021-12-08 11:37:01.823 [srv 1396] [Trace] Key value cannot be processed ‘LS:DATAMCU - MCU Health And Performance’
2021-12-08 11:37:01.828 [srv 1396] [Trace] Key value cannot be processed ‘LS:AVMCU - MCU Health And Performance’
2021-12-08 11:37:01.832 [srv 1396] [Trace] Key value cannot be processed ‘LS:AsMcu - MCU Health And Performance’
2021-12-08 11:37:01.838 [srv 1396] Received [141] bytes from ‘plugins’
2021-12-08 11:37:01.838 [srv 1396] [Trace] Key value cannot be processed ‘LS:ImMcu - MCU Health And Performance’
2021-12-08 11:37:01.842 [srv 1396] [Trace] Key value cannot be processed ‘LS:USrv - DBStore’
2021-12-08 11:37:01.846 [srv 1396] [Trace] Key value cannot be processed ‘LS:USrv - Conference Mcu Allocator’
2021-12-08 11:37:01.850 [srv 1396] [Trace] Key value cannot be processed ‘LS:JoinLauncher - Join Launcher Service Failures’
2021-12-08 11:37:01.855 [srv 1396] [Trace] Key value cannot be processed ‘LS:MediationServer - Health Indices’
2021-12-08 11:37:01.859 [srv 1396] Received [128] bytes from ‘local’
2021-12-08 11:37:01.862 [srv 1396] [Trace] Key value cannot be processed ‘LS:MediationServer - Global Counters’
2021-12-08 11:37:01.867 [srv 1396] [Trace] Key value cannot be processed ‘LS:MediationServer - Global Per Gateway Counters’
2021-12-08 11:37:01.871 [srv 1396] [Trace] Key value cannot be processed ‘LS:MediationServer - Media Relay’
2021-12-08 11:37:01.875 [srv 1396] [Trace] Key value cannot be processed ‘LS:A/V Auth - Requests’
2021-12-08 11:37:01.879 [srv 1396] [Trace] Key value cannot be processed ‘LS:DATAPROXY - Server Connections’
2021-12-08 11:37:01.880 [srv 1396] Received [128] bytes from ‘spool’
2021-12-08 11:37:01.883 [srv 1396] [Trace] Key value cannot be processed ‘LS:XmppFederationProxy - Streams’
2021-12-08 11:37:01.888 [srv 1396] [Trace] Key value cannot be processed ‘LS:A/V Edge - TCP Counters’
2021-12-08 11:37:01.894 [srv 1396] [Trace] Key value cannot be processed ‘LS:A/V Edge - UDP Counters’
2021-12-08 11:37:01.894 [srv 1396] [Warn ] Section ‘skype’ cannot provide data
2021-12-08 11:37:01.895 [srv 1396] [Trace] Sending data ‘skype’ id is [9139169048663] length [0]
2021-12-08 11:37:01.895 [srv 1396] perf: Section ‘skype’ took [150] milliseconds
2021-12-08 11:37:01.901 [srv 1396] Received [128] bytes from ‘mrpe’
2021-12-08 11:37:01.922 [srv 1396] Received [8421] bytes from ‘ps’
2021-12-08 11:37:01.943 [srv 1396] Received [3169] bytes from ‘winperf’
2021-12-08 11:37:01.969 [srv 1396] Received [128] bytes from ‘skype’
2021-12-08 11:37:06.374 [srv 1396] [Trace] Sending data ‘logwatch’ id is [9139169048663] length [72634]
2021-12-08 11:37:06.375 [srv 1396] perf: Section ‘logwatch’ took [4863] milliseconds
2021-12-08 11:37:06.390 [srv 1396] Received [72762] bytes from ‘logwatch’
2021-12-08 11:37:06.740 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:06.741 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:06.742 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_NETFramework_NETCLRMemory’ in 5004ms sends NO DATA
2021-12-08 11:37:06.742 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_W3SVC_WebService’ in 5003ms sends NO DATA
2021-12-08 11:37:06.743 [srv 1396] [Warn ] On timeout in section ‘dotnet_clrmemory’ try reuse cache
2021-12-08 11:37:06.744 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:06.745 [srv 1396] [Warn ] On timeout in section ‘wmi_webservices’ try reuse cache
2021-12-08 11:37:06.745 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:06.746 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:06.746 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeActiveSync_MSExchangeActiveSync’ in 5003ms sends NO DATA
2021-12-08 11:37:06.747 [srv 1396] [Warn ] Section ‘wmi_webservices’ cannot provide data
2021-12-08 11:37:06.747 [srv 1396] [Warn ] Section ‘dotnet_clrmemory’ cannot provide data
2021-12-08 11:37:06.748 [srv 1396] [Warn ] On timeout in sub section ‘msexch_activesync’ try reuse cache
2021-12-08 11:37:06.748 [srv 1396] [Trace] Sending data ‘dotnet_clrmemory’ id is [9139169048663] length [0]
2021-12-08 11:37:06.749 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:06.750 [srv 1396] [Trace] Sending data ‘wmi_webservices’ id is [9139169048663] length [0]
2021-12-08 11:37:06.750 [srv 1396] perf: Section ‘wmi_webservices’ took [5011] milliseconds
2021-12-08 11:37:06.751 [srv 1396] perf: Section ‘dotnet_clrmemory’ took [5011] milliseconds
2021-12-08 11:37:06.751 [srv 1396] Received [128] bytes from ‘dotnet_clrmemory’
2021-12-08 11:37:06.772 [srv 1396] Received [128] bytes from ‘wmi_webservices’
2021-12-08 11:37:11.751 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:11.753 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeAvailabilityService_MSExchangeAvailabilityService’ in 5002ms sends NO DATA
2021-12-08 11:37:11.753 [srv 1396] [Warn ] On timeout in sub section ‘msexch_availability’ try reuse cache
2021-12-08 11:37:11.754 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:16.758 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:16.759 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeOWA_MSExchangeOWA’ in 5004ms sends NO DATA
2021-12-08 11:37:16.769 [srv 1396] [Warn ] On timeout in sub section ‘msexch_owa’ try reuse cache
2021-12-08 11:37:16.772 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:21.776 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:21.777 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeAutodiscover_MSExchangeAutodiscover’ in 5004ms sends NO DATA
2021-12-08 11:37:21.777 [srv 1396] [Warn ] On timeout in sub section ‘msexch_autodiscovery’ try reuse cache
2021-12-08 11:37:21.778 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:26.788 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:26.790 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeISClientType_MSExchangeISClientType’ in 5011ms sends NO DATA
2021-12-08 11:37:26.791 [srv 1396] [Warn ] On timeout in sub section ‘msexch_isclienttype’ try reuse cache
2021-12-08 11:37:26.792 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:31.795 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:31.799 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeISStore_MSExchangeISStore’ in 5006ms sends NO DATA
2021-12-08 11:37:31.800 [srv 1396] [Warn ] On timeout in sub section ‘msexch_isstore’ try reuse cache
2021-12-08 11:37:31.800 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:36.803 [srv 1396] [Err ] Timeout [5] seconds broken when query WMI
2021-12-08 11:37:36.804 [srv 1396] [Warn ] Object ‘Win32_PerfRawData_MSExchangeRpcClientAccess_MSExchangeRpcClientAccess’ in 5003ms sends NO DATA
2021-12-08 11:37:36.804 [srv 1396] [Warn ] On timeout in sub section ‘msexch_rpcclientaccess’ try reuse cache
2021-12-08 11:37:36.805 [srv 1396] [Trace] cma::provider::WmiCachedDataHelper: no data to provide, cache is also empty
2021-12-08 11:37:36.805 [srv 1396] [Warn ] Section ‘msexch’ cannot provide data
2021-12-08 11:37:36.805 [srv 1396] [Trace] Sending data ‘msexch’ id is [9139169048663] length [0]
2021-12-08 11:37:36.806 [srv 1396] perf: Section ‘msexch’ took [35064] milliseconds
2021-12-08 11:37:36.815 [srv 1396] Received [128] bytes from ‘msexch’
2021-12-08 11:37:36.816 [srv 1396] perf: Answer is ready in [40340] milliseconds
2021-12-08 11:37:36.816 [srv 1396] Send [94929] bytes of data

Seems “MSEXCH” is causing the most latency, but I already disabled it?
How can this still be running?
Do I need to activate the config somewhere to the agent?