Ticket #2673 (closed defect: fixed)

Opened 3 months ago

Last modified 3 months ago

Add more debug/tuning output to mapserv

Reported by: dmorissette Assigned to: dmorissette
Priority: normal Milestone: 5.2 release
Component: MapServer C Library Version: unspecified
Severity: normal Keywords:
Cc: sdlime, jmckenna

Description

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.

Change History

07/02/08 10:25:59 changed by 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

07/02/08 10:26:03 changed by dmorissette

  • status changed from new to closed.
  • resolution set to fixed.

07/02/08 10:32:02 changed by jmckenna

  • cc changed from sdlime to sdlime, 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?

07/02/08 10:42:33 changed by 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.

07/02/08 10:44:34 changed by jmckenna

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

07/02/08 10:47:31 changed by jmckenna

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

07/02/08 11:36:08 changed by 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

07/03/08 11:05:52 changed by jmckenna

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

07/03/08 14:09:13 changed by 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.