Layer timings in map->debug mode

[refractions]

By writing out the time required to
- open data sources
- query data sources
- fetch features
- draw features
- close data sources
for each layer processed, users can more easily tune their map files and
understand where their performance bottlenecks are. That will lead to faster map
files and make mapserver look even better than it does now!
This is probably best done for the map->debug flag rather than the layer->debug
flag, since timings are really most useful in comparison with each other.

[woodbri@…]

Paul, this looks great! I would love to see this implemented. Here are some
additiona thoughts I posted to the list about this:

So I am back to trying to do some performance tuning of my mapfiles. On 
my layer post someone suggested using DEBUG ON. I think this is or a 
similar mapfile option is the correct approach. Unfortunately, on 
Mapserver 4.01, DEBUG ON was less than helpful. I only got a single line:

Mon Jan 10 14:57:21 
2005,3687,192.168.1.211,north_america_v40,3,-71.460613 42.571728 
-71.317747 42.666972,-71.389180 42.619350,all ,normal execution

I turned on layer in the MAP .. END block and in every LAYER .. END 
block but only got the above single line for a map drawn. So adding 
DEBUG ON to the layers gave me no additional information about the 
layer. In fact, when I got a parse error in the mapfile I did not get a 
record in the logfile.

This is a fairly old version of mapserver and maybe this has changed in 
the newer versions, may be not.

At any rate, here is what I would like to see:

1) execution time(s) for every block the has DEBUG ON, so if I only have 
it in the MAP block I only get a summary, if I have it in a LAYER block 
than I get detailed stats about that layer.
2) number of connections/shapefiles opened by block
3) number of objects drawn by block, maybe also the number of objects 
scanned and not drawn
4) the map scale as drawn

With these basic stats, it would be easy for us to make changes to the 
mapfile and evaluate the impact of the changes.

Why these stats? Well time is somewhat obvious, we need to identify what 
is taking up time. Connections or shapefiles opened will tell us how 
well our data is organized and how our tileindexes are working or not. 
And finally, the number of object that are being drawn, may tell us 
where we might want to thin out the detail, and scale helps us relate it 
to our mapfile since it works based on MIN/MAXSCALE.

I would be happy to have additional stats also if you think there are 
others that would help with performance tuning.

Output formats! Ideally it should be easy to parse the log file with 
Perl. I don't have a problem with multiple lines as ling as there a 
unique id the tie the lines together, like

date, uid, "map", map_name, bbox, scale, exec_time, etc
date, uid, "layer", layer_number, layer_name, exec_time, files, objects

I will follow up by creating a bug with this same request.

By the way, I have been running siege and bombard ( 
http://www.joedog.org/siege/ ) to stress test my servers and evaluate 
performance at each zoom scale for all my mapfiles. Now that I know 
where my problems lie, I am trying to fix them, but I am finding it is 
really hard to know what is causing the performance issues or even which 
of my 100 layers are causing it. It is really dumb, but I now have to 
guess which layers might be the problem and delete a layer at a time, 
run a 10-20 min stress test and repeat for all suspect layers to see 
which ones are cause what type of impact. If I had the logging tools 
above, I could run a stress test, summarize it with Perl and know 
exactly what layer(s) need to be focused on.

[jmckenna]

wasn't this addressed with ticket#2673 and other 5.x closed tickets?

[woodbri]

Jeff,

This is partially covered by the changes addressed in #2673, but I do not think that we return any stats on numbers of shapefiles or number of shapes read from each shapefile, which would be useful to have for understanding how well your data is organized on disk. I'm OK, if you want to close this because what we have is way better than what we had in the past when this was written.

[pramsey]

Logging the number of features will probably require an addition to the layerinfo so the information can get passed back up to the msDrawMap routine by the specific drivers. Knowing now many features go into a layer is a useful performance tuning metric, but the change would be a bit invasive. This probably calls for a new issue or RFC if it's a high priority.