Performance comparison of various elements

[MarkMaldaba]

I have written a test script to check performance of various constructs, when rendered by DomPDF.

I have committed it to my local fork of DomPDF: MarkMaldaba@95b59f2

I don't know if this is something you would want to merge into the main repository - if so, let me know and I will create a PR. I'll be happy to make changes, e.g. to coding style, if guidance is provided.

The script takes a simple HTML snippet (e.g. <div></div>) and creates an HTML file whose body contains many instances of this snippet (10,000 in my tests). It then renders it, outputting timing and memory usage information.

It has thrown up some interesting and (to me, at least) surprising results:

> php test_performance.php whitespace 10000
Profiling PDF generation using 'whitespace' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         1,804,688     1,806,944     0
Load          1,830,752     2,175,320     0
Render        2,835,280     3,257,656     0.046875
Output        2,836,712     3,257,656     0

> php test_performance.php empty_span 10000
Profiling PDF generation using 'empty_span' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         1,824,688     1,826,944     0
Load          1,850,752     2,260,320     0.03125
Render        31,770,448    84,405,184    5.96875
Output        31,773,232    84,405,184    0

> php test_performance.php empty_div 10000
Profiling PDF generation using 'empty_div' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         1,804,672     1,806,976     0
Load          1,830,752     2,175,360     0.015625
Render        51,269,080    168,720,384   17.15625
Output        51,271,872    168,720,384   0

> php test_performance.php break_tag 10000
Profiling PDF generation using 'break_tag' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         1,734,656     1,737,064     0
Load          1,760,736     1,877,872     0.015625
Render        36,735,072    43,800,976    82.40625
Output        36,741,832    43,800,976    0.015625

So, <span> tags are 5 times faster than <div> tags, which are nearly 5 times faster than <br> tags!

Initial take-home seems to be to avoid <br> tags, but some more research needed. I suggest this ticket be used for general discussion around this issue, with any specific actionable items being spun off as separate tickets.

(For reference, the tests were run using the current 'develop' branch using PHP 5.4.45 on Windows.)

[MarkMaldaba]

Also - I forgot to mention - just look at the memory usage! Not just at the peaks (which, interestingly, don't follow the timings as <div> is more expensive than <br>) but at the amount of memory that is left unreclaimed at the end of the render.

[MarkMaldaba]

I've added a new test to the script[1] which checks for memory leaks by ensuring we unset() the DomPDF object before doing a final memory check. The results are not good!

Profiling PDF generation using 'empty_span' over 1000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         1,710,640     1,712,992     -
Load          1,736,744     1,768,184     0.015625
Render        5,364,592     10,751,800    0.28125
Output        5,367,376     10,751,800    0
End           5,367,864

As you can see, even destroying the DomPDF object does not free up the memory, so the memory leak will persist even if the calling code tidies up nicely.

[1] MarkMaldaba@5890cca

[PHPGangsta]

Nice tests!

I just saw that memory_get_usage() internally triggers a garbage collection, so your values should be correct. But if you don't use memory_get_usage() in a script, just unsetting a variable does not free memory directly. You habe to call gc_collect_cycles() to force a garbage collection:
http://php.net/manual/en/function.gc-collect-cycles.php

Make sure you have zend.enable_gc enabled in your php.ini, or call gc_enable() to activate the circular reference collector.

For DomPDF to speed up: It might make sense to disable the automatic garbage collector in some places, where nothing can be collected anyway, and the automatic garbage collector just wastes time. A nice read:
https://tideways.com/profiler/blog/how-to-optimize-the-php-garbage-collector-usage-to-improve-memory-and-performance
https://blog.blackfire.io/performance-impact-of-the-php-garbage-collector.html
In a heavy function with lots of objects, it might make sense to disable gc, and re-enable it at the end (and do one manual gc run at the end). Maybe that speeds up things a lot, like in the composer installer.

PHP 7.3 will have some nice improvements in garbage collection:
https://react-etc.net/entry/improvements-to-garbage-collection-gc-php-7-3-boosts-performance-in-benchmark

There is a difference between memory_get_usage() and memory_get_usage(true), maybe the second one gives more insights.

And of cause: please use a recent version of PHP that is still supported, and has a better garbage collector. It has improved over the years. PHP 5.4 is 6 years old. Please use PHP 7.1 or 7.2, which are the "fully supported" versions today:
http://php.net/supported-versions.php

DomPDF definitly needs some performance improvements, see the issues labeled "performance":
https://github.com/dompdf/dompdf/issues?q=is%3Aissue+label%3APerformance

I totally support you working on performance improvements!

[MarkMaldaba]

Thanks for replying! :-)

