Local access mode terribly slow after few pages opened

lolodomo commented 5 years ago

I am running server snapshot 1544 and Android app 2.5

App is almost unusable in local access mode. Page loading take several seconds and I can then see that icons take time to be loaded. Image cache seems to be no more used ? I tried to clear the image cache but it does not resolve the problem.

The app is working normally (faster) when I am in remote access mode.

It could be relative to the most recent version of the server I am running. I will try to downgrade to an older version.

lolodomo commented 5 years ago

In fact, it does not work better with a server v1480. In fact, it is more and more slower after opening several pages. When it begins to be very slow, if I close the app (stop it), and restart it, this is normal again for few pages and finally it is slow again.

lolodomo commented 5 years ago

I tried again in remote access mode and even after 10 or even 20 pages opened, the speed remains the same (fast). So the problem is only in local access mode.

lolodomo commented 5 years ago

I try to correlate the two problems:

remote access: constant perf but live update not working
local access: degraded perf with the time but live update working

Maybe there is a problem with SSE, maybe the subscriptions are never released and this is the source of the degraded perf in local access. In remote access, if the SSE is not working, it cannot degrade perf. This is just an idea of course.

maniac103 commented 5 years ago

Sorry, but: where's the filled out issue template, and where's the application log? Of particular interest would be (for me) whether you can reproduce this in demo mode, and whether you need to visit different pages to reproduce this or whether going back-and-forth between two pages is sufficient. Also, what do you mean by 'in remote access, if SSE is not working...'? SSE support does not depend on the type of connection.

lolodomo commented 5 years ago

I don't know how to produce and provide logs, sorry. Is it explained somewhere ?

This can easily be reproduced by opening any same page several times. After a "force stop" of the app and a start, opening a page with only 2 widgets, the slowlness starts after around 8 opening.

But it is the same if I visit different pages. It generally happens before 10 pages opened.

PS: Access to the demo is terribly slow but it could be not relative to the zpp.

maniac103 commented 5 years ago

FWIW, I can not reproduce this against my local server, even after going back and forth 20+ times between two pages.

lolodomo commented 5 years ago

Did you test with the official 2.5 ? Maybe the 2.5 is buggy. I will wait for the 2.6 (which is planed for soon ?) and then let you know if my problems are resolved. If not, I will provide the logs.

maniac103 commented 5 years ago

I tested with a build off master as of last week. I'm not aware of any significant changes in connection or SSE handling since 2.5 though. Judging from the release logs of the beta builds the only thing touching SSE was https://github.com/openhab/openhab-android/pull/1109

It's easy to test though: just install the beta version of the app (you can do that in parallel to the stable version) and give it a try.

lolodomo commented 5 years ago

Just tried on the same Android device to enter and ext the same page 30 times with Basic UI and it is always very fast. So I clearly don't think there is any problem with my OH server.

maniac103 commented 5 years ago

@lolodomo From that log it seems like the app doesn't detect SSE support, which seems fishy. Can you open http://<your-server-ip>:8080/rest in a browser and add the output here?

Besides that, everything looks pretty straightforward at first:

App opens, queries main sitemap
Gets response ~300ms later, displays it, starts long-polling
~3s later you click on the page link

... then things start to get weird, as the response takes ~6.5s (!) to arrive. Question now is whether the request takes that long to be sent out or whether server takes that long to process the query for whatever reason. I guess this is somehow related to the image loading either way. I'll see about adding an option which adds additional logging, in particular of the HTTP library. Would you be willing to try a beta build of that which is built by me (as opposed to the CI)? This would allow us to refine logging without the need to merge + release after each step.

lolodomo commented 5 years ago

Ok

I will provide the result of the request only this evening.

Note that this is very fast with Basic UI so I think the server is ok.

maniac103 commented 5 years ago

Note that this is very fast with Basic UI so I think the server is ok.

