#2673 closed defect (fixed)
Add more debug/tuning output to mapserv
Reported by: | dmorissette | Owned by: | 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 (9)
comment:1 by , 16 years ago
comment:2 by , 16 years ago
Resolution: | → fixed |
---|---|
Status: | new → closed |
comment:3 by , 16 years ago
Cc: | added |
---|
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?
comment:4 by , 16 years ago
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.
comment:5 by , 16 years ago
yes I was referring to shp2img. I think a total would be an excellent enhancement. Should I open another ticket for that?
comment:6 by , 16 years ago
shp2img currently outputs a "msDrawMap() total time"....so maybe my comments are invalid?
comment:7 by , 16 years ago
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
comment:8 by , 16 years ago
question: why is the shp2img total-time addition only applied to "-all_debug" and not "-map_debug" also?
comment:9 by , 16 years ago
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.
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.
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: