Comment 1 Martin Oberhuber 2008-09-05 14:20:26 EDT

The SystemPreferencesManager, and its initDefaults() method, is loaded from by means of an org.eclipse.core.runtime.preferences extension (SystemPreferenceInitializer). It looks like this one is executed on the "main" thread and likely before RSEUIPlugin and Workbench are fully initialized.

But what is the RSEUIPlugin here waiting for? Why can't it continue? It's weird that the classloader would need to wait 5000 msec, especially given that the ModelInitializer Job is fully decoupled from the main thread which starts it...

Perhaps it would help to use a naked Thread here rather than a Job? Not sure.
I guess I'd want to check whether this issue is reproducable.

Comment 2 Martin Oberhuber 2008-09-05 14:24:56 EDT

With a "suspend VM" type of breakpoint, I was able to get this interesting picture from early startup on a Windows machine on a fresh empty workspace: Apparently, "main" is busy in the UI thread activating the RSE Perspective, while "Worker-4" is the RSEInitJob (in the classloader) and "Worker-0" is initializing Preferences at the same time.

I'm not yet sure why this should be an issue that leads to the observed delay...

Thread [main] (Suspended)	
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 442
        [...]
	RSEUIPlugin(SystemBasePlugin).start(BundleContext) line: 619	
	RSEUIPlugin.start(BundleContext) line: 387	
	BundleContextImpl$2.run() line: 1009	
	AccessController.doPrivileged(PrivilegedExceptionAction<T>) line: not available [native method]	
        [...]
	EclipseLazyStarter.postFindLocalClass(String, Class, ClasspathManager) line: 111	
        [...]
	ExtensionRegistry.createExecutableExtension(RegistryContributor, String, String) line: 867	
        [...]
	Perspective.createPresentation(PerspectiveDescriptor) line: 259
        [...]
	WorkbenchPage.setPerspective(IPerspectiveDescriptor) line: 3665	
        [...]
	HandlerService.executeCommand(String, Event) line: 178	
        [...]
	MenuItem(Widget).sendEvent(Event) line: 1003	
	Display.runDeferredEvents() line: 3823	
	Display.readAndDispatch() line: 3422	
	Workbench.runEventLoop(Window$IExceptionHandler, Display) line: 2382	
        [...]
Thread [Worker-0] (Suspended (breakpoint at line 507 in SystemPreferencesManager$1))	
	SystemPreferencesManager$1.run(IProgressMonitor) line: 507	
	Worker.run() line: 55	
Thread [Worker-4] (Suspended)	
	FileInputStream.open(String) line: not available [native method]	
        [...]
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 443	
        [...]
	RSEPersistenceManager.<init>(ISystemRegistry) line: 195	
	RSECorePlugin.getPersistenceManager() line: 331	
	RSECorePlugin.getThePersistenceManager() line: 216	
	RSEInitJob.run(IProgressMonitor) line: 197	
	Worker.run() line: 55	

Comment 3 Martin Oberhuber 2008-09-05 14:34:44 EDT

Little later, RSEUIPlugin is in getMessageFile() still from start(), while the Persistence Manager accesses Preferences to get the default persistence provider ID...

...100 ms later, RSEUIPlugin still gets its XML message file while the Persistence Provider tries to find the RemoteSystems Project from the Workspace...

...next, RSEUIPlugin loads class for SubSystemConfigurationAdapter, while the SystemProfileManager loads class for SystemProfile...

...next, RSEUIPlugin loads class for SystemTypeAdpater, while SystemHostPool gets accessed from the RSELocalConnectionInitializer as part of InitJob...

...next, RSEUIPlugin instantiates the SystemViewAdapterFactory, while the local initializer creates its host (and sets the default user id)...

...next, RSEUIPlugin is done while the local initializer does a createExecutableExtension() for its subsystem.


...Can't see the real problem yet...

Comment 4 Martin Oberhuber 2008-09-18 15:52:19 EDT

I have reproducably seen this warning now on many installations, on opening the RSE Perspective for the very first time by clicking the "Add perspective" toolbar button and then double clicking the RSE perspective:

  * jee ganymede sr1 package on windows
  * Install of RSE into dropins/ on linux
  * Install of RSE with classic update on solaris 10

It seems a new issue in RSE 3.0.1 (not observed with 3.0), and it seems not to happen in a debug workspace (only released bits). The user-visible effect of this is that opening the RSE Perspective the first time is slower than expected (due to 5 seconds waiting on the thread). Raising priority.

Comment 5 Martin Oberhuber 2008-09-18 17:39:32 EDT

I was finally able to get a complete thread dump of the issue in the debugger, by doing the following:
  * Fresh install of Eclipse SDK + RSE SDK
  * Launch, Import > Plug-in Development > Plug-ins and Fragments > all RSE
  * Debug Perspective
  * Run > Add Java Exception Breakpoint > "BundleException"
  * Edit Breakpoint Properties, "Suspend VM"
  * Run > Debug > PDE (in a new empty WS).

It turns out that at the time the plugin times out waiting (5000 ms), the main thread is in RSEUIPlugin.start() busy loading the SystemMessageFile:

