frozen editor while panning or zooming of the map

classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

frozen editor while panning or zooming of the map

Stephan Knauss
Hello,

I sometimes suffer delays of 10-15s when panning or zooming the map.

I had the impression it started to become worse when tile serving was
switched over to https, but switching back to http did not fully fix it.
With JOSM being updated in parallel all not that great to track down
such issues. Just seeing in the terminal window large gaps between tile
requests. Hiding imagery tiles always makes it fast. So it is certainly
related.

So today I tried again to reproduce it, this time with YourKit Profiler
connected.

I noticed some shorter delays, but couldn't fully reproduce the extreme
delays.

Majority of time (about 60%) was spent in what I guess is tile loading:
HttpClient.java:91
org.openstreetmap.josm.tools.HttpClient.connect(ProgressMonitor)

I have typically the two DG layers active sometimes also esri and bing
to compare the images and alignment. With my large screen having 4k
resolution, I might have a significant larger window visible than the
average user.
I sometimes feared that mapbox might throttle the tile delivery. My
connection itself is a fast 50 MBit link which typically is fast towards
mapbox.

I then thought to make it a bit harder for JOSM and reduced the maximum
connections per host down from 12 connections to 6 connections.

I got multiple seconds of frozen map now. After panning or zooming the
view is frozen. Mouse still moves, but the line I am currently painting
no longer follows the cursor. Just jumps back after five to ten seconds.

Now the majority of time is spent here:

HostLimitQueue.java:30
org.openstreetmap.josm.data.cache.HostLimitQueue.poll(long, TimeUnit)

Can you please give some high-level explanation on how the GUI is
connected to tile loading?

My expectation would be that tile loading happens in the background. In
case of a blocked download (for whatever reason) my expectation would be
that just the background tiles are not updated. panning, zooming or
editing should not wait on it.
Is there a critical section somewhere which would be better not shared
between the editor and tile loading?

How much personal details is recorded in the profiler snapshots? Would
it help if I share one? Anyone more experienced interested in running a
profiling session via skype?


If I read the call tree correctly, then below:
HttpClient.java:91
org.openstreetmap.josm.tools.HttpClient.connect(ProgressMonitor)
the routines
HttpClient.java:149 <...>
sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode()
and
HttpClient.java:149 <...> java.net.HttpURLConnection.getResponseCode()

use 40% of the time there. Do I get it right that this is only used for
logging? Maybe only do this then in case log-level is at least info

