Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [udig-devel] Something strange with map rendering
Good research thanks for that Andrea. I think the issue is that the RenderManager controls when the display is updated (which is ever 1 second). I should be able to fix this issue by updating the screen when the data is finished being render irregardless of whether the 1 second has been reached. 

Jesse

On 7-Jan-07, at 5:39 AM, Andrea Aime wrote:


Andrea Aime ha scritto:

Hi,
today I was fiddling a little with uDig and, well... there is something strange I keep on seeing during map rendering from old versions to now. 
I have the strong impression the actual rendering process does not
start when I release the mouse after a zoom or a pan, but some 0.2-0.3 
second after that, adding to the perception the UI is slow.
Maybe it's the Eclipse job system that does not start the rendering
job right away, or maybe it's just an impression, but yet, it's funny
to see the CPU load totally to zero for such a long time... it's rendering a map, I would expect it to use actual CPU, and see the load 
right away...


Ok, did a little investigation and found that on a simple map uDig
throws aways 2/3 to 4/5 of the actual time used to display the
resulting image in some kind of waits.

I've used the StopWatch class attached to get timings, and applied
the attached patch to the other classes (I could not get svn to
generate a diff with StopWatch.java included, complains about some
non ASCII char, don't know...).
The class is really scripty, as the method I used to gather timings.
Time gathering works by resetting the timer when the mouse is released
(so it'll works just for zoom and pan), and then printing the elapsed time in selected places in the code.
I'm using a single postgis layer (whole world contries, 6MB .shp when converted as a shapefile) have a look at what happens: 

(zooming in using window)
[EventJob] Mouse released - Stopwatch reset at 1168175951828
[CompositeRendererJob] run started:	515
[RenderExecutorImpl] scheduling render job:	515
[RenderJob] run started:	515
[BasicFeatureRenderer] prepare:	515
[BasicFeatureRenderer] start rendering:	547
[BasicFeatureRenderer] rendering ended:	797
[RenderJob] run terminated:	797
[CompositeRendererJob] run terminated:	1218
(the following is image conversion between RenderedImage and swt image) 
[ViewportPaneSWT] create image, before:	1218
[ViewportPaneSWT] create image, after:	1218

(panning)
[EventJob] Mouse released - Stopwatch reset at 1168175989343
[CompositeRendererJob] run started:	500
[RenderExecutorImpl] scheduling render job:	500
[RenderJob] run started:	500
[BasicFeatureRenderer] prepare:	516
[BasicFeatureRenderer] start rendering:	547
[BasicFeatureRenderer] rendering ended:	813
[RenderJob] run terminated:	813
[CompositeRendererJob] run terminated:	1203
[ViewportPaneSWT] create image, before:	1203
[ViewportPaneSWT] create image, after:	1203

(zooming in in a very small area, some ten Greek islands)
[EventJob] Mouse released - Stopwatch reset at 1168176024968
[CompositeRendererJob] run started:	500
[RenderExecutorImpl] scheduling render job:	500
[RenderJob] run started:	500
[BasicFeatureRenderer] prepare:	500
[BasicFeatureRenderer] start rendering:	532
[BasicFeatureRenderer] rendering ended:	719
[RenderJob] run terminated:	719
[CompositeRendererJob] run terminated:	1203
[ViewportPaneSWT] create image, before:	1203
[ViewportPaneSWT] create image, after:	1203

Well, in both you can see actual rendering takes no more than 400ms
on the whole image (world countries) and less than 200ms in the very
zoomed in case, yet the total time is basically unchanged, 1.2 seconds. First we can see rendering is started 500ms after the command, and then that composite render closes the rendering cycle always after 700ms from 
when it was started... in the worst case, uDig is spending 1second (an
eternity in my book) doing nothing, no wonder I can't see the cpu
usage go up.
To give you a user level comparison, asking the same layer to Geoserver from a browser using: http://localhost:8080/geoserver/wms? bbox=-180,-90,180,90&styles=&Format=image/ png&request=GetMap&layers=topp:world&width=500&height=250&srs=EPSG: 4326 (same image size as the one I used in uDig, I used a quite small udig window) takes 0.8 seconds (FasterFox timings). Not only it's faster, but consider Geoserver has to encode the image into png, and the browser has to decode it, whilst uDig does not have to perform such work. 

I haven't investigated further, yet I would urge uDig developers
to put some thoughts and identify why that much valuable time is
thrown away. Oh, the patches are against 1.1.x branch.

Cheers
Andrea


package net.refractions.udig.project;

/**
 * A simple utility class to add timed printlns in an algorithm
 *
 * @author aaime
 *
 */
public class StopWatch {
    static long start;

    public static void reset(Object context, String msg) {
        System.out.println();
        System.out.println();
        start = System.currentTimeMillis();
System.out.print("[" + context.getClass().getSimpleName() + "] " + msg 
                + " - ");
        System.out.println("Stopwatch reset at " + start);
    }

    protected static void mark(String msg) {
        long elapsed = System.currentTimeMillis() - start;
        System.out.println(msg + ":\t" + elapsed);
    }

    public static void mark(Object context, String msg) {
        mark("[" + context.getClass().getSimpleName() + "] " + msg);
    }
}
Index: net.refractions.udig.libs/.classpath
===================================================================
--- net.refractions.udig.libs/.classpath	(revisione 23698)
+++ net.refractions.udig.libs/.classpath	(copia locale)
@@ -1,49 +1,49 @@
-<?xml version="1.0" encoding="UTF-8"?>
-<classpath>
-	<classpathentry kind="src" path=""/>
- <classpathentry exported="true" kind="lib" path="lib/commons- collections-2.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/commons- pool-1.2.jar"/> - <classpathentry exported="true" kind="lib" path="lib/commons- codec-1.3.jar"/> - <classpathentry exported="true" kind="lib" path="lib/geoapi-2.0- tiger.jar" sourcepath="/Users/Jesse/Development/GeoAPI-2_0_0/ sources"/> - <classpathentry exported="true" kind="lib" path="lib/ log4j-1.2.8.jar"/> - <classpathentry exported="true" kind="lib" path="lib/opengis- legacy-0.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ units-0.01.jar"/> - <classpathentry exported="true" kind="lib" path="lib/wkb4j-1.0- RC1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ xmlrpc-2.0.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ hsqldb-1.8.0.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ xerces-2.4.0.jar"/> - <classpathentry exported="true" kind="lib" path="lib/commons- lang-2.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- api-2.2.x.jar" sourcepath="/gt2-api"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- arcgrid-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- brewer-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- coverage-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- db2-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2-epsg- wkt-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- geotiff-2.2.x.jar" sourcepath="/Users/Jesse/Development/repo/ geotools/gt2.2.x/plugin/geotiff"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- gml-2.2.x.jar" sourcepath="/Users/Jesse/Development/repo/geotools/ gt2.2.x/plugin/gml"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- hsql-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- image-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2-indexed- shapefile-2.2.x.jar" sourcepath="/gt2-indexed-shapefile"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- main-2.2.x.jar" sourcepath="/gt2-main"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- mysql-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2-oracle- spatial-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- postgis-2.2.x.jar" sourcepath="/gt2-postgis"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- referencing-2.2.x.jar" sourcepath="/gt2-referencing"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- render-2.2.x.jar" sourcepath="/gt2-render"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- shapefile-2.2.x.jar" sourcepath="/gt2-shapefile"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- shapefile-renderer-2.2.x.jar" sourcepath="/gt2-shapefile-renderer"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- validation-2.2.x.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- wfs-2.2.x.jar" sourcepath="/gt2-wfs"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- wms-2.2.x.jar" sourcepath="/gt2-wms"/> 
-	<classpathentry exported="true" kind="lib" path="lib/jdom-1.0.jar"/>
- <classpathentry exported="true" kind="lib" path="lib/mysql- connector-java-3.0.10.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ vecmath-1.3.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ jts-1.7.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ spatialdb-0.1.jar"/> - <classpathentry exported="true" kind="lib" path="lib/ picocontainer-1.2.jar"/> - <classpathentry exported="true" kind="lib" path="lib/gt2- arcsde-2.2.x.jar" sourcepath="C:/java/gt2.2.x/plugin/arcsde"/> - <classpathentry exported="true" kind="lib" path="lib/ concurrent-1.3.4.jar"/> - <classpathentry kind="con" path="org.eclipse.jdt.launching.JRE_CONTAINER"/> - <classpathentry kind="con" path="org.eclipse.pde.core.requiredPlugins"/> 
-	<classpathentry kind="output" path="bin"/>
-</classpath>
+<?xml version="1.0" encoding="UTF-8"?>
+<classpath>
+	<classpathentry kind="src" path=""/>
+ <classpathentry exported="true" kind="lib" path="lib/commons- codec-1.3.jar"/> + <classpathentry exported="true" kind="lib" path="lib/geoapi-2.0- tiger.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ log4j-1.2.8.jar"/> + <classpathentry exported="true" kind="lib" path="lib/opengis- legacy-0.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ units-0.01.jar"/> + <classpathentry exported="true" kind="lib" path="lib/wkb4j-1.0- RC1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ xmlrpc-2.0.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ hsqldb-1.8.0.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ xerces-2.4.0.jar"/> + <classpathentry exported="true" kind="lib" path="lib/commons- lang-2.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- api-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- arcgrid-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- brewer-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- coverage-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- db2-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2-epsg- wkt-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- geotiff-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- gml-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- hsql-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- image-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2-indexed- shapefile-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- main-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- mysql-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2-oracle- spatial-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- postgis-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- referencing-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- render-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- shapefile-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- shapefile-renderer-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- validation-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- wfs-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- wms-2.2.x.jar"/> 
+	<classpathentry exported="true" kind="lib" path="lib/jdom-1.0.jar"/>
+ <classpathentry exported="true" kind="lib" path="lib/mysql- connector-java-3.0.10.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ vecmath-1.3.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ jts-1.7.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ spatialdb-0.1.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ picocontainer-1.2.jar"/> + <classpathentry exported="true" kind="lib" path="lib/gt2- arcsde-2.2.x.jar"/> + <classpathentry exported="true" kind="lib" path="lib/ concurrent-1.3.4.jar"/> + <classpathentry exported="true" kind="lib" path="lib/commons- pool-1.2.jar"/> + <classpathentry exported="true" kind="lib" path="lib/commons- collections-2.1.jar"/> + <classpathentry kind="con" path="org.eclipse.jdt.launching.JRE_CONTAINER"/> + <classpathentry kind="con" path="org.eclipse.pde.core.requiredPlugins"/> 
+	<classpathentry kind="output" path="bin"/>
+</classpath>
Index: net.refractions.udig.render.feature.basic/src/net/ refractions/udig/render/internal/feature/basic/ BasicFeatureRenderer.java 
===================================================================
--- net.refractions.udig.render.feature.basic/src/net/refractions/ udig/render/internal/feature/basic/BasicFeatureRenderer.java (revisione 23698) +++ net.refractions.udig.render.feature.basic/src/net/refractions/ udig/render/internal/feature/basic/BasicFeatureRenderer.java (copia locale) 
@@ -20,6 +20,7 @@

 import net.refractions.udig.core.TransparencyRemovingVisitor;
 import net.refractions.udig.project.ILayer;
+import net.refractions.udig.project.StopWatch;
 import net.refractions.udig.project.internal.ProjectPlugin;
 import net.refractions.udig.project.internal.StyleBlackboard;
import net.refractions.udig.project.internal.render.impl.RendererImpl; 
@@ -193,7 +194,7 @@
     @SuppressWarnings("unchecked")
     private void render(Graphics2D graphics, Envelope bounds,
 			IProgressMonitor monitor) throws RenderException {
-
+        StopWatch.mark(this, "prepare");
         getContext().setStatus(ILayer.WAIT);
getContext().setStatusMessage (Messages.BasicFeatureRenderer_rendering_status); 
         String endMessage=null;
@@ -288,7 +289,7 @@
 							: RenderingHints.VALUE_ANTIALIAS_OFF);
             if( monitor.isCanceled() )
                 return;
-
+            StopWatch.mark(this, "start rendering");
 			renderer2.setJava2DHints(hints);
 			renderer2.paint(graphics, paintArea, validBounds);

@@ -330,6 +331,7 @@
 				}
 			}
 		}
