CPU Use Investigation

[Michael McSharry]

Attached is a plugin that goes through initialization to complete the handshake with HS, but does not initiate any internal processing. Let us confirm we have a starting point that does not have high CPU.

[Jeeves]

Attached is a plugin that goes through initialization to complete the handshake with HS, but does not initiate any internal processing. Let us confirm we have a starting point that does not have high CPU.

After loading this version of the plugin, CPU use is ~1.5. With debug enabled, the logs look identical.

[Michael McSharry]

Is 1.5 low or is it what you consider high?

[Jeeves]

Is 1.5 low or is it what you consider high?

That is low, essentially idle;

Quoting my previous post:

%CPU %MEM START   TIME COMMAND
6.9  5.8  18:47   2:05 /usr/bin/mono /usr/local/homeseer/HSConsole.ex
0.4  1.7  18:47   0:08 /usr/bin/mono /usr/local/homeseer/HSPI_BLOccup
0.4  1.7  18:47   0:07 /usr/bin/mono /usr/local/homeseer/HSPI_BLEmail
0.6  2.9  18:47   0:12 /usr/bin/mono /usr/local/homeseer/HSPI_ImperiH
0.3  1.9  18:47   0:05 /usr/bin/mono /usr/local/homeseer/HSPI_SCREPOS
0.5  3.3  18:47   0:10 /usr/bin/mono /usr/local/homeseer/HSPI_BULLET.
0.6  2.9  18:47   0:11 /usr/bin/mono /usr/local/homeseer/HSPI_ULTRANE
[B][COLOR="Red"]101[/COLOR][/B]  3.0  19:09   8:32 /usr/bin/mono /usr/local/homeseer/HSPI_MCSMQTT

Currently the plugin appears to be at an idle state:

 %CPU %MEM START   TIME COMMAND
 1.2  4.6 May19  10:29 /usr/bin/mono /usr/local/homeseer/HSConsole.exe --log
 0.4  2.2 May19   3:30 /usr/bin/mono /usr/local/homeseer/HSPI_BLOccupied.exe
 0.4  1.8 May19   3:30 /usr/bin/mono /usr/local/homeseer/HSPI_BLEmail.exe
 0.4  3.0 May19   3:47 /usr/bin/mono /usr/local/homeseer/HSPI_ImperiHome.exe
 0.1  2.0 May19   1:33 /usr/bin/mono /usr/local/homeseer/HSPI_SCREPOSITORY.exe
 0.4  4.1 May19   3:37 /usr/bin/mono /usr/local/homeseer/HSPI_BULLET.exe
 0.5  2.6 May19   4:38 /usr/bin/mono /usr/local/homeseer/HSPI_ULTRANETATMO3.exe
15.3  5.1 May19 132:39 /usr/bin/mono /usr/local/homeseer/HSPI_ZWave.exe
[COLOR="Red"] 0.4[/COLOR]  2.4 11:00   0:43 /usr/bin/mono /usr/local/homeseer/HSPI_MCSMQTT.exe

Small sidenote; I keep seeing that the debug file should be "mcsMQTT_Debug.txt", that is not the case; I see:

[Michael McSharry]

You are correct that there is no underscore in the Debug file name.

the logs look identical.

This does not make sense to me because the threads to start MQTT connection have debug output and this section was removed from the debug version. What was posted in the other thread includes the debug for at least the case where Disconnect was false.

In this debug I also see that ""MQTT Thread Client Created" did not exist. This means that there was never a return from m2mqtt.dll in one of two places. The first is with mucking with certificates. The second is creating the client object. It is likely the certificates since that is what is different in your case. This explains where it is just spinning its wheels looking for something that never happens.

This sequence should have been bypassed if Disconnect from Broker was checked at the time the plugin started. This will show in the debug "MQTT Thread Started with broker 192.168.1.35, Shutdown=False, Disconnect=True" . Can you repeat the sequence where Disconnect is set on the General tab and the plugin 3.4.0.0 or 3.4.0.2 is started. Post the debug. It is better to post the file rather than copy/paste to assure I have full visibility.

