Bug #48403 [Com]: shell_exec() is much slower than running from shell

Edit report at https://bugs.php.net/bug.php?id=48403&edit=1 ID: 48403 Comment by: oliver at openbrackets dot net Reported by: gregor at hostgis dot com Summary: shell_exec() is much slower than running from shell Status: Not a bug Type: Bug Package: Performance problem Operating System: Linux PHP Version: 5.2.9 Block user comment: N Private report: N New Comment: 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! Previous Comments: ------------------------------------------------------------------------ [2014-08-15 13:08:36] info at sistemasgsl dot com 15/08/2014 Same problem. It's a bug. ------------------------------------------------------------------------ [2009-06-01 23:23:00] gregor at hostgis dot com 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. ------------------------------------------------------------------------ [2009-05-28 04:34:04] gregor at hostgis dot com 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. ------------------------------------------------------------------------ [2009-05-27 23:03:07] rasmus@php.net 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\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. ------------------------------------------------------------------------ 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 https://bugs.php.net/bug.php?id=48403 -- Edit this bug report at https://bugs.php.net/bug.php?id=48403&edit=1