|Title|Clicking on 'more info' on http://www.jspwiki.org/wiki/Main takes a very long time
|Date|24-Sep-2005 01:28:46 EEST
|[Bug criticality]|LightBug
|Browser version|
|[Bug status]|ClosedBug
|[PageProvider] used|
|Servlet Container|
|Operating System|
|Java version|

Clicking on 'more info' on http://www.jspwiki.org/wiki/Main takes a very long time. 

I would like to profile what the problem is and maybe then fix it.
Therefore I need the complete wiki-data-directory of the site http://www.jspwiki.org/
Is there a way to get this? 
Or could some one create a tgz/zip file?

-- KeesKuip

Ok.  Here's a snapshot of the latest file. [http://www.ecyrd.com/~jalkanen/JSPWiki/snapshot.tgz].  I will also put it on [JSPWikiSnapshot].


OK, here are the first results. (I already posted yesterday but I thought my measurements were wrong so I removed them late at night).

Here's how I test:
* undeploy JSPWiki
* deploy war
* start profiler (which starts tomcat)
* call page Main
* start profiling the cpu.
* call page 'More info' of Main-page
* stop profiling (measurement 1)
* call page Main
* start profiling the cpu.
* call page 'More info' of Main-page
* stop profiling (measurement 2)
* .. and the same way for (measurement 3)

I measure 262883/263008/269400 msec. (measurement 1/2/3) for jspwiki v2.2.33.

I notice a hotspot in FileUtil.java.copyContents(). I changed the method so that it would read more than 1 byte/char at one time and write more than 1 byte/char at one time. This resulted in a measurement of 53657/34565/35238 msec.

The result is an improvement in speed of 5-7 times the orginal. Not bad for a first run!. I attached the new FileUtil.java (It is backward compatible).

-- KeesKuip

More results.

In the snapshot after the fileutils-patch I noticed a hotspot in loading property files. When I call page 'More Info' of the page 'Main' I see that there are 2419 invocations to properties.load(). That must be wrong!

So I debugged it a little bit and saw that very often the propertyfile is asked that had just been asked before. So I decided to cache only (in a safe way) the last loaded propertyfile in [VersioningFileProvider.java]. That resulted in 150 invocations to properties.load(). Much less, but I smell bad programming here.

The measurements are:\\
before: 53657/34565/35238 msec (see previous post)\\
after: 19417/19251/18634 msec.\\
An improvement of almost 2x.

So patch 1 and 2 together give an improvement in cpu-time of about 13x.
(Mind you: This patch does give a 2x improvement but calling load-properties 150x for  1 page just smells like something is wrong in the design.) 

This patch is downward compatible.

More to come.

-- KeesKuip.

The next culprit was the PageSizeTag. It calculates the pagesize in a very cpu-intensive manner. The pagesize is then initialized in wikipage.setSize() so the next time it is known immediately.

A wikipage is loaded with the "PageManager" that lets a "FileProvider" implements its "getPageInfo()" method. This getPageInfo() returns a WikiPage. So why not set the size of the WikiPage in that method? I did it for VersioningFileProvider and got the following measurements:\\ 
before: 19417/19251/18634 msec. (see previous post)\\
after: 9330/8021/7890 msec.\\
An improvement of more than 2x.

So all patches together give an improvement in cpu-time of more than 30x.

This patch is downward compatible. The patch is also done in [VersioningFileProvider.java]. So the attached file combines patch 2 and 3.

-- KeesKuip

Oef, A major setback!

I changed the FileUtils.copyContents() (see patch1) twice. One for an InputStream and once for a Reader. The changes were both perfectly allowed and good. But there is a reader TranslatorReader which has not implemented its contract as a Reader good. The  results are that with the changes in patch1 I get empty pages. So for now I've reversed the change in copyContents of the Reader. 

The performance improvement of patch1 will now be 4x ! I measure 66529 msec.

I've already patched TranslaterReader, but it will not perform any better. The problem is this: The CheckVersionTag wants to now if a page exists with a certain versionnumber. So it only want's to know if a page exists but then the complete page is read in memory and translated. This is just bad! The pageExists takes 56222 msec of the total of 66529 msec!!!! 

Just look at the profile for this problem:

-- KeesKuip

Kees, don't worry.  The 2.3 translator works far better with respects to your first issue.  Don't worry about it too much.  The latter is a problem, I admit.  It is easily fixed by making the call to pageExists() use the pageExists( page.getName() ) instead of just page - this way any existence of the page is checked.

-- JanneJalkanen

OK, your right! If I check if the pageExists(page.getName()) AND verify that the version number is smaller then we can be pretty sure that pageExists(page.getName(), version) exists.

I think The performance gain would then be back to 30x. Which would be nice because the frontpage gets defaced quite often and it takes a long time to de-deface it. 

-- KeesKuip.

First many thanks for improving the speed of JSPWiki, I am very happy about this! After making these fixes can you perhaps check whether similar bottlenecks exist in the page preview or page save actions? Under JSPWiki 2.2.28 or 2.2.33 these seem to be highly variable, and sometimes taking very long, which is very annoying in the process of editing (especially when waiting for preview to fix unwanted ~CamelCase). On the JSPWiki.org site this may be attributed to concurrency issues, but on our test intranet site the problem occurs as well and concurrency can be excluded. -- Gregor Hagedorn, 2005-10-04


