Bug 191280

Summary: [dstore] Expand fails for folder "/folk" with 3361 children
Product: [Tools] Target Management Reporter: Martin Oberhuber <mober.at+eclipse>
Component: RSEAssignee: David McKnight <dmcknigh>
Status: RESOLVED FIXED QA Contact: Martin Oberhuber <mober.at+eclipse>
Severity: major    
Priority: P1 Keywords: contributed
Version: 2.0Flags: kmunir: review+
ddykstal.eclipse: review+
Target Milestone: 2.0   
Hardware: PC   
OS: Windows XP   
Whiteboard:
Bug Depends on: 190803    
Bug Blocks:    
Attachments:
Description Flags
screen capture for where the bottleneck code is
none
Fixes to improve the performance of query for large folder
mober.at+eclipse: iplog+
update the problem with rename in virtual file mober.at+eclipse: iplog+

Description Martin Oberhuber CLA 2007-06-06 11:14:31 EDT
+++ This bug was initially created as a clone of Bug #190803 +++

* connected to a Solaris dstore-unix server (szg-anar, Running).
* Expand "Root" filter
* Expand "/folk" fokder
  --> "Pending" message is shown
  --> After about 2:30 minutes it returns but shows an empty folder. No exception messages are shown or logged, neither on the client nor on the server.

Doing the same on the same host through an SSH Only connection returns a result of 3361 folder children within about 3 seconds.

It looks like the dstore daemon tries to refresh the children of "/folk" two levels deep which takes too long. Is there any kind of timeout?

Client is RSE 2.0RC2 on WinXP / eclipse 3.3RC3 / Sun 1.6.0_01.
Server is RSE 2.0RC2 on Solaris / Sun 1.4.2_05.
Comment 1 Martin Oberhuber CLA 2007-06-06 14:10:48 EDT
Dave - how can we add debugging information to understand what's going on here?
Comment 2 Xuan Chen CLA 2007-06-07 00:55:57 EDT
I added some trace statement inside the DStore server code to track time.

And I created a folder with around 40000 subfolders, and the following is the time recorded:

Scenario 1:
Expand the folder (dummy) for the first time:

. UniversalFileSystemMiner#handleQueryAll  -  time elapsed:  90,668 ms
     - internalQueryAll  -  23143 ms
        -- createDataElement()   - 8,084 ms
        -- clsfy.start()         - 11,984 ms
     -  statusDone()             - 67,002 ms
          -- mainly is in DataStore#refresh() method called by element isdone

   So in this scenario, the bottleneck is the statusDone() method.


Scenario 2:
Refresh the folder (dummy):
   UniversalFileSystemMiner#handleQueryAll  -  time elapsed:  1539,577 ms
    - internalQueryAll  -  1469,480 ms
        -- createDataElement()   - 1448,837 ms
        -- clsfy.start()         - 11,933 ms
     -  statusDone()             - 69,870 ms

So in scenario #2, the bottleneck is the createDataElement() method, which caused this refresh operation run for more than 25 minutes.

I could see the reason why createDataElement() running for such a long time in this scenario is the nested loop inside this  method:

	// Check if the current Objects in the DataStore are valid... exist
	// on the remote host
	try {
        	for (int i = 0; i < currentObjList.length; ++i) {
		found = false;
		DataElement previousElement = (DataElement) currentObjList[i];
	        	for (int j = 0; j < list.length && !found; ++j) 
		{
							
								
                           .
                           .
                           .
Comment 3 Xuan Chen CLA 2007-06-08 11:07:26 EDT
For Scenario #1, the bottleneck is the XMLgenerator#generate() method call for dataelement dummy(the big folder).  Please see the attachment for the sceen capture where I halted the thread.
Comment 4 Xuan Chen CLA 2007-06-08 11:11:52 EDT
Created attachment 70698 [details]
screen capture for where the bottleneck code is
Comment 5 Xuan Chen CLA 2007-06-12 16:23:27 EDT
Created attachment 71085 [details]
Fixes to improve the performance of query for large folder

I made the following fixes to improve the performance (mainly for the refresh case):
. Move the init() method from the constructor of FileClassifer to its start() method
. Merge the nested loop and the loop update/create dataelement into one loop through the result of listFile operation.  This fix applied for both regular file/folder and virtual file/folder inside a archive file.

Legal Message: I, Xuan Chen, declare that I developed attached code from
scratch, without referencing any 3rd party materials except material licensed
under the EPL. I am authorized by my employer, IBM Canada Ltd. to make this
contribution under the EPL.
Comment 6 David McKnight CLA 2007-06-12 16:34:07 EDT
Please review the patch.
Comment 7 David Dykstal CLA 2007-06-12 21:47:33 EDT
The patch is large - but I get the general idea of what's going on. I approve. 
Comment 8 David McKnight CLA 2007-06-13 10:51:52 EDT
I've applied the patch for this.
Comment 9 Kushal Munir CLA 2007-06-13 13:13:49 EDT
Looks ok to me.
Comment 10 Xuan Chen CLA 2007-06-14 02:39:52 EDT
I found a problem with the patch for handling the virtual file case.  

I used :

String oldValue = deObj.getAttribute(DE.A_VALUE);
							String newValue = rootPath + ArchiveHandlerManager.VIRTUAL_SEPARATOR + virtualPath;
							if (!oldValue.startsWith(newValue))  
         ^^^^^^^^^^
						    {
						        deObj.setAttribute(DE.A_VALUE, newValue); //$NON-NLS-1$
						    }
It is not correct if I rename a name from "dummy1" to "dummy"

I will provide a patch to fix this problem.  

I need to change to equals() instead of startsWith().


Sorry about it.
Comment 11 Xuan Chen CLA 2007-06-14 02:42:13 EDT
Created attachment 71268 [details]
update the problem with rename in virtual file

Legal Message: I, Xuan Chen, declare that I developed attached code from
scratch, without referencing any 3rd party materials except material licensed
under the EPL. I am authorized by my employer, IBM Canada Ltd. to make this
contribution under the EPL.
Comment 12 David McKnight CLA 2007-06-14 08:56:53 EDT
I've committed the update.
Comment 13 Martin Oberhuber CLA 2008-08-13 13:20:53 EDT
[target cleanup] 2.0 RC3 was the original target milestone for this bug