php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Bug #69900 Commandline input/output weird behaviour
Submitted: 2015-06-22 14:45 UTC Modified: 2015-07-06 12:12 UTC
Votes:1
Avg. Score:5.0 ± 0.0
Reproduced:1 of 1 (100.0%)
Same Version:1 (100.0%)
Same OS:1 (100.0%)
From: nerdbeere2k at gmail dot com Assigned: ab
Status: Closed Package: *General Issues
PHP Version: 5.5.26 OS: Windows
Private report: No CVE-ID:
 [2015-06-22 14:45 UTC] nerdbeere2k at gmail dot com
Description:
------------
Explaining my whole setup for this would take some time so i'm gonna try to describe it as short as possible.
I have a java application where i send some string to php-cli via standard input and read a result string back from standard output to do something else with it.
I do this several times, so the php-cli process is getting several commands to work off, and i read the results back.

The issue/bug now is that for every fgets call i make the process hangs for 100ms.

This worked like a charm until version php-5.5.17 and broke in version php-5.5.18. php-5.6.* seems to have this issue as well.

The changelog didn't exactly point towards a change that might've led to this as far as i could see.
Especially weird is that it all works fine if i put a "usleep(1)" before the fgets call...

I wrote some example breaking down the problem to as few lines as possible:
<?php
while(!feof(STDIN)){
    // usleep(1) <- adding this seems to fix this behaviour...
	// THIS WILL BLOCK FOR 100ms for every fgets call
    $s = fgets(STDIN);
    fwrite(STDOUT, $s);
}
?>

This script is called from a java application like this (tested on jdk1.8.0_20):

public static void main(String[] args) {
	try {
		Process p = Runtime.getRuntime().exec("./php-5.5.18/php.exe -f ./php-5.5.18/test.php");
		InputStream inputStream = p.getInputStream();
		OutputStream outputStream = p.getOutputStream();
		byte[] buffer = new byte[1024];
		while(p.isAlive()){
			outputStream.write("TEST\r\n".getBytes());
			outputStream.flush();
			int read = inputStream.read(buffer);
			if(read > -1){
				System.out.println(new String(buffer, 0, read));
			}
		}
	} catch (IOException ex) {
		ex.printStackTrace();
	}
}


Patches

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2015-06-24 09:22 UTC] ab@php.net
-Status: Open +Status: Feedback
 [2015-06-24 09:22 UTC] ab@php.net
Thanks for the report.

I've modified your snippet to see the timings

<?php
while(!feof(STDIN)){
    // usleep(1) <- adding this seems to fix this behaviour...
        // THIS WILL BLOCK FOR 100ms for every fgets call
        $t0 = microtime(1);
        $s = fgets(STDIN);
        $t1 = microtime(1);
        echo "fgets() took ", (($t1 - $t0)*1000), "ms\n";
    fwrite(STDOUT, $s);
}

But i don't reproduce this. Call it like

echo hello | php.exe -n bugs\69900.php

on my machine, either PHP 5.5 or 7, the output is like

fgets() took 0.015974044799805ms
hello
fgets() took 0.015974044799805ms

Please provide a stable reproduce case for what you describe. Otherwise, the issue you experience is probably not fgets().

Thanks.
 [2015-06-24 11:19 UTC] nerdbeere2k at gmail dot com
Hello ab,

first thank you very much for looking into this! i tried to simplify this more by removing the java part, and the issue seems to occur here too.

I'd agree with you, its probably not a fgets problem but seems to be a general problem with the STDIN/STDOUT stream, but i can't point out what it could be as i am not familiar with the php internals.

However, this is the php-only testcase i came up with where the problem occurs:

<?php
$descriptorspec = array(0 => array("pipe", "r"),1 => array("pipe", "w"), 2 => array("file", "error-output.txt", "a"));
$pipes = array();

$process = proc_open(PHP_BINARY.' -f test.php', $descriptorspec, $pipes);
if(is_resource($process)){
    for($i = 0; $i < 10; $i++){
        fwrite($pipes[0], "hello\r\n");
        $t0 = microtime(1);
        $s = fgets($pipes[1]);
        $t1 = microtime(1);
        echo $s;		
        echo "fgets() took ", (($t1 - $t0)*1000), "ms\n";
    }
    
    fclose($pipes[0]);
    fclose($pipes[1]);
    
    proc_close($process);
} else die("process creation failed!");
?>
and the test.php file:
<?php
while(!feof(STDIN)){
	$s = fgets(STDIN);
	fwrite(STDOUT, $s);
}
?>

