Stack trace from timing out PHP MapScript CGI

[Doug]

Thanks for the ideas.

"top" does show 100% CPU use when the requests are being serviced.  Don't know
if that's normal.  Again, this is on Fedora Core 2 with a dual-CPU, 2GHz P4
machine.  I'm not sure of the disk arrangement, but I can find that out.  I'll
also see if we can run the Postgres queries directly.

Gregory S. Williamson wrote:
> Doug,
>
> Don't know much about PHP or the possible issues of Mapserver itself, but I'd check the postgres side of things by running equivalent SQL with "EXPLAIN ANALYZE" to make sure that indexes are being used and that its returning an appropriate number of rows. You might also try running the same queries against postgres simultaneously and see if the response bottleneck is there. If it is you might post back the results; if the response is snappy from postgres itself then it would seem the delay might be elsewhere, or in a combination of postgres and mapserver fighting for disk i/o.
>
> You might also post some details about the server(s) being used, # of CPUS, OS, disk arrangement etc. Sometimes running top or other diagnostics will help isolate where the problem is.
>
> HTH,
>
> Greg Williamson
> DBA
> GlobeXplorer LLC
>
>
> -----Original Message-----
> From:   Doug [mailto:ummmmm at MYREALBOX.COM]
> Sent:   Tue 11/16/2004 2:02 PM
> To:     MAPSERVER-USERS at LISTS.UMN.EDU
> Cc:
> Subject:        [UMN_MAPSERVER-USERS] Stack trace from timing out PHP MapScript CGI
> I posted here a couple of weeks ago asking about our CGI PHP MapScript
> application that appears to quit responding periodically.
> <http://lists.umn.edu/cgi-bin/wa?A2=ind0410&L=mapserver-users&T=0&F=&S=&X=30762F284AB96B2313&P=50619>
> Context refresher:
>
> MapServer/MapScript 4.2.5, PHP 4.3.8 (cgi), PostgreSQL 7.4.3, PostGIS 0.8.2,
> Apache 2.0.51, Fedora Core 2 SMP (Dual CPU 2GHz P4).
>
> Application posts to PHP file, which does a map->draw() (of shapefile layers),
> followed by a couple of queryByRect() on non-shown (PostGIS) layers, manual
> point->draw()s with custom, numbered labels, then a map->save().
>
> I had observed that regularly the PHP processes seem to hang or stall, so
> somebody on #Mapserver suggested that I compile with debug options and try to
> obtain a stack trace when this happens.
>
> Unfortunately, I've been unable to duplicate the exact situation, but I have
> seen some similar ones where client requests to the PHP CGIs stack up and time
> out.  In fact, I can force that to happen simply by getting several clients to
> make a simultaneous request of the server.  Today, I forced 7 such
> simultaneous requests, and every single one of them timed out.  Normally, when
> this kind of condition occurs, the MapServer stderr also reports:
>
> [Mon Nov 15 21:17:39 2004] [error] [client 32.83.226.185] PHP Fatal error:
> Maximum execution time of 30 seconds exceeded in var/www/html/offender/map.php
> on line 87
>
> But this didn't happen in my forced test today.  i.e. my clients timed out,
> but the PHP CGIs didn't seem to.  Obviously, I need to play with either my
> client or server timeouts, but can anything useful be determined by these
> stack traces?:
>
>  From last night's "natural" slowdown (which was so bad that most/all requests
> during a 30 minute period timed out):
>
> #0  0x00ac8402 in ?? ()
> #1  0x005e11ea in lseek64 () from /lib/tls/libc.so.6
> #2  0x00581a37 in _IO_file_seek_internal () from /lib/tls/libc.so.6
> #3  0x0058175a in _IO_new_file_seekoff () from /lib/tls/libc.so.6
> #4  0x00578a2a in _IO_seekoff_unlocked () from /lib/tls/libc.so.6
> #5  0x0057e08d in fseek () from /lib/tls/libc.so.6
> #6  0x0030b5c2 in msSHPReadBounds (psSHP=0x8f0d858, hEntity=36339712,
> padBounds=0xfef2dd70) at mapshape.c:1163
> #7  0x0030bb32 in msSHPWhichShapes (shpfile=0x8fcebc0, rect= {minx =
> 511572.85125965299, miny = 3562542.8004036499, maxx = 513272.85125965299, maxy
> = 3563562.8004036499}, debug=0) at mapshape.c:1338
> #8  0x0032e14a in msLayerWhichShapes (layer=0x8d92198, rect= {minx =
> 511572.85125965299, miny = 3562542.8004036499, maxx = 513272.85125965299, maxy
> = 3563562.8004036499}) at maplayer.c:198
> #9  0x00330a02 in msDrawVectorLayer (map=0xf6ff3008, layer=0x8d92198,
> image=0x8f0e7e0) at mapdraw.c:751
> #10 0x00330711 in msDrawLayer (map=0xf6ff3008, layer=0x8d92198,
> image=0x8f0e7e0) at mapdraw.c:639
> #11 0x00330028 in msDrawMap (map=0xf6ff3008) at mapdraw.c:317
> #12 0x0030006f in mapObj_draw (self=0xf6ff3008) at mapscript_i.c:419
> #13 0x002f2279 in php3_ms_map_draw (ht=0, return_value=0x8d550ac,
> this_ptr=0x8d5502c, return_value_used=1) at php_mapscript.c:3311
> #14 0x0811dcfa in execute (op_array=0x8d650d4) at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1635
> #15 0x0811dac9 in execute (op_array=0x8d425dc) at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1679
> #16 0x0811dac9 in execute (op_array=0x8d3ef8c) at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1679
> #17 0x08112fd3 in zend_execute_scripts (type=8, retval=0x0, file_count=3) at
> /usr/src/php-4.3.8/Zend/zend.c:891
> #18 0x080f089c in php_execute_script (primary_file=0xfef30780)at
> /usr/src/php-4.3.8/main/main.c:1734
> #19 0x081220b2 in main (argc=1, argv=0xfef30844) at
> /usr/src/php-4.3.8/sapi/cgi/cgi_main.c:1592
>
>  From today's artificial one (which lasted less than a minute after the
> simultaneous requests were finished):
>
> #0  0x005fc7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
> #1  0x0050f85a in lseek64 () from /lib/tls/libc.so.6
> #2  0x004afbf7 in _IO_file_seek_internal () from /lib/tls/libc.so.6
> #3  0x004af91a in _IO_new_file_seekoff () from /lib/tls/libc.so.6
> #4  0x004a6bea in _IO_seekoff_unlocked () from /lib/tls/libc.so.6
> #5  0x004ac24d in fseek () from /lib/tls/libc.so.6
> #6  0x0080c5c2 in msSHPReadBounds (psSHP=0x9d5e190, hEntity=63127552,
> padBounds=0xfeebf8a0) at mapshape.c:1163
> #7  0x0080cb32 in msSHPWhichShapes (shpfile=0x9e1f860, rect={minx =
> 400998.78413511597, miny = 3697149.2200513999, maxx = 402698.78413511597, maxy
> = 3698169.2200513999}, debug=0) at mapshape.c:1338
> #8  0x0082f14a in msLayerWhichShapes (layer=0x9be1d60, rect={minx =
> 400998.78413511597, miny = 3697149.2200513999, maxx = 402698.78413511597, maxy
> = 3698169.2200513999}) at maplayer.c:198
> #9  0x00831a02 in msDrawVectorLayer (map=0xf6fc4008, layer=0x9be1d60,
> image=0x9d5e388) at mapdraw.c:751
> #10 0x00831711 in msDrawLayer (map=0xf6fc4008, layer=0x9be1d60,
> image=0x9d5e388) at mapdraw.c:639
> #11 0x00831028 in msDrawMap (map=0xf6fc4008) at mapdraw.c:317
> #12 0x0080106f in mapObj_draw (self=0xf6fc4008) at mapscript_i.c:419
> #13 0x007f3279 in php3_ms_map_draw (ht=0, return_value=0x9ba4254,
>      this_ptr=0x9ba41d4, return_value_used=1) at php_mapscript.c:3311
> #14 0x0811dcfa in execute (op_array=0x9bb4c84)  at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1635
> #15 0x0811dac9 in execute (op_array=0x9b917dc)  at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1679
> #16 0x0811dac9 in execute (op_array=0x9b8deec) at
> /usr/src/php-4.3.8/Zend/zend_execute.c:1679
> #17 0x08112fd3 in zend_execute_scripts (type=8, retval=0x0, file_count=3) at
> /usr/src/php-4.3.8/Zend/zend.c:891
> #18 0x080f089c in php_execute_script (primary_file=0xfeec22b0) at
> /usr/src/php-4.3.8/main/main.c:1734
> #19 0x081220b2 in main (argc=1, argv=0xfeec2374) at
> /usr/src/php-4.3.8/sapi/cgi/cgi_main.c:1592
>
> Basically, it seems that it takes very few simultaneous requests for our
> system to fall behind.  If it gets even more requests than that minimum, it
> seems to be unable to recover for sometimes half an hour or more.
>
> I've seen people claiming very good performance of similar applications on
> slower systems, so I'm trying to understand what could be causing this behaviour.
>
> Here's hoping the stack traces will at least help us pinpoint the likely
> cuplrit(s).
>
> Doug
>
>