1259441 - FF45: Significant increase of delay in communication between PageMod and Backgroundscript

Status: RESOLVED DUPLICATE of bug 1222690

(Add-on SDK Graveyard :: General, defect)

Description

[Daniel Spruth]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.75 Safari/537.36

Steps to reproduce:

My extension was more likely too run into communication timeouts with PageMods after update to Firefox 45. (Currently we dismiss any worker if a message takes longer than 10 seconds to be answered.)
So I wrote a small example Extension as proof of concept, and tested it in Firefox 45 (see actual results) and also in Firefox 44 (see expected results).

In the extension output you can clearly see a significant increase of the time a message needs from Backgroundscript to Contentscript.

The attached extension starts sending messages to the contentscript in an interval of 25ms after a mainframe load was detected. After all content documents got loaded successfully, it keeps measuring for about 10s to include possible delays of the loaded pages. After that timeout, it writes the data seen below to the console, which contains informations about the communication delay between content and backgroundscript. Once the results are logged, another pageload can be done for testing.

I used some bigger pages for my tests, and the results might be slightly affected by loaded ads or similar delays, but in general there shouldn't be such a big reproducable difference between 2 browser versions.


Actual results:

Load measurement for http://www.spiegel.de/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 5264 requests
			 Max: 11626
			 Min: 4
			 Avg: 279.43275075987845
			 About 1 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 5264 requests
			 Max: 1131
			 Min: 4
			 Avg: 43.47701367781155
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 20 requests
			 Max: 1425
			 Min: 20
			 Avg: 713.65

Load measurement for http://www.focus.de/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 1699 requests
			 Max: 5390
			 Min: 4
			 Avg: 89.51442024720424
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 1699 requests
			 Max: 709
			 Min: 4
			 Avg: 28.081812831077105
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 7 requests
			 Max: 685
			 Min: 160
			 Avg: 331.14285714285717

Load measurement for http://www.heise.de/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 5492 requests
			 Max: 7914
			 Min: 4
			 Avg: 133.23379461034233
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 5492 requests
			 Max: 696
			 Min: 4
			 Avg: 48.38037144938092
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 23 requests
			 Max: 456
			 Min: 37
			 Avg: 242.7826086956522

Load measurement for http://example.com/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 353 requests
			 Max: 82
			 Min: 4
			 Avg: 5.592067988668555
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 353 requests
			 Max: 167
			 Min: 4
			 Avg: 5.705382436260623
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 1 requests
			 Max: 578
			 Min: 578
			 Avg: 578

Load measurement for https://www.google.de/?gws_rd=ssl in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 387 requests
			 Max: 663
			 Min: 4
			 Avg: 12.24547803617571
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 387 requests
			 Max: 19
			 Min: 4
			 Avg: 6.056847545219639
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 1 requests
			 Max: 103
			 Min: 103
			 Avg: 103

Load measurement for https://www.youtube.com/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2478 requests
			 Max: 1757
			 Min: 4
			 Avg: 29.691686844229217
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2478 requests
			 Max: 627
			 Min: 4
			 Avg: 13.383373688458434
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 8 requests
			 Max: 549
			 Min: 10
			 Avg: 141.125

Load measurement for http://www.nytimes.com/ in Firefox(x86) 45.0.1 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2402 requests
			 Max: 6305
			 Min: 4
			 Avg: 64.40549542048294
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2402 requests
			 Max: 530
			 Min: 4
			 Avg: 19.26519567027477
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 9 requests
			 Max: 531
			 Min: 104
			 Avg: 218.88888888888889


Expected results:

Load measurement for http://www.spiegel.de/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2946 requests
			 Max: 1598
			 Min: 4
			 Avg: 81.79327902240325
			 About 1 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2946 requests
			 Max: 1230
			 Min: 4
			 Avg: 66.75254582484725
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 20 requests
			 Max: 1330
			 Min: 10
			 Avg: 552.2

Load measurement for http://www.focus.de/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2098 requests
			 Max: 602
			 Min: 4
			 Avg: 19.15395614871306
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2098 requests
			 Max: 627
			 Min: 4
			 Avg: 18.340324118207818
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 7 requests
			 Max: 644
			 Min: 42
			 Avg: 358.85714285714283

Load measurement for http://www.heise.de/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 4829 requests
			 Max: 936
			 Min: 4
			 Avg: 52.95816939324912
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 4829 requests
			 Max: 933
			 Min: 4
			 Avg: 50.5506316007455
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 23 requests
			 Max: 418
			 Min: 154
			 Avg: 311.4782608695652

Load measurement for http://example.com/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 301 requests
			 Max: 56
			 Min: 4
			 Avg: 14.458471760797343
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 301 requests
			 Max: 44
			 Min: 4
			 Avg: 14.401993355481727
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 1 requests
			 Max: 482
			 Min: 482
			 Avg: 482

Load measurement for https://www.google.de/?gws_rd=ssl in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 333 requests
			 Max: 170
			 Min: 5
			 Avg: 15.42042042042042
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 333 requests
			 Max: 184
			 Min: 4
			 Avg: 15.588588588588589
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 1 requests
			 Max: 100
			 Min: 100
			 Avg: 100

Load measurement for https://www.youtube.com/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2437 requests
			 Max: 706
			 Min: 4
			 Avg: 19.04185473943373
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2437 requests
			 Max: 593
			 Min: 4
			 Avg: 16.525646286417725
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 8 requests
			 Max: 642
			 Min: 26
			 Avg: 169.375

Load measurement for http://www.nytimes.com/ in Firefox(x86) 44.0.2 on winnt
	From Background to Contentscript Communication: 
		 Tracked 2390 requests
			 Max: 1415
			 Min: 4
			 Avg: 28.377405857740587
			 About 0 requests failed due to missing target
	From Contentscript to Background Communication: 
		 Tracked 2390 requests
			 Max: 1180
			 Min: 4
			 Avg: 24.794142259414226
	Ping Messages sent directly on initialization of ContentScript: 
		 Tracked 9 requests
			 Max: 1018
			 Min: 54
			 Avg: 505.44444444444446

Comment 1

[Loic]

Do you have a testcase add-on to reproduce the issue? If yes, could you attach the xpi to the bug report and give details to reproduce the bug.

Comment 2

[Daniel Spruth]

Attachment: Extension to reproduce the described bug

Comment 3

[Loic]

What's the output of your extension? The web console of Firefox?

Comment 4

[Daniel Spruth]

Javascript Console of Firefox. Ensure to set extensions.sdk.console.logLevel to info

Comment 5

[Loic]

Regression range:
https://hg.mozilla.org/integration/fx-team/pushloghtml?fromchange=3189c9d88f1357c98dbd7c08c8615af138268807&tochange=5cdf66dfef92364072336ce276f9f2c70d421718

Dave Townsend — Bug 1129662: sdk/page-worker should use a remote page. r=krizsa

Both non-e10s/e10s modes are affected.

Dave, could you check why your patch regressed the perf.

Comment 7

[Loic]

Tracking removed because duped.