Announcement

Collapse
No announcement yet.

mcsMQTT - Slow initial config page load

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    mcsMQTT - Slow initial config page load

    Since initial configuration of the plug-in, it seems to take an excessive period of time just to load the config page. I just timed it at ~40 seconds, and this happens on any consecutive refresh as well. Is this intended? It seems quite excessive.

    I have also noticed that if I add a device to history, h or d, everything quits responding for ~30 seconds. When doing this the system time in the header quits updating as well, unlike the delay when loading the config page.

    if this isn't expected, what do I need to look at to troubleshoot it?
    This is all on an ODroid XU4, which otherwise has no issues with performance.
    Thanks!

    #2
    first thing is to understand the number of topics being managed. is it on the 1000's? Is swap being used because RAM becomes filled? How big is the History database? is there a backlog when looking at Statistics page for receive queue and average time to process message?

    I can add timestamps in the debug to help isolate if that will help.

    Comment


      #3
      Attached is a build with selective timestamps as page is being constructed. Debug needs to be enable on General Tab. Data is in file in \Data\mcsMQTT\mcsMQTT Debug.txt. Unzip the file into your HS3 folder after renaming same file so you can restore your configuration after the testing.
      Attached Files

      Comment


        #4
        Originally posted by Michael McSharry View Post
        Attached is a build with selective timestamps as page is being constructed. Debug needs to be enable on General Tab. Data is in file in \Data\mcsMQTT\mcsMQTT Debug.txt. Unzip the file into your HS3 folder after renaming same file so you can restore your configuration after the testing.
        Michael, thank you for your (always) quick efforts. It seems I'm being mocked as an update last night ate the boot partition of my HS3 server.

        When I get it back up, I'll test this.

        Comment


          #5
          Originally posted by Michael McSharry View Post
          Attached is a build with selective timestamps as page is being constructed. Debug needs to be enable on General Tab. Data is in file in \Data\mcsMQTT\mcsMQTT Debug.txt. Unzip the file into your HS3 folder after renaming same file so you can restore your configuration after the testing.
          Michael,
          I updated the plugin, then loaded the config page.
          I then shutdown homeseer, copied out that debug log and removed the history database and started back up Homeseer.
          I then loaded up the config page again and copied out the log.

          With a 300Mb history - Page Timing Start - 00:59:55 - 1:00:22 - 27 seconds.
          With no history - Page Timing Start - 00:50:37 - 00:50:45 - 8 seconds.

          8 doesn't feel bad, 27 certainly does. Is that a normal load time? I did notice there seems to be a 20 second pause after an "ActoOnMessageForTrigger" line.
          Logs are attached.
          Attached Files

          Comment


            #6
            You appear to have a significant number of items that mcsMQTT is managing with about 1700 received items and 600 non-plugin devices. This in itself is not a issue. I captured the timing info below for your two runs and then for mine. The actual page rendering time in all three cases is about 2 seconds. On your system there are periods of time when the rendering is paused as the CPU is doing something else. In one case there was a 6 second pause that looks to be doing something not related to mcsMQTT. In the second case the pause was 19 seconds and part of it was mcsMQTT servicing received messages which is reflected with "ActoOnMessageForTrigger" lines.

            My HS install does not have much happening other than handling MQTT traffic so there is not a contention for CPU or RAM. RAM page swap is slow so pauses like seen in the debug could be attributed to it. I'm a Linux novice, but there should be some tools available to look at RAM utilization. I think even top or htop show if swap is being activated.

            On the Association tab it is best to use the available filters to reduce the number of items that need to be rendered. I first thought this may have been the problem when I saw 6 seconds before BuildAssociationTable was done. Since it did not repeat in your second test case the number of items being rendered does not appear to be a specific cause.

            History & Charting are intended for analysis which is typically targeted to specific things rather than a save everything for a long time situation. Large database is not a problem in itself, but does tax the system overall. If resources are constrained then this is an area were some savings can be achieved.

            If you have other functionality that could tend to be CPU or RAM intensive then collecting timing data related to those may help isolate. If mcsMQTT stops executing for 6 or 19 seconds then something else is using this time. It could be OS or it could be some application. I'm sorry I cannot be more definitive but don't know anything else I can do with mcsMQTT debug.

            Code:
            8 seconds page rendering time (6 second pause)
            11/23/2019 00:50:37    10773    | Page Timing Start - 00:50:37 - 00:50:45
            11/23/2019 00:50:37    11262    | Page Timing FilterRebuild Done  
            11/23/2019 00:50:38    11900    | Page Timing Association Tab BuildTableReverse Sort Done
            
            11/23/2019 00:50:44    17865    | Page Timing Association Tab BuildAssociationTable Done
            
            11/23/2019 00:50:45    18958    | Page Timing Association Tab Filter Done  
            11/23/2019 00:50:45    18960    | Page Timing Association Tab DisplayRow Done  
            11/23/2019 00:50:45    18970    | Page Timing AssociationTab Done  
            11/23/2019 00:50:45    19011    | Page Timing Edit Tab Done  
            11/23/2019 00:50:45    19208    | Page Timing General Tab Done  
            11/23/2019 00:50:45    19231    | Page Timing Statistics Tab Done  
            11/23/2019 00:50:45    19270    | Page Timing History Tab Done  
            11/23/2019 00:50:45    19345    | Page Timing Chart Tab Done  
            11/23/2019 00:50:45    19369    | Page Timing FormatScreen Done  
            11/23/2019 00:50:45    19384    | Page Timing End     
            
            27 seconds page rendering time (26 second pause)
            11/23/2019 00:59:55    38079    | Page Timing Start - 00:59:55 - 1:00:22
            11/23/2019 00:59:55    38302    | Page Timing FilterRebuild Done  
            11/23/2019 00:59:55    38614    | Page Timing Association Tab BuildTableReverse Sort Done  
            11/23/2019 00:59:56    39699    | Page Timing Association Tab BuildAssociationTable Done  
            11/23/2019 00:59:56    39741    | Page Timing Association Tab Filter Done  
            11/23/2019 00:59:56    39743    | Page Timing Association Tab DisplayRow Done  
            11/23/2019 00:59:56    39751    | Page Timing AssociationTab Done  
            11/23/2019 00:59:56    39772    | Page Timing Edit Tab Done  
            11/23/2019 00:59:56    39859    | Page Timing General Tab Done  
            11/23/2019 00:59:56    39869    | Page Timing Statistics Tab Done  
            11/23/2019 00:59:56    39894    | Page Timing History Tab Done
            
            11/23/2019 01:00:22    65540    | Page Timing Chart Tab Done  
            
            11/23/2019 01:00:22    65551    | Page Timing FormatScreen Done  
            11/23/2019 01:00:22    65559    | Page Timing End 
            
            part of chart tab (3 second pause, 19 second pause, 3 second pause)
            
            11/23/2019 00:59:56    39894    | Page Timing History Tab Done  
            11/23/2019 00:59:59    42419    | ActoOnMessageForTrigger Topic rtl_433/rtl_sdr-Pi/events,Payload={"time":"2019-11-22 17:59:58","model":"Ambient Weather F007TH Thermo-Hygrometer","device":74,"channel":6,"battery":"Low","temperature_F":63.1,"humidity":70,"mic":"CRC"}  
            
            11/23/2019 00:59:59    42847    | ActoOnMessageForTrigger Topic rtl_433/rtl_sdr-Pi/devices/Ambient_Weather_F007TH_Thermo-Hygrometer/6/mic,Payload=CRC  
            11/23/2019 01:00:18    61293    | ActoOnMessageForTrigger Topic rtl_433/rtl_sdr-Pi/events,Payload={"time":"2019-11-22 18:00:17","model":"Ambient Weather F007TH Thermo-Hygrometer","device":214,"channel":8,"battery":"OK","temperature_F":92.7,"humidity":15,"mic":"CRC"}  
            
            11/23/2019 01:00:18    61827    | ActoOnMessageForTrigger Topic rtl_433/rtl_sdr-Pi/devices/Ambient_Weather_F007TH_Thermo-Hygrometer/8/mic,Payload=CRC  
            11/23/2019 01:00:21    64439    | ActoOnMessageForTrigger Topic rtl_433/rtl_sdr-Pi/events,Payload={"time":"2019-11-22 18:00:20","model":"Ambient Weather F007TH Thermo-Hygrometer","device":135,"channel":3,"battery":"OK","temperature_F":65.2,"humidity":69,"mic":"CRC"}  
            
            
            
            
            My Odroid C1 timing (2 seconds)
            11/23/2019 8:51:27 AM    32131757    | Page Timing End 
            11/23/2019 8:51:25 AM    32129301    | Page Timing Start

            Comment


              #7
              Hmm. I'll have to do some digging. This build has < 650 devices in total. ~100 events.
              When the page pauses while loading, htop shows that mcsMQTT is using some 230% cpu across two instances.
              HConsole.exe --log is using a great majority of the memory on this device, HSPI_Bullet.exe is using an obscene amount of CPU for idling, but otherwise, I see nothing outstanding.

              When calling up the page, I see a spike in one of the HS threads CPU (35%). If the system is pausing, I certainly don't see where (and I don't experience this changing to any other plugin or screen).

              I tried digging through with trace, but I'm not familiar enough with it to make sense of the information (particularly with mono on top of everything).

              It's good to know the historical information, I was hoping to keep long term records but I may have to find another way if that is not the intent.

              If it's useful, I also noticed that the BLE page (unused currently) loads instantly.

              Apologies for the rambling post, it was more of a braindump as I troubleshoot.

              Comment


                #8
                Building the Association table with many items will consume some time without giving a break back to the OS. This will explain why the BLE page loads quickly vs. the main mcsMQTT page. When the OS gives the CPU to another application is is unknown it will take before it gives mcsMQTT a chance again. If there were many threads waiting then it could be some time.

                If you setup a filter on the Assocation tab it will persist. You can test this out by doing a filter that will result in less that 20 items being displayed. If the page loads more quickly then you have a method to improve the initial load times. I also noticed in one of our test debug files that the mcsMQTT page was loaded before the mcsMQTT initialization completed. There are two phases to the init. The first is what the plugins needs to run. The second is to prepare a user interface.

                If you are a Visual Studio user then you are welcome to the source if that will help you with debug. It is VB.NET.

                Comment


                  #9
                  Originally posted by Michael McSharry View Post
                  Building the Association table with many items will consume some time without giving a break back to the OS. This will explain why the BLE page loads quickly vs. the main mcsMQTT page. When the OS gives the CPU to another application is is unknown it will take before it gives mcsMQTT a chance again. If there were many threads waiting then it could be some time.

                  If you setup a filter on the Assocation tab it will persist. You can test this out by doing a filter that will result in less that 20 items being displayed. If the page loads more quickly then you have a method to improve the initial load times. I also noticed in one of our test debug files that the mcsMQTT page was loaded before the mcsMQTT initialization completed. There are two phases to the init. The first is what the plugins needs to run. The second is to prepare a user interface.

                  If you are a Visual Studio user then you are welcome to the source if that will help you with debug. It is VB.NET.
                  I have developed with it previously, but to say I'm exceedingly familiar with VS would be misleading. I'm a far better debugger than programmer. If it's documented it may give me a better idea of program execution and flow. This wouldn't be on github/etc, would it?

                  Currently I have a filter (by Mqtt Topic and JSON Payload Key) on the associations page that is only displaying 50 items (I assume these are the filters you mean) with the only check box being "Include Received MQTT Topics", yet my load times are still ~30sec. I changed this to be a Filter by HS Device Categories down to 13 devices, load time is still ~30 seconds.

                  Comment


                    #10
                    I recently uploaded source at link in post #31 at https://forums.homeseer.com/forum/li...ng-state/page3 There was later a delta update on post #92. I would not call it well-documented, but page construction is in file MQTTASP with the flow shown in the debug analysis in post #6 above. The same thread where the source is located also contains discussion where I helped another user get setup with it.

                    There is something happening in your system where scheduling takes control away from mcsMQTT and mcsMQTT does not get it back for many seconds. Our first debug approach tried to find where mcsMQTT was slow but that seemed to show that no specific sequence was slow, but slices of time at "random" times were being taken from mcsMQTT execution. Another way to approach it is to backup HS or install another copy of HS and then start with only mcsMQTT and then add to it until the behavior returns. \Config\mcsMQTT.ini and \Data\mcsMQTT\ is where the mcsMQTT setup exists.

                    Comment


                      #11
                      Originally posted by Michael McSharry View Post
                      I recently uploaded source at link in post #31 at https://forums.homeseer.com/forum/li...ng-state/page3 There was later a delta update on post #92. I would not call it well-documented, but page construction is in file MQTTASP with the flow shown in the debug analysis in post #6 above. The same thread where the source is located also contains discussion where I helped another user get setup with it.

                      There is something happening in your system where scheduling takes control away from mcsMQTT and mcsMQTT does not get it back for many seconds. Our first debug approach tried to find where mcsMQTT was slow but that seemed to show that no specific sequence was slow, but slices of time at "random" times were being taken from mcsMQTT execution. Another way to approach it is to backup HS or install another copy of HS and then start with only mcsMQTT and then add to it until the behavior returns. \Config\mcsMQTT.ini and \Data\mcsMQTT\ is where the mcsMQTT setup exists.
                      I'll try stripping down mcsMQTT until I find something noteworthy. As I mentioned, it only seems to be during the mcsMQTT's load, which makes me wonder if there's something ugly in the DB or maybe mono has something to do with it.

                      Thanks for the assistance!

                      Comment


                        #12
                        Originally posted by Jeeves View Post

                        I'll try stripping down mcsMQTT until I find something noteworthy. As I mentioned, it only seems to be during the mcsMQTT's load, which makes me wonder if there's something ugly in the DB or maybe mono has something to do with it.

                        Thanks for the assistance!
                        I am new to the plugin, but today I noticed my MCSMQTT plugin was pegging the CPU. I have just been doing mosquito_pubs from my MQTT broker machine-- and homeseer was seeing 2 MQTT messages in the stats windows when this happened. I shut off the plugin and restarted-- but I have the simplest of setups and I this I saw this.
                        HS3 Pro Edition 3.0.0.435 (Windows Server 8.1 on ESXi box)

                        Plug-Ins Enabled:
                        Z-Wave:,RaspberryIO:,AirplaySpeak:,Ecobee:,
                        weatherXML:,JowiHue:,APCUPSD:,PHLocation:,Chromecast:,EasyTr igger:

                        Comment


                          #13
                          There are two timing drivers. HS takes much longer than MQTT message processing. This is especially noticeable at startup when the plugin collects all the HS devices. You can save this time with option on General tab at bottom to only enumerate devices with use of button. The only reason that you want to enumerate them is if you are going to have an existing device be used as the source of a MQTT messsage.

                          The second thing, which is likely not your situation, is that mcsMQTT listens for all MQTT traffic. If you have a considerable amount of this traffic that is not intended for HS then the General tab setting can be used to subscribe to only topics where HS device are associated.

                          To address the relative slowness of HS there was an express mode introduced. This mode minimizes the access to HS. It has some limitations, but generally will work fine for most uses. Express mode is selected on a topic by topic checkbox on Association tab. The general tab has a setting to make newly discovered topics automatically be setup for Express mode.

                          The Statistic tab contains information related to processing MQTT traffic. The manual also contains a Performance Considerations sections that documents the benchmarking that was done.

                          If you continue to see excessive CPU usage then I would like to work with you to understand why.

                          Comment


                            #14
                            Michael,
                            I apologize for drudging this back up, but I'm still suffering this issue. I never found a cause.

                            Attached are GIFs of loading the MQTT config and the BLE config.

                            Prior to this, I blew away the MQTT database and history, and rebooted. The DB at this time is 61K and the History is 12K.
                            https://streamable.com/yyzlvs

                            Compare to opening the BLE settings: https://streamable.com/arxm2g

                            edit: sorry, seems this forum doesn't like animated gifs, I've replaced the links.

                            Comment


                              #15
                              As of 5.4.0.0 mcsMQTT (any page) will delay response to browser requests until it completes initialization. In developer mode the console will show progress through initialization with the last line being "initialization complete". Can you enable developer mode to view this? If you wait a few minutes do you still get slow MQTT page loads?

                              Comment

                              Working...
                              X