The output that php-5.5.26 generates when calling it is as follows:

C:\tmp\php_bug_report_69900\>.\php-5.5.26\php.exe -f passproc.php
hello
fgets() took 100.00491142273ms
hello
fgets() took 100.00610351562ms
hello
fgets() took 100.00610351562ms
hello
fgets() took 100.00586509705ms
hello
fgets() took 100.00514984131ms
hello
fgets() took 100.00586509705ms
hello
fgets() took 100.00610351562ms
hello
fgets() took 100.00491142273ms
hello
fgets() took 100.00610351562ms
hello
fgets() took 100.00586509705ms

The output with php-5.5.17 is as follows:

C:\tmp\php_bug_report_69900\>.\php-5.5.17\php.exe -f passproc.php
hello
fgets() took 19.001007080078ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms
hello
fgets() took 0ms


Hope this helps! Thanks again!
 [2015-06-24 11:22 UTC] nerdbeere2k at gmail dot com
By the way, if you call the process like this:

$process = proc_open(PHP_BINARY.' <?php while(!feof(STDIN)){ $s = fgets(STDIN); fwrite(STDOUT, $s); } ?>', $descriptorspec, $pipes);

The problem doesnt occur... just in case someone wonders why i used two separate files.
 [2015-06-25 07:31 UTC] nerdbeere2k at gmail dot com
-Status: Feedback +Status: Open
 [2015-06-25 07:31 UTC] nerdbeere2k at gmail dot com
Status Open
 [2015-06-25 13:15 UTC] ab@php.net
-Status: Open +Status: Feedback
 [2015-06-25 13:15 UTC] ab@php.net
Thanks for the second code snippet. However it turns the ticket to completely different story. When I run it, i reproduce your findings on Windows, but not on Linux.

It might be related on Windows to bugfixes to the proc_open as it previously could block while reading/writing pipes from the child. You initially say it's reproducable on both Linux/Windows and the initial snippet doesn't involve proc_open().

So I'm just not sure what we're investigating on :) Is the last one the code reproducing your exact situation? If not, it's probably worth to workout a snippet not involving proc_open().

Thanks.
 [2015-06-25 18:50 UTC] nerdbeere2k at gmail dot com
-Status: Feedback +Status: Open -Operating System: Linux, Windows +Operating System: Windows
 [2015-06-25 18:50 UTC] nerdbeere2k at gmail dot com
Hello ab,

first: thanks again for replying!

i must admit i didnt test my last code snippet with Linux, but initially i got a report for my java application which stated that it'd run very slow since upgrading php to 5.6.
The environment from that report is Linux, and after i investigated the problem i supposed that this was the source of the problem without specifically testing it on Linux...
So i might've been wrong, and if you say so, i probably was and i'm sorry for that! I will take Linux out of the OS list.

Concerning proc_open(): i don't think the problem is related to proc_open(), because the java and the php snippet basically do the same thing and the timings and output of both are pretty much equal...

I'm also not sure what we're investigating on :) i had hoped maybe someone had an idea what to do! What would you advise?
 [2015-06-26 20:19 UTC] ab@php.net
@nerdbeere2k, thanks for the additional input.

Ok, i've compiled your java snippet and tested on windows and linux. It clearly shows, that it's a Windows only issue. Were nice if you could confirm that.

Also it shows that proc_open isn't involved. Still i suspect pipe handling. But this already gives the direction to debug.

Thanks.
 [2015-06-28 14:50 UTC] nerdbeere2k at gmail dot com
Hello ab,

i didnt have time to respond until now, but i hope this still helps.
i set up a vm and tested this on debian and can confirm that this is a windows only issue!
 [2015-06-30 09:26 UTC] ab@php.net
-Assigned To: +Assigned To: ab
 [2015-07-01 15:11 UTC] ab@php.net
-Status: Assigned +Status: Feedback
 [2015-07-01 15:11 UTC] ab@php.net
@nerdbeere2k 

