From 02a0afa88392b58d17b118fe8fe17c55389bd899 Mon Sep 17 00:00:00 2001 From: Kai Krueger Date: Wed, 1 Sep 2010 20:19:26 +0000 Subject: [PATCH] [renderd] Add a munin graph to show how much time renderd spends rendering tiles of various zoom levels With this graph, it is hopefully possible to see where (i.e. towards which zoomlevel) most of the rendering time goes, and thus might give some indication where optimisations in the style sheet are best focused at, if performance is an issue. It useses purely wallclock time and thus does not account for individual resources. --- daemon.c | 21 ++++++++---- daemon.h | 9 ++++- gen_tile.cpp | 11 ++++++ munin/renderd_zoom_time | 76 +++++++++++++++++++++++++++++++++++++++++ 4 files changed, 110 insertions(+), 7 deletions(-) create mode 100755 munin/renderd_zoom_time diff --git a/daemon.c b/daemon.c index 36104bf..f3a6780 100644 --- a/daemon.c +++ b/daemon.c @@ -47,6 +47,15 @@ static renderd_config config; int noSlaveRenders; int hashidxSize; +void statsRenderFinish(int z, long time) { + pthread_mutex_lock(&qLock); + if ((z >= 0) && (z <= MAX_ZOOM)) { + stats.noZoomRender[z]++; + stats.timeZoomRender[z] += time; + } + pthread_mutex_unlock(&qLock); +} + struct item *fetch_request(void) { struct item *item = NULL; @@ -84,9 +93,6 @@ struct item *fetch_request(void) item->inQueue = queueRender; } - if ((item->req.z >= 0) && ( item->req.z <= MAX_ZOOM)) { - stats.noZoomRender[item->req.z]++; - } pthread_mutex_unlock(&qLock); @@ -532,9 +538,12 @@ void *stats_writeout_thread(void * arg) { fprintf(statfile, "ReqPrioRendered: %li\n", lStats.noReqPrioRender); fprintf(statfile, "ReqBulkRendered: %li\n", lStats.noReqBulkRender); fprintf(statfile, "DirtyRendered: %li\n", lStats.noDirtyRender); - for (i = 0; i <= MAX_ZOOM; i++) { - fprintf(statfile,"ZoomRendered%02i: %li\n", i, lStats.noZoomRender[i]); - } + for (i = 0; i <= MAX_ZOOM; i++) { + fprintf(statfile,"ZoomRendered%02i: %li\n", i, lStats.noZoomRender[i]); + } + for (i = 0; i <= MAX_ZOOM; i++) { + fprintf(statfile,"TimeRenderedZoom%02i: %li\n", i, lStats.timeZoomRender[i]); + } fclose(statfile); if (rename(tmpName, config.stats_filename)) { syslog(LOG_WARNING, "Failed to overwrite stats file: %i", errno); diff --git a/daemon.h b/daemon.h index abbbab6..1f8980a 100644 --- a/daemon.h +++ b/daemon.h @@ -35,7 +35,14 @@ typedef struct { long noReqPrioRender; long noReqBulkRender; long noReqDroped; - long noZoomRender[MAX_ZOOM + 1]; + long noZoomRender[MAX_ZOOM + 1]; + long timeReqRender; + long timeReqPrioRender; + long timeReqBulkRender; + long timeZoomRender[MAX_ZOOM + 1]; } stats_struct; +void statsRenderFinish(int z, long time); + + #endif diff --git a/gen_tile.cpp b/gen_tile.cpp index 0b2135a..567e8a8 100644 --- a/gen_tile.cpp +++ b/gen_tile.cpp @@ -543,7 +543,17 @@ void *render_thread(void * arg) metaTile tiles(req->xmlname, item->mx, item->my, req->z); if (maps[i].ok) { + timeval tim; + gettimeofday(&tim, NULL); + long t1=tim.tv_sec*1000+(tim.tv_usec/1000); + ret = render(maps[i].map, req->xmlname, maps[i].prj, item->mx, item->my, req->z, size, tiles); + + gettimeofday(&tim, NULL); + long t2=tim.tv_sec*1000+(tim.tv_usec/1000); + syslog(LOG_DEBUG, "DEBUG: DONE TILE %s %d %d-%d %d-%d in %.3lf seconds", + req->xmlname, req->z, item->mx, item->mx+size-1, item->my, item->my+size-1, (t2 - t1)/1000.0); + statsRenderFinish(req->z, t2 - t1); } else { syslog(LOG_ERR, "Received request for map layer '%s' which failed to load", req->xmlname); ret = cmdNotDone; @@ -574,3 +584,4 @@ void *render_thread(void * arg) } return NULL; } + diff --git a/munin/renderd_zoom_time b/munin/renderd_zoom_time new file mode 100755 index 0000000..b2163e2 --- /dev/null +++ b/munin/renderd_zoom_time @@ -0,0 +1,76 @@ +#!/bin/sh +# +# Plugin to monitor the rendering throughput of Renderd +# +# Parameters: +# +# config (required) +# autoconf (optional - used by munin-config) +# + +if [ "$1" = "config" ]; then + + echo 'graph_title Renderd time spent by zoom' + echo 'graph_args --base 1000 -l 0' + echo 'graph_vlabel time spent per ${graph_period}' + echo 'graph_category renderd' + echo 'graph_info Displays the amount of time renderd has spent rendering tiles of a given zoom per ${graph_period}' + echo 'zoomtime1.label zoom z0 - z8' + echo 'zoomtime1.type DERIVE' + echo 'zoomtime1.min 0' + echo 'zoomtime1.cdef zoomtime1,1000,/' + echo 'zoomtime1.draw AREA' + echo 'zoomtime1.info Time for Metatiles z0 - z8' + echo 'zoomtime2.label zoom z9 - z12' + echo 'zoomtime2.type DERIVE' + echo 'zoomtime2.min 0' + echo 'zoomtime2.cdef zoomtime2,1000,/' + echo 'zoomtime2.draw STACK' + echo 'zoomtime2.info Time for Metatiles for z9 - z12' + echo 'zoomtime3.label zoom z13 - z14' + echo 'zoomtime3.type DERIVE' + echo 'zoomtime3.min 0' + echo 'zoomtime3.cdef zoomtime3,1000,/' + echo 'zoomtime3.draw STACK' + echo 'zoomtime3.info Time for Metatiles for z13 - z14' + echo 'zoomtime4.label zoom z15 - z16' + echo 'zoomtime4.type DERIVE' + echo 'zoomtime4.min 0' + echo 'zoomtime4.cdef zoomtime4,1000,/' + echo 'zoomtime4.draw STACK' + echo 'zoomtime4.info Time for Metatiles for z15 - z16' + echo 'zoomtime5.label zoom z17 - z18' + echo 'zoomtime5.type DERIVE' + echo 'zoomtime5.min 0' + echo 'zoomtime5.cdef zoomtime5,1000,/' + echo 'zoomtime5.draw STACK' + echo 'zoomtime5.info Time for Metatiles for z17 - z18' + + exit 0 +fi + +req0=`sed -e '/^TimeRenderedZoom00/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req1=`sed -e '/^TimeRenderedZoom01/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req2=`sed -e '/^TimeRenderedZoom02/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req3=`sed -e '/^TimeRenderedZoom03/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req4=`sed -e '/^TimeRenderedZoom04/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req5=`sed -e '/^TimeRenderedZoom05/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req6=`sed -e '/^TimeRenderedZoom06/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req7=`sed -e '/^TimeRenderedZoom07/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req8=`sed -e '/^TimeRenderedZoom08/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req9=`sed -e '/^TimeRenderedZoom09/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req10=`sed -e '/^TimeRenderedZoom10/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req11=`sed -e '/^TimeRenderedZoom11/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req12=`sed -e '/^TimeRenderedZoom12/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req13=`sed -e '/^TimeRenderedZoom13/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req14=`sed -e '/^TimeRenderedZoom14/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req15=`sed -e '/^TimeRenderedZoom15/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req16=`sed -e '/^TimeRenderedZoom16/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req17=`sed -e '/^TimeRenderedZoom17/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` +req18=`sed -e '/^TimeRenderedZoom18/!d' -e 's/.*: //' -e q /var/run/renderd/renderd.stats` + +echo "zoomtime1.value " `expr $req0 + $req1 + + $req2 + $req3 + $req4 + $req5 + $req6 + $req7 + $req8` +echo "zoomtime2.value " `expr $req9 + $req10 + + $req11 + $req12` +echo "zoomtime3.value " `expr $req13 + $req14` +echo "zoomtime4.value " `expr $req15 + $req16` +echo "zoomtime5.value " `expr $req17 + $req18` \ No newline at end of file