|
|
php.net | support | documentation | report a bug | advanced search | search howto | statistics | random bug | login |
[2009-05-27 07:37 UTC] gregor at hostgis dot com
Description: ------------ Commands executed via shell_exec() take a lot longer to run than when run directly from the Unix shell. In the example code below, a task that takes 0.5-0.7 seconds takes 5 seconds. This effect is reliable, and a given task's "how much longer it takes than it should" ratio seems constant. In the simple case below, it takes 8-10 times longer than it should. For a specific more complex test case at our side, the task consistently takes 14 seconds from shell and 83 seconds from shell_exec() This effect is apparently identical for the entire family of process-handling functions: passthru, exec, shell_exec, and popen all show the exact same "slowness multipliers" as described above. This report may be similar to http://bugs.php.net/bug.php?id=15746 However, this is for Linux systems and not specific to Windows NT or NETPBM. Reproduce code: --------------- <?php // gdal_translate converts GIS data // in this case, simply copy a GeoTIFF with no transforms $command = 'gdal_translate /tmp/in.tif /tmp/out.tif'; $t0 = microtime(true); exec($command); $t1 = microtime(true); printf("%.1f seconds", $t1 - $t0); ?> Expected result: ---------------- When run from the shell, this takes 0.5 to 0.7 seconds. Actual result: -------------- This takes 5.0-5.5 seconds. PatchesPull RequestsHistoryAllCommentsChangesGit/SVN commits
|
|||||||||||||||||||||||||||
Copyright © 2001-2024 The PHP GroupAll rights reserved. |
Last updated: Sun Dec 15 09:01:27 2024 UTC |
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.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!