I've uploaded WikiEngine.java with the new (simple) pageExists(). Could you check that method Janne? because I removed a lot of code that maybe I didn't understand correctly.

The results are : 3033/3135/2406 msec.

Thats 80x faster as my first measurement. (wow) 

Could you please delete/forget FileUtil.java because it doesn't function wel with TranslaterReader?

Gregor, you say concurrency can be excluded but there's Lucene running in a separate thread. Is that maybe what you see? I'll see if I got time to profile some more.

-- KeesKuip

Just a quick note... Pleasepleaseplease start posting diffs instead of new files.  These are nearly worthless to me, as I need to manually check what happened, and for a large file such as WikiEngine.java this is hard.  And if something is hard, I am unlikely to be bothered, no matter what it does.  I only have limited time to work on JSPWiki.  I'll look into this sometime in the future.

With Eclipse, for example, creating a diff (or in Eclipse-talk, a patch) is trivial.  Choose Team->Create Patch.

-- JanneJalkanen

Ok, point taken.
I will create some patch files for you tonight. Against what version? 
Are you using Linux? Yes, than you can use 'meld' (sourceforge) as an excellent merge tool.

-- KeesKuip

I'd prefer 2.3.x, since that's where main development goes now.  If the patch is simple, then 2.2.33 is fine, too.

I use Linux or OSX, but always Eclipse (which has a wonderful merge tool already ;-)

-- JanneJalkanen

I attached the 2 patches. I created them using 'diff -u' (unified diff) with 2.2.33.

-- KeesKuip

Thanks Kees!  (They looked diff -c to me, though.) I took the VersioningFileProvider patch in 2.3.29, but the other patch is a bit problematic: it assumes that the history is not "gappy", i.e. nobody has deleted any versions from the middle.  This is not a good assumption for the future, so it can't be done :-/.  I think the proper way to fix this is to fix the entire Provider interface :-/

-- JanneJalkanen

OK, I'm not very happy about the other patch but I understand your reasoning.

So why not extend the WikiPageProvider-interface with a pageExist(String name, int version) method? This would be the simplest thing to do for now and it can be very fast because now I can circumvent the CachingProvider which takes all the time when filling in the attributes of the metadata of that WikiPage. 

How's that? I'll be happy to program it and send you a patch-diff-u (I really want it to be faster).

-- KeesKuip

That would be a right way to do it, yes.  The trouble is that that breaks the API, and I want to change the API completely anyway... I'd rather do it in full.

However, note that page histories are being cached.  If pageExists() were to call getVersionHistory() and check it from that list, it might be a lot faster (except for simple cases).

-- JanneJalkanen

Couldn't we decide to hack PageManager and CachingProvider it only for speeding up VersioningFileProvider? I think a complete rebuild of Provider would take a serious amount of time.

I really think this is a problem. I timed the time it needs to click 'More info' on the www.jspwiki.org and it took 2,5 minutes! That's 2,5 minutes that the wiki is taking 100% cpu (now imagine 24 people clicking on it in 1 hour). This is one of the first things a new user of jspwiki notices (I noticed it anyway).

-- KeesKuip

Hacking PageManager and CachingProvider is okay; but changing the API should be done very carefully, and preferably many changes at a time.  Otherwise you end up with "this provider works with 2.2.12, this provider with 2.3.42-2.3.85, this provider with 2.4.x, but not with 2.4.5-7", etc.  This gets very confusing to the users at some point.  This is why I would like to make major changes all at once.

So, I would like to investigate if there are things we can do with the current code base that does not involve changing the API... Those changes can even be drastic, we'll clean them up later.

-- JanneJalkanen

Here's the patch [VersioningFilePageExistPatch.patch].
The WikiEngine now asks the pageManager.pageExist(pageName, version). If the provider is a CachingProvider and that CachingProvider has a realProvider of VersioningFileProvider I ask directly the PageInfo from the VersioningFileProvider. The results are below.

before: 62182 / 52527 / 52050 msec.\\
after: 7835 / 4118 / 5619 msec.\\

I fabricated the patch with the command : 'diff -u changed_file original_file'. Is that the right way to do it?

-- KeesKuip

Thanks!  I looked into it, but I figured it would be dumb to just tie it to a single provider.  So I created a VersioningProvider interface with {{"pageExists( String name, int version"}} and made VersioningFileProvider and CachingProvider implement it.  It's now ''very'' fast.  The change is in 2.3.30, now in CVS.

The correct command would be "diff -Naur <original_file> <new_file>", for example:
diff -Naur JSPWiki_orig/ JSPWiki_mychanges/

Try to use this from a top -level directory, i.e. not "diff -Naur ../../../JSPWiki_orig/src/com/ecyrd/jspwiki/Release.java Release.java".  This confuses all patch programs.

-- JanneJalkanen

Thanks, I checked the latest source out with the following results:\\
4569 / 4303 / 2232 msec.\\
That is an improvement of 60-100x of the first results.

-- KeesKuip

Well, thanks for providing such a good profile; it was easy to fix after your hard work!

-- JanneJalkanen