ID: 48403 User updated by: gregor at hostgis dot com Reported By: gregor at hostgis dot com Status: Bogus Bug Type: Performance problem Operating System: Linux PHP Version: 5.2.9 New Comment:
I get "current: -1 max: -1" in all cases. # su - www -c "/var/www/cgi-bin/foof" current: -1 max: -1 # curl http://localhost/cgi-bin/foof current: -1 max: -1 # php foof.php current: -1 max: -1 # curl http://localhost/~gregor/foof.php current: -1 max: -1 I agree, it's something about the shell environment which PHP sets up. The same command in a bash CGI doesn't do this, so it's not Apache forking, but PHP forking under Apache. Previous Comments: ------------------------------------------------------------------------ [2009-05-27 23:03:07] [email protected] That points to memory thrashing to me. The brk calls are fiddling with the data segment size. Compile this little test: #include <stdio.h> #include <sys/time.h> #include <sys/resource.h> int main() { struct rlimit rlim; getrlimit(RLIMIT_DATA,&rlim); printf("current: %ld max: %ld\n",rlim.rlim_cur,rlim.rlim_max); } And shell-exec that from php-cli and from php-apache and see what you get. Just want to double check that you are indeed running in the same environment in both. You could also check removing all ulimits from the php-apache environment and see if that makes a difference. It still isn't something we can fix here. By the time you have done the fork+exec, PHP is out of the picture. It is down to the OS and the environment the shell exec is running in at that point, so you need to figure out how that environment differs between the two. ------------------------------------------------------------------------ [2009-05-27 22:41:47] gregor at hostgis dot com This is the shp2img debugging output. Not surprisingly, all of the time is spent in that one block, where strace indicates that it's reading from the source file. [Wed May 27 15:03:48 2009].37407 msLoadMap(): 0.005s [Wed May 27 15:03:48 2009].38982 msDrawRasterLayerLow(TVA_20090112): entering. [Wed May 27 15:03:48 2009].51233 msDrawGDAL(): src=0,8546,36257,23683, dst=46,0,300,196 [Wed May 27 15:03:48 2009].51283 msDrawGDAL(): red,green,blue,alpha bands = 1,2,3,0 GM - HERE'S THE MAJOR TIME DELAY [Wed May 27 15:05:20 2009].540097 msDrawMap(): Layer 0 (TVA_20090112), 92.502s [Wed May 27 15:05:20 2009].540769 msDrawMap(): Drawing Label Cache, 0.001s [Wed May 27 15:05:20 2009].540788 msDrawMap() total time: 92.503s [Wed May 27 15:05:20 2009].541477 msSaveImage() total time: 0.175s [Wed May 27 15:05:20 2009].541729 msFreeMap(): freeing map at 0x64a9e0. [Wed May 27 15:05:20 2009].541779 shp2img total time: 92.509s [Wed May 27 15:01:06 2009].116590 msLoadMap(): 0.004s [Wed May 27 15:01:06 2009].118137 msDrawRasterLayerLow(TVA_20090112): entering. [Wed May 27 15:01:06 2009].121616 msDrawGDAL(): src=0,8546,36257,23683, dst=46,0,300,196 [Wed May 27 15:01:06 2009].121656 msDrawGDAL(): red,green,blue,alpha bands = 1,2,3,0 GM - HERE'S THE MAJOR TIME DELAY [Wed May 27 15:01:20 2009].873917 msDrawMap(): Layer 0 (TVA_20090112), 14.756s [Wed May 27 15:01:20 2009].874566 msDrawMap(): Drawing Label Cache, 0.001s [Wed May 27 15:01:20 2009].874585 msDrawMap() total time: 14.758s [Wed May 27 15:01:21 2009].58318 msSaveImage() total time: 0.184s [Wed May 27 15:01:21 2009].58650 msFreeMap(): freeing map at 0x64a9e0. [Wed May 27 15:01:21 2009].58702 shp2img total time: 14.946s Now for clips of the strace output, which I find very odd. This is immediately after it prints the bands, where it is reading the source file. The PHP-Apache version has A LOT of extra brk() calls, and they are 6X as long as the brk()s in the CLI version. Hmmmm? CLI version: 0.000060 mmap(NULL, 200704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2ba65f6db000 0.000039 lseek(4, 228401152, SEEK_SET) = 228401152 0.000032 read(4, "\'n5(n6)l2)j.)l+)k)\'i+\'j1+p:3yF=\204"..., 4096) = 4096 0.000042 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 192512) = 192512 0.000291 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096 0.000652 lseek(4, 228601856, SEEK_SET) = 228601856 0.000033 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 192512) = 192512 0.000154 read(4, "-eT/eT0aO0[G,R=(J4$I3\"M8!O; M: I"..., 4096) = 4096 0.000470 brk(0x7b2000) = 0x7b2000 0.000053 lseek(4, 228798464, SEEK_SET) = 228798464 0.000040 read(4, "|M7|N8\177N6\203P5\211R8\211S:\205Q;\204R<\206S9\206R5"..., 192512) = 192512 0.000157 read(4, "8vL4zS3~\\3~`3x]2qU2jJ3gB3hB3mJ2u"..., 4096) = 4096 0.000449 lseek(4, 228995072, SEEK_SET) = 228995072 0.000038 read(4, "\223Q?\221O>\216L<\211g8\205b4\...@2t?/d4(U% O\33\34L\26"..., 192512) = 192512 0.000161 read(4, "\315\362\316\320\362\314\322\361\310\321\361\305\316\360"..., 4096) = 4096 0.000466 lseek(4, 229191680, SEEK_SET) = 229191680 0.000035 read(4, "\321\207_\330\215d\330\214e\324\207b\317\201^\310{[\300"..., 192512) = 192512 0.000150 read(4, "H\253eH\257jJ\261nM\262mP\265kP\274nQ\305sV\311x[\311{"..., 4096) = 4096 0.000465 brk(0x7e2000) = 0x7e2000 Apache version: 0.000066 mmap(NULL, 200704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2b7a32a0d000 0.000035 lseek(44, 228401152, SEEK_SET) = 228401152 0.000024 read(44, "\'n5(n6)l2)j.)l+)k)\'i+\'j1+p:3yF=\204"..., 4096) = 4096 0.000039 read(44, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 192512) = 192512 0.000307 read(44, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4096) = 4096 0.001006 brk(0x7b8000) = 0x7b8000 0.001624 brk(0x7e8000) = 0x7e8000 0.000043 lseek(44, 228601856, SEEK_SET) = 228601856 0.000027 read(44, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 192512) = 192512 0.000142 read(44, "-eT/eT0aO0[G,R=(J4$I3\"M8!O; M: I"..., 4096) = 4096 0.002333 brk(0x818000) = 0x818000 0.000052 lseek(44, 228798464, SEEK_SET) = 228798464 0.000028 read(44, "|M7|N8\177N6\203P5\211R8\211S:\205Q;\204R<\206S9\206R5"..., 192512) = 192512 0.000161 read(44, "8vL4zS3~\\3~`3x]2qU2jJ3gB3hB3mJ2u"..., 4096) = 4096 0.002332 brk(0x848000) = 0x848000 0.000050 lseek(44, 228995072, SEEK_SET) = 228995072 0.000028 read(44, "\223Q?\221O>\216L<\211g8\205b4\...@2t?/d4(U% O\33\34L\26"..., 192512) = 192512 0.000158 read(44, "\315\362\316\320\362\314\322\361\310\321\361\305\316\360"..., 4096) = 4096 0.002320 brk(0x878000) = 0x878000 0.000045 lseek(44, 229191680, SEEK_SET) = 229191680 0.000026 read(44, "\321\207_\330\215d\330\214e\324\207b\317\201^\310{[\300"..., 192512) = 192512 0.000138 read(44, "H\253eH\257jJ\261nM\262mP\265kP\274nQ\305sV\311x[\311{"..., 4096) = 4096 0.002317 brk(0x8a8000) = 0x8a8000 0.000050 lseek(44, 229388288, SEEK_SET) = 229388288 0.000034 read(44, "ze4wb3w...@6v<7v;7{?8\177E6\202G3\204G3\203F"..., 192512) = 192512 0.000143 read(44, "6j>5f=2b:.`6*[4)U2&O/\"L-\37J*\37J)\37L"..., 4096) = 4096 0.002322 brk(0x8d8000) = 0x8d8000 Am I reading this right? When run from CLI, it does 3 sets of seek and read then a brk for 470us. When run from Apache, it does 1 seek and read then a brk for 2300us. ------------------------------------------------------------------------ [2009-05-27 22:36:25] gregor at hostgis dot com > 1. Higher memory footprint for Apache+PHP which means > less memory left for the shell exec I'd think that 1024MB would be enough for a 60MB process! But, see below for some very interesting strace results. > 2. Different non-privileged user id, most likely which > could affect where temp files are stored and such Doesn't affect the tempfile storage, and the system only has the one disk array and no ramdisks) so all places would be equally fast. I'm also the sysadmin, I know their hardware pretty well. > 3. If you are running your Apache in a vm or a chroot > environment, things might be very different there Nope. Again, I'm the sysadmin and I did not configure it as such. > 4. You will probably have less file descriptors available > to you, so if your shell exec needs a lot, it may be starved User 'www' gets the same 1024 FDs as everybody else. I verified that way back, by su'ing to www and running the same command and PHP apps from Bash, PHP CLI, and Apache. The output of 'ulimit -a' is identical for user www and for my regular account. > Comparing the strace output from > the two along with some intermediate timings > as you mentioned would be interesting. Coming right up, and boy is it interesting. ------------------------------------------------------------------------ [2009-05-27 22:07:29] [email protected] Interesting. So, the differences between the fork+exec from PHP-CLI and PHP-Apache might be: 1. Higher memory footprint for Apache+PHP which means less memory left for the shell exec 2. Different non-privileged user id, most likely which could affect where temp files are stored and such 3. If you are running your Apache in a vm or a chroot environment, things might be very different there 4. You will probably have less file descriptors available to you, so if your shell exec needs a lot, it may be starved of those That's all I can think of right now. Comparing the strace output from the two along with some intermediate timings as you mentioned would be interesting. ------------------------------------------------------------------------ [2009-05-27 22:01:59] gregor at hostgis dot com > [email protected] > Any exec() function implies fork() > This may explain the time it takes I'm not sure I follow you. When I watch the 'top' and 'ps axu' output, the shp2img or gdal_translate task is running the whole time. It is not spending 68 seconds forking and then running the job in 14 seconds. This same program from CLI, does not exhibit this slow execution. If fork() is being slow, surely it would affect the CLI version? And if I run the shp2img command from a four-line Bourne shell CGI script, it runs in 14 seconds -- that seems to eliminate Apache and fork() as likely culprits. What I find bizarre, is that the shp2img process has exactly the same 'top' and 'ps axu' output in both cases: 59 MB RSS, 115 MB VSZ, 9.8 MB shared memory, 99-100% CPU. Overall system CPU usage hovers at 40%, with only flickers of "wait" -- this too is identical regardless of how shp2img is started. > [email protected] > It could also be a memory issue. > If you are running up against the per-process memory-limit > then the code may run much slower as it has to > try to do the same image operations in less memory. I have memory_limit set to 256 MB Since shp2img for this case uses 60 MB, this should be plenty. Still, I have upped it to 1024 MB (we have a lot of RAM to play with) and this had no effect. I will run some profiling/timing stuff from within shp2img, since its debug output includes tmestamps, and get back to you with those. ------------------------------------------------------------------------ The remainder of the comments for this report are too long. To view the rest of the comments, please view the bug report online at http://bugs.php.net/48403 -- Edit this bug report at http://bugs.php.net/?id=48403&edit=1
