Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.

Bug 262557

Summary: [Edit] Save in Compare Editor throws OperationCanceledException
Product: [Eclipse Project] Platform Reporter: Tomasz Zarna <tomasz.zarna>
Component: CompareAssignee: Tomasz Zarna <tomasz.zarna>
Status: RESOLVED FIXED QA Contact:
Severity: major    
Priority: P2 CC: cgold, daniel_megert, eric_jodet, markus.kell.r, Mike_Wilson, Olivier_Thomann, steffen.pingel, Szymon.Brandys
Version: 3.5Flags: daniel_megert: review+
Target Milestone: 3.5 RC1   
Hardware: All   
OS: All   
Whiteboard:
Attachments:
Description Flags
Fix for problem 1 none

Description Tomasz Zarna CLA 2009-01-27 10:03:05 EST
I20090127-0100

This has been observed for the first time in bug 260374, comment 0 when saving from the context menu. With the steps below the exception is thrown when save is triggered either way: from context menu, by ctrl+s, from main toolbar, from file > save.

1. Create a Java project
2. Create a new Java class named A in default package:
---

public class A {

}
---
3. Create a package named p1.
4. Copy the class to p1 package. You should get:
---
package p1;

public class A {

}
---
5. Select and compare both files. The only difference is package declaration, shown in Java Structure Compare pane and in content merge pane below.
6. Double click on the Compilation Unit node in Java Structure Compare pane.
7. Switch to the right side pane, edit it and try to save:

org.eclipse.swt.SWTException: Failed to execute runnable (org.eclipse.core.runtime.OperationCanceledException)
	at org.eclipse.swt.SWT.error(SWT.java:3860)
	at org.eclipse.swt.SWT.error(SWT.java:3775)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:136)
	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:3852)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3473)
	at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2388)
	at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2352)
	at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2204)
	at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:499)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:333)
	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:492)
	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:113)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:194)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:368)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
	at java.lang.reflect.Method.invoke(Unknown Source)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:550)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:505)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1264)
	at org.eclipse.equinox.launcher.Main.main(Main.java:1240)
Caused by: org.eclipse.core.runtime.OperationCanceledException
	at org.eclipse.jdt.core.dom.ASTConverter.checkCanceled(ASTConverter.java:402)
	at org.eclipse.jdt.core.dom.ASTConverter.convert(ASTConverter.java:2642)
	at org.eclipse.jdt.core.dom.ASTConverter.convert(ASTConverter.java:1263)
	at org.eclipse.jdt.core.dom.CompilationUnitResolver.convert(CompilationUnitResolver.java:256)
	at org.eclipse.jdt.core.dom.ASTParser.internalCreateAST(ASTParser.java:933)
	at org.eclipse.jdt.core.dom.ASTParser.createAST(ASTParser.java:657)
	at org.eclipse.jdt.internal.ui.compare.JavaStructureCreator.createStructureComparator(JavaStructureCreator.java:294)
	at org.eclipse.jdt.internal.ui.compare.JavaStructureCreator.createStructureComparator(JavaStructureCreator.java:253)
	at org.eclipse.compare.structuremergeviewer.StructureCreator.internalCreateStructure(StructureCreator.java:102)
	at org.eclipse.compare.structuremergeviewer.StructureCreator.access$0(StructureCreator.java:90)
	at org.eclipse.compare.structuremergeviewer.StructureCreator$1.run(StructureCreator.java:80)
	at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:70)
	at org.eclipse.compare.internal.Utilities$4.run(Utilities.java:779)
	at org.eclipse.ui.internal.UILockListener.doPendingWork(UILockListener.java:155)
	at org.eclipse.ui.internal.UISynchronizer$3.run(UISynchronizer.java:158)
	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:133)
	... 23 more