Basic UI works totally different (doesn't use the REST API), so I don't think we should draw too many conclusions from that.

maniac103 commented 5 years ago

Here's an apk built off current master with #1234 and #1231 applied: openhab-beta-debug.zip Please

uninstall the beta version you currently have installed (my build is incompatible because I don't have signing keys access)
rename the file from .zip to .apk (the .zip file extension is to work around github limitations)
then install the apk

After installing please

enable 'show debug messages' in settings (right above 'view log'), which will enable HTTP connection logging
reproduce the issue and
let me know about the resulting log.

While you're at it, please try whether #1229 is better now as well. Thanks!

mueller-ma commented 5 years ago

The crash is fixed: https://github.com/openhab/openhab-android/pull/1234/commits/f13a3566f7068920d8bdd1b5fbd7ebe1f8d9fa7a

maniac103 commented 5 years ago

03-04 21:17:35.522  9539  9616 D OkHttp  : --> GET https://<openhab-local-address>:8443/rest/sitemaps/events/2b5bcad8-bfbe-42fb-afbb-2a86b5eff292?sitemap=maison&pageid=0001
03-04 21:17:35.522  9539  9616 D OkHttp  : User-Agent: openHAB client for Android
03-04 21:17:35.522  9539  9616 D OkHttp  : Accept-Encoding: 
03-04 21:17:35.522  9539  9616 D OkHttp  : Accept: text/event-stream
03-04 21:17:35.522  9539  9616 D OkHttp  : Cache-Control: no-cache
03-04 21:17:35.522  9539  9616 D OkHttp  : --> END GET
03-04 21:17:35.523  9539  9616 D OkHttp  : <-- HTTP FAILED: java.io.IOException: Canceled
03-04 21:17:35.523  9539  9616 W PageConnectionHolderFragment: SSE processing failed for https://<openhab-local-address>:8443/rest/sitemaps/maison/0001, using long polling

This seems to be the root cause. Normally when you press back to go back by one page, the connection of said page should be canceled and fully discarded. In your case it looks like the subscription isn't canceled though (or not properly), thus the half-canceled connection then switches to long polling, which in turn causes state tracking confusion. I'll have another look at this tomorrow; we're probably lacking a check whether the HTTP call was canceled somewhere.

maniac103 commented 5 years ago

Turns out this is a bug/shortcoming in the SSE library, in particular in the callback here: https://github.com/openhab/openhab-android/blob/master/mobile/src/main/java/org/openhab/habdroid/ui/activity/PageConnectionHolderFragment.java#L547-L549

This is called from here: https://github.com/heremaps/oksse/blob/master/src/main/java/com/here/oksse/RealServerSentEvent.java#L101 ... and there's no indication whether the callback happens due to being canceled or due to an actual failure. I'll think about this.

GitHub
openhab/openhab-android
openHAB client for Android. Contribute to openhab/openhab-android development by creating an account on GitHub.

GitHub
heremaps/oksse
An extension library for OkHttp to create a Server-Sent Event (SSE) client. - heremaps/oksse

maniac103 commented 5 years ago

New test apk off current master + #1234 and #1237: openhab-beta-debug.zip

@lolodomo Please give it a try; I suspect it will fix your issue.

lolodomo commented 5 years ago

Excellent news: on my tablet and a local access, the problem is fully solved. I opened almost 100 pages without any slowness and without crash.

lolodomo commented 5 years ago

And live update seems to work well.

So only remaining problem is the quick crash when on remote access.

maniac103 commented 5 years ago

On my phone and a remote access, the app is crashing after few seconds, even if I do nothing and remain on the main page.

Can you grab the log after a crash (and before the next crash)? FWIW, I can't repro at the moment.

lolodomo commented 5 years ago

I tried again with the remote access and it is working well. I probably made a mistake previously and installed the wrong APK.

So it looks like you fixed my two problems.

Thank you for a so quick fix.

maniac103 commented 5 years ago

That's great :+1: A 2.7.0 will happen in the next few weeks (needs to happen before end of April, at which time GCM will be gone)

lolodomo commented 5 years ago

Let me know in which beta the fix will be included and I will install this one.

maniac103 commented 5 years ago

@lolodomo 2.6.4 beta should be fine. Plesse confirm.

lolodomo commented 5 years ago

Apk file is missing, I see only source files.

maniac103 commented 5 years ago

Right, but 2.6.3 has your fix already as well and is also rolled out to the Play Store already.

lolodomo commented 5 years ago

I can confirm that beta 2.6.4 is ok for me.

lolodomo commented 5 years ago

Just want to mention that the app is crashing at the 2 first startups after installation. Then it is ok. At the fist startup, I just ignored the slideshow and then it crashes.

maniac103 commented 5 years ago

Just want to mention that the app is crashing at the 2 first startups after installation

That's probably https://github.com/openhab/openhab-android/issues/1247

openhab / openhab-android

Local access mode terribly slow after few pages opened #1228