Speed benchmark for HG

[bkenobi]

I had a discussion with a HG user on PM the other day about my Advanced Smart Lights code to help him get things set up.  When everything was working correctly, he noticed that there was a large delay (or at least perceived delay) from the time a motion detector sensed motion and when the light turned on.  Part of this is due to X10 protocol being utilized.  The other part is HG overhead.  This got me thinking that maybe some systems run faster than others and that it might be nice to know what kind of a performance hit might be experienced by using a Raspberry Pi versus a 12 core PC.

To understand this, I thought a simple test that could be easily run on multiple systems would be useful.  I was hoping that a few people with different systems could run the attached code and post the mono output.  I have attached an example of my output for reference.

To use the hgx script:

• download script (hgx)
• go to configure->automation->[any group]
• actions->import
• select new script and edit
• select program tab and compile (upper left)
• select back to exit the script
• select the script again
• enter the name of a module that you want to test with (ideally a switch, light, dimmer)
• control the module with either RF, PLC, or HG itself

For reference:
The script will watch for a module with the given name to turn on.  When it sees that command, it will immediately turn it off.  I don't even have a module hooked up to actuate, I just used address A1.  With the official release of HG (not using the updated XTenLib posted yesterday), the command sequence will be (assuming A1):

Code: [Select]

A1
AON
HG runs code
A1
AOFFIf you run some calculations, a sequence of 4 commands will take a minimum of 1.67 seconds.

If you are using the updated XTenLib file:

Code: [Select]

A1
AON
HG runs code
AOFFThis version uses 1 less command, so it would take a minimum of 1.25 seconds.

This test is VERY basic as far as HG goes, so I would anticipate each system taking very close to this minimum time.  If so, I'll construct a more rigorous test to see if more complex code takes more/less time on different systems.  Thanks for considering running this test!

[RoChess]

Could actually automate this.

Certain motion sensors, such as the Aeon-Labs or Fibaro 4-in-1 models can also report Luminance values.

By placing sensor close to light source, you can automate the timing. Have the motion sensor trigger the scene (and start clock), then after complex scene finishes, turn the light on. Then on Luminance value you turn the light back off and stop the clock.

Result will be an interesting "benchmark" value, that can be compared between different systems. Perhaps use a powerful 12-core system to get a theoretical base value of say 10 seconds. That way it is easy to compare against.

Could even do a stress test, by having the scene activate based on luminance value as well, so it goes into a constant loop of on/off. The motion sensor could be used to abort the stress test or configure like X amount of test runs.

[bkenobi]

That would certainly be a next step that could be considered!

I reviewed my results that I posted this morning and found that there is a large lag between the commands that seems to last for between 0.5-1.2 seconds.  I'm not clear what's happening in this period, but that extra second would explain why the sequence which should take ~1.67 seconds takes closer to 2.5-3 seconds.

The first tab of the spreadsheet contains primarily the raw mono output for each test.  The second tab tabulates delta times between different events.  As seen in the 3rd table, there is a large time gap between when HG sets A1 to ON and when the script sends the OFF command.  I do have quite a few widgets enabled in HG (though significantly less than are available).  I'll try rerunning with only the script enabled to see if that makes any difference.

[bkenobi]

I updated HG to the current committed code on github (compile required), turned off all programs except the test module, and tried the test procedure again.  The attached data shows that the transmission time might be slower.  The RF code was hard to say what was happening since HG now sees both the RF and PLC communication from the CM15A.  The AON only command seemed to be slightly slower (~0.4  seconds slower).  The full command set (A1, AON) seemed much slower (4 versus 2.3 seconds) and certainly slower than the minimum theoretical needed time (1.67 seconds).  I didn't run the HG test this time.

[bkenobi]

I've been thinking about this for a few weeks now (well, months really).  I originally posted that HG seemed to take significantly longer than necessary to turn on a module than necessary when triggered from an outside command (X10 to X10).  I just realized that there is still an issue to some degree even if the first command isn't X10.  I switched my front motion sensor from using an X10 transmitter (PowerFlash) to using a GPIO input.  Since HG should see the GPIO change nearly instantly and the X10 transmitter should take around a second there should be a noticeable difference in speed.  However, it still seems to take around the same time to have a light turn on whether it's via GPIO or via X10 (indirect) command.