[Jeeves]

You are correct that there is no underscore in the Debug file name.


This does not make sense to me because the threads to start MQTT connection have debug output and this section was removed from the debug version. What was posted in the other thread includes the debug for at least the case where Disconnect was false.

In this debug I also see that ""MQTT Thread Client Created" did not exist. This means that there was never a return from m2mqtt.dll in one of two places. The first is with mucking with certificates. The second is creating the client object. It is likely the certificates since that is what is different in your case. This explains where it is just spinning its wheels looking for something that never happens.

This sequence should have been bypassed if Disconnect from Broker was checked at the time the plugin started. This will show in the debug "MQTT Thread Started with broker 192.168.1.35, Shutdown=False, Disconnect=True" . Can you repeat the sequence where Disconnect is set on the General tab and the plugin 3.4.0.0 or 3.4.0.2 is started. Post the debug. It is better to post the file rather than copy/paste to assure I have full visibility.

You are correct, I apologize. I did not know to look for that single line. There is no line in the debug log starting with "MQTT Thread Started".

See attached.

I have also downloaded the updated 3.4.0.4 build and started it with the "disconnected" box, checked. It is also attached.

The CPU is high when using it:

 1.2  5.5 May19  13:49 /usr/bin/mono /usr/local/homeseer/HSConsole.exe --log
 0.4  2.2 May19   4:21 /usr/bin/mono /usr/local/homeseer/HSPI_BLOccupied.exe
 0.4  1.8 May19   4:22 /usr/bin/mono /usr/local/homeseer/HSPI_BLEmail.exe
 0.4  3.1 May19   4:42 /usr/bin/mono /usr/local/homeseer/HSPI_ImperiHome.exe
 0.1  2.0 May19   1:58 /usr/bin/mono /usr/local/homeseer/HSPI_SCREPOSITORY.exe
 0.4  4.2 May19   4:30 /usr/bin/mono /usr/local/homeseer/HSPI_BULLET.exe
 0.5  2.8 May19   5:46 /usr/bin/mono /usr/local/homeseer/HSPI_ULTRANETATMO3.exe
15.0  5.3 May19 161:16 /usr/bin/mono /usr/local/homeseer/HSPI_ZWave.exe
 103  3.3 17:02   2:59 /usr/bin/mono /usr/local/homeseer/HSPI_MCSMQTT.exe

The differences between the two logs are:
- Spawning MQTT Threads
- MQTT Thread Started with broker 192.168.1.35, Shutdown=False, Disconnect=True, Client=False, Connected=False
(at the end of the log)
- Page Timing Start
- Page Timing End

[Michael McSharry]

Found it and corrected in 3.4.0.5. 10 second timing loop was bypassed when connection to broker did not occur. This made it a 0 second timing loop.

[Jeeves]

Found it and corrected in 3.4.0.5. 10 second timing loop was bypassed when connection to broker did not occur. This made it a 0 second timing loop.

I can confirm with 3.4.0.5 I am seeing what appear to be 'correct' CPU loads.

I'm not sure this explains the high load in the previous configuration when it was connected to the broker using authentication (no SSL) with several associations.

Without setting up another listener I do not have an immediate way to test this.

However, thank you very much! I look forward to testing the SSL code.

[Pete]

If you have any spare RPi's around you can configure brokers on them to do just about anything with Node Red. Well like CPU temperature or something similar. Here have repurposed all of the old RPi's to tinker with.

Here checking on Homeseer mono processes I get a bit more granularity running HTop than Top.

1 - ssh to your box
2 - sudo apt-get install htop
3 - adjust settings in htop and save with F10 (done)
[ATTACH]68928[/ATTACH]
4 - restart htop and filter with "hs"
[ATTACH]68927[/ATTACH]