HG is slow

[bkenobi]

When I send a command from HG to turn on a light, it takes less than a second for the module to respond.  This issue is present for me when I send a command from a X10 controller via PLC or RF to the CM15 and then have the CM15 send a command to the light module by PLC.  Are you saying that running this configuration you see the light turn on in less than a second?

[Gene]

Ok... so it's a different scenario from the one I figured out.
Tell me what kind of test I can do to reproduce? Do I have to send a command with an RF remote and see if CM15 route it through PLC?
Give me some example.

Cheers,
g.

[bkenobi]

Simple test:

• Install test-C#.hgx
• Configure 2 X10 modules ("Entry lights" and "Entry switch").  The switch doesn't need to have a physical module, but the light must be real module of some kind (preferably a relay style light or appliance module or non-ramping dimmable module).  The relay is helpful because it gives an audible notification for when the command is executed by the module.
• With the switch and light both off in HG, send an on command with either an RF or PLC controller (any type should work from my testing).
• With a stop watch, time how long it takes from when you press the on button on the controller to when the relay clicks or the light turns on

The HG interface will obviously show a much slower response than the actual light due to the polling of the web page, but the light itself should ideally turn on very quickly.  X10 takes fractions of a second to send, but in practice it should respond in under 1 second.  Since this is 2 commands, the best case would be something less than 2 seconds.  When this is run via AHP's SDK, the response is 1.5-2 seconds.  When run with Mochad, the response seems to be just over 2 seconds (2.1-2.2s).  HG seems to take 2.8-3.5 seconds.

It would be good to confirm that this is consistent for you and that it's not something else in my setup that could be improved.

[bkenobi]

I just got a very useful response from a senior member at the X10 forums about optimal time for this operation:

You are actually receiving B6 B_ON and sending A6 A_ON. Given that each code is sent twice and each doublet must be followed by 3 silent cycles, B6 B_ON uses 50 cycles of the powerline. A6 A_ON requires the same amount of time but most X10 receivers will react to the first copy of the function code which would be 36 powerline cycles. So, the minimum time will be 1.43 seconds and this is without any time allowed for the CM15A to react to B6 B_ON and send A6 A_ON.

    http://digilander.libero.it/cvolpato/elettronica/X-10_Transmission_Theory.htm

Basically, best case for this operation would be 1.43s.  I'm seeing 1.5s with AHP, so something close to that would be great.

I wrote a little script to use Mochad for this test.  I think it's useful in case you wanted to see a comparison of speed.

The other question I had was about the implementation of the USB drivers.  I know that Mochad uses the libusb-1.0.0 development drivers since there's nothing built into Linux to handle connecting to the CM15.  What drivers are you using in HG?  Since they are the same for both Windows and Linux, I'm assuming they are built into .NET 4 framework.  Is it possible this is what is slowing things down?  If so, perhaps it would be possible to use Mochad with the web helper in HG since Mochad will connect to any TCP client?

[Gene]

Hi Ben,

hg is also using libusb. I just sent r351 update that is aimed to solve some threading and memory performance issues.
Pheraps it can give a better x10 response too. Didn't test though.

g.

[bkenobi]

I'm still trying to get r351 to work on my raspi.  I've tried the install 2 or 3 times now and each time going from a working 345 image, I get a broken 351.

[Jens]

With R345 on raspian with cm15pro i can confirm that x10 is as fast as hue lightning, I tend to say that even x10 is already realtime

BUT, I cannot go further than R345 as mentioned in the bugs thread r350-r351, Gene, we need your help I guess. How can we help providing logs etc?

cheers
Jens

[bkenobi]

It depends on what you mean by fast.  If you push a button on the HG display (web or Android), the light will responds very quickly.  My question is about sending an X10 command over the PLC, having HG see the command, HG sending a new PLC command, and having the light turn on.  In this case, I do not expect things to be instantaneous as the PLC transmission is not capable of being that fast.

I just tested r352 and it appears to be around the same speed.  I have logging turned on and am redirecting the output to a file in my /home/pi directory.  Watching the contents of this file, I see the following:

2014-03-29T11:38:39.1426200-07:00       HomeAutomation.X10      B6      -      Status.Level     1
2014-03-29T11:38:39.4001950-07:00       HomeAutomation.X10      A6      -      Status.Level     1

I believe this can be interpreted as HG sees the PLC command at 11:38:39.1426200 and then responds with the reply at 11:38:39.4001950.  If so, that is a difference of 0.25 seconds that it took HG to respond.  If that's the case, then if I take the optimum time for a transmission to occur 2 ways (1.43s) and add this delta, I'd have 1.687 seconds.  I'm still seeing close to 3 seconds though before the light actually turns on.

