Stack trace from timing out PHP MapScript CGI

Wed Nov 17 11:26:29 PST 2004

Too many negatives in that sentence for me :-)  You're saying that 100% CPU
utilization is normal if the CPU is the bottleneeck or if it's something else?

I checked and I think we have a single SCSI (/dev/sda) disk in use at this
time.  Looks like there are two disks on the system, but I don't think the
second one is allocated at all.

There really shouldn't be any other significant activity on the system other
than the MapServer HTTP requests (and the subsequent HTTP requests for the
generated map images).  In addition to this PHP MapScript application, we do
have two other "mapserv"-only applications using this same MapServer, one of
which shares some of the same shapefiles.  But that's pretty much all this
machine is doing.

Doug

Ed McNierney wrote:
> 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