My understanding about PHP garbage collection is that really you don't need to worry about it. It doesn't really matter when garbage collection happens; it just happens when it needs to. The reason get_memory_usage() triggers garbage collection is that this is the only way it can reliably report on memory usage, but that is incidental.

Personally, I'm sceptical that we'll get much of a performance improvement by playing with garbage collection, but I'd be happy to be proved wrong... :-)

There is a difference between memory_get_usage() and memory_get_usage(true), maybe the second one gives more insights.

Actually, I think this will give less insight, as this reports how much memory PHP has requested from the operating system, which is only loosely coupled with the memory requirements of the script it is running. For example, if your script requires 5k of memory, PHP might decide it is most efficient to request 1MB of memory from the OS, but knowing this doesn't really help to optimise your code at all, and you can't control it.

Your point about PHP versions is good. However, I have re-tested on PHP 5.6.18 and the profile is broadly similar. Therefore, I think this is about inefficiencies in the DomPDF code (or its dependencies) rather than anything related to PHP internal optimisations, and therefore that is definitely where I will be focussing my efforts.

If you're able to test on PHP 7.2, it might be interesting to see how it compares...

DomPDF definitly needs some performance improvements, see the issues labeled "performance":
https://github.com/dompdf/dompdf/issues?q=is%3Aissue+label%3APerformance

Thanks for the pointer - this ticket should probably have that tag added, too.

[bsweeney]

Don't make a PR just yet but I am interested in discussing the topic more.

There have been some people who have worked to improve performance, but considering some of the outstanding deficiencies in basic HTML and CSS support it hasn't been a priority. Most of the performance notes you've made can be explained by how the code actually works. For example, anything that breaks a line results in additional layout calculation, and breaking within the same frame increases the line box count which requires more tracking within that frame.

... or something like that. I'd really have to sit down and think about these things to provide a truly good, accurate explanation.

There are a number of circular references that likely cause heartburn for the GC. I wonder if unsetting these references in a destructor would help with GC. We do have some resource release in the dispose method that is used during page layout.

At one point we had made significantly more effort to clean up object references with destructors in v0.6.2, but that was in relation to a memory leak.

FYI, I've noticed a significant performance boost moving to PHP 7.x and encourage you to try setting up a system to test. Or use a project like phpbrew, which is how I manage testing across PHP variants.

[MatthiasKuehneEllerhold]

I've found memprof is a really nice tool for profiling scripts for memory leaks.

I've tested @MarkMaldaba script on PHP7.2.10.

You HAVE to call gc_collect_cycles(); before calling memory_get_usage(); to get useful results (at least in PHP7.2).

And a small nitpick: you forgot to unset($HTML); after Line 101. ;)

Using both small additions I get these:

$ php tests/performance/test_performance.php empty_span 10000
Profiling PDF generation using 'empty_span' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,614,144     2,969,472     -
Load          2,638,952     2,969,472     0.020193815231323
Render        32,256,704    74,261,640    1.664183139801
Output        32,257,976    74,261,640    0.01250696182251
End           4,676,848

As you can see the GC of PHP7.2 made a huge leap forward and correctly collects (almost) all formerly claimed memory of DomPDF.

[PHPGangsta]

Hi,

I just ran the tests on PHP 7.2.10 on an Ubuntu Server using Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz
Memory usage is roughly the same as PHP 5.4 on Windows, but speed is 3-10 times faster(!):

$ php test_performance.php whitespace 10000
Profiling PDF generation using 'whitespace' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,597,920     2,953,248     -
Load          2,622,744     2,953,248     0.0025770664215088
Render        3,876,472     4,538,648     0.015590906143188
Output        3,877,512     4,538,648     4.7922134399414E-5
End           3,877,968
$ php test_performance.php empty_span 10000
Profiling PDF generation using 'empty_span' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,618,400     2,973,728     -
Load          2,643,224     2,973,728     0.011754989624023
Render        32,261,208    74,266,160    0.99475407600403
Output        32,262,480    74,266,160    9.7990036010742E-5
End           32,262,936
$ php test_performance.php empty_div 10000
Profiling PDF generation using 'empty_div' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,597,920     2,953,248     -
Load          2,622,744     2,953,248     0.0078949928283691
Render        51,882,128    124,739,360   2.3427541255951
Output        51,883,400    124,739,360   8.5830688476562E-5
End           51,883,856
$ php test_performance.php break_tag 10000
Profiling PDF generation using 'break_tag' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,528,280     2,883,608     -
Load          2,553,104     2,883,608     0.0080909729003906
Render        36,158,096    49,725,776    6.9758410453796
Output        36,168,776    49,725,776    0.00062298774719238
End           36,169,232

