Hi All,
Been using OH/Habdroid for about 7/8 years. In the last 4 years, on a Synology NAS in Docker.
Performance issues have been increasing in frequency, and I started stripping things out to find out where the problem might be. This was done on 3.0.0M5. Rules, gone. Persistence, gone. etc etc. I decided to follow what Kai is doing and do a clean build on 3.0.0.M5. I now have a feeling that there are in fact at least two problems. The usual “I switched the KNX light on and it takes 3 seconds to respond”, and poor loading of Habdroid.
At present, I have a simple installation of OH3M5. No items, nothing apart from a very simple sitemap with a single frame and a text item.
Android Openhab version 4.6 (2.15.0)
Also tried the 4.9 Beta.(2.15.15-Beta)
Trace Logging Enabled.
Problem: When I start the Openhab on the Android (S7/S20), the application opens and I see the rotating icon before the site map loads. It can be in that state for up to many seconds.
Log from Habdroid
12-20 17:16:12.896 9651 9690 D ConnectionFactory: checkAvailableConnection: found types [ConnectionType(type = Wifi, network=502)]
12-20 17:16:12.896 9651 9690 D AbstractConnection: Checking reachability of http://<openhab-local-address>:8085/ (via 502)
12-20 17:16:12.899 9651 9690 D AbstractConnection: Socket connected (attempt 0)
12-20 17:16:12.899 9651 9690 D ConnectionFactory: Connecting to local URL via ConnectionType(type = Wifi, network=502)
12-20 17:16:27.749 9651 9651 D ServerProperties: Server returned sitemaps: [Sitemap(name=garnhams, label=Main Menu, icon=null, homepageLink=http://<openhab-local-address>:8085/rest/sitemaps/garnhams/garnhams)]
12-20 17:16:27.769 9651 9651 D MainActivity: Configured sitemap is 'garnhams', selected Sitemap(name=garnhams, label=Main Menu, icon=null, homepageLink=http://<openhab-local-address>:8085/rest/sitemaps/garnhams/garnhams)
Log from openhab
2020-12-20 17:14:40.804 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-12-20 17:15:09.318 [DEBUG] [est.sitemap.internal.SitemapResource] - Run clean SSE subscriptions job
2020-12-20 17:15:40.805 [DEBUG] [core.karaf.internal.FeatureInstaller] - Running scheduled sync job
2020-12-20 17:16:26.326 [DEBUG] [est.sitemap.internal.SitemapResource] - Received HTTP GET request from IP 192.168.1.96 at 'sitemaps'
2020-12-20 17:16:26.480 [DEBUG] [est.sitemap.internal.SitemapResource] - Received HTTP GET request at 'http://192.168.1.19:8085/rest/sitemaps'.
2020-12-20 17:16:27.492 [DEBUG] [est.sitemap.internal.SitemapResource] - Received HTTP GET request from IP 192.168.1.96 at 'sitemaps/garnhams/garnhams'
Any ideas why there is such a delay between “connecting to local URL” and “Server returned Sitemaps”? Or what I could do to investigate further?
I’d say the server is just too slow. The issue shouldn’t be caused by the app, so I cannot say more to this issue.
Can you move your post to a different category?
Thanks for the responses. I have been investigating further and have used Wireshark to see what is happening with the IP packets.
There is a 4-second gap between habdroid indicating it is “connecting to local URL” and the HTTP GET appearing on the LAN. Although only 4 seconds in this example, I sometimes see delays of 30 seconds. The reason I haven’t shown one of those examples is because they occur after long periods of inactivity. Closing habdroid and then reopening results in a sub-second response time to show the sitemap when done immediately, and will then go back to long delays after a long period of non use.
Tested this on OH3.0.0 Release version, and the habdriod beta.
The response time of the server between seeing the packet and it responding seem to be around 0.5 seconds, which might suggest it is not the server that is the cause.
Are there any additional logging levels on habdriod that could show what is happening in those 4 seconds?
I am happy to explore the idea that it is something external to the habdroid app that is causing the problem (device OS/ IP Stack etc), but at the moment habdroid seems to be my best route to diagnosis. BTW, I am seeing this problem on two Samsung S7s and also on two S20’s.
16:14:04 Habdriod start
Habdroid shows some errors:
12-29 16:14:04.905 15286 15286 I zygote64: Rejecting re-init on previously-failed class java.lang.Class<androidx.core.view.ViewCompat$2>: java.lang.NoClassDefFoundError: Failed resolution of: Landroid/view/View$OnUnhandledKeyEventListener;
Then:
12-29 16:14:05.523 15286 15327 D ConnectionFactory: Connecting to local URL via ConnectionType(type = Wifi, network=502)
12-29 16:14:09.345 15286 15286 I ServerProperties: Server has rest api version 4
12-29 16:14:09.939 15286 15286 D ServerProperties: Server returned sitemaps: [Sitemap(name=garnhams, label=Main Menu, icon=null, homepageLink=http://<openhab-local-address-openHAB>:8086/rest/sitemaps/garnhams/garnhams)]
Wireshark:
16:04:08.81 GET /rest/sitemaps
16:14:09.36 HTTP/1.1 200 OK, JavaScript Object Notation
Openhab Log
2020-12-29 16:14:09.027 [DEBUG] [est.sitemap.internal.SitemapResource] - Received HTTP GET request from IP 192.168.1.244 at 'sitemaps'
I’d like to see an unfiltered Android app log first. The log in the first post is filtered, right? Of particular interest would be the timing of ‘MainActivity’ reporting ‘onActiveConnectionChanged’. If that one is delayed vs. the ConnectionFactory line, something is blocking the main loop in the app (although I’d expect an ANR message in that case), if it’s not delayed, it’s the actual request that’s delayed for whatever reason. Maybe some power saving bullshit being enabled for the app?
Can you share some more lines before the posted ones? Line 3 implies an active connection already exists at the time the log starts, so the server properties query already should be started at that point.
At the later point (16:14:05.523 in your log) another connection check is done for some reason (probably mobile network change or something), at which point it likely finds out that old and new connection match (both using the local WiFi), thus the ‘onActiveConnectionChanged’ callback doesn’t happen again.
Probably the best idea is force stopping the app (swipe out of recents), starting it again and then sharing the full log.
Hi Danny, here is the full log. I also have a log from today where it took nearly 50 seconds to load. For that I also have a full video with a clock running beside it. That may not be possible to share here, but happy to put on a OneDrive share or similar.
Update: So it looks like before the sitemap is obtained, a call is made for a list of the rest URLs via IPAddress/rest/. I assume this is cached somewhere because whilst initial calls are slow, subsequent ones are fast. Tests via wget on the server indicate slow response from Openhab, but I note that there is no log record associated with the /rest/ request. I will follow up in a different category.