Is there a way to add more output to the X10 module so that it could output when it receives and when it sends commands?  I don't know how much this would help, but it seems like it might be good for debugging to at least try.

[bkenobi]

I just realized I could use HG to log a X10 command sequence.  I triggered the switch and let AHP turn the light on.  This is what HG logged:

2014-03-29T11:55:52.7697510-07:00       HomeAutomation.X10      B6      -      Status.Level     0
2014-03-29T11:55:53.6278830-07:00       HomeAutomation.X10      A6      -      Status.Level     0

So, HG saw the PLC B6 OFF at the same time as AHP and after AHP responded, HG saw the command.  This means, there could be a slightly longer time than the light would need to toggle.  Total time for the command was 0.858 seconds plus the time it takes for the first to be sent (~1.43/2 or 0.72s) which would be ~1.573 seconds.

[Gene]

Hi Ben,

just replaced the r356 in the testing folder.

https://sourceforge.net/projects/homegenie/files/testing/

I made some more cleanup and optimization in XTenLib.
Whenever you get a chance, please test it.

Thanks!
g.

[bkenobi]

I'm downloading now.  Will let you know.

[bkenobi]

I have r356 installed and running.  When I look at the log, I can see all the communication with the CM15A, which is great.  The only thing that might be nice would be outputting the time so I could be a bit more precise.  Looking at what it's displaying now, I'm seeing the following:

"2014-03-30T18:41:55.3470740-07:00   MIG.Gateways.WebServiceGateway   192.168.0.5   api/HomeAutomation.HomeGenie/Logging/Recent.Last/5000/1396230131702   HTTP   GET"
[X10] >> IN  5A 02 00 E9
[X10] >> OUT C3
[X10] >> IN  5A 02 01 E3
"2014-03-30T18:41:58.2072520-07:00   HomeAutomation.X10   B6   -   Status.Level   0"
"2014-03-30T18:41:58.2179060-07:00   HomeAutomation.X10   A6   -   Status.Level   0"
[X10] >> OUT C3
[X10] >> OUT 04 69
[X10] >> IN  55
[X10] >> OUT 06 63
[X10] >> IN  55
"2014-03-30T18:42:00.3185510-07:00   MIG.Gateways.WebServiceGateway   192.168.0.5   api/HomeAutomation.HomeGenie/Logging/Recent.Last/5000/1396230136697   HTTP   GET"

I don't have the exact time for the X10 events, but using the line right after/before yields the following.

Code: [Select]

Command Time Delta
CM15A sees start of A6 ON sequence 18:41:55.3470740 00:00:00.000
HG recognizes A6 ON sequence 18:41:58.2072520 00:00:02.860
HG starts to send B6 ON sequence 18:41:58.2179060 00:00:02.871
HG finished sending B6 ON sequence 18:42:00.3185510 00:00:04.972

I don't believe the 4.9 seconds at all.  My stop watch indicates closer to 2.5-3 seconds or so.

[bkenobi]

So this is what I've found.  When I use HG to monitor AHP, this is the incoming activity:

A6 ON
[X10] >> IN  5A 02 00 69
[X10] >> OUT C3
[X10] >> IN  5A 02 01 62
[X10] >> OUT C3

A6 OFF
[X10] >> IN  5A 02 00 69
[X10] >> OUT C3
[X10] >> IN  5A 02 01 63
[X10] >> OUT C3

B6 ON
[X10] >> IN  5A 02 00 E9
[X10] >> OUT C3
[X10] >> IN  5A 02 01 E2
[X10] >> OUT C3

B6 OFF
[X10] >> IN  5A 02 00 E9
[X10] >> OUT C3
[X10] >> IN  5A 02 01 E3
[X10] >> OUT C3

When using HG as the controller:

A6 ON
[X10] >> OUT 04 69
[X10] >> IN  55
[X10] >> OUT 06 62
[X10] >> IN  55

A6 OFF
[X10] >> OUT 04 69
[X10] >> IN  55
[X10] >> OUT 06 63
[X10] >> IN  55

B6 ON
[X10] >> IN  5A 02 00 E9
[X10] >> OUT C3
[X10] >> IN  5A 02 01 E2
[X10] >> OUT C3

B6 OFF
[X10] >> IN  5A 02 00 E9
[X10] >> OUT C3
[X10] >> IN  5A 02 01 E3
[X10] >> OUT C3