could you please check the build http://windows.php.net/downloads/snaps/ostc/69900/ which is linked in this mail http://news.php.net/php.internals/86976 ? Please be aware that you'll need add a stream context and/or additional proc_open config. The patch is unlikely to appear in PHP5, but in PHP7.

Be aware that this way can lead back to dead locks, though might be useful when used carefully.

The actual issue is - if the caller doesn't send EOF, the input seems to be buffered. So while PHP peeks the pipe, nothing is there. Seems that even if caller flush()es, it doesn't affect the pipe. So when it happens, PHP enters a timeout, and when peeking next time, the data seems to be available in the pipe. That's why fe the snippet like ... echo hello | php ... works as expected - because the echo command does properly close(). If we don't use peek()ing technique, blocking reads and dead locks can happen, which was reported many times.

In addition to this patch for PHP7 I'm going to investigate on ways to improve the situation in PHP5. Not sure we should even thing about unbuffered IO on pipes, but at least about decreasing the timeouts or maybe enforcing buffer flush before peek()ing.

Thanks.
 [2015-07-01 16:08 UTC] nerdbeere2k at gmail dot com
-Status: Feedback +Status: Assigned
 [2015-07-01 16:08 UTC] nerdbeere2k at gmail dot com
Hello ab,

thanks again for investing your time into this!

I tested the php executable from here http://windows.php.net/downloads/snaps/ostc/69900/php-7.0.0-dev-Win32-VC14-x64.zip with the code from your mail, so that:

$process = proc_open(PHP_BINARY.' -f test.php', $descriptorspec, $pipes, null, null, array("blocking_pipes" => true));

and added an fflush($pipes[0]) after the fwrite.

However, i somehow can't replicate your test-times... 

This is what it looks like with "blocking_pipes" => true:

>.\php-7.0.0\php.exe -f passproc.php
hello0
fgets() took 17.000913619995ms
hello1
fgets() took 99.004983901978ms
hello2
fgets() took 100.00610351562ms
hello3
fgets() took 100.00586509705ms
hello4
fgets() took 100.00610351562ms
hello5
fgets() took 100.00491142273ms
hello6
fgets() took 100.00610351562ms
hello7
fgets() took 100.00586509705ms
hello8
fgets() took 100.00610351562ms
hello9
fgets() took 100.00491142273ms

and this is what it looks like with "blocking_pipes" => false (or without setting $other_options at all):

>.\php-7.0.0\php.exe -f passproc.php
hello0
fgets() took 100.00610351562ms
hello1
fgets() took 100.00586509705ms
hello2
fgets() took 100.00514984131ms
hello3
fgets() took 100.00586509705ms
hello4
fgets() took 100.00610351562ms
hello5
fgets() took 100.00586509705ms
hello6
fgets() took 100.00514984131ms
hello7
fgets() took 100.00586509705ms
hello8
fgets() took 100.00610351562ms
hello9
fgets() took 100.00491142273ms

Using this version with java produces the same behaviour. So, somehow like before, after the first two reads.

Hope this helps.
 [2015-07-01 16:18 UTC] ab@php.net
-Status: Assigned +Status: Feedback
 [2015-07-01 16:18 UTC] ab@php.net
Thanks for the quick test. Have you also added the stream context i've mentioned while f'opening the stdin? Please see https://github.com/weltling/php-src/blob/5b8e0aa87849c16906a5e59da2d924d8aaa31b0c/ext/standard/tests/streams/proc_open_bug69900.phpt 

I even guess it's more about setting the right context to stdin than about the proc_open config.

Thanks.
 [2015-07-01 16:57 UTC] nerdbeere2k at gmail dot com
-Status: Feedback +Status: Assigned
 [2015-07-01 16:57 UTC] nerdbeere2k at gmail dot com
Hello ab,

sorry, i didnt change the stdin initialization stdin! I somehow missed that!

However, with it, it runs just fine in both PHP and Java!
 [2015-07-01 17:56 UTC] ab@php.net
@nerdbere2k, great, then it's the way so far. I'm waiting for the feedback in #69963 so far (it's same topic), maybe you could help with that as well. The way with pipe blocking reads is dangerous. Using it you're on your own with the dead locks in the pipe :( But anyway, should probably merge this tomorrow.