Comment 1 Tomasz Zarna CLA 2009-02-23 10:24:59 EST
Note that the save completes successfully, with the exception of the logged error.
Comment 2 Tomasz Zarna CLA 2009-02-25 08:47:31 EST
*** Bug 249755 has been marked as a duplicate of this bug. ***
Comment 3 Tomasz Zarna CLA 2009-02-25 08:47:45 EST
*** Bug 233902 has been marked as a duplicate of this bug. ***
Comment 4 Tomasz Zarna CLA 2009-02-25 08:52:45 EST
An alternative set of steps to reproduce the exception can be found on bug 233902.
Comment 5 Tomasz Zarna CLA 2009-03-03 07:45:43 EST
Given that this is not a regression introduced by bug 169386 as I initially thought, I'm removing target milestone to better match the reality, ie we are focused on fixing regressions at this stage.
Comment 6 Tomasz Zarna CLA 2009-04-21 10:35:43 EDT
Dani what do you think about this one? Looking at the root cause isn't it more like a JDT bug?
Comment 7 Dani Megert CLA 2009-04-22 07:03:51 EDT
> Looking at the root cause isn't it more like a JDT bug?
Nope, this is not JDT.

> we are focused on fixing regressions at this stage.
Right and this one is a regression caused by changes in Compare, though not by bug 169386 but by bug 193324.

There are several issues here:
1. the worker that computes the AST is canceled by Compare and hence the exception
   ==> the StructureCreate has to be prepared that an OperationCanceledException 
       is thrown by anyone that check the monitor, this (and hence the logging
       of the exception gets fixed by my patch).

2. createStructure is called twice for both sides on save:
   - once in UI thread via:
       org.eclipse.team.ui.mapping.SaveableComparison.doSave(IProgressMonitor)
   - once via org.eclipse.compare.internal.WorkerJob

This is very bad for performance reasons, especially because this means 4x building an AST in case of Java compare of which two are thrown away sometimes.
Comment 8 Dani Megert CLA 2009-04-22 07:05:09 EDT
Created attachment 132748 [details]
Fix for problem 1
Comment 9 Tomasz Zarna CLA 2009-04-23 12:04:00 EDT
(In reply to comment #7)
> 2. createStructure is called twice for both sides on save:
> - once via org.eclipse.compare.internal.WorkerJob

This one is called in reaction to CompareEditorInput.flushViewers() which takes place before actual save[1]. StructureDiffViewer listens for content changes[2] and does refresh when needed ie it schedules refreshTask to run asynch.

[1] org.eclipse.team.internal.ui.synchronize.LocalResourceSaveableComparison.performSave(IProgressMonitor) 
[2] org.eclipse.compare.structuremergeviewer.StructureDiffViewer line 208

> - once in UI thread via:
> org.eclipse.team.ui.mapping.SaveableComparison.doSave(IProgressMonitor)

And this one is called because StructureDiffViewer is listening on compare input changes[3] which are fired later on[4] in LocalResourceSaveableComparison.performSave.

[3] org.eclipse.compare.structuremergeviewer.StructureDiffViewer line 213
[4] [1] line 140

I know that this probably doesn't help much but the number of events, listeners and jobs involved in the process of saving and re-creating the structure overwhelmed me. I'm still on it, hopefully I will move forward tomorrow.
Comment 10 Tomasz Zarna CLA 2009-05-05 04:09:43 EDT
*** Bug 274735 has been marked as a duplicate of this bug. ***
Comment 11 Tomasz Zarna CLA 2009-05-05 04:53:20 EDT
I'll try to take a closer look at this in RC1, otherwise I will apply Dani's fix and continue the investigation during 3.6.
Comment 12 Dani Megert CLA 2009-05-05 12:00:59 EDT
Something changed: with I20090429-1800 I got tons of those exceptions in my .log while almost not noting them before.
Comment 13 Dani Megert CLA 2009-05-05 12:02:00 EDT
I suspect it now also happens when we update the structure:

!ENTRY org.eclipse.ui 4 0 2009-05-05 16:21:27.052
!MESSAGE Unhandled event loop exception
!STACK 0
org.eclipse.swt.SWTException: Failed to execute runnable (org.eclipse.core.runtime.OperationCanceledException)
	at org.eclipse.swt.SWT.error(SWT.java:3881)
	at org.eclipse.swt.SWT.error(SWT.java:3796)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:137)
	at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:3855)
	at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3476)
	at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2405)
	at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2369)
	at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2221)
	at org.eclipse.ui.internal.Workbench$5.run(Workbench.java:500)
	at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
	at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:493)
	at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
	at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:113)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:194)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:368)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:559)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:514)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1311)
	at org.eclipse.equinox.launcher.Main.main(Main.java:1287)
