Regression: My Places > Tracks screen again very slow to open (20 sec)

[sonora]

Again, the time it takes to open the "My Places > Tracks screen" on my setup (~3000 Tracks in 70 folders) has increased to ~20 sec of watching the spinner. And also similarly long every time I enter the "Visible Tracks" screen. See log here: logcat.log.txt.

On previous occasions, this had been due to excessive individual File I/O, sometimes in obsolete operations (like here 24ff4cb) or sometimes in repetitive loops not bundling things as a stream. I had fixed on some occasions which had brought the opening time for the dialog down to about 3 sec. Now it's back to 20 sec.

Needs investigating. Perhaps a result of porting some code to a shared library?

[alex-osm]

Yes, when reading gpx files, the shared library is currently used. But recently there were changes to speed up reading the file list using platform method - 41f30f1

Did you try latest nightly version of OsmAnd?

[Rowin63]

Hm. Does not happen here running the ~4.9.0#3190 (1350 tracks in 75 folders, takes about 2-3sec), but all track folders are switched back to "last edited" again...

[alex-osm]

There was also fix of bug which cause mess with folders in DB - 18e91d1
It was introduced on 31.07.2024

[sonora]

@alex-osm I had not built an apk in a while. My build of our master branch 2024-09-07 still is fast. Build of 2024-09-14 (late evening) exhibits the issue. I do not experience @Rowin63 's observation of sort order resets so far...

I guess we may in deed suspect 9d5683e.

[alex-osm]

@sonora I see. Can you may be send logs similar to those from first message, but from master branch 2024-09-07?
As you can see in TrackFolderLoaderTask we moved from File to KFile and PROGRESS_BATCH_SIZE was increased from 7 to 70.
BTW - TrackFolderLoaderTask is moving to shared lib as well. It will be there next week.

[sonora]

Sure, @alex-osm !

• I have meanwhile tested a little optimization, see this PR Use parallelStream() for GPX file access #20845, and it results in about 10 sec (instead of the now 20 sec) GPX tracks loading time: logcat_09-15_parallel.log.txt . So it does not address the root cause we have somehow introduced, it is only a secondary optimization (probably worth having).

• I also reinstalled the Sept. 7 build, and this is the respective log section logcat_09-07.log.txt, and it shows ~4 sec as the GPX tracks loading time.

[sonora]

I believe the problem are the countless I/O operations going on. We should probably cache the file tree, along these lines:

actual class NativeFile actual constructor(actual val file: KFile) {

    private var jFile = file.jFile()

    // Cache for file properties
    private val fileLength: Long by lazy { jFile.length() }
    private val lastModifiedTime: Long by lazy { jFile.lastModified() }
    private var cachedFiles: List<KFile>? = null

    actual fun length(): Long = fileLength

    actual fun lastModified(): Long = lastModifiedTime

    actual fun listFiles(): List<KFile>? {
        if (cachedFiles == null) {
            cachedFiles = jFile.listFiles()?.map { it.kFile() }
        }
        return cachedFiles
    }
}

[alex-osm]

NativeFile was introduced to eliminate slow kotlin calls when calling expensive methods like listFiles(). In other words, it shouldn't be a problem and should work as fast as before.
From the other hand we could cache the file tree, but it is not clear how and when it should be refreshed.

[sonora]

Yes, I have to admit I am still not sure which change exactly caused the current regressiion.

I think this 1410005 was a big performance gain last time I had looked into this. Essentially this had eliminated the expensive single file.exists() IOs.

[alex-osm]

@sonora Just merged new stage of shared library files with optimization fix of reading gpx db and root gpx folder. Also root folder cache was introduced. Please test.

[sonora]

Amazing, good work! I experience ~1 sec loading time, best ever since we left the foldout setup of the tracks screen behind many months ago!

What does not yet work is entering the 'Visible on map' screen, both via the MyPlaces>Tracks screen and via Configure map. The screen is empty and non-functional.

PS: Log confirms the speedup: 615 ms. But it also contains GPXUtilities read errors for a number of tracks, see here. These were often user tracks I had imported to debug some of our user issues. But objectively they seem ok, and can be displayed ok.

09-19 19:52:39.138 25763 26578 I GpxUtilities: Error reading gpx /storage/3939-6139/osmand/tracks/import/North_Creek_(Right_Fork)_2.gpx
09-19 19:52:39.144 25763 26635 I TrackFolderLoaderTask: Finished loading tracks. Took 615ms

[alex-osm]

Great news! There was side effect about broken screens. Fixed.

About read errors - could you may be attach the file to reproduce the error?

[sonora]

Perfect! Works flawless now, from what I see!

I have checked the handful of my ~3500 tracks which cause an 'Error reading GPX' logcat entry (the track referenced in my log snippet above was a test-edited version of the user-provided one in #19995), and find they indeed have small issues. Like a missing </trkseg> or </wpt> tag, which apparently was tolerated when displaying a track but it is of course a syntax issue, so I think no actionable problem here.

And I guess my PR #20845 has become obsolete, or is there any value still? (It would now need conflict resolving.)

[sonora]

PS: I just notice tbe following glitch still: Sometimes when first opening the MyPlaces tracks screen, or on rare occasions also upon a pull-down refresh there, the bottom stats seem incomplete, they show only 90% or so of all tracks. As if there are occasions where a final screen refresh is missing in the end to update the screen with the completed stats?

Repeated tries seem to always produce the complete stats then.

[alex-osm]

@sonora Next iteration of fixes :) Now statistics should be fixed and analysing of new tracks should be faster.
Please test.

[sonora]

Fantastic! I find no flaw so far!