Item9442: The javascript onload takes forever on 1.1 trunk

I raised this last week on IRC but it seems I never raised a bug item on it.

I have setup my Apache for mod_expires.

The URL I test with is

• http://merlin.lavrsen.dk/trunk/bin/view/Main/WebHome for 1.1.0
• http://merlin.lavrsen.dk/foswiki10/bin/view/Main/WebHome for 1.0.10

And it works perfectly. Once a page is loaded clicking on the same topic name in the breadcrumb to reload means that one GET is sent and ONE 200 OK response is returned with the html.

No other files are being loaded. Firefox caches everything as it should.

Still Firebug - and my eyes - see a significant delay from the page loads and till it is displayed fully.

In 1.0.9 the loading happens so the HTML is received after 2.08 seconds. In 1.1.0 it also takes 2.08 seconds. Slow but not slower then 1.0.9.

But the onload increased from 0.8 seconds to 1.5 seconds in addition to the 2.0.8 seconds making the page load take 3.5 seconds in 1.1.0. This is now so long that it is very annoying.

My client is an Atom 1.6 GHz machine with 1 GB of RAM. Not fast. Not the most slow either.

We need to find out why it takes an extra 0.7 seconds for the browser to init the already cached JS and CSS.

This creates a very bad impression of 1.1 to be a major performance set back compared to 1.0.10 and personally I'd rather stick to 1.0.9 if this is the performance we get from 1.1.0

-- KennethLavrsen - 09 Aug 2010

Micha and I discussed the issue and Micha noticed some important details that could be the root cause and therefore also a maybe not so difficult path to getting performance back

