Very inefficient decoding of large chunked messages! #112

domoran · 2017-02-07T10:41:44Z

In one of our legacy projects we download a ~200MB file in memory using chunked encoding. Calling getBody() on this (which calls decodeChunkedBody()) will take > 5 minutes for processing the response() since creates very inefficient copies of the body with each chunk (substr).

To make this more efficient we can use the offset parameter, to avoid copying the body during iteration.

Tests still passed.

Ocramius · 2017-02-07T10:49:41Z

Requires a performance test to prevent regressions. Unsure how to achieve that besides using relative timing of the regex applied to some data, and a large chunk of text passed to this method.

domoran · 2017-02-07T12:09:34Z

I added a performance test, by crafting a "worst case" packet and measuring relative timing.

Verified that test fails on old version:
git checkout e89dac7 src/Response.php

Edit: Fixed the formatting.

michalbundyra · 2017-02-07T13:31:07Z

src/Response.php

+
+        while (true) {
+            if (! preg_match("/^([\da-fA-F]+)[^\r\n]*\r\n/sm", $body, $m, 0, $offset)) {
+                if (! empty(trim(substr($body, $offset)))) {


! empty seems to be useless here

michalbundyra · 2017-02-07T13:31:28Z

src/Response.php

+                if (! empty(trim(substr($body, $offset)))) {
+                    // Message was not consumed completely!
+                    throw new Exception\RuntimeException(
+                        "Error parsing body - doesn't seem to be a chunked message"


Can we use single quotes around the error message string above?

michalbundyra · 2017-02-07T13:32:02Z

src/Response.php

+                    throw new Exception\RuntimeException(
+                        "Error parsing body - doesn't seem to be a chunked message"
+                    );
+                } else {


I think we don't need else statement here.

michalbundyra · 2017-02-07T13:33:10Z

test/ResponseTest.php

@@ -176,6 +177,54 @@ public function testChunkedResponseCaseInsensitiveZF5438()
        $this->assertEquals('c0cc9d44790fa2a58078059bab1902a9', md5($res->getContent()));
    }

+    /**
+     * @param number $chunksize the data size of the chunk to create


Please use int param type instead of number

michalbundyra · 2017-02-07T13:33:49Z

test/ResponseTest.php

+
+    /**
+     * @param Response $response
+     * @return the time that calling the getBody function took on the response


Please add return type.

michalbundyra · 2017-02-07T13:35:03Z

test/ResponseTest.php

+    private function makeChunk($chunksize)
+    {
+        $chunkdata = str_repeat("W", $chunksize);
+        return "$chunksize\r\n$chunkdata\r\n";


Not sure here, but maybe sprintf and/or PHP_EOL?

michalbundyra · 2017-02-07T13:35:21Z

test/ResponseTest.php

+     */
+    private function getTimeForGetBody(Response $response)
+    {
+        $time_start = microtime(true);


Please use camelCase variable names.

michalbundyra · 2017-02-07T13:37:30Z

test/ResponseTest.php

+        $time2 = $this->getTimeForGetBody($response);
+
+        // Make sure that the worst case packet will have an equal timing as the baseline
+        $errMsg = "Chunked response is not parsing large packets efficiently: " . ($time2 / $time1);


Please use sprintf there and single quotes.

michalbundyra · 2017-02-07T13:40:14Z

test/ResponseTest.php

+
+        // Make sure that the worst case packet will have an equal timing as the baseline
+        $errMsg = "Chunked response is not parsing large packets efficiently: " . ($time2 / $time1);
+        $this->assertTrue(2 > ($time2 / $time1), $errMsg);


Maybe we can use here assertLessThan?
Brackets around $time2 / $time1 are useless.

michalbundyra · 2017-02-07T13:41:48Z

test/ResponseTest.php

@@ -10,6 +10,7 @@
 namespace ZendTest\Http;

 use Zend\Http\Response;
+use Zend\Http\Headers;


Please have all imports in alphabetical order.

domoran · 2017-02-07T15:48:59Z

Fixed formatting comments.

domoran · 2017-02-07T15:56:04Z

Hmm ... the test seems flaky, failed under PHP 7 for the last build ... I cannot think of a way to make the test more stable except by increasing its runtime. (More data, increase ratio) Any ideas?

Ocramius · 2017-02-08T12:47:15Z

@domoran flakiness can probably be avoided by repeating the test, but indeed, it's a time-based test, so it will always be a risky one. Make sure the first iteration is removed from measurement to avoid autolading and other possible performance issues there.

Ocramius · 2017-02-07T12:42:31Z

test/ResponseTest.php

@@ -176,6 +177,54 @@ public function testChunkedResponseCaseInsensitiveZF5438()
        $this->assertEquals('c0cc9d44790fa2a58078059bab1902a9', md5($res->getContent()));
    }

+    /**
+     * @param number $chunksize the data size of the chunk to create


int, not number

Ocramius · 2017-02-07T12:56:39Z

test/ResponseTest.php

+        $headers = file_get_contents(__DIR__ . '/_files/response_chunked_head');
+        $response->setHeaders(Headers::fromString($headers));
+
+        // *** craft a special 'worst case' response, where 1000 1 Byte chunks are followed by a 1 MB Chunk ***


Should be in the test method docblock

Ocramius · 2017-02-07T12:56:46Z

test/ResponseTest.php

+    }
+
+    /**
+     * @small


Why @small?

Ocramius · 2017-02-07T12:57:26Z

test/_files/response_chunked_head

@@ -0,0 +1,6 @@
+Date: Sun, 25 Jun 2006 19:55:19 GMT


I would suggest moving this into the test method, via <<<'HEADER' (and remove all bits that aren't strictly needed)

Ocramius · 2017-02-08T14:35:42Z

Sorry for the previous commits - previous review from me was never submitted.

Ocramius · 2017-02-08T14:37:15Z

test/ResponseTest.php

+    }
+
+    /**
+     * @small


What's @small here?

Does the test fail with the previous code? (just asking, since can't try it on my machine atm)

On my machine the test does not fail at all. Neither with php7 nor php 5.6 ... small will be removed.

@domoran I was asking if the test fails when removing the patch from the chunk decoding block.

Yes, without the path the ratios are on my machine 2000-5000 under PHP7 and about 250 on PHP5.6 ... Test runs > 60 secs.

I can increase the ratio here to make the test pass, but there must be some other problem. I would not expect a ratio much larger than 1, after all this is only one iteration more than before.

Alright, going up with those timings is not gonna help, so I suppose that a different approach needs to be taken.

Could you poke me on Friday? I can probably work on it while traveling.

Ocramius · 2017-02-08T14:37:49Z

test/ResponseTest.php

+     */
+    private function makeChunk($chunksize)
+    {
+        $chunkdata = str_repeat('W', $chunksize);


Can be inlined

domoran · 2017-02-08T14:45:27Z

I dont get it. There must be a logic error in the test or a problem on php7.

How can one more regexp iteration inside the decodeChunkedBody be factor 30-50(!) slower than the baseline? This happens only on travis-ci and only with php 7 ...

On my machine I cannot reproduce. Even with php7 I get a ratio of 3-5 ... But with php5.6 there is the expected runtime ratio of 1 ... Maybe an issue with the regexp implementation on PHP 7?

Oh boy. Committing to Zend Framework is hard work.

Ocramius · 2017-02-08T14:47:43Z

Oh boy. Committing to Zend Framework is hard work.

Nah, you just found an annoyingly hard edge case.

Did you check whether you are running with xdebug or not? Try running tests with php -n (will probably fail on some curl-based scenarios).

If we can help out, let us know, we can certainly test on other environments as well.

PHP 7 has indeed changed many things in the regex engine, btw.

…ent on large requests!) Instead: Use offset parameter on preg_match() to iterate efficiently over the raw body.

To test performance problems with copying data in memory around, we craft a special worst case packet. 1000 chunks of 1 byte followed by 1 chunk of 1MB. In case of the old code, the 1MB chunk will be copied around in memory a thousand times, leading to a large performance drop. We test that the worst case packet will be parsed in the same time as a "baseline" packet (without the large chunk at the end).

- Make test more stable by increasing expected performance ratio

Ratio for old version now > 200.

weierophinney · 2018-04-26T15:21:58Z

I've rebased and pushed back to your branch; let's see if the tests present the same issue...

I have incorporated feedback in the merge.

Forward port #112

weierophinney · 2018-04-26T15:53:59Z

Thanks, @domoron! We have updated the test suite recently, and those updates ensured your performance-based tests now pass reliably! Merged for next release.

domoran mentioned this pull request Feb 7, 2017

Chunked Body: Decode extremely slow #111

Closed

Ocramius added awaiting author updates enhancement labels Feb 7, 2017

michalbundyra reviewed Feb 7, 2017

View reviewed changes

Ocramius reviewed Feb 8, 2017

View reviewed changes

Ocramius previously requested changes Feb 8, 2017

View reviewed changes

domoran added 9 commits April 26, 2018 10:19

Do not copy the response body around using substr (extremely ineffici…

60cd011

…ent on large requests!) Instead: Use offset parameter on preg_match() to iterate efficiently over the raw body.

Format according to style guide

f035be6

- Reformat code to fix style check errors

893aea3

- Make test more stable by increasing expected performance ratio

- More format fixes to make style check pass

167ed46

Remove unnecessary code, harmonize usage of strings, format

9f27a44

Try to remove Test Flakiness. Make worst case packet even worse.

5e6c9c8

Ratio for old version now > 200.

Repeat test to eliminate flakiness.

fd2c87d

Coding standards ...

78a5373

weierophinney force-pushed the master branch from 736e7bd to 78a5373 Compare April 26, 2018 15:21

weierophinney added a commit that referenced this pull request Apr 26, 2018

Adds CHANGELOG entry for #112

b42d0b8

weierophinney closed this in 5e9e91e Apr 26, 2018

weierophinney added a commit that referenced this pull request Apr 26, 2018

Merge branch 'hotfix/112-performance-chunked-decoding' into develop

9422140

Forward port #112

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Very inefficient decoding of large chunked messages! #112

Very inefficient decoding of large chunked messages! #112

domoran commented Feb 7, 2017

Ocramius commented Feb 7, 2017

domoran commented Feb 7, 2017 •

edited

Loading

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

michalbundyra Feb 7, 2017

domoran commented Feb 7, 2017

domoran commented Feb 7, 2017

Ocramius commented Feb 8, 2017

Ocramius Feb 7, 2017

Ocramius Feb 7, 2017

Ocramius Feb 7, 2017

Ocramius Feb 7, 2017

Ocramius commented Feb 8, 2017

Ocramius Feb 8, 2017

Ocramius Feb 8, 2017

domoran Feb 8, 2017

Ocramius Feb 8, 2017 •

edited

Loading

domoran Feb 8, 2017

Ocramius Feb 8, 2017

Ocramius Feb 8, 2017

domoran commented Feb 8, 2017

Ocramius commented Feb 8, 2017

weierophinney commented Apr 26, 2018

weierophinney commented Apr 26, 2018

Very inefficient decoding of large chunked messages! #112

Very inefficient decoding of large chunked messages! #112

Conversation

domoran commented Feb 7, 2017

Ocramius commented Feb 7, 2017

domoran commented Feb 7, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

domoran commented Feb 7, 2017

domoran commented Feb 7, 2017

Ocramius commented Feb 8, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Ocramius commented Feb 8, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Ocramius Feb 8, 2017 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

domoran commented Feb 8, 2017

Ocramius commented Feb 8, 2017

weierophinney commented Apr 26, 2018

weierophinney commented Apr 26, 2018

domoran commented Feb 7, 2017 •

edited

Loading

Ocramius Feb 8, 2017 •

edited

Loading