I'm not sure why sometimes my memory usage is higher than yours, PHP7 should bring some memory savings (10-20%). Maybe it's because I'm using 64bit, and you 32bit PHP/Operating-System?

$ php -v
PHP 7.2.10-0ubuntu0.18.04.1 (cli) (built: Sep 13 2018 13:45:02) ( NTS )
Copyright (c) 1997-2018 The PHP Group
Zend Engine v3.2.0, Copyright (c) 1998-2018 Zend Technologies
    with Zend OPcache v7.2.10-0ubuntu0.18.04.1, Copyright (c) 1999-2018, by Zend Technologies

@MatthiasKuehneEllerhold That looks interesting! I trusted some comments on php.net, thought that memory_get_usage() triggers gc_collect_cycles() internally. But you proved that to be wrong, I should not trust others and check myself :-(
http://php.net/manual/de/function.memory-get-usage.php#101104
http://php.net/manual/de/function.memory-get-usage.php#94645

I just did a very quick test: Disable GC at the start of the render() method, and enabling it at the end:

$ git diff
diff --git a/src/Dompdf.php b/src/Dompdf.php
index d031938..df37e8d 100644
--- a/src/Dompdf.php
+++ b/src/Dompdf.php
@@ -701,6 +701,8 @@ class Dompdf
      */
     public function render()
     {
+        gc_disable();
+
         $this->saveLocale();
         $options = $this->options;

@@ -864,6 +866,9 @@ class Dompdf
         }

         $this->restoreLocale();
+
+        gc_enable();
+        gc_collect_cycles();
     }

     /**

before:

$ php test_performance.php break_tag 10000
Profiling PDF generation using 'break_tag' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,528,280     2,883,608     -
Load          2,553,104     2,883,608     0.0082650184631348
Render        36,158,096    49,725,776    6.9973478317261
Output        36,168,776    49,725,776    0.00060415267944336
End           36,169,232

after:

$ php test_performance.php break_tag 10000
Profiling PDF generation using 'break_tag' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,528,584     2,883,912     -
Load          2,553,408     2,883,912     0.0081119537353516
Render        36,158,432    49,719,360    2.7755401134491
Output        36,169,112    49,719,360    0.00069785118103027
End           36,169,568

The memory consumption did not increase, but the speed is 2.5 times better (2.7 seconds instead of 7 seconds)!
That's a very easy patch with a dramatic improvement.

@bsweeney Maybe you can tell where it makes sense to do this (disable gc and re-enable later) in the code, it should be tested everywhere where hard work is done on lots of objects (loadHtml() maybe?).

[MatthiasKuehneEllerhold]

@PHPGangsta Did you add a gc_collect_cycles() to the GetProfilingInfo() function too? You're values seem to indicate that you didnt...

Composer did something similar see https://news.ycombinator.com/item?id=8686934 .

[PHPGangsta]

@MatthiasKuehneEllerhold No, I did not add it somewhere else, just did a very quick test of disabling and re-enabling GC inside render(). I trust you when you say that you have to call it manually before memory_get_usage() 😄

I wrote about the Composer Installer 5 comments above, that they did exactly the same: disable_gc before some hard work on lots of objects, and re-enabling it afterwards. See my comment above, and the 2 links inside to tideways and blackfire:
#1813 (comment)
I just did the same in the render() method, I did not invent that idea, just applied it 😄

[MatthiasKuehneEllerhold]

Oh sorry, my bad.

[MarkMaldaba]

Hmmm... I can report a similar saving (better, even -> from ~82s -> ~15s) by adding the gc_collect() lines in, when running the break_tag test.

The savings appear to be less good when running the empty_div test, but are still impressive.

I stand corrected! it appears that there may be some good performance wins to be got, by playing with PHP's garbage collection!

Is there any reason not to add the gc_enable/disable lines suggested by @PHPGangsta into the main codebase? We probably need to do a bit more testing on real-world renderings, I suppose, but from what I can see so far, the speed improvement is substantial whilst the memory use is not much different, which makes it a clear win, in my book.

The reason I started this investigation is due to the fact that a relatively long, but relatively simple HTML file, with very light mark-up (no tables, images, floats, etc.) and very little tag nesting, is taking about 8 hours to render! I will re-test with the gc_enable/disable lines in place, to see what difference it makes. If it matches what we've seen above it will be a massive improvement, but would still be taking about 1.5 hours... in which case, this won't be the end of the optimisation story.

In response to @MatthiasKuehneEllerhold:

And a small nitpick: you forgot to unset($HTML); after Line 101. ;)

No I didn't - that is deliberate. For testing memory leaks, we want to compare Start with End, and if you unset $HTML then this will not be a fair comparison (as the variable is set before Start is called).

[MarkMaldaba]

Update: I've re-run my problem PDF, with the gc_enable/disable lines in place, and execution time has dropped from 8 hours, to 55 minutes! Awesome improvement - we will certainly be deploying this fix.

[MarkMaldaba]

FYI: I've just spotted the following on the PHP.net documentation for garbage collection:

Of course, by turning off the garbage collection for certain parts of your application, you do risk creating memory leaks because some possible roots might not fit into the limited root buffer. Therefore, it is probably wise to call gc_collect_cycles() just before you call gc_disable() to free up the memory that could be lost through possible roots that are already recorded in the root buffer. This then leaves an empty buffer so that there is more space for storing possible roots while the cycle collecting mechanism is turned off.

Therefore, this strategy isn't wholly risk free, plus we should probably add a call to gc_collect_cycles() to the start of the render() function, too.

[PHPGangsta]

@MarkMaldaba Good catch!

I just thought about something else: What happens if gc is already disabled by the user, outside of dompdf? Then we would enable it at the end of render(), which might not be what the user expects...

I guess we have to check the status of the gc in the beginning, only disable it if it is not already disabled, and only re-enable it at the end if it was enabled at the beginning of the funktion. Like this:

$ git diff
diff --git a/src/Dompdf.php b/src/Dompdf.php
index d031938..b817cc6 100644
--- a/src/Dompdf.php
+++ b/src/Dompdf.php
@@ -701,6 +701,12 @@ class Dompdf
      */
     public function render()
     {
+        $gcEnabledAtStart = gc_enabled();
+        if ($gcEnabledAtStart) {
+            gc_collect_cycles();
+            gc_disable();
+        }
+
         $this->saveLocale();
         $options = $this->options;

@@ -864,6 +870,11 @@ class Dompdf
         }

         $this->restoreLocale();