[21:41] <Lavr> Didn't I waise a bug report about the slow init of JS? I cannot find it.
[21:41] <gac410> I remember seeing it
[21:43] <Lavr> I raised one about edit but I cannot find the one about normal view and the time it takes from HTML is loaded and until the already cached JS is loaded.
[21:44] <Lavr> I will raise it then. It is what makes trunk seem so dead slow.
[21:45] <MichaelDaum> Lavr, I tried to repro your findings about js taking ca a second to init the page ... without success. can you please attach the raw html to the bug report?
[21:46] <Lavr> I just tried again. Same thing. http://merlin.lavrsen.dk/trunk/bin/view/Main/WebHome
[21:46] <Lavr> My test server is public as it has been for several years.
[21:46] <Lavr> And compare with http://merlin.lavrsen.dk/foswiki10/bin/view/Main/WebHome
[21:47] <Lavr> Which is what would be 1.0.10
[21:47] <Lavr> Both loads the html in 2.08 seconds +/- 50 ms.
[21:47] * MichaelDaum checking
[21:48] <Lavr> But the time it takes before onload is done has increased from dramaticly. And I am talking also the basic human impression.
[21:48] <Lavr> I am testing with an Atom 1.6 GHz machine. Not the most fast machine in the world but not the most slow either.
[21:49] <MichaelDaum> I get 2 seconds til  first byte arives, and 3 seconds til page is ready
[21:49] <MichaelDaum> (on a second load with js cached)
[21:50] <Lavr> It takes 0.8 seconds to load 1.0.10 which I already feel is slow. And in 1.1 I get 1.4-1.5 seconds on top of the 2 seconds.
[21:50] <MichaelDaum> not here
[21:50] <Lavr> So why is 1.1 JS init increased from 0.8 to 1.4?
[21:51] <MichaelDaum> 1.6 to load, 2.4 to be ready
[21:51] <MichaelDaum> on 1.0.10
[21:51] <MichaelDaum> ca same delay between load and ready
[21:51] <Lavr> I consistantly measure AND experience a much longer delay on trunk. And this is with Firefox latest and greatest
[21:51] <MichaelDaum> fluctuates a lot
[21:52] <Lavr> You also see the fluctuations of the 2 Mbit ADSL line. I see it on a Gigabit Ethernet.
[21:53] <MichaelDaum> There are 44 components with misconfigured ETags
[21:53] <MichaelDaum> according to YSlow
[21:53] * ktwilight_ has quit IRC (Remote host closed the connection)
[21:53] <MichaelDaum> favicon.ico hasn't got any expire header
[21:54] <MichaelDaum> both have 22 files, 4 js files
[21:55] <Lavr> What I see in Firebug is that mod_expires works. None of the JS or CSS is reloaded or checked for timestamp.
[21:56] * ktwilight has joined #foswiki
[21:56] <Lavr> The onload is browser running the JS already cached. Or CSS.
[21:56] <Lavr> And the only JS we really have active on Main.WebHome are the search and jump fields in WebTopBar.
[21:57] <MichaelDaum> I have a 1.57sec delay to get a single png
[22:02] <Lavr> When I use Wireshark I see ONE GET answered by one 200 reply with the HTML. Nothing loaded from server. mod_expires works great. ALl the delay is in the browser.
[22:02] <MichaelDaum> http://merlin.lavrsen.dk/trunk/pub/System/ProjectLogos/favicon.ico has got an etag but no expire header
[22:03] <MichaelDaum> try wget --server-response http://merlin.lavrsen.dk/trunk/pub/System/ProjectLogos/favicon.ico
[22:04] <Lavr> Yes. What should I look for
[22:04] <Lavr> ?
[22:05] <Lavr> It loads in 0 seconds and saves it
[22:05] <MichaelDaum> how's your apache configured? is your foswiki in a vhost or using some conf.d file?
[22:05] <Lavr> conf.d
[22:05] <Lavr> no virtual
[22:06] <Lavr> no mod_perl no mod_fcgi at the moment either. Plain good old CGI.
[22:06] <MichaelDaum> grep for ExpiresDefault and check the  <location> or <file...> or <directory> it is placed into
[22:07] <MichaelDaum> most probably it only applies to pngs and family plus css and js
[22:07] <MichaelDaum> not so on ico
[22:08] <MichaelDaum> add a FileETag none as etags are making things worse for browser caching. relying on Expires headers is enuf
[22:09] <MichaelDaum> receiving pngs from your server takes longer than the html
[22:09] <MichaelDaum> bout twice as long
[22:10] * MichaelDaum is on a wireless
[22:11] <Lavr> But the ico is not attempted reloaded. I can see that on Wireshark.
[22:11] * MichaelDaum clearing the browser cache
[22:12] <MichaelDaum> pattern loads a lot of js that is not used on that url, e.g. calendar.js
[22:13] <MichaelDaum> pattern_edit.js
[22:13] <MichaelDaum> there are 11 additional js files on trunk
[22:14] <Lavr> If the JS is not running it should not delay anything. There must be a lot of code that runs.
[22:16] <MichaelDaum> can you disable OptimizePageLayout for a moment?
[22:16] <MichaelDaum> on trunk
[22:17] <Lavr> Done
[22:18] <MichaelDaum> thats better, isn't it
[22:18] <Lavr> Loading in my Firebug now takes 0.1 seconds longer. From 3.5 seconds to 3.65
[22:18] <Lavr> So not better
[22:19] <MichaelDaum> don't use firebug + net pane for measuring the times
[22:19] <MichaelDaum> use lori instead
[22:19] <Lavr> lori?
[22:19] <MichaelDaum> firebug in itself is taking away a lot of cpu
[22:20] <Lavr> lori (Life-of-request info)   ?
[22:20] <MichaelDaum> https://addons.mozilla.org/en-US/firefox/addon/1743/
[22:20] <Lavr> Installing
[22:20] <MichaelDaum> then measure times while disabling firebug
[22:21] <MichaelDaum> I've got a 600ms delay between dom ready and page loaded
[22:22] <MichaelDaum> still too much js loaded to the page
[22:23] <Lavr> I get 2.081 / 2.668 for trunk
[22:23] <Lavr> And 2.068 / 2.485 for 1.0.10
[22:23] <MichaelDaum> that's okay for the amount of js being loaded ... and init'ed
[22:24] <Lavr> So less diff. Let me try with page optimize on again
[22:24] <MichaelDaum> 600ms for that number of js is normal...so now it is to down the number of js loaded by default
[22:24] <MichaelDaum> e.g. why does it load pattern_edit
[22:24] <MichaelDaum> on a view screen
[22:25] <MichaelDaum> or calendar.js with no calendar in sight
[22:25] <MichaelDaum> bgiframe is only needed for IEs
[22:26] <Lavr> With page optimize I get 2.080 / 2.716 for trunk
[22:26] * MichaelDaum checking again
[22:26] <MichaelDaum> y
[22:27] <MichaelDaum> okay still 600ms hm
[22:28] <Lavr> I created the Item9442: The javascript onload takes forever on 1.1 trunk for this one. I will paste the discussion we have now in to this later
[22:28] <MichaelDaum> checked 10 calls to main.webhome... all of them had a 600ms difference between dom ready and page loaded
[22:28] <MichaelDaum> k
[22:29] <Lavr> One difference from 1.0.10 to 1.1.0 is the intro of JQuery js files. Do they all run some init code?
[22:29] <MichaelDaum> nope
[22:30] * MichaelDaum checking 10 calls to main.webhome on 1.0.10 now
[22:31] <MichaelDaum> that's about a 40ms diff between dom ready and page loaded
[22:31] <MichaelDaum> 400ms I mean
[22:31] <Lavr> 1.0.10 is also slow. It is just that my experience is that on 1.1 you feel the delay "on your body" now. LIke it has passed some threshold.
[22:31] <Lavr> Some human experience threshold that is.
[22:32] * MichaelDaum now comparing skin=plain on both
[22:32] <Lavr> What is left using /trunk/pub/System/BehaviourContrib/behaviour.js ?  I thought everything had gone jQuery now.
[22:33] <MichaelDaum> y
[22:34] <MichaelDaum> skin plain also loads jquery but is significantly faster initing the page
[22:34] <MichaelDaum> with about 250ms seconds diff
[22:35] <Lavr> The 4 jQuery js files are for sure new since 1.0.10. 
[22:35] <MichaelDaum> the extra jquery do count
[22:35] <MichaelDaum> during init
[22:35] <MichaelDaum> but only about an extra 100ms roughly
[22:36] <MichaelDaum> so there are another 100ms that are spent somewhere else
[22:37] <MichaelDaum> 200ms difference between trunk and 1.0.10 is what I can see on your server
[22:37] <MichaelDaum> with jquery being the obvious difference
[22:38] <MichaelDaum> jscalendar is different as well
[22:38] <MichaelDaum> there's no jscalendar loaded on 1.0.10 as far as I can see
[22:38] <Lavr> Hmmm. Have someone changed that plugin to always load the JS?
[22:39] <MichaelDaum> similarly pattern_edit.js
[22:39] <Lavr> It can be that some edit js needs to be loaded for EditTablePlugin that edits in view mode. But then it should still only be if there is an edit table on the page.
[22:40] <MichaelDaum> next difference is foswiki_edit.js ... loaded on trunk ... not so on 1.0.10
[22:42] <Lavr> So it seems we may have a good chance of winning some performance back simply by loading these js files more intelligently.
[22:43] <MichaelDaum> seems so
[22:43] <Lavr> The delay when you edit is not so critical. It is the navigation where you jump from link to link - often knowing exactly where you want to go - that slows down with the long page loading.

