php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login

go to bug id or search bugs for

Bug #62658 When enable –with-curlwrappers option, stream_get_contents() may cpu 100%
Submitted: 2012-07-25 10:26 UTC Modified: 2013-11-08 08:37 UTC
Votes:2
Avg. Score:5.0 ± 0.0
Reproduced:1 of 1 (100.0%)
Same Version:0 (0.0%)
Same OS:1 (100.0%)
From: sopl dot wang at gmail dot com Assigned: pierrick (profile)
Status: Closed Package: cURL related
PHP Version: master-Git-2012-07-25 (Git) OS: ALL
Private report: No CVE-ID: None
View Add Comment Developer Edit
 [2012-07-25 10:26 UTC] sopl dot wang at gmail dot com 
Description:
------------
When enable `–with-curlwrappers` option, with http(s)/ftp(s)/other curl-wrapped 
stream protocols, file_get_contents(), stream_get_contents() and alike functions 
may lead consume 100% cpu cycle on waiting for receive.

When `strace` problem php process, following will be develop:

<pre>
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(7, [6], [6], [], {15, 0})        = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0)     = 0 (Timeout)
</pre>

The reason we found is in 'ext/curl/streams.c', function php_curl_stream_read(), 
line 174:

<code>
  select(curlstream->maxfd + 1, &curlstream->readfds, &curlstream->writefds, 
&curlstream->excfds, &tv)
</code>

When select(), `writefds` always can write and immediate return, no block at 
here and, upper module will detect that no data could read and re-invoke this 
function (`php_curl_stream_read()`), a nonblock loop, lead this consume 100% cpu 
bug.

If the link very slow, this 100% cpu problem may take the system load very high.

Test script:
---------------
Enable `–with-curlwrappers` and test:

<code>
<?php
while (true)
  file_get_contents('http://soplwang.com');
</code>

Expected result:
----------------
Expect the behavior like native php does…

When `strace`, native php generate:

<pre>
poll([{fd=3, events=POLLIN|POLLERR|POLLHUP}], 1, 60000) = 1 ([{fd=3, 
revents=POLLIN}])
</pre>

Actual result:
--------------
When `strace`, generate:

<pre>
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
poll([{fd=3, events=POLLIN}], 1, 0)     = 0 (Timeout)
...
</pre>

Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2012-09-28 19:44 UTC] pierrick@php.net 
Do you still have this issue ? I tried on my local build and everything work as 
expected. If it doesn't work could you give me more details about your build ? 
libcurl version ?
 [2012-09-28 19:44 UTC] pierrick@php.net
-Status: Open +Status: Feedback -Assigned To: +Assigned To: pierrick
 [2012-10-07 13:49 UTC] sopl dot wang at gmail dot com
-Status: Feedback +Status: Assigned
 [2012-10-07 13:49 UTC] sopl dot wang at gmail dot com 
Still have issue (a bit different of output, but still cpu 100%) when I build 
and test on php-5.4.7 GA release. Follow is my build config:

./configure --prefix=/usr/local/webserver/php5.4.7 --with-config-file-
path=/usr/local/webserver/php5.4.7/etc --with-mysql=/usr/local/webserver/mysql5 
--with-mysqli=/usr/local/webserver/mysql5/bin/mysql_config --with-iconv-dir=/usr 
--with-freetype-dir --with-jpeg-dir --with-png-dir --with-zlib --with-libxml-
dir=/usr --enable-xml --disable-rpath --enable-bcmath --enable-shmop --enable-
sysvsem --enable-inline-optimization --with-curl=/usr --with-curlwrappers --
enable-ftp --enable-mbregex --enable-fpm --with-fpm-user=www --with-fpm-
group=www --disable-ipv6 --enable-mbstring --with-mcrypt --with-gd=/usr --
enable-gd-native-ttf --with-openssl --with-mhash --enable-pcntl --enable-sockets 
--enable-gd-jis-conv --disable-debug --enable-sysvshm --enable-soap --with-pdo-
mysql=shared,/usr/local/webserver/mysql5 --with-pdo-sqlite=shared --with-
sqlite=shared --enable-pdo=shared

Test script
-----------
./sapi/cli/php <<<'<?php while(1) file_get_contents("http://www.l4ka.org");'