As expected, the B6 ON/OFF are the same since those are sent by the wall switch.  Also as expected, the A6 ON/OFF are different.  In the first case, AHP is sending the A6 ON/OFF and in the second HG is acting as the controller.  The only thing I'm wondering is if there's a reason that HG is sending half as many octlets as AHP.  I'm wondering if HG is taking 2 cycles to send a single command.  If so, then it would definitely take much longer to control the light.  In fact, if it takes 1.43 seconds minimum to send 2 commands, then this would effectively be requiring 3 commands or a total of 2.145 seconds plus computing overhead.  I'm seeing something on the order of 2.5-3 seconds, so this seems like a plausible explanation.

[bkenobi]

I modified the XTenLib.dll to output the time and ran a few tests.  The tests were:

• HG sends B6 ON command, AHP receives it and turns A6 ON, HG sees A6 ON
• HG sends B6 OFF command, AHP receives it and turns A6 OFF, HG sees A6 OFF
• AHP sends B6 ON, HG receives B6 ON and turns B6 ON
• AHP sends B6 OFF, HG receives B6 OFF and turns B6 OFF

I took the commands and created a delta time for these steps.  This is not an ideal way to test since I'm still using HG to watch for commands.  The best way would be to have a 3rd controller monitor for times, but I don't have that available.  As such, the AHP response time should be exactly correct.  But, the HG command will not include the time for AHP to send the command nor the time for the response to go over the power lines.  I believe this may be critical, but I don't currently have a way to deal with that.

That being said, here's what I found:

command sent from HG web interface      
2014-04-05T08:47:20.2184060-07:00       HomeAutomation.X10      B6      -      Status.Level     1   08:47:20.2184060   
2014-04-05T08:47:20.2457730-07:00       >>>>>OUT 04 E9   08:47:20.2457730   
2014-04-05T08:47:20.6611630-07:00       <<<<< IN 55   08:47:20.6611630   
2014-04-05T08:47:20.7517040-07:00       >>>>>OUT 06 E2   08:47:20.7517040   
2014-04-05T08:47:21.1739230-07:00       <<<<< IN 55   08:47:21.1739230   
2014-04-05T08:47:21.5902020-07:00       <<<<< IN 5A 02 00 69   08:47:21.5902020   
2014-04-05T08:47:21.6578180-07:00       >>>>>OUT C3   08:47:21.6578180   
2014-04-05T08:47:22.0144670-07:00       <<<<< IN 5A 02 01 62   08:47:22.0144670   
2014-04-05T08:47:22.0188050-07:00       HomeAutomation.X10      A6      -      Status.Level     1   08:47:22.0188050   
2014-04-05T08:47:22.1635670-07:00       >>>>>OUT C3   08:47:22.1635670   
      
Command   Time   Delta
HG command sent (B6 ON)   08:47:20.2184060   00:00:00.000
X10 B6 ON   08:47:20.7517040   00:00:00.534
X10 A6 ON (sent from AHP)   08:47:22.0144670   00:00:01.796
HG understands A6 ON   08:47:22.0188050   00:00:01.801
      
      
command sent from HG web interface      
2014-04-05T08:55:58.8141920-07:00       HomeAutomation.X10      B6      -       Status.Level    0   08:55:58.8141920   
2014-04-05T08:55:58.8875600-07:00       >>>>>OUT 04 E9   08:55:58.8875600   
2014-04-05T08:55:59.3044940-07:00       <<<<< IN 55   08:55:59.3044940   
2014-04-05T08:55:59.3909610-07:00       >>>>>OUT 06 E3   08:55:59.3909610   
2014-04-05T08:55:59.6393730-07:00       MIG.Gateways.WebServiceGateway  192.168.0.5     api/HomeAutomation.HomeGenie/Logg$   08:55:59.6393730   
2014-04-05T08:55:59.8165680-07:00       <<<<< IN 55   08:55:59.8165680   
2014-04-05T08:56:00.2335510-07:00       <<<<< IN 5A 02 00 69   08:56:00.2335510   
2014-04-05T08:56:00.2949440-07:00       >>>>>OUT C3   08:56:00.2949440   
2014-04-05T08:56:00.6566460-07:00       <<<<< IN 5A 02 01 63   08:56:00.6566460   
2014-04-05T08:56:00.6585640-07:00       HomeAutomation.X10      A6      -       Status.Level    0   08:56:00.6585640   
2014-04-05T08:56:00.7983860-07:00       >>>>>OUT C3   08:56:00.7983860   
      
