Browser load times

🛎️ Get Help
62

Very helpful! - That's the first bit of detail that's been specifically documented, beyond "there are random delays". So your comment makes it sound NOT related to DB access. - Rather is more scheduler/thread related.

Since you have detailed times around this specific occurrence (1 in 1500) do you have details around hub resources at that approximate time. - I'm pretty sure you use HubInfo, but wasn't sure if you were capturing other resource info during this occurrence - Anything notable in terms of a CPU spike at this time?

And yes, having some more detailed knowledge of how events are dispatched in RM via access to the Groovy code would be even better - But your observation that the random delay is always between the trigger and the 1st action, does seem like a thread invocation/scheduling issue.

Thanks for the extra effort and python work to capture and document this!

2 Likes
63

I use Watchtower to collect that data. I had a look at the graphs around that event (captures every 5 minutes) and there's really nothing special going on: CPU, temperature, memory, DB - all look the same in the hours prior and after the event (and not significantly different from baseline).

The tooling could be improved to collect also from the event websocket, the hub runtime stats endpoint, etc. along with the hub logs so correlations could be made, but, honestly, I don't expect to find anything super useful.

I'll PM @gopher.ny with the exact timestamp in case he can see something relevant in the engineering logs.

In the meantime I turned on logging on a bunch more rules. We'll see if the 1 in 1500 ratio sticks :wink:

3 Likes
64

Here is a fresh example. These long delays are rare on my hub, but they do happen.

I updated the tool to fetch the contents of /hub/advanced/freeOSMemoryHistory around the time of the outlier event, in case that context can be of use.

[ Names obfuscated for sharing — IDs preserved. ]
Timespan: 2026-04-26 12:10:42.034000 to 2026-04-28 08:11:41.407000 (1 day, 20:00:59.373000)
Total log entries: 44340
Trigger->Action samples: 3640
Unique App IDs: 22 (146, 147, 148, 149, 399, 400, 442, 537, 619, 620, 621, 622, 691, 693, 781, 818, 886, 888, 965, 966, 968, 1052)
Mean: 0.0745s
Stdev: 0.0729s
Median: 0.0690s
Min: 0.0090s
Max: 3.1020s

--- Histogram ---
0.0090s - 0.3183s | ############################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################################## (3630)
0.3183s - 0.6276s | #########                      (9)
0.6276s - 0.9369s |                                (0)
0.9369s - 1.2462s |                                (0)
1.2462s - 1.5555s |                                (0)
1.5555s - 1.8648s |                                (0)
1.8648s - 2.1741s |                                (0)
2.1741s - 2.4834s |                                (0)
2.4834s - 2.7927s |                                (0)
2.7927s - 3.1020s | #                              (1)

Fetching memory/CPU history from http://<hub>/hub/advanced/freeOSMemoryHistory ...
  Got 1657 samples (2026-04-22 14:13:12 to 2026-04-28 08:50:01)

--- Outliers (delay > 1.00s) ---
Found: 1

=== Outlier #1: app id=1052 name='grand-sumac' delay=3.1020s ===
    Trigger at 2026-04-27 16:10:26.383000  Action at 2026-04-27 16:10:29.485000
  [ 27765] 2026-04-27 16:10:02.034           type=dev id=417   name='gentle-jade' msg='gentle-jade : Presence : Not Present! Last report received 29697 seconds ago.'
  [ 27766] 2026-04-27 16:10:03.133 +  1.099s type=app id=1052  name='grand-sumac' msg="Triggered: Power level of noble-spark, calm-jade, golden-otter, misty-opal, tidy-heron, hidden-onyx, fierce-beetle, fierce-yarrow, hidden-thistle, sandy-kestrel, brisk-cliff, glossy-ember(<span style='color:black'>111, 0, 418, 0, 0, 425, 845, 145, 222, 0, 1, 63</span>) any *changed* "
  [ 27767] 2026-04-27 16:10:03.211 +  0.078s type=app id=1052  name='grand-sumac' msg='Action: Off: misty-otter (Command only switches that are on)'
  [ 27768] 2026-04-27 16:10:03.222 +  0.011s type=app id=1052  name='grand-sumac' msg='Action: Wait for event:  --> elapsed time: 0:02:00'
  [ 27769] 2026-04-27 16:10:14.169 + 10.947s type=dev id=514   name='grand-newt' msg='grand-newt : grand-newt temperature is 23.0°C'