Output
------
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {26871452, 912511643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912536643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912553643}) = 0
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
clock_gettime(CLOCK_MONOTONIC, {26871452, 912606643}) = 0
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {26871452, 912643643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912668643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912685643}) = 0
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
clock_gettime(CLOCK_MONOTONIC, {26871452, 912738643}) = 0
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
clock_gettime(CLOCK_MONOTONIC, {26871452, 912775643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912800643}) = 0
clock_gettime(CLOCK_MONOTONIC, {26871452, 912817643}) = 0
select(4, [3], [3], [], {15, 0})        = 1 (out [3], left {15, 0})
System version
--------------
LSB Version:	:core-4.0-amd64:core-4.0-ia32:core-4.0-noarch:graphics-4.0-
amd64:graphics-4.0-ia32:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-
ia32:printing-4.0-noarch
Distributor ID:	CentOS
Description:	CentOS release 5.6 (Final)
Release:	5.6
Codename:	Final

Curl version
------------
curl 7.21.6 (x86_64-unknown-linux-gnu) libcurl/7.21.6 OpenSSL/0.9.8b zlib/1.2.3 
libidn/0.6.5
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s 
rtsp smtp smtps telnet tftp 
Features: IDN Largefile NTLM SSL libz
 [2012-10-07 13:59 UTC] sopl dot wang at gmail dot com 
You may try use `file_get_contents` to open a very slow website to help reproduce 
this problem. When open a very very slow website, this issue will be more evident.
 [2012-11-17 00:53 UTC] pierrick@php.net 
Here's what I have on my side with today's version of the master branch :

select(4, [3], [], [], {15, 0})         = 1 (in [3], left {4, 999876})
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "1\r\n1\r\n", 16384, 0, NULL, NULL) = 6
select(4, [3], [], [], {15, 0})         = 1 (in [3], left {5, 182})
poll([{fd=3, events=POLLIN|POLLPRI}], 1, 0) = 1 ([{fd=3, revents=POLLIN}])
recvfrom(3, "1\r\n1\r\n", 16384, 0, NULL, NULL) = 6

I compiled it with the same curl version 7.21.6. As you can see I can't reproduce it. My select don't have 
anything in the Output file descriptor. Can you test if you still have this different output in your strace ? Do 
you use the exact same script you sent in your previous comment ?
 [2012-11-17 00:53 UTC] pierrick@php.net
-Status: Assigned +Status: Feedback
 [2013-02-18 00:35 UTC] php-bugs at lists dot php dot net 
No feedback was provided. The bug is being suspended because
we assume that you are no longer experiencing the problem.
If this is not the case and you are able to provide the
information that was requested earlier, please do so and
change the status of the bug back to "Open". Thank you.
 [2013-11-08 07:19 UTC] kaiwang dot chen at gmail dot com 
I just experienced exactly same problem, which should have been fixed as of 5.3.18/5.4.8/5.5.0 with this patch https://github.com/php/php-src/commit/936553d666405bc783511979b17d78d51905b9cd

sopl's analysis is correct, and he was affected because his version is 5.4.7

To reproduce the problem, one need an old php version and a slow connection which could be simulated with:

1) on host A providing http service, enforce traffic control with

  tc qdisc add dev em1 root handle 1:0 netem delay 500msec

2) on host B runs 

  strace -ttt ./sapi/cli/php <<< '<?php  file_get_contents("http://hostA");'

3) on host A, drop the traffic control rule

  tc qdisc del dev em1 root

Then search the strace output for "recvfrom\|select.*= 2\|poll.*= 1" in your vim editor, you will find between matched lines thousands of "select ... = 1" and "poll ... = 0" wasting cpu cycles.

PS: curlwrappers has been totally removed from php as voted https://wiki.php.net/rfc/curl-wrappers-removal-rfc
 [2013-11-08 08:37 UTC] sopl dot wang at gmail dot com
-Status: No Feedback +Status: Closed
 [2013-11-08 08:37 UTC] sopl dot wang at gmail dot com 
@kaiwang, thank you, very much!

At Dec2012, I re-test it on php5.4-master after @pierrick's last feedback, and this issue disappeared... So, I assume that may be Curl's issue... (based on @pierrick's comments).

Ok, actually, I'm always turn off 'curlwrappers' from then on.

Any way, thank you! Your work fixed my puzzle.
 
PHP Copyright © 2001-2024 The PHP Group
All rights reserved. 		Last updated: Sun May 05 10:01:31 2024 UTC