### Eclipse Workspace Patch 1.0
#P JOSM
Index: src/org/openstreetmap/josm/tools/HttpClient.java
===================================================================
--- src/org/openstreetmap/josm/tools/HttpClient.java (revision 14108)
+++ src/org/openstreetmap/josm/tools/HttpClient.java (working copy)
@@ -144,13 +144,15 @@
              try {
                  connection.connect();
                  final boolean hasReason = reasonForRequest != null &&
!reasonForRequest.isEmpty();
-                Logging.info("{0} {1}{2} -> {3}{4}",
-                        requestMethod, url, hasReason ? (" (" +
reasonForRequest + ')') : "",
-                        connection.getResponseCode(),
-                        connection.getContentLengthLong() > 0
-                                ? (" (" +
Utils.getSizeString(connection.getContentLengthLong(),
Locale.getDefault()) + ')')
-                                : ""
-                );
+                if (Logging.isLoggingEnabled(Logging.LEVEL_INFO)) {
+                    Logging.info("{0} {1}{2} -> {3}{4}",
+                            requestMethod, url, hasReason ? (" (" +
reasonForRequest + ')') : "",
+                            connection.getResponseCode(),
+                            connection.getContentLengthLong() > 0
+                                    ? (" (" +
Utils.getSizeString(connection.getContentLengthLong(),
Locale.getDefault()) + ')')
+                                    : ""
+                    );
+                }
                  if (Logging.isDebugEnabled()) {
                      Logging.debug("RESPONSE: {0}",
connection.getHeaderFields());
                  }



Stephan


Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Michael Zangl-3
Hi,

No, getResponseCode() is not only for logging. It just happens to be the
first method that is called on the HTTP result and triggers the Thread
to wait for the HTTP response (therefore the long wait). Since we need
the response any way, it won't be a noticeable performance improvement
to wrap that block in an if statement.

Tile loading should be in background. You can completely ignore those
loader threads and need to focus on the AWT Event Thread instead. This
is the thread that should not be blocked. It can be blocked by several
things, e.g.:
* Synchronisation (waiting e.g. for a tile thread)
* Graphics rendering (filters / ...)
* Stop-the-world garbage collection
* ...

All the things you *should* not see but something happened in your case
that triggered one of those many possible events.

Since your freeze are multiple seconds, they might be long enough for
you to trigger a stack trace. For this, you need a tool that generates
such strack traces (e.g. VisualVM) connected to JOSM and ready to do a
stack trache just by klicking one button (open the correct tab, put the
window next to JOSM). Once JOSM freezes, quickly trigger that button. If
you are fast enough, you get the exact spot where JOSM spends it's time.

Michael

On 10.09.2018 01:11, Stephan Knauss wrote:

> Hello,
>
> I sometimes suffer delays of 10-15s when panning or zooming the map.
>
> I had the impression it started to become worse when tile serving was
> switched over to https, but switching back to http did not fully fix it.
> With JOSM being updated in parallel all not that great to track down
> such issues. Just seeing in the terminal window large gaps between tile
> requests. Hiding imagery tiles always makes it fast. So it is certainly
> related.
>
> So today I tried again to reproduce it, this time with YourKit Profiler
> connected.
>
> I noticed some shorter delays, but couldn't fully reproduce the extreme
> delays.
>
> Majority of time (about 60%) was spent in what I guess is tile loading:
> HttpClient.java:91
> org.openstreetmap.josm.tools.HttpClient.connect(ProgressMonitor)
>
> I have typically the two DG layers active sometimes also esri and bing
> to compare the images and alignment. With my large screen having 4k
> resolution, I might have a significant larger window visible than the
> average user.
> I sometimes feared that mapbox might throttle the tile delivery. My
> connection itself is a fast 50 MBit link which typically is fast towards
> mapbox.
>
> I then thought to make it a bit harder for JOSM and reduced the maximum
> connections per host down from 12 connections to 6 connections.
>
> I got multiple seconds of frozen map now. After panning or zooming the
> view is frozen. Mouse still moves, but the line I am currently painting
> no longer follows the cursor. Just jumps back after five to ten seconds.
>
> Now the majority of time is spent here:
>
> HostLimitQueue.java:30
> org.openstreetmap.josm.data.cache.HostLimitQueue.poll(long, TimeUnit)
>
> Can you please give some high-level explanation on how the GUI is
> connected to tile loading?
>
> My expectation would be that tile loading happens in the background. In
> case of a blocked download (for whatever reason) my expectation would be
> that just the background tiles are not updated. panning, zooming or
> editing should not wait on it.
> Is there a critical section somewhere which would be better not shared
> between the editor and tile loading?
>
> How much personal details is recorded in the profiler snapshots? Would
> it help if I share one? Anyone more experienced interested in running a
> profiling session via skype?
>
>
> If I read the call tree correctly, then below:
> HttpClient.java:91
> org.openstreetmap.josm.tools.HttpClient.connect(ProgressMonitor)
> the routines
> HttpClient.java:149 <...>
> sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode()
> and
> HttpClient.java:149 <...> java.net.HttpURLConnection.getResponseCode()
>
> use 40% of the time there. Do I get it right that this is only used for
> logging? Maybe only do this then in case log-level is at least info
>
> ### Eclipse Workspace Patch 1.0
> #P JOSM
> Index: src/org/openstreetmap/josm/tools/HttpClient.java
> ===================================================================
> --- src/org/openstreetmap/josm/tools/HttpClient.java    (revision 14108)
> +++ src/org/openstreetmap/josm/tools/HttpClient.java    (working copy)
> @@ -144,13 +144,15 @@
>               try {
>                   connection.connect();
>                   final boolean hasReason = reasonForRequest != null &&
> !reasonForRequest.isEmpty();
> -                Logging.info("{0} {1}{2} -> {3}{4}",
> -                        requestMethod, url, hasReason ? (" (" +
> reasonForRequest + ')') : "",
> -                        connection.getResponseCode(),
> -                        connection.getContentLengthLong() > 0
> -                                ? (" (" +
> Utils.getSizeString(connection.getContentLengthLong(),
> Locale.getDefault()) + ')')
> -                                : ""
> -                );
> +                if (Logging.isLoggingEnabled(Logging.LEVEL_INFO)) {
> +                    Logging.info("{0} {1}{2} -> {3}{4}",
> +                            requestMethod, url, hasReason ? (" (" +
> reasonForRequest + ')') : "",
> +                            connection.getResponseCode(),
> +                            connection.getContentLengthLong() > 0
> +                                    ? (" (" +
> Utils.getSizeString(connection.getContentLengthLong(),
> Locale.getDefault()) + ')')
> +                                    : ""
> +                    );
> +                }
>                   if (Logging.isDebugEnabled()) {
>                       Logging.debug("RESPONSE: {0}",
> connection.getHeaderFields());
>                   }
>
>
>
> Stephan
>
>

Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Stephan Knauss
Hello Michael,

On 10.09.2018 22:07, Michael Zangl wrote:
> Tile loading should be in background. You can completely ignore those
> loader threads and need to focus on the AWT Event Thread instead. This
> is the thread that should not be blocked. It can be blocked by several
> things, e.g.:
> * Synchronisation (waiting e.g. for a tile thread)
> * Graphics rendering (filters / ...)
> * Stop-the-world garbage collection

Thanks. This is also my understanding. I try to figure out where it
blocks. With it being reproducible quite easy I hope to be able to
contribute a meaningful analysis of the problem.

I just started with YourKit, but I worked with similar tools before. So
hoping I get similar results from that one.

The AWT Eventqueue looks a bit generic. YourKit can point to "Long AWT
Events" in the "Threads" tab. I have for example one longer than 5s.

What I not yet understand is, why the marked red bar of the event
duration stretches much longer than the section where it prints a
stack-trace.

It looks to be here:
org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer$TileSet.visitTiles(Consumer,
Consumer) AbstractTileSourceLayer.java:1293

which is:
        public void visitTiles(Consumer<Tile> visitor,
Consumer<TilePosition> missed) {
             tilePositions().parallel().forEach(tp ->
visitTilePosition(visitor, tp, missed));
         }


So it seems to be something with tile handling, which would be
consistent to my assumption that it has something to do with tile loading.

I not yet fully understand the timeline view of the profiler here.
It lists two sections, one with "Sample duration" 900ms and one with
5.200ms.

Are the ForkJoinPool.commonPool threads the one doing the parallel work?
Most of them are blocked on synchronized (paintMutex) in
org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.lambda$paintTileImages$2(List,
Object, Graphics2D, Tile) AbstractTileSourceLayer.java:1027

What I not understand is when looking at the one in the pool working, it
is drawing a tile:
org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.drawImageInside(Graphics2D,
BufferedImage, TileAnchor, TileAnchor, Shape)
AbstractTileSourceLayer.java:993

But I don't see that one consuming massive CPU. Think I have to re-check
how to better record the profiler logs. Maybe sampling faster?

Is there any specific class or behavior you could point to with this
(limited) level of information to further check?


Thanks,

Stephan

Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Stephan Knauss
On 11.09.2018 08:04, Stephan Knauss wrote:
> The AWT Eventqueue looks a bit generic. YourKit can point to "Long AWT
> Events" in the "Threads" tab. I have for example one longer than 5s.

I stored a snapshot here. Can't shorten the timeline I think, but
resetting telemetry caused only the last "long event" of 8s having call
stacks I think.

http://downloads.osm-tools.org/josm-custom-2018-09-11(7).zip

I don't understand why the events tab does not have call stacks recorded.

It seemed that whenever I did not use JOSM for a few minutes because I
scrolled around in the profiler or source and then go back to JOSM and
zoom I got a wait. One time over 22 seconds.

Can someone more familiar with the profiler confirm that the AWT loop is
not blocked but simply busy for that long?

Is it filling tasks to JCSCachedTileLoder.submit()?
I don't know how to limit the CPU analysis to that timeframe to see
where the cycles go.

Stephan

Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Stephan Knauss
Hello,

On 11.09.2018 23:06, Stephan Knauss wrote:
> http://downloads.osm-tools.org/josm-custom-2018-09-11(7).zip

Another question regarding the blocked painting.
If I get the stack right, we are inside the painting loop in
org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.drawInViewArea(Graphics2D,
MapView, ProjectionBounds) AbstractTileSourceLayer.java:1514

What is the reason that here tiles are loaded and not simply painted? If
tiles are available, they can be painted. If tiles are due to be loaded
this is something to expected to take longer, so why not offloading this
to a later point in time?

Or maybe it was intended to do so? The (before mentioned)
JCSCachedTileLoaderJob.submit() might do this. But according to the
profiler this method then takes away 71% of the time in the painting
loop. In my case multiple seconds.

Later on a lot of time is spent here:
HostLimitQueue.java:143 <...>
java.util.concurrent.ThreadPoolExecutor.setCorePoolSize(int)

which seems to be part of a "trick" to exploit a side effect of the
method. Looks like this was implemented by wiktorn.

Shall I create a ticket with the details up to now to better track it?

The following snippet os a call stack of what I believe a single call.

"Name","Level"
"AWT-EventQueue-0  Runnable CPU usage on sample: 234ms","1"
"java.util.concurrent.ThreadPoolExecutor.setCorePoolSize(int)","2"
"org.openstreetmap.josm.data.cache.HostLimitQueue.offer(Runnable)
HostLimitQueue.java:143","2"
"org.openstreetmap.josm.data.cache.HostLimitQueue.offer(Object)
HostLimitQueue.java:30","2"
"java.util.concurrent.ThreadPoolExecutor.execute(Runnable)","2"
"org.openstreetmap.josm.data.cache.JCSCachedTileLoaderJob.submit(ICachedLoaderListener,
boolean) JCSCachedTileLoaderJob.java:168","2"
"org.openstreetmap.josm.data.imagery.TMSCachedTileLoaderJob.submit(boolean)
TMSCachedTileLoaderJob.java:150","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.loadTile(Tile,
boolean) AbstractTileSourceLayer.java:891","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.access$100(AbstractTileSourceLayer,
Tile, boolean) AbstractTileSourceLayer.java:141","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer$TileSet.loadAllTiles(boolean)
AbstractTileSourceLayer.java:1272","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer$TileSet.access$1000(AbstractTileSourceLayer$TileSet,
boolean) AbstractTileSourceLayer.java:1183","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.drawInViewArea(Graphics2D,
MapView, ProjectionBounds) AbstractTileSourceLayer.java:1514","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer.access$2700(AbstractTileSourceLayer,
Graphics2D, MapView, ProjectionBounds) AbstractTileSourceLayer.java:141","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer$TileSourcePainter.doPaint(MapViewGraphics)
AbstractTileSourceLayer.java:1892","2"
"org.openstreetmap.josm.gui.layer.AbstractTileSourceLayer$TileSourcePainter.paint(MapViewGraphics)
AbstractTileSourceLayer.java:1886","2"
"org.openstreetmap.josm.gui.MapView.paintLayer(Layer, Graphics2D)
MapView.java:468","2"
"org.openstreetmap.josm.gui.MapView.drawMapContent(Graphics2D)
MapView.java:583","2"
"org.openstreetmap.josm.gui.MapView.paint(Graphics) MapView.java:490","2"
"java.awt.EventDispatchThread.run()","2"


Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Dirk Stöcker
Hello Stephan,

> Shall I create a ticket with the details up to now to better track it?

Yes. Please create a ticket and copy all relevant details there.
Discussions in the mailinglist tend to be forgotten, the JOSM wiki is our
main communication channel (as you can easily see when you look at the
timeline :-).

Ciao
--
http://www.dstoecker.eu/ (PGP key available)

Reply | Threaded
Open this post in threaded view
|

Re: frozen editor while panning or zooming of the map

Stephan Knauss
On 14.09.2018 09:12, Dirk Stöcker wrote:
> Hello Stephan,
>
>> Shall I create a ticket with the details up to now to better track it?
>
> Yes. Please create a ticket and copy all relevant details there.
created https://josm.openstreetmap.de/ticket/16734

> Discussions in the mailinglist tend to be forgotten, the JOSM wiki is
> our main communication channel (as you can easily see when you look at
> the timeline :-).
I hoped the mailing list being a bit more interactive so to easier track
down the issue.

Please let me know if any further details/reproduction are needed.

Thanks,

Stephan