+
+        if ($gcEnabledAtStart) {
+            gc_enable();
+            gc_collect_cycles();
+        }
     }

     /**

I think we agree that we should implement it. Question is: Where in the code, in which functions? Just in render()? And maybe later in other functions?

[eothein]

Is this something which a Bachelor student at our college could investigate for his Bachelor thesis?

Kind regards
Jens Buysse

[PHPGangsta]

I just ran the performance test "break_tag" with PHP 7.3.0 RC4 without disabling the GC:

Profiling PDF generation using 'break_tag' over 10000 iterations.
STEP          MEMORY USE    PEAK MEMORY   EXECUTION TIME
Start         2,554,656     2,890,168     -
Load          2,582,544     2,890,168     0.0080699920654297
Render        36,167,440    49,747,400    2.2574598789215
Output        36,243,656    49,747,400    0.0005500316619873
End           36,244,112

As you can see, PHP 7.3 fixed the GC-performance-hit, it is even faster than PHP 7.2 with disabled GC!

Summary:

PHP 7.2 with GC enabled (current DomPDF Code): 7s
PHP 7.2 with GC disabled: 2,7s
PHP 7.3 with GC enabled (current DomPDF Code): 2,3s

If DomPDF disables the GC in the render() function, it improves performance of PHP <= 7.2. For 7.3 it's not needed anymore to disable the GC.

@MarkMaldaba Could you please test your big document that takes hours with PHP 7.3? It should be faster than 55 minutes with 7.3.

[bsweeney]

@eothein it certainly seems to be the case that this might be a good area for investigation. I don't know the release of PHP 7.3 changes your thoughts on that since it appears that GC has significantly improved. Your student could independently study pre-7.3 GC methods and analyze for efficiency in a white box environment. Or perform a comparison between the methods used in the various PHP versions as compared with other research on the topic. PHP is certainly not the only managed memory programming environment.

[bsweeney]

@PHPGangsta this is great news. I've been pretty happy with where PHP has been moving in its 7.x releases (though tbh I'm not able to keep up with the latest developments since my day-job is now in other environments).