Works fine for me. You should really use 2 decimals for the time. I got 0.044s without PHP, 0.04s with PHP..

Hi, Jani. Thanks for looking into this so quickly. I will reciprocate by staying on top of this with equal eagerness; we have paying customers who would be very keen to see this fixed. I doubt that my problem is using only 1 decimal place, as the difference between 14 seconds and 84 seconds is not a subtle one. ;)

I find your result surprising, 0.04 seconds -- do you in fact have GDAL installed and are you manipulating a TIFF? The slowdown is with a task that takes some time; something like "ls" is trivial.

I would be glad to provide instructions on the installation of GDAL, as well as our test data and some other commands exhibiting this effect. I may be able to provide a server and root access as well.

Perhaps you can provide me the same image to test with, I tried with 
some file I had available. Apart from different file, I did exactly same 
as you. You didn't specify whether you run that test under some 
webserver or using PHP CLI?

> Perhaps you can provide me the same image to test with

The file is available for a short time at this URL:
   http://www.cartograph.com/images.tmp/2043.tif.gz
It's a 3 GB TIFF, but gzipped for faster download.


> Apart from different file, I did exactly same as you.

I find the result of 0.04 seconds fishy, though. I assume that you have GDAL installed when you run the test?


> You didn't specify whether you run that test under 
> some webserver or using PHP CLI?

Here's where we get into how I narrowed it down to being something about PHP and Apache.

run from shell - 14 seconds
PHP on CLI - 14 seconds
PHP as Apache DSO - 84 seconds
Perl CGI - 14 seconds

I would have to set up a dedicated test server in order to test other scenarios, such as disabling Zend Optimizer or running PHP as CGI. On our production server, those are not an option.

Note that the 14/84 test is for a shp2img using this same TIFF and a mapfile -- the gdal_translate was <1 second to 4 seconds. I will be glad to provide those as needed, if the gdal_translate test fails to replicate our results on your environment.

This proves it's not bug:
run from shell - 14 seconds
PHP on CLI - 14 seconds

And since you're using 3rd party extensions (Zend Optimizer) -> bogus.
Please contact Zend for support.

> This proves it's not bug:
> run from shell - 14 seconds
> PHP on CLI - 14 seconds

I disagree. It means that the bug is evident only when running under the webserver, which introduces a few more variables.


> And since you're using 3rd party extensions (Zend Optimizer)
>  -> bogus. Please contact Zend for support.

I have disabled Zend Optimizer. It had no effect on the times at all: 13-15 for CLI, 80-85 for the same command being run in a ten-line PHP program.

Any exec() function implies fork(). This means the apache process (and potentially all its threads) have to be forked before the exec().

This may explain the time it takes (and this is why apache2 as a separate daemon to spawn CGI processes).

It could also be a memory issue.  The fork overhead would be a constant on all shell execs.  However, manipulating a large image is a memory-intensive operation.  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.  But again, I don't see how this could be called a PHP issue.  Check your per-process limits and see if increasing them makes a difference.

> lbarnaud@php.net
> 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.


> rasmus@php.net
> 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.

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.

> 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.

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\200@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\200@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, "zE4wB3wA4x@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.

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.

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.

Our workaround is rather crude: I wrote a Perl CGI program, then have our PHP program run generate an URL to it and call file_get_contents() to collect the output. This is rather barbaric, but if PHP's exec() family runs at 1/6 speed, it seems our only option.

This issue occurs only in PHP, and only when running as an Apache DSO. The issue does not occur with CGI programs in Perl or Bourne shell, so is not Apache's environment but something in how PHP and Apache work together. As such, the sentiment that "once we call exec() it's not our problem" seems less than productive.

I am glad to continue working on it, as we would be most eager to see a real diagnosis and fix for this.

15/08/2014 Same problem. It's a bug.

TL;DR this problem does not occur in php-fpm 

Just for the record, I did some testing with Imagick cmd line calls: (the  Fill Area Flag "^" is not supported via Imagick extension) 

convert img.jpg -resize 200x200^ -gravity center -extent 200x200 thumb.jpg

100 operations on a 2MB jpeg image. Results below:

bash loop: for i in {1..100}; do convert ... ; done   : 4.4s
php-cli  : for ($i = 0; $i<100; $i++) { exec($cmd); } : 4.4s
php-fpm  : for ($i = 0; $i<100; $i++) { exec($cmd); } : 4.4s

No difference whatsoever for this workload in the 3 environments. 

- No slow performance of "convert" 
- shell forking for each exec() call is insignificant for this test case

php -v
PHP 7.2.1

Moral of story: Who runs php on apache anyway? Use nginx/lighttpd + php-fpm!

> Moral of story: Who runs php on apache anyway? Use nginx/lighttpd + php-fpm!

laughable attitude! 

php-fpm brings a ton of other troubles (php-options per directory/htaccess and so on) and as long as a benchmark on a 6 years old 4-core desktop machine with current patchlevel (metldown/spectre) shows 10000 requests/second on our core-cms show me *one* valid reason for rebuild many hundret of vhost-configs with your perfered toy

@ spam2 at rhsoft dot net 

Ok, calm down. The final comment was intended as a "joke", thought that might have been obvious? I know that php's most popular deployment SAPI is still apache, probably.

Your usage is 100% opposite from ours. We have multiple own-iron app-servers running the same app for a single domain/app with load balancer in front.

So we switched from apache 15yrs ago and never looked back. Hence the joke. 
The whole php process per webserver process/worker is completely unsuitable for our type of usage, so php-fpm was the obvious choice. 

Peace and love...enjoy.

I believe i have solved this, it is not an out right problem with either PHP or apache, rather a process prioritization problem that cane be solved by adding `nice -n -20' before the command to be executed. for the full answer see https://stackoverflow.com/questions/14277910/php-exec-performance/48505455#48505455

https://stackoverflow.com/questions/14277910/php-exec-performance/48505455#48505455 is nonsense because the command on the left side is ececuted and than the output piped to "nice" which is way too late

and no webserver setup would allow "sudo" anyways

You are correct, i had to add the user apache was running as a sudoer, i know this is not optimal. Maybe there is a was to allow the apache user to run nice without the sudo, but that is not the point.

The slowness of exec() is do to low process priority and is not actually a bug in either PHP or apache.

@ spam2 at rhsoft dot net

> https://stackoverflow.com/questions/14277910/php-exec-performance/48505455#48505455 is nonsense 
> because the command on the left side is ececuted and than the output piped to "nice" which is way too late

No. Your comment is nonsense. How can someone be so arrogrant, rude and clueless at the same time? 

2nd time in a fortnight. 

Please think before you post!

oliver at openbrackets dot net: when it's about the shell startup-time implicitly done by exec() itself it is too late - period

fortwebsolutions at gmail dot com: "to run the apache user with nice" just start httpd itself with nice in front - niceness is inherited - or on a modern system:

/etc/systemd/system/httpd.service.d:
[Service]
Nice=-15

-20 is a bad idea anyways

Same problem. It's a bug. php version 7.2.5

Hello,

Bug always present in PHP 7.3 ... request take a long time with shell_exec, but not in bash. 

Please..