Add more debug/tuning output to mapserv

[dmorissette]

At the moment, with debug level 2 (tuning), we only get the map loading and map rendering time but other times such as the time spent ins msSaveImage() is not logged. This ticket is to add more timing output at debug level 2 in mapserv.c to help in tuning maps.

[dmorissette]

Done in r7769.

Added logging of the total processing time, taken from immediately after the map is done loading and until end of execution. e.g.

[Wed Jul  2 10:07:42 2008].7920 msLoadMap(): 0.095s
[Wed Jul  2 10:07:42 2008].33956 msDrawMap(): Layer 9 (popplace), 0.001s
[Wed Jul  2 10:07:42 2008].69084 msDrawMap(): Drawing Label Cache, 0.035s
[Wed Jul  2 10:07:42 2008].69095 msDrawMap() total time: 0.046s
[Wed Jul  2 10:07:42 2008].90373 msSaveImage() total time: 0.021s
[Wed Jul  2 10:07:42 2008].90436 mapserv request processing time (loadmap not incl.): 0.082s

To get the overall execution time, add the "msLoadMap()" number and the "mapserv request processing time" number. In the example above: the overall execution time is approximately 0.095+0.082=0.177s

If you set the MS_DEBUG and MS_ERRORFILE environment variables in your web server then mapserv will log the overall execution time with a line like this at the end of the output:

[Wed Jul  2 10:07:42 2008].90522 mapserv total execution time: 0.178s

[jmckenna]

question: the average user won't know to add msLoadMap and request processing time (so you have created a total when using env variables)...but what about a total for the commandline users?

[dmorissette]

By commandline, do you mean shp2img? This ticket adds this output to mapserv (the CGI) only... we'd need to explicitly add the same to shp2img if that's what you are talking about.

[jmckenna]

yes I was referring to shp2img. I think a total would be an excellent enhancement. Should I open another ticket for that?

[jmckenna]

shp2img currently outputs a "msDrawMap() total time"....so maybe my comments are invalid?

[dmorissette]

I have modified shp2img in r7770 to produce a total as well is "-all_debug 2" is used. e.g.

[Wed Jul  2 11:32:20 2008].144765 msLoadMap(): 0.128s
[Wed Jul  2 11:32:20 2008].146236 msDrawMap(): Layer 9 (popplace), 0.001s
[Wed Jul  2 11:32:20 2008].187407 msDrawMap(): Drawing Label Cache, 0.041s
[Wed Jul  2 11:32:20 2008].187419 msDrawMap() total time: 0.043s
[Wed Jul  2 11:32:20 2008].189936 msSaveImage() total time: 0.003s
[Wed Jul  2 11:32:20 2008].190016 shp2img total time: 0.173s

[jmckenna]

question: why is the shp2img total-time addition only applied to "-all_debug" and not "-map_debug" also?

[dmorissette]

Because the total-time starts counting before the map is loaded (to include the map loading time), but -map_debug sets the map->debug value and this value is set only *after* the map is loaded. At that time it's too late to initialize the 'total-time' counter.

Of course since shp2img is only a test/debug'ing utility it may not hurt to always init the total-time counter before loading the mapfile and reporting the value only if one of all_debug or map_debug or map->debug (in the mapfile) is set, but even if that change sounds awfully simple it's too late for this in 5.2, I have exceeded my quota of build problems in beta4 so I would suggest you file a enhancement ticket to add this in 5.4.