-- KennethLavrsen - 09 Aug 2010

From what I can gather in the above conversation, the issue is we are loading too much unnecessary JS.

Set to confirmed.

-- PaulHarvey - 10 Aug 2010

When I went through changing ADDTOHEAD to ADDTOZONE recently, I tried to rationalise the dependencies as much as possible without changing too much code. Some, such as BehaviourContrib, I couldn't eliminate because the JS is depended on by core extensions, without any explicit statement of that dependency (such as an ADDTOZONE) in the extension itself.Even if the dependency is expressed, the extensions are ubiquitous enough that the dependency is "always on" anyway.

• Core
  • EditTablePlugin
  • JSCalendarContrib
  • TinyMCEPlugin
  • TwistyPlugin
  • TwistyContrib
  • PatternSkin
• Non-core
  • EditRowPlugin
  • SlionSkin

The problem is that to resolve the dependency in the plugins requires an ADDTOZONE call, which creates a dependency on the ZonePlugin that wasn't there before for 1.0.9 users. ADDTOHEAD{"BehaviourContrib"} would be a workaround.

-- CrawfordCurrie - 10 Aug 2010

Why not add a dependency on ZonePlugin? That's what it is for: let plugin authors move forward while still providing backwards compatibility.

-- MichaelDaum - 10 Aug 2010

My timing tests are as follows, using ObjectPlugin:4d448ff7e6b0 and FastCGIEngineContrib with expires/headers "properly" configured (although my refresh button negates that stuff). On Firefox with Lori. {OptimizePageLayout} = 1;. I keep hitting refresh until I get what I estimate is a representative total (not first byte) view.

PatternSkin on TestTopicTiming (view)