Thread [main] (Suspended)	
	SystemBasePlugin.loadMessageFile(Bundle, String) line: 306	
	RSEUIPlugin.getMessageFile(String) line: 624	
	RSEUIPlugin.start(BundleContext) line: 389	
	BundleContextImpl$2.run() line: 1009	
	AccessController.doPrivileged(PrivilegedExceptionAction<T>) line: not available [native method]	
	BundleContextImpl.startActivator(BundleActivator) line: 1003	
	BundleContextImpl.start() line: 984	
        [...]
	ConfigurationElement.createExecutableExtension(String) line: 243	
        [...]
	WorkbenchPage.setPerspective(IPerspectiveDescriptor) line: 3665	


It seems that this is not a deadlock situation, but simply the RSEUIPlugin.start() method being too slow (taking too much time). DaveM, do you think there is a chance to defer loading of the SystemMessageFile into a Job, rather than having it in Activator.start()?

Comment 6 Martin Oberhuber 2008-09-18 17:42:41 EDT

As mentioned previously, Thread Worker-3 is at the same time busy running the RSEInitJob, which also creates executable extensions (for subsystems) and locks the classloader:

Thread [Worker-3] (Suspended)	
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 443	
	ClasspathManager.findLocalClass(String) line: 423	
	DefaultClassLoader.findLocalClass(String) line: 193	
	BundleLoader.findLocalClass(String) line: 368	
	SingleSourcePackage.loadClass(String) line: 33	
	MultiSourcePackage.loadClass(String) line: 31	
	BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 441	
	BundleLoader.findClass(String, boolean) line: 397	
	BundleLoader.findClass(String) line: 385	
	DefaultClassLoader.loadClass(String, boolean) line: 87	
	DefaultClassLoader(ClassLoader).loadClass(String) line: 251	
	DefaultClassLoader(ClassLoader).loadClassInternal(String) line: 319	
	ClassLoader.defineClass1(String, byte[], int, int, ProtectionDomain, String) line: not available [native method]	
	DefaultClassLoader(ClassLoader).defineClass(String, byte[], int, int, ProtectionDomain) line: 620	
	DefaultClassLoader.defineClass(String, byte[], ClasspathEntry, BundleEntry) line: 165	
	ClasspathManager.defineClass(String, byte[], ClasspathEntry, BundleEntry, ClassLoadingStatsHook[]) line: 554	
	ClasspathManager.findClassImpl(String, ClasspathEntry, ClassLoadingStatsHook[]) line: 524	
	ClasspathManager.findLocalClassImpl(String, ClassLoadingStatsHook[]) line: 455	
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 443	
	ClasspathManager.findLocalClass(String) line: 423	
	DefaultClassLoader.findLocalClass(String) line: 193	
	BundleLoader.findLocalClass(String) line: 368	
	BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 444	
	BundleLoader.findClass(String, boolean) line: 397	
	BundleLoader.findClass(String) line: 385	
	DefaultClassLoader.loadClass(String, boolean) line: 87	
	DefaultClassLoader(ClassLoader).loadClass(String) line: 251	
	DefaultClassLoader(ClassLoader).loadClassInternal(String) line: 319	
	ClassLoader.defineClass1(String, byte[], int, int, ProtectionDomain, String) line: not available [native method]	
	DefaultClassLoader(ClassLoader).defineClass(String, byte[], int, int, ProtectionDomain) line: 620	
	DefaultClassLoader.defineClass(String, byte[], ClasspathEntry, BundleEntry) line: 165	
	ClasspathManager.defineClass(String, byte[], ClasspathEntry, BundleEntry, ClassLoadingStatsHook[]) line: 554	
	ClasspathManager.findClassImpl(String, ClasspathEntry, ClassLoadingStatsHook[]) line: 524	
	ClasspathManager.findLocalClassImpl(String, ClassLoadingStatsHook[]) line: 455	
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 443	
	ClasspathManager.findLocalClass(String) line: 423	
	DefaultClassLoader.findLocalClass(String) line: 193	
	BundleLoader.findLocalClass(String) line: 368	
	SingleSourcePackage.loadClass(String) line: 33	
	BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 441	
	BundleLoader.findClass(String, boolean) line: 397	
	BundleLoader.findClass(String) line: 385	
	DefaultClassLoader.loadClass(String, boolean) line: 87	
	DefaultClassLoader(ClassLoader).loadClass(String) line: 251	
	DefaultClassLoader(ClassLoader).loadClassInternal(String) line: 319	
	ClassLoader.defineClass1(String, byte[], int, int, ProtectionDomain, String) line: not available [native method]	
	DefaultClassLoader(ClassLoader).defineClass(String, byte[], int, int, ProtectionDomain) line: 620	
	DefaultClassLoader.defineClass(String, byte[], ClasspathEntry, BundleEntry) line: 165	
	ClasspathManager.defineClass(String, byte[], ClasspathEntry, BundleEntry, ClassLoadingStatsHook[]) line: 554	
	ClasspathManager.findClassImpl(String, ClasspathEntry, ClassLoadingStatsHook[]) line: 524	
	ClasspathManager.findLocalClassImpl(String, ClassLoadingStatsHook[]) line: 455	
	ClasspathManager.findLocalClass_LockClassLoader(String, ClassLoadingStatsHook[]) line: 443	
	ClasspathManager.findLocalClass(String) line: 423	
	DefaultClassLoader.findLocalClass(String) line: 193	
	BundleLoader.findLocalClass(String) line: 368	
	BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 444	
	BundleLoader.findClass(String, boolean) line: 397	
	BundleLoader.findClass(String) line: 385	
	DefaultClassLoader.loadClass(String, boolean) line: 87	
	DefaultClassLoader(ClassLoader).loadClass(String) line: 251	
	BundleLoader.loadClass(String) line: 313	
	BundleHost.loadClass(String, boolean) line: 227	
	BundleHost(AbstractBundle).loadClass(String) line: 1274	
	EquinoxRegistryStrategy(RegistryStrategyOSGI).createExecutableExtension(RegistryContributor, String, String) line: 160	
	ExtensionRegistry.createExecutableExtension(RegistryContributor, String, String) line: 867	
	ConfigurationElement.createExecutableExtension(String) line: 243	
	ConfigurationElementHandle.createExecutableExtension(String) line: 51	
	SubSystemConfigurationProxy.getSubSystemConfiguration() line: 247	
	SystemRegistry.getSubSystemConfigurationsBySystemType(IRSESystemType, boolean, boolean) line: 340	
	SystemRegistry.getSubSystemConfigurationsBySystemType(IRSESystemType, boolean) line: 325	
	SystemRegistry$1$CreateHostOperation.run() line: 1588	
	SystemProfileManager.runOperation(ISystemProfileOperation) line: 95	
	SystemProfileManager.run(ISystemProfileOperation) line: 86	
	SystemRegistry.createHost(String, IRSESystemType, String, String, String, String, int, boolean, ISubSystemConfigurator[]) line: 1609	
	SystemRegistry.createHost(String, IRSESystemType, String, String, String, String, int, ISubSystemConfigurator[]) line: 1509	
	SystemRegistry.createLocalHost(ISystemProfile, String, String) line: 1477	
	RSELocalConnectionInitializer.run(IProgressMonitor) line: 52	
	RSEInitJob.runInitializer(IConfigurationElement, IProgressMonitor) line: 298	
	RSEInitJob.run(IProgressMonitor) line: 213	
	Worker.run() line: 55	


