Major performance issues for a simple PDF file

[timvandermeij]

I have created a simple PDF file using Scribus 1.5.0svn. Notice that the file size is large for a two-page PDF file, so I can only suspect that Scribus is doing something really unefficient when exporting the PDF file. Nevertheless, the PDF file below renders instantly with both Adobe Acrobat Reader DC and Foxit Reader (within 0.5 seconds), however PDF.js takes 27 seconds to render only the first page of this file. I have no idea why PDF.js is taking such an excessive amount of time, but we need to do better here, given that other viewers do not have any problems with this file. Are there perhaps inefficient patterns in this file that the optimizer could remove? I notice that the PDF file contains an excessive amount of resources in the Resources dictionary of each page (XObject, Font, Pattern and ExtGState).

Below is the PDF file. I made this myself, so anyone is free to use this as a test case in a PR that addresses this issue:
test.pdf

[Rob--W]

The CPU profiler shows that most of the time is spent in PartialEvaluator_hasBlendModes:

pdf.js/src/core/evaluator.js

Lines 144 to 200 in a0aa781

	hasBlendModes: function PartialEvaluator_hasBlendModes(resources) {
	if (!isDict(resources)) {
	return false;
	}
	var processed = Object.create(null);
	if (resources.objId) {
	processed[resources.objId] = true;
	}
	var nodes = [resources];
	while (nodes.length) {
	var key;
	var node = nodes.shift();
	// First check the current resources for blend modes.
	var graphicStates = node.get('ExtGState');
	if (isDict(graphicStates)) {
	graphicStates = graphicStates.getAll();
	for (key in graphicStates) {
	var graphicState = graphicStates[key];
	var bm = graphicState['BM'];
	if (isName(bm) && bm.name !== 'Normal') {
	return true;
	}
	}
	}
	// Descend into the XObjects to look for more resources and blend modes.
	var xObjects = node.get('XObject');
	if (!isDict(xObjects)) {
	continue;
	}
	xObjects = xObjects.getAll();
	for (key in xObjects) {
	var xObject = xObjects[key];
	if (!isStream(xObject)) {
	continue;
	}
	if (xObject.dict.objId) {
	if (processed[xObject.dict.objId]) {
	// stream has objId and is processed already
	continue;
	}
	processed[xObject.dict.objId] = true;
	}
	var xResources = xObject.dict.get('Resources');
	// Checking objId to detect an infinite loop.
	if (isDict(xResources) &&
	(!xResources.objId || !processed[xResources.objId])) {
	nodes.push(xResources);
	if (xResources.objId) {
	processed[xResources.objId] = true;
	}
	}
	}
	}
	return false;
	},

To profile (using Chrome), simply:

1. Download test.pdf from above.
2. Visit https://mozilla.github.io/pdf.js/web/viewer.html?file=
3. Open the developer tools, go to the Profiles tab.
4. Open test.pdf with PDF.js
5. Select "Target: pdf.worker.js" and click on Start to profile
6. Whenever you feel ready (e.g. when the CPU is idle), stop the capture.
7. Analyse the results.

[timvandermeij]

Thank you for profiling this! This code seems to loop over (potentially) all ExtGState and XObject dictionaries, and there are a lot of them in this PDF file. I'm afraid the in operator might cause delays here.

[timvandermeij]

I have narrowed down the flaw a bit. For the first page,

pdf.js/src/core/evaluator.js

Line 182 in a0aa781

if (processed[xObject.dict.objId]) {

is triggered almost 31000 times, meaning that we attempt to process a lot of XObjects that we already processed before.

[Snuffleupagus]

This seems to do the trick, but I've not had time to run tests yet: master...Snuffleupagus:issue-6961.
Also, I'm not sure what kind of test we can add for this, will look into this more later tonight.

[timvandermeij]

Funny, I also tried using getKeys() in a local test, but with no result, possibly because I missed master...Snuffleupagus:issue-6961#diff-0b94c2e77a5259f7a728122fdbf9f46aR182. Thanks for looking into this!

[Snuffleupagus]

So, my patch seems to pass all tests locally, but there're two problems:

• First of all, how do we test this? Given that the run time is hardware/software dependent, I'm not sure how we can assert that a test doesn't run for too long!?
• Second of all, I don't understand why the patch actually works ;-)
  https://github.com/Snuffleupagus/pdf.js/blob/21a19c1a1cdeb1bb9ddae8a44e7da00c241c899e/src/core/evaluator.js#L193-L197 ought to be enough, since as far as I can tell xObject.dict.objId always seem to equal xObjects.getRaw(key).toString() in this PDF file.

[timvandermeij]

The only test I can imagine is a unit test where we assert that the number of processed XObjects is less than it is currently. It's not great, but it's the only kind of test I can come up with since measuring the runtime is not an option. Otherwise I think it suffices to review the patch, test it manually and make sure that the test suite passes.

Regarding the second point, I would have to look into this more. If they are equal then the current code should do, so I'm not yet sure what the difference is with your patch.

[Rob--W]

First of all, how do we test this? Given that the run time is hardware/software dependent, I'm not sure how we can assert that a test doesn't run for too long!?

27 seconds for such a simple PDF is excessive. We could create a suite of PDFs whose rendering time is measured (can be as simple as subtracting two time stamps), and then report the results to some central place. If we occasionally look at the results (e.g. a table, or a fancy graph), then we should get a good picture of what rendering times are normal and detect performance regressions.

Second of all, I don't understand why the patch actually works ;-)

What exactly is unclear? Replacing getAll with getKeys seems like an obvious boost, is there something else with your patch that magically improves the runtime?

[Snuffleupagus]

What exactly is unclear? Replacing getAll with getKeys seems like an obvious boost, is there something else with your patch that magically improves the runtime?

The getKeys change is not noticeable in the grand scheme of things, the real improvement comes from master...Snuffleupagus:issue-6961#diff-0b94c2e77a5259f7a728122fdbf9f46aR186.
In practice that check seem, for all intents and purposes, to be equal to an already existing check just below (as I commented above):

https://github.com/Snuffleupagus/pdf.js/blob/21a19c1a1cdeb1bb9ddae8a44e7da00c241c899e/src/core/evaluator.js#L193-L197 ought to be enough, since as far as I can tell xObject.dict.objId always seem to equal xObjects.getRaw(key).toString() in this PDF file.

[Rob--W]

Using getAll results in traversing the whole tree and fetching Refs.
Using getKeys merely requires looking up all keys. But I think that if you call fetch on every Ref value, then you're getting a similar runtime as when you're using .getAll. By skipping .fetch if the Ref is already known, you're saving the overhead of resolving Refs.

(this is my guess, I didn't check whether it is really the reason).

[yurydelendik]

The reason above somewhat right. We had a thought to disable getAll(), not for performance but because it can pull recursively not-needed data into operator list. We probably need to review all getAll usages and remove it.

[Snuffleupagus]

@Rob--W You are absolutely correct, I don't know how I missed that myself. Thank you!