+                StopWatch.mark(this, "rendering ended");
 	}

 	protected GTRenderer getRenderer() {
Index: net.refractions.udig.project/src/net/refractions/udig/ project/StopWatch.java 
===================================================================
--- net.refractions.udig.project/src/net/refractions/udig/project/ StopWatch.java (revisione 0) +++ net.refractions.udig.project/src/net/refractions/udig/project/ StopWatch.java (revisione 0) 
@@ -0,0 +1,31 @@
+package net.refractions.udig.project;
+
+/**
+ * A simple utility class to add timed printlns in an algorithm
+ *
+ * @author aaime
+ *
+ */
+public class StopWatch {
+    static long start;
+
+    public static void reset(Object context, String msg) {
+        System.out.println();
+        System.out.println();
+        start = System.currentTimeMillis();
+
+ System.out.print("[" + context.getClass().getSimpleName() + "] " + msg 
+                + " - ");
+        System.out.println("Stopwatch reset at " + start);
+    }
+
+    protected static void mark(String msg) {
+        long elapsed = System.currentTimeMillis() - start;
+        System.out.println(msg + ":\t" + elapsed);
+    }
+
+    public static void mark(Object context, String msg) {
+        mark("[" + context.getClass().getSimpleName() + "] " + msg);
+    }
+
+}
_______________________________________________
User-friendly Desktop Internet GIS (uDig)
http://udig.refractions.net
http://lists.refractions.net/mailman/listinfo/udig-devel

Back to the top