I'm going to post data comparing the following:

Trigger	Controlled	Time
X10 PLC	X10 PLC	?
X10 RF	X10 PLC	?
GPIO	X10 PLC	?
HG web	X10 PLC	?
HG Android	X10 PLC	?

If there's a significant difference that's repeatable, I'd really hope that we could look at tracking down the source.  I was willing to let the slow response go as an artifact of X10 being used.  But, now that other users see it as an issue and the fact that GPIO seems to have the same issue, I think it's worth investigating.

[bkenobi]

Test	Trigger	Controlled	Min Time	Average Time	Max Time
1	HG web (direct)	X10 PLC	0.866	1.2141	1.863
2	X10 PLC	X10 PLC	1.771	2.1082	2.672
3	X10 RF	X10 PLC	2.624	2.9812	3.068
4	GPIO	X10 PLC	0.868	1.1821	1.888
5	HG web	X10 PLC	1.733	2.0461	2.606
6	HG Android	X10 PLC	0.873	1.8203	2.309
7	ASL X10 PLC	X10 PLC	3.344	3.344	3.344
8	ASL GPIO	X10 PLC	2.282	2.282	2.282

Notes:

• Case 1 is a baseline controlling the light from HG by sending the command directly.
• All non-needed modules were disabled.  X10 HC/UC A1 was used for all tests.  GPIO 25 used.
• Tests 1-6 had 10 instances run.  Reduced instances was run for cases 7 and 8.
• All test performed on Raspberry Pi model B
• ASL = Advanced Smart Lights
• HG web page was loaded for all tests which could add some overhead
• Logging was turned on within ASL for all but tests 11 and 12
• Mono logging was enabled for all testing to make it possible to generate times
• All log files were written to a network file share which could add some overhead

Based on these results, I'd say that GPIO is definitely faster than X10 in any form (which it should be).  GPIO is basically the same speed as sending a direct command via the web or android.  Sending a command via X10 should take approximately 0.835 seconds.  So it appears that in the best case runs for GPIO, HG web, and HG Android the response was excellent.  In the case of trigger via X10, the minimum time should be approximately 1.67 seconds.  So it appears that X10 PLC can react in that amount of time.

That being said, I see a lot of variation in the results and each of the tests showed that HG could take over twice as long as theoretically minimum for no apparent reason.

Finally, when using my real world code (Advance Smart Lights), I find that there is a massive performance hit when using loops at least on the Raspi.  I'd appreciate a recommendation at this point.  Would I be better served upgrading the Raspi to something more powerful?  Or, would I find some benefit to optimizing the code somehow?  If optimizing would be best, any recommendations on how?

[bkenobi]

I've rerun some testing and updated the table.  This includes all the same data as before with a few new tests.

Test	Trigger	Controlled	Min Time	Average Time	Max Time
1	HG web (direct)	X10 PLC	0.866	1.214	1.863
2	X10 PLC	X10 PLC	1.771	2.108	2.672
3	X10 RF	X10 PLC	2.624	2.981	3.068
4	GPIO	X10 PLC	0.868	1.182	1.888
5	HG web	X10 PLC	1.733	2.046	2.606
6	HG Android	X10 PLC	0.873	1.820	2.309
7	ASL X10 PLC	X10 PLC	2.085	2.627	3.344
8	ASL GPIO	X10 PLC	2.282	2.282	2.282
9	ASL X10 PLC	X10 PLC	1.814	2.031	2.453
10	ASL HG X10 PLC	X10 PLC	2.230	2.538	3.335
11	ASL X10 PLC NoLog	X10 PLC	1.807	2.226	2.914
12	ASL GPIO NoLog	X10 PLC	1.349	1.707	2.270

It appears that the logging of data (writing to a network drive) makes a difference, so I'll disable it in the default config and upload a new copy of Advanced Smart Lights to the Contributions thread.  But, I'm still a bit confused how sometimes it can take an extra second to execute for no apparent reason.  I'm curious if there's a reason for this.  And, if so, is there a way to eliminate it.