Command   Time   Delta
HG command sent (B6 OFF)   08:55:58.8141920   00:00:00.000
X10 B6 OFF   08:55:59.3909610   00:00:00.577
X10 A6 OFF (sent from AHP)   08:56:00.6566460   00:00:01.843
HG understands A6 OFF   08:56:00.6585640   00:00:01.845
      
      
command sent from AHP      
2014-04-05T09:00:29.0631090-07:00       <<<<< IN 5A 02 00 E9   09:00:29.0631090   
2014-04-05T09:00:29.1476360-07:00       >>>>>OUT C3   09:00:29.1476360   
2014-04-05T09:00:29.4871290-07:00       <<<<< IN 5A 02 01 E2   09:00:29.4871290   
2014-04-05T09:00:29.4915170-07:00       HomeAutomation.X10      B6      -       Status.Level    1   09:00:29.4915170   
2014-04-05T09:00:29.5319770-07:00       HomeAutomation.X10      A6      -       Status.Level    1   09:00:29.5319770   
2014-04-05T09:00:29.6531090-07:00       >>>>>OUT C3   09:00:29.6531090   
2014-04-05T09:00:30.1587340-07:00       >>>>>OUT 04 69   09:00:30.1587340   
2014-04-05T09:00:30.5786750-07:00       <<<<< IN 55   09:00:30.5786750   
2014-04-05T09:00:30.6643090-07:00       >>>>>OUT 06 62   09:00:30.6643090   
2014-04-05T09:00:31.0823130-07:00       <<<<< IN 55   09:00:31.0823130   
      
Command   Time   Delta
X10 B6 ON (sent from AHP)   09:00:29.0631090   00:00:00.000
HG understands B6 ON   09:00:29.4915170   00:00:00.429
HG command sent (A6 ON)   09:00:29.5319770   00:00:00.469
X10 A6 ON   09:00:30.6643090   00:00:01.601
      
      
command sent from AHP      
2014-04-05T09:06:18.9933690-07:00       <<<<< IN 5A 02 00 E9   09:06:18.9933690   
2014-04-05T09:06:19.0666360-07:00       >>>>>OUT C3   09:06:19.0666360   
2014-04-05T09:06:19.4165440-07:00       <<<<< IN 5A 02 01 E3   09:06:19.4165440   
2014-04-05T09:06:19.4207080-07:00       HomeAutomation.X10      B6      -       Status.Level    0   09:06:19.4207080   
2014-04-05T09:06:19.4400480-07:00       HomeAutomation.X10      A6      -       Status.Level    0   09:06:19.4400480   
2014-04-05T09:06:19.5729060-07:00       >>>>>OUT C3   09:06:19.5729060   
2014-04-05T09:06:20.0788370-07:00       >>>>>OUT 04 69   09:06:20.0788370   
2014-04-05T09:06:20.5010090-07:00       <<<<< IN 55   09:06:20.5010090   
2014-04-05T09:06:20.5086860-07:00       MIG.Gateways.WebServiceGateway  192.168.0.5     api/HomeAutomation.HomeGenie/Logging/RealTime.EventStream/        HTTP    GET   09:06:20.5086860   
2014-04-05T09:06:20.5843740-07:00       >>>>>OUT 06 63   09:06:20.5843740   
2014-04-05T09:06:21.0047190-07:00       <<<<< IN 55      
      
Command   Time   Delta
X10 B6 ON (sent from AHP)   09:06:18.9933690   00:00:00.000
HG understands B6 ON   09:06:19.4207080   00:00:00.428
HG command sent (A6 ON)   09:06:19.4400480   00:00:00.447
X10 A6 ON   09:06:20.5843740   00:00:01.591

So:

• 00:00:01.801
• 00:00:01.845
• 00:00:01.601
• 00:00:01.591

The total time it takes AHP to toggle a light when HG sends the command is 1.8-1.85 seconds.  The time it takes for HG to toggle a light is 1.6 seconds plus transmission time (probably half of the 1.43 seconds, or 0.715 seconds) or 2.3 seconds.  I'm still seeing much longer (closer to 3 seconds).

[Gene]

I wonder if all these >>>>>OUT C3 are really needed. Perhaps this is the problem. HG is sending unneeded "Poll Reply" (0xC3).
Maybe these should only be sent in presence of a single byte input message 0x5A (poll request).
Currently HG seem to send poll reply everytime the input message starts with 0x5A.
Can you see how do AHP behaves? Do AHP log messages sent to the interface?
Anyway I will give it a try making HG send poll reply only when a single byte is received and see if everything continues to work.

Cheers,
g.