Performance down between 0469d9f and b7a21f0 about phar-stream-wrapper HOT 9 CLOSED

Short update: It got better a bit and performance checks are now also part of automated tests, see
b9d2f0b#diff-23cdebbe45c2dda5cda2ff746b280fe6R139

However, there's still some room for improvements concerning Phar\Reader...

from phar-stream-wrapper.

I guess(!) it's the debug_backtrace since the unserialize polyfill most probably is not used in Drupal. If you could create an xdebug cachegrind (https://xdebug.org/docs/profiler) or similar performance report and attach the profiling data with each function call it would be easier to analyse what's really going on in Drush/Drupal.

from phar-stream-wrapper.

Yep, will take a closer look tomorrow. We did have one profiling run and it indicated a ton of files/folders were getting scanned every command we ran, but that was on a more complex site in production. The above timings were done on a separate clean install and didn't have time to set up full xdebug access there yet.

There's a backtrace in the version diff (don't have it in front of me now)? How did I miss that hehe...

from phar-stream-wrapper.

Yes... unfortunately there is... and there's another one pending in PR #22

I could dig into these specific setups as well in case it can be reproduced on e.g. some DDEV/Docker environment.

from phar-stream-wrapper.

I cant' upload the profiles since they are too large - 107MB (4.5MB gzipped) for 2.0.1 and 717MB (32MB gzipped) for 2.1.0.

Interestingly, the v2.1.0 debug_backtrace calls (9885 of them) only take 50ms (all of it own time) which is just 0,1% of the total time 69 365 with profiling enabled in v2.1.0. It had the same number of calls in v2.0.1 but took 21ms. (I thought it was only in 2.1.0 but apparently not.)

Directory scanning does seem to be the major time sink here. The number of calls to drush_scan_directory() stays the same at 2570, but the time shoots up from 6435 (72.3%) to 66176 (95.4%). Its own time stays around ~400ms.

Own time leader for 2.1.0 is TYPO3\PharStreamWrapper\Phar\Reader->extractData with 18299ms (27.2%) which seems to go crazy with tons file operations. It also calls strpos 1 710 430 times and strlen 1 482 802 times. It only takes 72+18ms but still... Most of it seems to be down to callling TYPO3\PharStreamWrapper\Phar\Reader->resolveManifestLength 741 375 times, which in turn calls TYPO3\PharStreamWrapper\Phar\Reader::resolveFourByteLittleEndian 780 915 times and does another 780-850k of substr, unpackand ìs_string`each.
None of these calls were in 2.0.1 so I guess that's where most of the extra time is.

Some other calls in TYPO3\PharStreamWrapper\Phar\Reader end up taking a lot of own time, see screenshots for comparison.

from phar-stream-wrapper.

Thx for analyzing that further. Could you please send me these gzipped profiles? Either via mail to [email protected], Drupal Slack (@olly) or some other download link (Dropbox, GoogleDrive, Gist, ...)? Thx in advance!

from phar-stream-wrapper.

Sure, here you go:
2.0.1
2.1.0
In case you get issues with path mappings the docroot was in /var/aegir/platforms/test and the fresh site was under /var/aegir/platforms/test/sites/drushtest.ny-webb.se for both profiles.

from phar-stream-wrapper.

Please test the references pull-requests #31 (PHP7) or #32 (PHP5) and check whether the originally reported bug of this ticket is solved. Thanks!

from phar-stream-wrapper.

I can confirm that the current release is performing much better. I have not made any timing measurements, but I also no longer have a reason to do so. Thank you very much! :)

from phar-stream-wrapper.