MQTT timing test with openHAB?

Im thinking of testing how long a message takes to arrive and be displayed in the sitemap/basic UI. So i guess start measuring from when the python based mqtt client publishes up until openhab receives it and it is shown in the basic ui. Is there a good way to do this? Any ideas?

It’s all less than 1 second, therefore it’s maybe more interesting, if it will matter and what’s your usecase at all? Do you want to do any time critical stuff with your setup?

Maybe the first and most easy thing is to publish a message, have the UI open at t the same time and just use your watch to get the duration…

Also theoretically there if a difference between

  1. Openhab will receive the message
  2. The item status will be updated
  3. The gui is updated

What is relevant to you?

There is a whole lot of stuff between the thing sending the message and openHAB showing it on MainUI.

Device -> MQTT Broker -> MQTT binding -> openHAB event bus -> MainUI (in your browser)

Assuming all your clocks are synchronized very closely, you could probably configure debug logging and look at the logs in each of those places and come up with an approximate end-to-end time. But like Matthias said, it’s going to be much less than a second unless there is something wrong going on so I’m not really sure the timestamps in the logs at all of these places are precise enough to give you an answer. And because it’s so fast, the mere act of turning on the debug logging is going to impact the performance.

I guess im relying on miliseconds. What im trying to see is the time it takes (maybe a graph) to just display a normal mqtt message vs the time it takes to run a transformation with a custom script and then display…so like a comparison…and maybe do this 100 times to see the difference in a graph? Do you guys have any ideas?

I guess maybe I don’t have to measure the time when the ui is updated…just need to know when the item is updated after the incoming mqtt transformation is complete

You might be able to get that info by putting the MQTT binding into trace logging mode and compare timestamps.

If you’re good with Java development, you could hook up a profiler perhaps, but that’s a really heavy lift.

It sounds like you might really just be after the amount of time your transformation takes. You could do that in a rule. Take a timestamp, call your transformation on the untransformed message, take a timestamp again and calculate the delta.,

i was thinking if i just check the timestamps of when the items are updated (i publish once but two items store it, one with transformation and one without) so if I just check when the items are updated and take that difference I guess that should be enough for me…is there a place to view this info? Should i open the openhab.log file?

The problem is compare the timestamp to what? You need two timestamps to figure out how long something takes. An Item is only updated once so there’s only one timestamp. You’d need the timestamp from when the message was received by the binding or when it was sent by the publisher in addition to the timestamp of the Item update.

But let’s go back to Matthias’ question. Why does this matter? Why do you care? Are you experiencing problems? Trying to optimize something? Figure out if your hardware is powerful enough? Idle curiosity? In general, figuring out this sort of information is a lot of work and it can be really hard to get right (your measurements will impact the timing you are trying to measure). Given the amount of effort and challenges in getting this right most of the time, it’s usually not worth the effort unless you are experiencing a real problem.

i send one message to one topic, but i have three items storing that message from the same topic. The message is sent at the same time so i’d only have to compare the times when they’re received. Two items don’t have any transformations and receive the msg at the exact same time (from events.log) and the one doing the transformation is a couple miliseconds slower. But events.log isnt updating properly and sometimes doesn’t include all changes. Is there a better way to monitor when the items are updated without relying on a rule?

That’s a different problem and is probably where you should focus. I’ve never seen nor heard of events.log just dropping long entries. Logging in openHAB is blocking so it’s not like it gets overwhelmed with log statements and drops them. The part of the program with the log statements will just stop until the statement has been written out to disk.

Are you certain that the missed events are changes? By default, events.log will not have an entry for updates to the same state. But you can turn that on if you wanted to by changing the logger for ItemStateEvent to DEBUG in $OH_USERDATA/etc/log4j2.xml or though the karaf console.

If events.log is truly not including all the events you need to immediately file an issue because something is really broken.