[Patch] load session performance strongly depends on order of layers

[GerdP]

What steps will reproduce the problem?

I have a *.joz file containing ~272 layers, 1-122 are geo image layers, 123-244 are gpx tracks and 255-272 are rather small files containing the marker layers from gpx files with way points (so they appear at the top in the list of layers)

1. I have changed the order of those layers so that the marker layers are at the bottom of the list instead and saved that to a different markers-last.joz file
2. I compared the time that it takes to load the two different *.joz files. Both are nearly the same size, ~2.1 MB.

What is the expected result?

Times should be similar, esp. when both files are loaded a few times so that the disk cache doesn't matter.

What happens instead?

The time to load is very different. The markers-last.joz file takes ~7 seconds, the other less then 2s.

Please provide any additional information below. Attach a screenshot if possible.

I think the reason could be that the *.joz file contains a directory layers which contains the data for the waypoint gpx layers. My guess: With the faster version the data is stored at the beginning of the zip file, the slower version has it at the end.

If that's true it would be good to always store the content of the layers directory first in the zip file, no matter where the layers appear in the layer list.
The number of layers is probably not important, the size of the *.joz file mainly depends on the number of
<geoimage> sections, in my case ~37400 images.

Relative:URL: ^/trunk
Repository:UUID: 0c6e7542-c601-0410-84e7-c038aed88b3b
Last:Changed Date: 2024-01-16 08:06:33 +0100 (Tue, 16 Jan 2024)
Revision:18940
Build-Date:2024-01-17 02:31:01
URL:https://josm.openstreetmap.de/svn/trunk

Identification: JOSM/1.5 (18940 en) Windows 10 64-Bit
OS Build number: Windows 10 Home 2009 (19045)
Memory Usage: 257 MB / 1888 MB (117 MB allocated, but free)
Java version: 17.0.8+7-LTS, Azul Systems, Inc., OpenJDK 64-Bit Server VM
Look and Feel: com.sun.java.swing.plaf.windows.WindowsLookAndFeel
Screen: \Display0 1920×1080 (scaling 1.00×1.00)
Maximum Screen Size: 1920×1080
Best cursor sizes: 16×16→32×32, 32×32→32×32
System property file.encoding: Cp1252
System property sun.jnu.encoding: Cp1252
Locale info: en_DE
Numbers with default locale: 1234567890 -> 1234567890
VM arguments: [-Djpackage.app-version=1.5.18789, --add-modules=java.scripting,java.sql,javafx.controls,javafx.media,javafx.swing,javafx.web, --add-exports=java.base/sun.security.action=ALL-UNNAMED, --add-exports=java.desktop/com.sun.imageio.plugins.jpeg=ALL-UNNAMED, --add-exports=java.desktop/com.sun.imageio.spi=ALL-UNNAMED, --add-opens=java.base/java.lang=ALL-UNNAMED, --add-opens=java.base/java.nio=ALL-UNNAMED, --add-opens=java.base/jdk.internal.loader=ALL-UNNAMED, --add-opens=java.base/jdk.internal.ref=ALL-UNNAMED, --add-opens=java.desktop/javax.imageio.spi=ALL-UNNAMED, --add-opens=java.desktop/javax.swing.text.html=ALL-UNNAMED, --add-opens=java.prefs/java.util.prefs=ALL-UNNAMED, -Djpackage.app-path=%UserProfile%\AppData\Local\JOSM\HWConsole.exe]

Plugins:
+ OpeningHoursEditor (36196)
+ RoadSigns (36196)
+ apache-commons (36176)
+ buildings_tools (36200)
+ comfort0 (36200)
+ o5m (36126)
+ pbf (36176)
+ poly (36126)
+ reltoolbox (36200)
+ reverter (36196)
+ undelete (36126)
+ utilsplugin2 (36200)

Validator rules:
+ c:\josm\core\resources\data\validator\combinations.mapcss
+ c:\josm\core\resources\data\validator\geometry.mapcss
+ c:\josm\core\resources\data\validator\relation.mapcss
+ c:\josm\core\resources\data\validator\unnecessary.mapcss
+ d:\java_tools\JOSM\mygeometry.mapcss
+ https://josm.openstreetmap.de/josmfile?page=Rules/GermanySpecific&zip=1

Last errors/warnings:
- 00000.509 W: extended font config - overriding 'filename.Myanmar_Text=mmrtext.ttf' with 'MMRTEXT.TTF'
- 00000.511 W: extended font config - overriding 'filename.Mongolian_Baiti=monbaiti.ttf' with 'MONBAITI.TTF'
- 00001.087 E: java.security.KeyStoreException: Windows-ROOT not found. Cause: java.security.NoSuchAlgorithmException: Windows-ROOT KeyStore not available