Caused by: org.eclipse.core.runtime.OperationCanceledException
	at org.eclipse.jdt.core.dom.ASTConverter.checkCanceled(ASTConverter.java:402)
	at org.eclipse.jdt.core.dom.ASTConverter.convert(ASTConverter.java:2643)
	at org.eclipse.jdt.core.dom.ASTConverter.convert(ASTConverter.java:1264)
	at org.eclipse.jdt.core.dom.CompilationUnitResolver.convert(CompilationUnitResolver.java:256)
	at org.eclipse.jdt.core.dom.ASTParser.internalCreateAST(ASTParser.java:933)
	at org.eclipse.jdt.core.dom.ASTParser.createAST(ASTParser.java:657)
	at org.eclipse.jdt.internal.ui.compare.JavaStructureCreator.createStructureComparator(JavaStructureCreator.java:294)
	at org.eclipse.jdt.internal.ui.compare.JavaStructureCreator.createStructureComparator(JavaStructureCreator.java:253)
	at org.eclipse.compare.structuremergeviewer.StructureCreator.internalCreateStructure(StructureCreator.java:102)
	at org.eclipse.compare.structuremergeviewer.StructureCreator.access$0(StructureCreator.java:90)
	at org.eclipse.compare.structuremergeviewer.StructureCreator$1.run(StructureCreator.java:80)
	at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:70)
	at org.eclipse.compare.internal.Utilities$4.run(Utilities.java:779)
	at org.eclipse.ui.internal.UILockListener.doPendingWork(UILockListener.java:155)
	at org.eclipse.ui.internal.UISynchronizer$3.run(UISynchronizer.java:158)
	at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
	at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:134)
	... 23 more
Comment 14 Dani Megert CLA 2009-05-05 12:02:42 EDT
Maybe I find time to debug tomorrow but no promise. But this is definitely a must fix for 3.5 now.
Comment 15 Tomasz Zarna CLA 2009-05-06 03:54:44 EDT
*** Bug 275034 has been marked as a duplicate of this bug. ***
Comment 16 Tomasz Zarna CLA 2009-05-06 04:53:36 EDT
What is strange about the stack from Steffen (bug 275034, comment 0) is the fact it shows that there was a deferred event setting focus on compare editor and it's run after the editor was disposed.
Comment 17 Tomasz Zarna CLA 2009-05-06 10:13:45 EDT
I filed bug 275153 to address the regression mentioned by Dani in comment 7 and others discovered while investigation the issue. 

For now, I guess we will apply patch suggested by Dani, even though it does not fix the real cause but just hides the consequences. 

I still don't know what change made those exception to show up so often.

Dani, I'm not sure if it's fair to ask you to review your own patch... I would give it +1 if you asked me. But again, I would consider it a temporarily fix, safe enough to release now, but to be revisited during 3.6 (by addressing bug 275153).
Comment 18 Dani Megert CLA 2009-05-06 11:33:56 EDT
Tomasz, we need to find and fix the cause for this for 3.5 as creating two ASTs in parallel is also a performance issue.

This is a P2 if not a P1 issue.
Comment 19 Tomasz Zarna CLA 2009-05-08 04:45:40 EDT
I filed two separate bugs:
- bug 275286 indicating similar problem when opening compare editor
- bug 275289 indicating similar problem when editing in compare editor
Comment 20 Tomasz Zarna CLA 2009-05-08 06:05:54 EDT
Apparently the fix from bug 275286 drastically reduces number of OCE observed by Dani in comment 12.
Comment 21 Dani Megert CLA 2009-05-11 09:15:00 EDT
+1 to commit the attached patch given we continue to work on the other issues like bug 275286.
Comment 22 Tomasz Zarna CLA 2009-05-11 10:09:15 EDT
Thanks Dani. The patch has been released. Available in builds >=I20090511-2000.