I guess that the RSEUIPlugin.start() method is simply doing too much work.

Comment 7 Martin Oberhuber 2008-09-18 17:54:17 EDT

It turns out that Worker-3 locks the classloader trying to load org.eclipse.rse.core.subsystems.SubSystemConfiguration which is in RSEUIPlugin. Perhaps the problem is that RSEUIPlugin.start() cannot continue with message file reading because the classloader is locked... it is suspicious anyways that the Activator would stand at the place where it is... 

perhaps the RSEInitJob should be allowed to launch only after RSEUIPlugin is loaded, but that's a problem since the RSEInitJob is declared in CorePlugin and extandable...

Comment 8 Martin Oberhuber 2008-09-18 17:56:00 EDT

But then I'm really wondering how the deadlock can finally be resolved...

Comment 9 Martin Oberhuber 2008-09-18 18:03:03 EDT

Here is one idea to fix this:

1.) Modify SystemBasePlugin#loadMessageFile() to not load the message file
    synchronously, but launch a Job to load the Message file. Instead of the
    actual SystemMessageFile object, return a stub as follows:

2.) LazySystemMessageFile extends SystemMessageFile {
       // Constructor gets constructed with the Job object for loading 
       // All public methods wait for completion of the Job before
       // delegating to the original SystemMessageFile

That way, the loadMessageFile() method can return quickly, message file can be loaded in background, and in case a message is needed before the loading completes, access methods just wait for the load job.

Does that make sense? - I think that it may help RSE startup performance, and getting stuff out of Activator.start() is always a good idea.

Comment 10 David McKnight 2008-09-25 10:52:09 EDT

(In reply to comment #9)
> Here is one idea to fix this:
> 
> 1.) Modify SystemBasePlugin#loadMessageFile() to not load the message file
>     synchronously, but launch a Job to load the Message file. Instead of the
>     actual SystemMessageFile object, return a stub as follows:
> 
> 2.) LazySystemMessageFile extends SystemMessageFile {
>        // Constructor gets constructed with the Job object for loading 
>        // All public methods wait for completion of the Job before
>        // delegating to the original SystemMessageFile
> 
> That way, the loadMessageFile() method can return quickly, message file can be
> loaded in background, and in case a message is needed before the loading
> completes, access methods just wait for the load job.
> 
> Does that make sense? - I think that it may help RSE startup performance, and
> getting stuff out of Activator.start() is always a good idea.
> 

The SystemMessageFile loads the message file directly from it's constructor:

	public SystemMessageFile (String messageFileName, InputStream messageFile, InputStream dtdStream) 
	{
		// have we already loaded this message file?
		msgFile = getFromCache(messageFileName);
		
		// now, we haven't. Load it now.		
		this.dtdInputStream = dtdStream;
		if (msgFile == null) 
		{
			Document doc = loadAndParseXMLFile(messageFile);
			msgFile=new MessageFileInfo(messageFileName.toUpperCase(), messageFileName, doc);
			msgfList.add(msgFile);
		}		
	}

I imagine we could move the loadAndParseXMLFile to a separate method that can be overridden (by LazySystemMessageFile) but, since loadAndParseXMLFile is private, we'd have to change it to protected and, as a result, change API.  Is that the sort of thing you had in mind?

Comment 11 Martin Oberhuber 2008-09-25 11:16:43 EDT

Technically, I had thought about a proxy / delegate pattern as below. The code below should basically work. You might only need to handle the case that loading the message file throws a RuntimeException or Error, or the Job never gets executed due to early cancellation (I'm not 100% sure whether the JobChangeAdapter is called in that case, so clients might wait forever in that case).

And, of course you'll need to implement all the other public methods the same way as the getMessage method below.

public class LazyMessageFile extends SystemMessageFile {
  private Job fInitJob;
  private SystemMessageFile fRealMessageFile;
  private mutable boolean fIsLoaded = false;
  private final Object fSyncObject = new Object();

  public LazyMessageFile(final String messageFileName, 
      final InputStream messageFile, final InputStream dtdStream)
  {
    fInitJob = new Job("Get Messagefile") {
      public IStatus run(IProgressMonitor mon) {
        fRealMessageFile = new SystemMessageFile(messageFileName, messageFile,
             dtdStream);
      }
    };
    fInitJob.addJobChangeListener(new JobChangeAdapter() {
       done(IJobChangeEvent event) {
         synchronized(fSyncObject) {
            fIsLoaded = true; fSyncObject.notifyAll();
         }
       }
    });
    //fInitJob.setDaemon(true);
    fInitJob.schedule();
  }

  private void waitUntilLoaded() {
    synchronized(fSyncObject) {
    while(!fIsLoaded) {
       fSyncObject.wait();
    }
  }

  public SystemMessage getMessage(String msgId) {
    waitUntilLoaded(); 
    return fRealMessageFile.getMessage(msgId);
  }

  //...
}

Comment 12 David McKnight 2008-09-25 11:44:12 EDT

(In reply to comment #11)
> Technically, I had thought about a proxy / delegate pattern as below. The code
> below should basically work. You might only need to handle the case that
> loading the message file throws a RuntimeException or Error, or the Job never
> gets executed due to early cancellation (I'm not 100% sure whether the
> JobChangeAdapter is called in that case, so clients might wait forever in that
> case).
> 
> And, of course you'll need to implement all the other public methods the same
> way as the getMessage method below.
> 
> public class LazyMessageFile extends SystemMessageFile {
>   private Job fInitJob;
>   private SystemMessageFile fRealMessageFile;
>   private mutable boolean fIsLoaded = false;
>   private final Object fSyncObject = new Object();
> 
>   public LazyMessageFile(final String messageFileName, 
>       final InputStream messageFile, final InputStream dtdStream)
>   {
>     fInitJob = new Job("Get Messagefile") {
>       public IStatus run(IProgressMonitor mon) {
>         fRealMessageFile = new SystemMessageFile(messageFileName, messageFile,
>              dtdStream);
>       }
>     };
>     fInitJob.addJobChangeListener(new JobChangeAdapter() {
>        done(IJobChangeEvent event) {
>          synchronized(fSyncObject) {
>             fIsLoaded = true; fSyncObject.notifyAll();
>          }
>        }
>     });
>     //fInitJob.setDaemon(true);
>     fInitJob.schedule();
>   }
> 
>   private void waitUntilLoaded() {
>     synchronized(fSyncObject) {
>     while(!fIsLoaded) {
>        fSyncObject.wait();
>     }
>   }
> 
>   public SystemMessage getMessage(String msgId) {
>     waitUntilLoaded(); 
>     return fRealMessageFile.getMessage(msgId);
>   }
> 
>   //...
> }
> 

But the constructor for LazyMessageFile still needs to call it's super constructor if it's going to extend SystemMessageFile.

Comment 13 Martin Oberhuber 2008-09-25 11:56:24 EDT

(In reply to comment #12)
> But the constructor for LazyMessageFile still needs to call it's super
> constructor if it's going to extend SystemMessageFile.

Ok, I see what you mean. Well, this problem can easily be fixed with a backward compatible API change by adding an additional Constructor to SystemMessageFile:

  /**
   * Dummy Constructor for allowing derived classes.
   * 
   * Note that this does not initialize the object as needed, so
   * its methods will not actually be useable. Extenders who use
   * this constructor will need to override all public and protected
   * methods with their own implementation that meets the API specification.
   *
   * One option of doing this is delegating to a real SystemMessageFile
   * in such implementations.
   */
  protected SystemMessageFile() {
  }

Comment 14 Martin Oberhuber 2008-09-25 11:59:53 EDT

Note that you'll need to rev up org.eclipse.rse.core to 3.1 when you make this change since it's adding API. And you'll need to add an @since tag. 

Another option for handling this would be to create LazyMessageFile as a nested class inside SystemMessageFile. This allows making the argument-less default SystemMessageFile constructor private.

Yet another option is making SystemMessageFile itself lazy with exactly the same code (Job etc). The result would be a faster Constructor, but slower getMessage() -- that way, you could make the enhancement without changing *any* API.

Comment 15 David McKnight 2008-09-25 12:05:59 EDT

An odd thing is happening when I try this.  I get the following exception when loadAndParseXMLFile() is called from within a Job.  If it's not in a job, I don't hit this. 

java.io.IOException: Read error
	at java.io.FileDescriptor.read(FileDescriptor.java:85)
	at java.io.FileInputStream.read(FileInputStream.java:179)
	at org.apache.xerces.impl.XMLEntityManager$RewindableInputStream.read(Unknown Source)
	at org.apache.xerces.impl.XMLEntityManager.setupCurrentEntity(Unknown Source)
	at org.apache.xerces.impl.XMLVersionDetector.determineDocVersion(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XML11Configuration.parse(Unknown Source)
	at org.apache.xerces.parsers.XMLParser.parse(Unknown Source)
	at org.apache.xerces.parsers.DOMParser.parse(Unknown Source)
	at org.apache.xerces.jaxp.DocumentBuilderImpl.parse(Unknown Source)
	at org.eclipse.rse.services.clientserver.messages.SystemMessageFile.loadAndParseXMLFile(SystemMessageFile.java:695)
	at org.eclipse.rse.services.clientserver.messages.SystemMessageFile.<init>(SystemMessageFile.java:127)
	at org.eclipse.rse.services.clientserver.messages.LazySystemMessageFile$1.run(LazySystemMessageFile.java:42)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)

Comment 16 Martin Oberhuber 2008-09-25 12:10:51 EDT

The reason for this might be that the Constructor is called multiple times, so multiple Jobs get spawned. One of your constructor arguments is the DTDStream. I guess that Xerces don't like multiple Threads reading from the same Stream.

You could probably fix this by adding an ISchedulingRule to the Job, to ensure that all LazyMessageFile Constructors can call the Job only sequentially. But that's only for trying.

In the end, I think what you'll probably need to do, is move the "Lazy" logic right into SystemMessageFile (and make all SystemMessageFile instances lazy). Since SystemMessageFile looks like it needs to be Eclipse
independent, you won't have access to the Job class -- but that won't hurt
since you can easily use a Thread instead of the Job. You'll need a Semaphore to avoid multiple Threads running at the same time.

Comment 17 David McKnight 2008-09-25 12:43:23 EDT

(In reply to comment #16)
> The reason for this might be that the Constructor is called multiple times, so
> multiple Jobs get spawned. One of your constructor arguments is the DTDStream.
> I guess that Xerces don't like multiple Threads reading from the same Stream.
> 
> You could probably fix this by adding an ISchedulingRule to the Job, to ensure
> that all LazyMessageFile Constructors can call the Job only sequentially. But
> that's only for trying.
> 
> In the end, I think what you'll probably need to do, is move the "Lazy" logic
> right into SystemMessageFile (and make all SystemMessageFile instances lazy).
> Since SystemMessageFile looks like it needs to be Eclipse
> independent, you won't have access to the Job class -- but that won't hurt
> since you can easily use a Thread instead of the Job. You'll need a Semaphore
> to avoid multiple Threads running at the same time.
> 

I put in a scheduling rule but that didn't help.  I then moved the opening of the streams to the job itself (rather than in SystemBasePlugin) like this:

 fInitJob = new Job("Get Messagefile") {
    protected IStatus run(IProgressMonitor mon)                     {				  
	try {
		InputStream messageFile = url.openStream();
		InputStream dtdFile = dtdURL.openStream();
		fRealMessageFile = new SystemMessageFile(messageFileName, messageFile,dtdFile);
		messageFile.close();
		dtdFile.close();
	}
	 catch (Exception e){						  
	}
	return Status.OK_STATUS;
}

And that seemed to resolve the loading issue.

Comment 18 Martin Oberhuber 2008-09-25 12:53:39 EDT

Ah, of course. Because the SystemMessageFile loads lazily, Streams will be closed by the caller already at the time the DTD is about to be loaded.

Unfortunately, I'm not aware of a method that would allow you to clone the Stream such that the Job is shielded against premature close. All you could do is read the Stream into Memory completely in the Constructor, and only defer XML parsing... but you'd likely not win too much by that.

It looks like you won't get around making an API change. I propose adding a new Constructor

  /**
   * Lazy Constructor.
   * URLs are opened in a background Thread.
   */
  SystemMessageFile(String fileName, URL messageURL, URL dtdURL)

Which always has "lazy" semantics. Pulling that change through the layers is a bit messy, but likely the best solution.

Comment 19 David McKnight 2008-09-25 13:09:28 EDT

Created attachment 113492 [details]
patch to load system message file lazily

Here's what I have right now to resolve this in SystemMessageFile.  What do you think?

Comment 20 David McKnight 2008-09-26 10:45:21 EDT

Martin, are you going on comment on the patch?  The downside is that it changes API and therefore we have to move up the version to 3.1 instead of using 3.0.100.

Comment 21 Martin Oberhuber 2008-09-26 15:52:47 EDT

Dave please rework this patch, it has a couple of issues:

1. Javadocs missing @since tags for new API
2. Javadocs wrong ("It is the caller's responsibility to close this stream" is
   not true when an URL is passed)
3. Javadocs should mention the difference between the (old) constructors 
   which load synchronously and the (new) ones which don't
4. I'm not sure but doesn't SystemMessageFile need to run Eclipse-less? So
   you probably cannot use Job there
5. protected argument-less constructor in SystemMessageFile is not necessary

And probably more but I didn't do a full review since I found so many obvious no-no's.

Comment 22 David McKnight 2008-09-26 16:57:23 EDT

Created attachment 113632 [details]
updated patch with javadoc and using thread instead of job in system message file

Comment 23 Martin Oberhuber 2008-09-26 17:22:56 EDT

Hm... there's still a few things less than ideal:

1. I'm finding the new Javadocs confusing. Had to read it three times to
   understand what you mean. Perhaps if you read it again yourself you could
   come up with something easier to understand (and please try to avoid 
   referencing bugzilla's in public Javadocs).

2. When referencing other constructors in Javadoc, please use {@link } rather
   than <code> such that users can navigate

3. Why is the new SystemUIMessageFile constructor private when it's super
   constructor in SystemMessageFile is public? This is inconsistent unless
   you explain why you chose doing so (not sure but JDT might even issue a 
   warning for this)

4. In the LoadThread, you could run into a situation where IOException is 
   thrown and leads to not closing the Streams -- FindBugs would likely 
   issue a warning for this -- try...finally(close) should be used

5. In the LoadThread, you should simply get rid of the waitForLoad() and 
   notifyLoad() methods, and have the caller direcly call the original 
   Object methods (wait() and notifyAll()) -- your current code is unnecessary
   and only confusing, and actually even dangerous because catching away the
   InterruptedException can lead to an endless loop waiting for load

6. The getMessage() code is plain wrong. In case the LoadThread is used,
   fRealMessageFile == null until it finally gets loaded. You need
   to change the wait condition.

7. I think you should find a way for handling IOException during file loading.
   Currently, these are silently caught away, with the result that
   fRealMessageFile==null but fIsLoaded==true which is inconsistent.

 

Comment 24 Martin Oberhuber 2008-09-26 17:35:11 EDT

8. If I'm not mistaken, SystemMessageFile has a cache of already-loaded messages.
   It looks like your new asynchronous constructor is not making use of this.
   That is, when the same MessageFile is opened 5 times, it should load the
   file only once but with your new async code it will load 5 times.

Comment 25 David McKnight 2008-09-29 10:28:26 EDT

Created attachment 113744 [details]
updated patch

Comment 26 David McKnight 2008-09-29 10:34:40 EDT

(In reply to comment #23)
> Hm... there's still a few things less than ideal:
> 
> 1. I'm finding the new Javadocs confusing. Had to read it three times to
>    understand what you mean. Perhaps if you read it again yourself you could
>    come up with something easier to understand (and please try to avoid 
>    referencing bugzilla's in public Javadocs).


I tried to clarify the Javadocs a bit but I'm not sure which ones, in particular, you found the most confusing.  With the latest patch, is this still a problem?


> 3. Why is the new SystemUIMessageFile constructor private when it's super
>    constructor in SystemMessageFile is public? This is inconsistent unless
>    you explain why you chose doing so (not sure but JDT might even issue a 
>    warning for this)
> 

The reason I made the new SystemUIMessageFile constructor private is because the old one was private as well.  I believe they're private because we expect consumers to call the static getMessageFile() methods.  SystemMessageFile is more flexible since it gets used outside of Eclipse.

I think I've addressed the other issues in the patch.

Comment 27 Martin Oberhuber 2008-09-29 12:22:28 EDT

The Javadocs have much improved, I like them a lot better now. Perhaps my only comment regarding the Javadocs is that I'd like to see specified in the SystemMessageFile constructor as well as the SystemUIMessageFile factory method, what is the specified behavior in case there is an error loading the message file (from reading the code, it looks like an Object is returned, but trying to read any message from that object always returns a null message).

In terms of the code, it has also improved but I still see some issues:

1.) In case of lazy loading, when an IOException occurs in the LoadThread while
    trying to load the message, the fIsLoaded flag may never be set and ANY
    client may wait forever.
    Perhaps the simplest solution for this is to create an additional flag:
      fLoadThreadFinished -- guaranteed to be set when the Thread is done
      fLoadSuccessful -- only set if there was no error
    Also, the 
      fSyncObject.notifyAll()
    must be inside the finally() block to ensure that it is always called, 
    even if a RuntimeError occurs!

2.) LoadThread, try..finally: If _messageFileURL.openStream(); throws an
    exception, then dtdFile==null and you'll throw an NPE. You shouldn't try
    closing dtdFile if it is still null.

3.) Message File Caching: Since now multiple Threads can call getFromCache(),
    you should do this in order to avoid ConcurrentModificationException:

    private static final List msgfList = new SynchronizedList(new LinkedList());

    The MessageFileInfo class is thread-safe because it is immutable (only
    created once in the Constructor and never changed after). This fact
    should be documented (add a Javadoc saying "Thread-safe since immutable).
    You may also want to specify the immutability by making its instance
    variables final (then they can only be written in the Constructor.

4.) Hashtable messages: this is a different issue not related to lazy loading,
    but I'll mention it here since it's related: I absolutely don't understand
    why the keys in this hashtable are prefixed with the
    getMessageFileShortName() -- the Hashtable is private for the 
    SystemMessageFile class, so there will always ever be only one message
    file. Doing those extra prefix String operations seems redundant and
    and unnecessary waist of CPU and memory.

5.) For lazy message files, the printHTML() public API method won't work.
    You'll need to rewrite it similar as the getMessage() method. Same for
    scanForDuplicates()


Dave let me know when you're getting tired of this and I can make a try at getting this right myself.

Comment 28 David McKnight 2008-09-29 12:32:12 EDT

If you'd like to take it from here, I'm okay with that.

Comment 29 Martin Oberhuber 2008-09-29 14:34:06 EDT

Created attachment 113784 [details]
My version of the patch

Attached is my version of the patch.

Note that both rse.services and rse.ui bundles, as well as all associated features and the update site references get upversioned to 3.1.0 -- also, rse.ui now requires a 3.1 version of rse.services.

I think that the Threading is waterproof now, with a simpler code than the previous patches. Also, a small performance/memory improvement is made by not using concatenated Strings for the messages cache any more.

The following issues remain:

1. If multiple Threads ask for the same message file at the same time, it may
   be opened and parsed multiple times, which is not optimal. Note, though,
   that this could happen in the previous (synchronous) variant as well.
   As a remedy of this, it might be possible to introduce a ThreadGroup for the
   LoadThread, such that all LoadThread instances are always executed
   sequentially.

2. In the synchronous case, the Bundle which requested a SystemMessageFile
   object opened the Stream for the URL and could thus receive a Throwable,
   which was reported to the end user by means of a MessageBox.
   In the asynchronous case, opening of the Stream from the URL is deferred,
   so that very Throwable is thrown later in a context which has no access
   to the UI -- Users are not informed about the error.
   I'm not sure at the moment how this could be fixed -- right now, my only
   idea is to always open the Stream in the client as it was done before, 
   but - and this would be the API difference - allow the SystemMessageFile
   object/thread to close the Stream later on. That way, at least "file not
   found" messages would be issued to the client rather than the UI-less
   deferred Message File.

Comment 30 Martin Oberhuber 2008-09-29 14:41:53 EDT

Dave: I committed my version of the fix to HEAD, this should make it easier for you to compare your changes against mine for verification.

From the 2 issues I mentioned, I think we should think about fixing the 2nd one. Do you have any ideas?

Comment 31 Martin Oberhuber 2008-09-29 15:59:33 EDT

(In reply to comment #29)
> 1. If multiple Threads ask for the same message file at the same time, it may

Another solution for this might be to create the MessageFileInfo, and adding it to the MessageFileCache *before actually filling its XML contents*. 

boolean needToLoad = false;
synchronized(msgfList) {
    MessageFileInfo msgInfo = getFromCache(messageFileName);
    if (msgInfo==null) {
         msgInfo = new MessageFileInfo(...)
         msgfList.add(msgInfo);
         needToLoad = true;
    }
}
if (needToLoad) {
    msgInfo.load();
}
msgInfo.waitUntilLoaded();
...

Comment 32 David McKnight 2008-09-30 13:42:46 EDT

(In reply to comment #30)
> Dave: I committed my version of the fix to HEAD, this should make it easier for
> you to compare your changes against mine for verification.
> 
> From the 2 issues I mentioned, I think we should think about fixing the 2nd
> one. Do you have any ideas?
> 


I wouldn't expect customers to run into the 2nd issue under normal circumstances but if we need to report it, one way to deal with this would be via a callback.

Comment 33 David McKnight 2008-10-02 13:57:03 EDT

(In reply to comment #32)
> (In reply to comment #30)
> > Dave: I committed my version of the fix to HEAD, this should make it easier for
> > you to compare your changes against mine for verification.
> > 
> > From the 2 issues I mentioned, I think we should think about fixing the 2nd
> > one. Do you have any ideas?
> > 
> 
> 
> I wouldn't expect customers to run into the 2nd issue under normal
> circumstances but if we need to report it, one way to deal with this would be
> via a callback.
> 

Other alternatives could be to have SystemMessageFile.getMessage() throw an exception or return a special message indicating that there were load problems.

Comment 34 Martin Oberhuber 2008-11-12 13:23:45 EST

Fix involved an API addition:
Constructor SystemMessageFile(String,URL,URL)

Comment 35 Martin Oberhuber 2008-11-12 17:35:58 EST

I'm still seeing exactly the same error message with Eclipse 3.5m3, RSE 3.1m3 -- all plugins installed from ZIP into dropins, initial start, open RSE perspective. Apparently the SystemMessageFile wasn't the culprit.

The problem is 100% reproducable also without the org.eclipse.rse.tests plugin installed.

Comment 36 Martin Oberhuber 2009-03-18 08:15:11 EDT

Problem is still reproducable. Moving into our performance milestone.

Comment 37 Martin Oberhuber 2009-06-11 12:31:28 EDT

*** Bug 279913 has been marked as a duplicate of this bug. ***

Comment 38 Martin Oberhuber 2009-06-22 08:04:40 EDT

*** Bug 281061 has been marked as a duplicate of this bug. ***

Comment 39 Martin Oberhuber 2009-07-29 18:44:54 EDT

Ok, I think I finally found out what's really causing this trouble: RSEUIPlugin.start() initializes a Logger, which wants to read Preference defaults. In the RSEUIPlugin's Preference initializer, the MOdelChangeListener gets instanciated from a Job while the RSEUIPlugin is not yet activated.

Here is the backtrace:

SystemPreferencesManager.startModelChangeListening() line: 525	
SystemPreferencesManager.initDefaults() line: 120	
RSEUIPlugin.initializeDefaultPreferences() line: 119	
SystemPreferenceInitializer.initializeDefaultPreferences() line: 40	
PreferenceServiceRegistryHelper.runInitializer(IConfigurationElement) line: 276	
PreferenceServiceRegistryHelper.applyRuntimeDefaults(String, WeakReference) line: 130	
PreferencesService.applyRuntimeDefaults(String, WeakReference) line: 367	
DefaultPreferences.applyRuntimeDefaults() line: 163	
DefaultPreferences.loadDefaults() line: 236	
DefaultPreferences.load() line: 232	
DefaultPreferences(EclipsePreferences).create(EclipsePreferences, String, Object) line: 307	
DefaultPreferences(EclipsePreferences).internalNode(String, boolean, Object) line: 543	
DefaultPreferences.node(String, Object) line: 150	
PreferenceForwarder.getDefaultPreferences() line: 130	
PreferenceForwarder.getInt(String) line: 469	
Logger.initialize() line: 249	
Logger.<init>(Plugin) line: 135	
LoggerFactory.getLogger(Plugin) line: 45	
RSEUIPlugin(SystemBasePlugin).getLogger() line: 778	
RSEUIPlugin(SystemBasePlugin).start(BundleContext) line: 611	
RSEUIPlugin.start(BundleContext) line: 387	
BundleContextImpl$1.run() line: 782	
AccessController.doPrivileged(PrivilegedExceptionAction<T>) line: not available [native method]	
BundleContextImpl.startActivator(BundleActivator) line: 773	
BundleContextImpl.start() line: 754	
BundleHost.startWorker(int) line: 352	
BundleHost(AbstractBundle).start(int) line: 280	
SecureAction.start(Bundle, int) line: 408	
EclipseLazyStarter.postFindLocalClass(String, Class, ClasspathManager) line: 111	
ClasspathManager.findLocalClass(String) line: 449	
DefaultClassLoader.findLocalClass(String) line: 211	
BundleLoader.findLocalClass(String) line: 376	
BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 452	
BundleLoader.findClass(String, boolean) line: 405	
BundleLoader.findClass(String) line: 393	
DefaultClassLoader.loadClass(String, boolean) line: 105	
DefaultClassLoader(ClassLoader).loadClass(String) line: 252	
BundleLoader.loadClass(String) line: 321	
BundleHost.loadClass(String, boolean) line: 231	
BundleHost(AbstractBundle).loadClass(String) line: 1193	
EquinoxRegistryStrategy(RegistryStrategyOSGI).createExecutableExtension(RegistryContributor, String, String) line: 160	
ExtensionRegistry.createExecutableExtension(RegistryContributor, String, String) line: 874	
ConfigurationElement.createExecutableExtension(String) line: 243	
ConfigurationElementHandle.createExecutableExtension(String) line: 51	
PerspectiveDescriptor.createFactory() line: 172	
Perspective.loadPredefinedPersp(PerspectiveDescriptor) line: 744	
Perspective.createPresentation(PerspectiveDescriptor) line: 270	
Perspective.<init>(PerspectiveDescriptor, WorkbenchPage) line: 156	
Workbench3xImplementation.createPerspective(PerspectiveDescriptor, WorkbenchPage) line: 55	
WorkbenchPage.createPerspective(PerspectiveDescriptor, boolean) line: 1666	
WorkbenchPage.busySetPerspective(IPerspectiveDescriptor) line: 1030	
WorkbenchPage.access$16(WorkbenchPage, IPerspectiveDescriptor) line: 1021	
WorkbenchPage$19.run() line: 3709	
BusyIndicator.showWhile(Display, Runnable) line: 70	
WorkbenchPage.setPerspective(IPerspectiveDescriptor) line: 3707	
ShowPerspectiveHandler.openPerspective(String, IWorkbenchWindow) line: 152	
ShowPerspectiveHandler.openOther(IWorkbenchWindow) line: 124	
ShowPerspectiveHandler.execute(ExecutionEvent) line: 63	
HandlerProxy.execute(ExecutionEvent) line: 294	
Command.executeWithChecks(ExecutionEvent) line: 476	
HandlerService.executeCommand(String, Event) line: 178	
SlaveHandlerService.executeCommand(String, Event) line: 247	
ChangeToPerspectiveMenu(PerspectiveMenu).runOther(SelectionEvent) line: 376	
PerspectiveMenu$3.runWithEvent(Event) line: 130	
ActionContributionItem.handleWidgetSelection(Event, boolean) line: 584	
ActionContributionItem.access$2(ActionContributionItem, Event, boolean) line: 501	
ActionContributionItem$5.handleEvent(Event) line: 411	
EventTable.sendEvent(Event) line: 84	
MenuItem(Widget).sendEvent(Event) line: 1003	
Display.runDeferredEvents() line: 3880	
Display.readAndDispatch() line: 3473	
Workbench.runEventLoop(Window$IExceptionHandler, Display) line: 2405	
Workbench.runUI() line: 2369	
Workbench.access$4(Workbench) line: 2221	
Workbench$5.run() line: 500	
Realm.runWithDefault(Realm, Runnable) line: 332	
Workbench.createAndRunWorkbench(Display, WorkbenchAdvisor) line: 493	
PlatformUI.createAndRunWorkbench(Display, WorkbenchAdvisor) line: 149	
IDEApplication.start(IApplicationContext) line: 113	
EclipseAppHandle.run(Object) line: 194	
EclipseAppLauncher.runApplication(Object) line: 110	
EclipseAppLauncher.start(Object) line: 79	
EclipseStarter.run(Object) line: 368	
EclipseStarter.run(String[], Runnable) line: 179	
NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]	
NativeMethodAccessorImpl.invoke(Object, Object[]) line: 39	
DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 25	
Method.invoke(Object, Object...) line: 597	
Main.invokeFramework(String[], URL[]) line: 559	
Main.basicRun(String[]) line: 514	
Main.run(String[]) line: 1311	
Main.main(String[]) line: 1287	

Comment 40 Martin Oberhuber 2009-07-29 19:59:32 EDT

Created attachment 142960 [details]
Patch finally fixing the issue

Attached patch finally fixes the issue, by 2 changes:
  1.) SystemBasePlugin no longer initializes a Logger in its Activator.start()
  2.) SystemPreferencesManager makes sure that Preference Listening is not 
      started before RSEUIPlugin is fully started.

This brings down activation time of rse.ui to under 500 msec.

Comment 41 Martin Oberhuber 2009-07-29 20:11:40 EDT

Patch committed.

Comment 42 Martin Oberhuber 2009-08-03 12:14:02 EDT

*** Bug 285399 has been marked as a duplicate of this bug. ***