[GerdP]

My guess is probably wrong. I've traced the load process and it seems that it doesn't matter where in the zip file the data is stored, the access is always very fast. Still, I see very different load times depending on the order of the layers. Unfortunately my favorite order is extremely slow: I'd prefer to order the layers by date. For each date I have one folder containing several *.jpg, one gpx track and one waypoint file. The newest data would be at the top.

[GerdP]

The attached patch is just a quick hack. It changes the SessionWriter so that it writes the session in two passes. First anything that isn't a geoimage, than all the geoimage layers.
I have saved my existing fotos.joz as fotos1.joz using this patch. The time to write the file is not changed.
When I load the fotos1.joz I see no difference compared to fotos.joz regarding the result in the dialog, just the time to load is very different:

2024-01-21 10:27:02.898 INFO: Open file: F:\osm\fotos1.joz (2107893 bytes)
...
2024-01-21 10:27:07.005 FINE: SAX parsing completed in 4 ms

After closing all layers, load session fotos.joz:

2024-01-21 10:28:15.418 INFO: Open file: F:\osm\fotos.joz (2110696 bytes)
...
2024-01-21 10:28:33.784 FINE: SAX parsing completed in 4 ms

Double check: after closing all layers, load session fotos1.joz again:

2024-01-21 10:30:00.620 INFO: Open file: F:\osm\fotos1.joz (2107893 bytes)
...
2024-01-21 10:30:03.509 FINE: SAX parsing completed in 4 ms

So, 3..4 secs for fotos1.joz and ~18.5 secs for fotos.joz.
@taylor.smock
If I got that right a lot of the additional time is spent in GC. Any idea why the different order is so important?

[GerdP]

My findings up to now: This statement in GpxTracksSessionImporter seems to be the culprit

            String fileStr = (String) fileExp.evaluate(elem, XPathConstants.STRING);

It is either always executed in < 1 ms (fotos1.joz) or in up to ~140 ms with (fotos.joz), the last calls take much longer than the first ones.

Edit: The method calls com.sun.org.apache.xml.internal.dtm.ref.dom2dtm.DOM2DTM.getHandleFromNode(Node node) which scans the document sequentially until it finds the node elem. With fotos1.joz there are only a few nodes, but with fotos.joz all the entries for the geoimages come before the node, so this is a very slow loop (and there is a comment which warns about that).

[GerdP]

This stupid trick might be a solution, but I think the XPath expression should somehow allow to search only the node and its children?

src/org/openstreetmap/josm/io/session/GpxTracksSessionImporter.java

@@ -42 +42 @@
             XPathFactory xPathFactory = XPathFactory.newInstance();
             XPath xpath = xPathFactory.newXPath();
             XPathExpression fileExp = xpath.compile("file/text()");
-            String fileStr = (String) fileExp.evaluate(elem, XPathConstants.STRING);
+            String fileStr = (String) fileExp.evaluate(elem.cloneNode(true), XPathConstants.STRING);
             if (Utils.isEmpty(fileStr)) {
                 throw new IllegalDataException(tr("File name expected for layer no. {0}", support.getLayerIndex()));
             }

[GerdP]

• remove duplicated code

[GerdP]

Please review
The patch

• removes the duplicated code regarding XPath, use existing method OsmDataSessionImporter.extractFileName() instead
• improves that method to first try to find a "file" node given the current element before falling back to the possibly very slow XPath evaluate call (not sure if the XPath part is still needed, it is never used in my example).

The effect is that the order of the layers in the saved *.joz file no longer matters.
I don't like that the method extractFileName() is in OsmDataSessionImporter. Maybe better to move it to the interface SessionLayerImporter?

[SekeRob]

This is curious. Suddenly my fixed layers file with all my regulars having a .joz extension would not load anymore, a message appearing along the line of a broken header, probably since around OWS updated to stable 18940. Recreated it and saved. The extension is now .jos.

[GerdP]

I don't understand. Is this related to the attached patch?

[GerdP]

Maybe better to move it to the interface SessionLayerImporter?

This would also require a change in the opendata plugion. OpenDataSessionImporter refers to OsmDataSessionImporter.extractFileName()

[GerdP]

In 18954/josm:

fix #23427 load session performance strongly depends on order of layers
The patch

• removes the duplicated code regarding XPath and calls existing method OsmDataSessionImporter.extractFileName() instead
• improves that method to first try to find a "file" node given the current element before falling back to the possibly very slow XPath evaluate call (not sure if the XPath part is still needed, it is never used in my example).

[GerdP]

In 18955/josm:

see #23427: remove obsolete and unintended code from experiment