Please don't close this yet, the timeouts on the pipe still have to be revisited in php5. I guess without using blocking reads, they can be decrased to 1-2ms, still better than now. So I'll come back to you once more with this.

Thanks.
 [2015-07-02 19:51 UTC] ab@php.net
-Status: Assigned +Status: Feedback
 [2015-07-02 19:51 UTC] ab@php.net
@nerdbeere2k, this patch is now landed in master. Additionally i made an adjustment for the normal case. Please check your original case using one of the latest snapshots http://windows.php.net/downloads/snaps/master/ (so no stream context, just STDIN).

Thanks.
 [2015-07-04 10:05 UTC] nerdbeere2k at gmail dot com
-Status: Feedback +Status: Assigned
 [2015-07-04 10:05 UTC] nerdbeere2k at gmail dot com
Hello ab,

First, thanks again, this works pretty good!

i was not sure which version to use, so i took this one, which is from the day after your post:
http://windows.php.net/downloads/snaps/master/r57881e8/php-master-ts-windows-vc14-x86-r57881e8.zip

With this i get these results (using STDIN and STDOUT again, and removed "blocking_pipes" option):
>.\php-master\php.exe -f passproc.php
hello0
fgets() took 23.000955581665ms
hello1
fgets() took 2.0010471343994ms
hello2
fgets() took 2.000093460083ms
hello3
fgets() took 0.99992752075195ms
hello4
fgets() took 2.000093460083ms
hello5
fgets() took 1.9998550415039ms
hello6
fgets() took 1.0001659393311ms
hello7
fgets() took 0.99992752075195ms
hello8
fgets() took 2.000093460083ms
hello9
fgets() took 0.99992752075195ms

With blocking pipes set to true and STDIN + STDOUT it seems to be even faster (about 1ms):
>.\php-master\php.exe -f passproc.php
hello0
fgets() took 23.001909255981ms
hello1
fgets() took 0.99992752075195ms
hello2
fgets() took 1.0001659393311ms
hello3
fgets() took 0.99992752075195ms
hello4
fgets() took 0.99992752075195ms
hello5
fgets() took 1.0001659393311ms
hello6
fgets() took 0.99992752075195ms
hello7
fgets() took 0ms
hello8
fgets() took 0.99992752075195ms
hello9
fgets() took 1.0001659393311ms

I was wondering, if i stopped doing this via the command line and instead set up a socket communication between java <=> php (doing basically the same thing)... could i get rid of that 1ms every call?
 [2015-07-06 12:12 UTC] ab@php.net
@nerdbeere, grateful thanks for the tests. Generally, when you use it from Java, it's more about that the php counterpart doesn't use STDIN directly, so using the stream context. Then it'll use blocking read() on the pipe fd - which is indeed faster. Without it - it'll be going by 

- peek the pipe
- nothing there? sleep
- repeat

And on Windows it's principally hard to achieve to sleep less than 1ms. Blocking read() is of course faster, but less safe as mentioned earlier.

Regarding TCP you could try php.net/stream_socket_server , not sure what to do in Java.

Ok then, I'll update the NEWS for PHP7 already, will close the ticket when I backported the timeout improvement (but no stream context, etc., as mentioned) into 5.6.

Thanks )
 [2015-07-28 08:30 UTC] ab@php.net
Automatic comment on behalf of ab
Revision: http://git.php.net/?p=php-src.git;a=commit;h=20e765b841756a00a4b6f35783bbf74eab5d91ac
Log: Fixed bug #69900 Too long timeout on pipes
 [2015-07-28 08:30 UTC] ab@php.net
-Status: Assigned +Status: Closed
 [2015-07-28 15:45 UTC] ab@php.net
Automatic comment on behalf of ab
Revision: http://git.php.net/?p=php-src.git;a=commit;h=20e765b841756a00a4b6f35783bbf74eab5d91ac
Log: Fixed bug #69900 Too long timeout on pipes
 [2015-08-04 20:54 UTC] ab@php.net
Automatic comment on behalf of ab
Revision: http://git.php.net/?p=php-src.git;a=commit;h=20e765b841756a00a4b6f35783bbf74eab5d91ac
Log: Fixed bug #69900 Too long timeout on pipes
 
PHP Copyright © 2001-2017 The PHP Group
All rights reserved.
Last updated: Sun Feb 26 21:01:35 2017 UTC