Stack trace from timing out PHP MapScript CGI

Wed Nov 17 11:42:49 EST 2004

Doug -

Having "top" not show 100% CPU use is "normal" if the CPU is NOT the problem.  That would be the case, for example, if your disk subsystem were the bottleneck.  You should definitely find out as much detail as you can about your disk arrangement.  A single IDE drive will have a hard time handling a large number of random requests, for example, which seems to be consistent with the symptom you're seeing.  There could be other causes, of course, but it's worth looking into this one.

You should also know whether those disks are doing OTHER things at the same time, or if they're dedicated to MapServer data serving.

        - Ed

Ed McNierney
President and Chief Mapmaker
TopoZone.com / Maps a la carte, Inc.
73 Princeton Street, Suite 305
North Chelmsford, MA  01863
Phone: +1 978 251-4242   Fax: +1 978 251-1396

-----Original Message-----
From: UMN MapServer Users List [mailto:MAPSERVER-USERS at LISTS.UMN.EDU] On Behalf Of Doug
Sent: Wednesday, November 17, 2004 10:12 AM
To: MAPSERVER-USERS at LISTS.UMN.EDU
Subject: Re: [UMN_MAPSERVER-USERS] Stack trace from timing out PHP MapScript CGI

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
> stackup 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.7841351597, 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
>
>