Which log level to use to debug poor Main UI performance (e.g. 30 sec to load Semantic Model)

Platform information:

  • Hardware: Raspi 3 B+ (Raspian OS 10)
  • Attached Hardware: Amber Wireless AMB8465 (to read out Wireless M-Bus from water & heat meter), Aeotec Z-Wave Gen5+ (to read out power meter), Zigbee CC2531EMK Coordinator
  • Docker / Portainer 2.17.1
  • openHAB Software: 3.4.2 Release Build, Persistence via InfluxDB
  • openHAB Bindings: Homematic (logging heating, controlling lights & blinds), Gardena (logging soil humidity, watering yard), Alexa, MQTT, Zigbee
  • Homematic IP Hardware: CCU2 (2.61.7), multiple Homematic IP devices

I’m running a (probably) pretty average openHAB installation (~60 things, ~500 items, ~30 rules). Since a couple of weeks (the precise time is hard for me to pin down), the entire Main UI started to become somewhat laggy (e.g. loading time of the “Semantic Model”-page went up to between 20 - 30 seconds).
image
The loading times are similarly high when calling the “model tree” elsewhere in openHAB.

Everything else appears to be working normal. openHAB log (default log level) does not show any errors, except for these entries, which do not sound normal / maybe related:

2023-03-05 20:53:38.364 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:7519737e0f' takes more than 5000ms.
2023-03-05 20:54:29.212 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'systeminfo:computer:f9a13e06df' takes more than 5000ms.
2023-03-05 21:36:02.329 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zigbee:coordinator_cc2531:47a553414d' takes more than 5000ms.
2023-03-05 21:37:43.360 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'zigbee:coordinator_cc2531:zigbee_coordinator' takes more than 5000ms.
2023-03-09 01:04:11.941 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1749d25' takes more than 5000ms.

The loading times are also independent from the browser (tried on Firefox as well as iOS/Safari).

I do know that the Raspi 3 is not the fastest server for running openHAB and some other containers, but two things make me believe that it’s not a hardware problem:

  1. If I remember correctly the problem started rather abruptly (vs. building up over time with more an more items). So maybe something I did / added?
  2. Even if I’d use a Raspi 4 (which would be, as an assumption, twice as fast), I’d still be looking at loading times of ~10-15 seconds for the semantic model, which would still be too much.

I did try to re-install and restore the entire system (according to this), which did not change.

Does anyone have a clue on how to debug the system (which debug level?) to find the root cause? Is there a possibility to set the log level so that I can see what’s going on while the Semantic Model takes 20-30 seconds to load?

I suggest going a little easier on the emphasis. It has the unintended consequence of making your post harder to read. :wink:

A couple things to note:

  1. “Paper UI” is an OH2 interface. OH3 uses “Main UI”.
  2. There’s no basis for assuming that a Pi4 is “twice as fast” as a Pi3B+. Raspberry Pi 4 vs Raspberry Pi 3B+ — The MagPi magazine

If you completely reinstalled your system and still have an issue, then all I can suggest is:

  1. Remove things piece-by-piece to see if/when the lag disappears.
  2. Install a fresh openHABian and replicate your environment exactly. If you also experience the lag with openHABian, you’ll know for sure that it’s not a Docker issue.

Unfortunately, that’s all the help I can offer since I don’t use Docker. Others might have more advice on logging, but OH logging may not tell you much if the issue is related to Docker.

All things considered, an RPi 3 is underpowered for this sort of configuration. The problem isn’t the CPU, it’s the RAM.

  • RPi 4 is the minimum recommended hardware recommended in the docs now
  • Running OH in Docker with Portainer is only going to exacerbate the RAM problem as both of these consume RAM on their own and a container consumes more RAM than a natively installed service

When a machine runs out of RAM it will start to use swap (if available) which is great in that your whole machine doesn’t crash, but disk is sooo much slower than RAM your machine will become nearly unresponsive.