> [ 27770] 2026-04-27 16:10:26.383 + 12.214s type=app id=1052  name='grand-sumac' msg="Triggered: Power level of noble-spark, calm-jade, golden-otter, misty-opal, tidy-heron, hidden-onyx, fierce-beetle, fierce-yarrow, hidden-thistle, sandy-kestrel, brisk-cliff, glossy-ember(<span style='color:black'>111, 0, 209, 0, 0, 425, 845, 145, 222, 0, 1, 63</span>) any *changed* "
< [ 27771] 2026-04-27 16:10:29.485 +  3.102s type=app id=1052  name='grand-sumac' msg='Action: Off: misty-otter (Command only switches that are on)'
  [ 27772] 2026-04-27 16:10:29.503 +  0.018s type=app id=1052  name='grand-sumac' msg='Action: Wait for event:  --> elapsed time: 0:02:00'
  [ 27773] 2026-04-27 16:10:38.526 +  9.023s type=dev id=277   name='sleek-lichen' msg='sleek-lichen : sleek-lichen temperature is 22.0°C'
  [ 27774] 2026-04-27 16:11:16.438 + 37.912s type=app id=1039  name='lucky-pebble' msg='lucky-pebble: temperature average (4/4): 19.1 C'
  [ 27775] 2026-04-27 16:11:16.440 +  0.002s type=app id=1039  name='lucky-pebble' msg='lucky-pebble: Avg: 19.1 Stdev: 0.1 Min: 18.97 Max: 19.2 Median: 19.125'
  [ 27776] 2026-04-27 16:11:33.111 + 16.671s type=app id=965   name='zesty-garnet' msg='Required Expression false'
    Log entries inside the delay window: 0
    Memory/CPU samples within +/- 30 min of outlier:
       Δ vs event  Date/time                 Free OS     5m CPU avg     Total Java      Free Java    Direct Java
           -25.1m  2026-04-27 15:45:22         133752           0.81         331392         142855          10837
           -20.1m  2026-04-27 15:50:22         128004           0.54         331392         110703          10816
           -15.0m  2026-04-27 15:55:26         155724            0.5         331392         179290          10836
           -10.0m  2026-04-27 16:00:26         126752           0.89         331392         135366          10834
            -5.0m  2026-04-27 16:05:26         125552           1.21         331392         102678          10807
    *       +0.1m  2026-04-27 16:10:30         156328           0.57         331392         190552           8772
            +5.1m  2026-04-27 16:15:30         131128           0.71         331392         156668          10829
           +10.1m  2026-04-27 16:20:30         127872           0.56         331392         127475          10829
           +15.1m  2026-04-27 16:25:34         156660           0.92         331392         168461          10820
           +20.1m  2026-04-27 16:30:34         124332           0.65         331392          88350          10904
           +25.1m  2026-04-27 16:35:34         122204           0.72         331392          42076          10862
1 Like
65

Note the following from the Beta - V2.5.0.128 release notes:
- Reworked data access concurrency to hopefully fix the occasional long delays.

Given that your the only one (that I know of) that has instrumentation and automation setup to log and find this, it may be worth loading the new Beta, to see if HE staff moved the needle on this..

They seem to be going after potential DB concurrency issues, first the 1st line of the "TRIGGERED", but without us seeing RM internal code, they are likely making better guesses of where the delay may be happening, than I can.

Hopefully, you're able to update to the Beta, and we'll see if anything changes in 2 weeks or so. Again, really appreciate all your efforts here, to setup the monitoring framework for such a "rare" event. Your a better man that I...

3 Likes
66

Already loaded and started a new capture.

On .122 the outlier rate (which I arbitrarily set to > 300ms), stabilized around 0.4% after three days. We'll see what happens on .128.

I will be very interested to see if @vitaliy_kh sees an improvement, too.

Thanks - hopes it helps make a difference. I've always enjoyed building tools like this.

3 Likes
67

I am not on Beta. But certainly will update to the latest rev as soon as it will be released.

68

Not sure if you have any data to share? - But another update to Beta .131
Per the release notes:
- Hopefully fixed occasional long automation delays (if related to data cleanups)

I'm curious if anything notable was observed in .128

1 Like
69

.128 did not show improvement. I will load .131 tonight and start capturing.

4 Likes
70

.131 shows the best results so far, after 2+ days of runtime, I've not seen any delays larger than 600ms.

@vitaliy_kh there is now a public release that includes @gopher.ny 's fixes, you should give it a spin.

4 Likes
71

OK, updated both hubs (C7 and C8 Pro) to the latest 2.5.0.135
Let me see how this goes ...

1 Like