Change	Load	Response	Total	Load Difference
jquery-1.4.2	0.184	0.124	0.308
jquery-1.3.2	0.176	0.125	0.301	0.008
- JQueryBGIFrame	0.173	0.123	0.296	0.003
- JQueryEasing	0.168	0.125	0.293	0.005
- JQueryFoswiki	0.16	0.128	0.288	0.008
- JQueryPlugin	0.142	0.124	0.266	0.018
{Validation} = embedded	0.136	0.123	0.259	0.006
- pattern_edit	0.133	0.123	0.256	0.003
- foswiki_edit	0.13	0.124	0.254	0.003
- pattern	0.121	0.119	0.240	0.009
- foswikiForm	0.114	0.123	0.237	0.007
- foswikiCSS	0.11	0.123	0.233	0.004
- foswikiHTML	0.109	0.122	0.231	0.001
- foswikiEvent	0.108	0.122	0.230	0.001
- foswikiWindow	0.101	0.123	0.224	0.007
- foswikiString	0.1	0.123	0.223	0.001
- foswikiPref	0.097	0.120	0.217	0.003
- foswikiStyles	0.091	0.118	0.209	0.006
- foswikiStyles	0.091	0.118	0.209	0
- foswikilib	0.09	0.118	0.208	0.001
- behaviour	0.079	0.119	0.198	0.011
- variant_foswiki_noframe.css	0.079	0.119	0.198	0
- column_left.css	0.079	0.119	0.198	0
- layout.css	0.078	0.115	0.193	0.001
- style.css	0.072	0.115	0.187	0.006
- colors.css	0.064	0.120	0.184	0.008
- print.css	0.061	0.118	0.179	0.003

Analysis

Load time is supposed to be: 0.176 with 0.061 processing the document

Thing	Time	%
JQueryPlugin	0.018	10.23
BehaviourContrib	0.011	6.25
CSS	0.018	10.23
foswiki*	0.031	17.61
pattern*	0.012	6.82
foswiki_edit*	0.003	1.7
strikeone	0.006	3.41
JQueryFoswiki	0.008	4.55
JQueryEasing/BGIFrame	0.008	4.55
Document	0.061	34.66
Total	0.176	100.01

It seems that the load times are then roughly broken up as:

Thing	%
"legacy" js	32.38
"new" (JQuery) js	19.33
CSS	10.23
Document	34.66
Strikeone	3.4
Total	100

default skin on TestTopicTiming (view)

Change	Load	Response	Total	Load Difference
jquery-1.4.2	0.079	0.088	0.167
jquery-1.3.2	0.075	0.085	0.160	0.004
- JQueryBgiFrame	0.075	0.085	0.160	0
- JQueryEasing	0.068	0.086	0.154	0.007
- JQueryFoswiki	0.055	0.083	0.138	0.013
- JQueryPlugin	0.038	0.081	0.119	0.017
{Validation} = embedded	0.029	0.084	0.113	0.009
- base.css	0.026	0.083	0.109	0.003
- default.css	0.024	0.083	0.107	0.002

-- PaulHarvey - 12 Aug 2010

• #Set NOWYSIWYG = 0
• #Set TINYMCEPLUGIN_DISABLE = 0

okey doke, I did my bit. Not sure it's going to be enough, but that's as much as I can manage in a day.

-- CrawfordCurrie - 12 Aug 2010

Which core extensions are still using behaviour.js? I can only find TwistyPlugin, but it's jquery code version is now the default.

It looks like BehaviourContrib can be removed.

-- ArthurClemens - 12 Aug 2010

One file less: I have moved the code from foswikiStyles.js to jquery.foswiki.js.

-- ArthurClemens - 12 Aug 2010

Two other things to improve performance:

1. remove the icons from the left bar
2. combine the 3 pattern CSS files to 1
   • I am seriously considering this: why loading 3 separate files? The CSS is separated because this is handy for development, I no longer believe users will be using these 3 files. -- ArthurClemens - 15 Aug 2010
   • It won't make much difference, AFAICT. The CSS are loaded in parallel to the JS, and none is very big. -- CrawfordCurrie - 16 Aug 2010
   • It may help a tiny bit: I now offer the files compressed. -- ArthurClemens - 18 Aug 2010

-- ArthurClemens - 12 Aug 2010

Good work Crawford. I get 259ms total load time now; roughly 14% improvement.

-- PaulHarvey - 13 Aug 2010

OK, I'm finished. Reckon I've eliminated/combined/collapsed all I can.

-- CrawfordCurrie - 18 Aug 2010

A next step would be the smart combining of files and fragments. Theoretically, not sure if this holds in a dynamic environment as Foswiki.

-- ArthurClemens - 18 Aug 2010

Hi Crawford,

I will do repeat my tests tomorrow.

However, Twisties are broken because patter.js errors out due to missing foswikiForm and foswikicCSS.

This diff was required to get things going again:

diff --git a/PatternSkin/templates/foswiki.pattern.tmpl b/PatternSkin/templates/foswiki.pattern.tmpl
index 7b1dabc..15d54df 100644
--- a/PatternSkin/templates/foswiki.pattern.tmpl
+++ b/PatternSkin/templates/foswiki.pattern.tmpl
@@ -55,8 +55,11 @@
 }%%TMPL:P{"JavascriptFiles/foswikilib"}%%{
 }%%TMPL:P{"JavascriptFiles/foswikiString"}%%{
 }%%TMPL:P{"JavascriptFiles/foswikiPref"}%%{
-}%%TMPL:P{"LIBJS" id="PatternSkin/pattern" requires="JavascriptFiles/foswikilib,JavascriptFiles/foswikiPref"}%%TMPL:END%
-
+}%%TMPL:P{"JavascriptFiles/foswikiForm"}%%{
+}%%TMPL:P{"JavascriptFiles/foswikiCSS"}%%{
+}%%TMPL:P{"LIBJS" id="PatternSkin/pattern" requires="JavascriptFiles/foswikilib,JavascriptFiles/foswikiPref,JavascriptFiles/foswikiForm,Javasc
+%TMP:DEF{"JavascriptFiles/foswikiForm"}%%TMPL:P{"LIBJS" id="JavascriptFiles/foswikiForm" requires=""}%%TMPL:END%
+%TMP:DEF{"JavascriptFiles/foswikiCSS"}%%TMPL:P{"LIBJS" id="JavascriptFiles/foswikiCSS" requires=""}%%TMPL:END%
 %TMPL:DEF{"bodystart"}%<body class="%TMPL:P{"bodyclassname"}%">
 #PageTop%TMPL:END%

-- PaulHarvey

Apologies, pattern had a dependency on foswiki.Form that I'd missed somehow.

-- CrawfordCurrie - 18 Aug 2010

My impression both human and what the numbers say with Lori is that we are very near being back at 1.0.9 performance.

I am OK with closing the bug now - unless there are more glitches.

-- KennethLavrsen - 18 Aug 2010

In the last 24hrs or so, we added a new dependency JQueryLiveQuery. So I am seeing ~256ms now with it disabled, but ~265ms with it on. I was seeing ~260ms from Crawford's first round of changes.

My testing methodology is hardly robust, however, and so if the human experience is comparable to 1.0.9 then I am not too worried, we can downgrade to Normal.

I do want to know why JQueryEasing and JQueryBgiFrame are mandatory dependencies though, seems that dumping these could be an easy way to shave 4-5% off the onload time. They don't seem to be used in default or PatternSkin. Michael?

-- PaulHarvey - 19 Aug 2010

Bgiframe should only be loaded if the current browser is an IE6 or should be disabled by default, imho. Saves another 543 bytes Btw, we should add context identifiers to indicate the type of browser we have.

Eeasing adds additional animation styles, about 865 bytes extra. Can't possibly be a problem.

Both can't account for any perceivable extra load.

Nor can changing dependencies make any difference. livequery is used by almost all jquery modules, so that their widgets can be loaded via ajax.

Anything below 50ms difference is not significant. I'd only look for changes that add more than 100ms.

Another optimization step would be to combine any jquery...js with its jquery...init.js counterpart. That'd halfen the number of jquery files being loaded.

Is it possible to tell BuildContrib to concatenate two js files on build time? If that's not easily doable I'd prefer to defer this step for later and concentrate on the more sever ReleaseBlockers.

-- MichaelDaum - 19 Aug 2010

Our onload situation is a death by a thousand cuts. If nothing in the default skin uses easing (I don't see any call to .animate() ), then why not turn it off? It's like a 3-line diff; saves another HTTP requests, and if we can keep finding these easy 20-50ms savings then I would call that a win.

-- PaulHarvey - 19 Aug 2010

+1. After all the effort I put in to optimise out the default libs, it's frustrating to see time being eaten up again loading stuff that isn't used. And Paul is dead right; it's the extra separate HTTP requests that eat up the time.

-- CrawfordCurrie - 19 Aug 2010

Removed bgiframe and easing from defaultplugins. So I think this task has run its course; moving on to other ReleaseBlockers

-- PaulHarvey - 19 Aug 2010

Comparing a checkout of distro:36dd45606495 vs distro:c1d75950236d, which includes Arthur's simplified CSS and culling more foswikiilb stuff, we're 8% faster.

-- PaulHarvey - 27 Aug 2010