This does not eliminate lack of RAM as a cause of this behavior.

Based on what? You’ve run this experiment? I’d need more information on this before I can say one way or the other.

For that part you’d want to start with the console in the browser. Then work your way down through the API and into core. Also monitor your system resources using htop to confirm whether or not you are running out of RAM, CPU is pegging, or something else. It’s very easy to see whether or not it’s a hardware problem, let’s not make assumptions.

Thanks @rpwong and @rlkoshak for your thoughts!

Good ideas. Thanks. Will do.

I thought about this as well, but the way I read both htop…


… as well as the sysinfo-binding…

… it’s not that I have a huge margin left, but I’m also reliably not in an area where RAM has to swapped onto the really slow SD card. Or am I interpreting the readings incorrectly?

You’re referring to the different logging levels, correct?

That htop screen shot shows you are using 232 MB of swap. That’s 232 MB of stuff that should be in RAM but isn’t.

No, in developer tools in your browser you can see what MainUI is doing. Then yes, you might need to go into debug or trace logging in OH core and the bindings in question.

But the fact that your system has swapped out 232 MB, I’m guessing that’s the root cause.

Thanks, @rlkoshak. I somehow knew that my beloved Rapsi 3 would have to be replaced soon, but I always hoped it would just carry on for just a bit longer. Speed-wise things were generally ok, but (even with some containers not being started) constantly >200 MB in SWAP should be enough of a sign to get a replacement (and probably the root cause for the poor Main UI performance).

Btw: What I kept realizing through this: Shouldn’t swapping (like in my case) decrease the lifespan of an SD card dramatically? Swapping with a Raspi basically means constant I/O operations on the SD card…

Yes, and anything unnecessary such as e.g. Docker will add to these effects.
You should be moving to openHABian, it does swapping (well, paging it actually is) in ZRAM, i.e. keeps the paged-out pages in RAM but compresses them.

Why do you have 7 influxd processes each consuming memory? I only have one. :slight_smile:

Or change up how you have things installed. Don’t use Docker which consumes more RAM. Eliminate/move processes off the machine where possible. An RPi 3 could definitely run OH and maybe a couple other services like Mosquitto and InfluxDB, but not much more.

Of course, the easiest would be to use openHABian which does a whole lot to optimize the RAM usage as well as preserve the SD card by limiting writes.

Yes, I know. However, there are two reasons for being on Docker (and I also remember your post here @rlkoshak, which was spot on). First, I did not get wmbusmeters running in the first place on openHABian when I started with openHAB two years back (but it could’ve also been my mistake), and got it running immediately with the wmbusmeters docker image, and second, well, what shall I say, this entire “Docker/Portainer thing” is just my guilty pleasure as I wanted to learn some new piece of tech, …, and now I’m paying the price with a high RAM load and the need to buy new Hardware because of that. :wink:

Good question. II assume I did a pretty standard docker install. Any idea how I can check why this is the case? Besides the strange entries in htop, I do not experience any other problem.

I’m sure there are settings in InfluxDB to control how many processes and threads it is allowed to use. But that will largely be outside the scope of this forum. I find the InfluxDB doc to be pretty decent though.

I don’t use htop myself that much, apparently it shows all threads by default which is customizable with “Hide userland process threads”, see:

Just to confirm the obvious (I just spawned a test-install and restored my system via my docker-stack on a 8 GB Ram Quad Core PC): Everything runs really really smooth with that hardware. So it is a RAM-problem after and all as you pointed out, and I should definitely look for a Raspi 4 once the prices come down again (having a Quad Core PC running 24/7 is not what I’d like to do from an energy-consumption point of view).

Why not drop docker and Influx, eventually. Without both of these wasting RAM, OH worked fine for me on a 1GB RPI3, in a long time.

Thanks!

As mentioned here, it’s my guilty pleasure. Plus, I did not get wmbusmeters running on openHABian, hence the Raspbian / Docker-path.