Bug 336612 - [Workbench] Save blocks UI instead of reporting progress
Summary: [Workbench] Save blocks UI instead of reporting progress
Status: RESOLVED WORKSFORME
Alias: None
Product: Platform
Classification: Eclipse Project
Component: UI (show other bugs)
Version: 3.7   Edit
Hardware: PC Mac OS X
: P3 major with 1 vote (vote)
Target Milestone: ---   Edit
Assignee: Platform UI Triaged CLA
QA Contact: Paul Webster CLA
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-02-08 08:32 EST by Johannes Rieken CLA
Modified: 2014-07-02 04:40 EDT (History)
10 users (show)

See Also:


Attachments
stack dump (42.26 KB, text/plain)
2011-02-09 03:28 EST, Johannes Rieken CLA
no flags Details
Screenshot from Yourkit (105.75 KB, image/png)
2011-05-25 04:27 EDT, James Blackburn CLA
no flags Details
full backtrace (15.83 KB, text/plain)
2011-05-25 04:27 EDT, James Blackburn CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Johannes Rieken CLA 2011-02-08 08:32:34 EST
Build Identifier: 3.7M4

During my daily code work the Java Editor often becomes unresponsive and I see it waiting in the UI thread. 

A typical stacktrace is these situations is:


Name: main
State: TIMED_WAITING on org.eclipse.core.internal.jobs.Semaphore@196f5dd
Total blocked: 6,721  Total waited: 2,052

Stack trace: 
java.lang.Object.wait(Native Method)
org.eclipse.core.internal.jobs.Semaphore.acquire(Semaphore.java:39)
org.eclipse.core.internal.jobs.OrderedLock.doAcquire(OrderedLock.java:176)
org.eclipse.core.internal.jobs.OrderedLock.acquire(OrderedLock.java:110)
org.eclipse.core.internal.jobs.OrderedLock.acquire(OrderedLock.java:84)
org.eclipse.core.internal.resources.WorkManager.checkIn(WorkManager.java:118)
org.eclipse.core.internal.resources.Workspace.prepareOperation(Workspace.java:2252)
org.eclipse.core.internal.resources.Workspace.run(Workspace.java:2308)
org.eclipse.ui.actions.WorkspaceModifyOperation.run(WorkspaceModifyOperation.java:118)
   - locked org.eclipse.ui.actions.WorkspaceModifyDelegatingOperation@1885d14
org.eclipse.ui.internal.editors.text.WorkspaceOperationRunner.run(WorkspaceOperationRunner.java:75)
org.eclipse.ui.internal.editors.text.WorkspaceOperationRunner.run(WorkspaceOperationRunner.java:65)
org.eclipse.ui.editors.text.TextFileDocumentProvider.executeOperation(TextFileDocumentProvider.java:456)
org.eclipse.ui.editors.text.TextFileDocumentProvider.validateState(TextFileDocumentProvider.java:1074)
org.eclipse.ui.texteditor.AbstractTextEditor.validateState(AbstractTextEditor.java:4935)
org.eclipse.jdt.internal.ui.javaeditor.CompilationUnitEditor.doSave(CompilationUnitEditor.java:1276)
org.eclipse.ui.texteditor.AbstractTextEditor$TextEditorSavable.doSave(AbstractTextEditor.java:7176)
org.eclipse.ui.Saveable.doSave(Saveable.java:214)
org.eclipse.ui.internal.SaveableHelper.doSaveModel(SaveableHelper.java:349)
org.eclipse.ui.internal.SaveableHelper$3.run(SaveableHelper.java:195)
org.eclipse.ui.internal.SaveableHelper$5.run(SaveableHelper.java:277)
org.eclipse.jface.operation.ModalContext.runInCurrentThread(ModalContext.java:464)
org.eclipse.jface.operation.ModalContext.run(ModalContext.java:372)
org.eclipse.jface.window.ApplicationWindow$1.run(ApplicationWindow.java:759)
org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:70)
org.eclipse.jface.window.ApplicationWindow.run(ApplicationWindow.java:756)
org.eclipse.ui.internal.WorkbenchWindow.run(WorkbenchWindow.java:2613)
org.eclipse.ui.internal.SaveableHelper.runProgressMonitorOperation(SaveableHelper.java:285)
org.eclipse.ui.internal.SaveableHelper.runProgressMonitorOperation(SaveableHelper.java:264)
org.eclipse.ui.internal.SaveableHelper.saveModels(SaveableHelper.java:207)
org.eclipse.ui.internal.SaveableHelper.savePart(SaveableHelper.java:144)
org.eclipse.ui.internal.EditorManager.savePart(EditorManager.java:1369)
org.eclipse.ui.internal.WorkbenchPage.savePart(WorkbenchPage.java:3334)
org.eclipse.ui.internal.WorkbenchPage.saveEditor(WorkbenchPage.java:3347)
org.eclipse.ui.internal.SaveAction.run(SaveAction.java:76)
org.eclipse.jface.action.Action.runWithEvent(Action.java:498)
org.eclipse.ui.commands.ActionHandler.execute(ActionHandler.java:185)
org.eclipse.ui.internal.handlers.LegacyHandlerWrapper.execute(LegacyHandlerWrapper.java:109)
org.eclipse.core.commands.Command.executeWithChecks(Command.java:476)
org.eclipse.core.commands.ParameterizedCommand.executeWithChecks(ParameterizedCommand.java:508)
org.eclipse.ui.internal.handlers.HandlerService.executeCommand(HandlerService.java:169)
org.eclipse.ui.internal.keys.WorkbenchKeyboard.executeCommand(WorkbenchKeyboard.java:468)
org.eclipse.ui.internal.keys.WorkbenchKeyboard.press(WorkbenchKeyboard.java:786)
org.eclipse.ui.internal.keys.WorkbenchKeyboard.processKeyEvent(WorkbenchKeyboard.java:885)
org.eclipse.ui.internal.keys.WorkbenchKeyboard.filterKeySequenceBindings(WorkbenchKeyboard.java:567)
org.eclipse.ui.internal.keys.WorkbenchKeyboard.access$3(WorkbenchKeyboard.java:508)
org.eclipse.ui.internal.keys.WorkbenchKeyboard$KeyDownFilter.handleEvent(WorkbenchKeyboard.java:123)
org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
org.eclipse.swt.widgets.Display.filterEvent(Display.java:1044)
org.eclipse.swt.widgets.Display.sendEvent(Display.java:3954)
org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1435)
org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1458)
org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1443)
org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:1472)
org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:1468)
org.eclipse.swt.widgets.Canvas.sendKeyEvent(Canvas.java:462)
org.eclipse.swt.widgets.Control.doCommandBySelector(Control.java:971)
org.eclipse.swt.widgets.Display.windowProc(Display.java:5337)
org.eclipse.swt.internal.cocoa.OS.objc_msgSend(Native Method)
org.eclipse.swt.internal.cocoa.NSResponder.interpretKeyEvents(NSResponder.java:60)
org.eclipse.swt.widgets.Composite.keyDown(Composite.java:587)
org.eclipse.swt.widgets.Display.windowProc(Display.java:5247)
org.eclipse.swt.internal.cocoa.OS.objc_msgSendSuper(Native Method)
org.eclipse.swt.widgets.Widget.callSuper(Widget.java:220)
org.eclipse.swt.widgets.Widget.windowSendEvent(Widget.java:2042)
org.eclipse.swt.widgets.Shell.windowSendEvent(Shell.java:2194)
org.eclipse.swt.widgets.Display.windowProc(Display.java:5309)
org.eclipse.swt.internal.cocoa.OS.objc_msgSendSuper(Native Method)
org.eclipse.swt.widgets.Display.applicationSendEvent(Display.java:4805)
org.eclipse.swt.widgets.Display.applicationProc(Display.java:4912)
org.eclipse.swt.internal.cocoa.OS.objc_msgSend(Native Method)
org.eclipse.swt.internal.cocoa.NSApplication.sendEvent(NSApplication.java:128)
org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3451)
org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2640)
org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2604)
org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2438)
org.eclipse.ui.internal.Workbench$7.run(Workbench.java:671)
org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:664)
org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:115)
org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:369)
org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:622)
org.eclipse.equinox.launcher.Main.basicRun(Main.java:577)
org.eclipse.equinox.launcher.Main.run(Main.java:1410)


Reproducible: Always

Steps to Reproduce:
1. Write code
2. Save
3. Wait
Comment 1 Dani Megert CLA 2011-02-08 09:40:10 EST
>During my daily code work the Java Editor often becomes unresponsive and I see
>it waiting in the UI thread. 
What do you mean by "unresponsive"? Wait forever, minutes, seconds?

>Steps to Reproduce:
>1. Write code
>2. Save
>3. Wait
Not here. Works fine for me.


There are two issues:
1) The UI being unresponsive (no progress dialog). This should not happen as from the stack trace one can see that
IWorkbenchWindow.run(boolean, boolean, IRunnableWithProgress) is used, which should not block the UI, but report progress instead.

2) The editor waits for a lock. We need to see where that lock is taken to decided whether we can do something or not (most likely not, except when the taken lock is to coarse grained). If you see this again, please open a separate bug report with a complete stack traces, so that we can see who locks.


Moving to Platform UI to investigate 1). Note that this is on Mac OS X.
Comment 2 Johannes Rieken CLA 2011-02-09 03:28:46 EST
Created attachment 188569 [details]
stack dump
Comment 3 Johannes Rieken CLA 2011-02-09 03:30:24 EST
> What do you mean by "unresponsive"? Wait forever, minutes, seconds?

Unresponsive means that I don't get the busy cursor, but the 'dead' curser - beach ball on macs. This can easily take 30 seconds - in average I would say it's 10 seconds.

Find a full stack dump attached now.
Comment 4 Dani Megert CLA 2011-02-09 04:37:37 EST
> Find a full stack dump attached now.
Looks like the SaveManager is causing the wait. Johannes, please take another stack trace when it happens again, so that we're sure it's the SaveManager. We can then open a new bug for that.
Comment 5 John Arthorne CLA 2011-05-24 14:02:08 EDT
Yes in this case the workspace is doing a "snapshot" (incremental save of critical workspace state to disk to aid in crash recovery). This should only happen every 5 minutes or so, so there may be other culprits in your case.
Comment 6 Dani Megert CLA 2011-05-25 02:15:50 EDT
(In reply to comment #5)
> Yes in this case the workspace is doing a "snapshot" (incremental save of
> critical workspace state to disk to aid in crash recovery). This should only
> happen every 5 minutes or so, so there may be other culprits in your case.

Not knowing the save manager in detail: does it do that independent of events (e.g. resource deltas) or could it be, that if I only save lets say every 6 or 7 minutes, I always run into this? Also, there might be something that makes the save manger perform very slow in Johannes case.
Comment 7 James Blackburn CLA 2011-05-25 04:27:12 EDT
Created attachment 196516 [details]
Screenshot from Yourkit

The exact same thing frequently happens in CDT at the end of a build.  CDT does a #refreshLocal of the build tree, and a ctrl-S while this is happening causes the UI thread to lock-up. (I'm on NFS so this may be especially bad...)

In the attached, main is waiting for Worker-1 for 20s.
Comment 8 James Blackburn CLA 2011-05-25 04:27:51 EDT
Created attachment 196517 [details]
full backtrace
Comment 9 James Blackburn CLA 2011-05-25 04:40:13 EDT
I can do exactly the same thing without a build.  
 1) Select a big project: Right click > refresh
 2) ctrl-S in a dirty editor.
Cursor spins for 10 seconds.
Comment 10 John Arthorne CLA 2011-05-25 13:22:40 EDT
(In reply to comment #9)
> I can do exactly the same thing without a build.  
>  1) Select a big project: Right click > refresh
>  2) ctrl-S in a dirty editor.
> Cursor spins for 10 seconds.

It is known/expected that you can't save when another thread has locked the file being saved. If you are refreshing, building, etc, then this is working as intended. The question in this case is why during a typical edit/save/edit/save workflow would it always be blocking?
Comment 11 James Blackburn CLA 2011-05-25 13:28:50 EDT
(In reply to comment #10)
> It is known/expected that you can't save when another thread has locked the
> file being saved. 

That's fine. However the UI should not 'lock-up' for 10s of seconds a time.  When this occurs, it appears that eclipse has crashed. 
At the very least, if save is blocked, there should be a progress dialog (allowing cancellation) and the UI should remain live.
Comment 12 James Blackburn CLA 2011-09-30 04:11:32 EDT
This can also happen if a plugin has a really slow resource change handler hooked in.  With egit, if you synchronize 2 CDT branches, ctrl-S locks up the IDE main thread for minutes.

See backtrace in bug 323839 comment 34
https://bugs.eclipse.org/bugs/attachment.cgi?id=204057

Given Save does I/O and that I/O can fire a chain of builds and resource deltas (which hold the WS lock), save should report progress / run in a background thread so the user doesn't think the whole IDE has crashed.
Comment 13 John Arthorne CLA 2011-09-30 15:38:44 EDT
So the crux of the problem is the use of BusyIndicator#showWhile:

org.eclipse.jface.window.ApplicationWindow$1.run()
org.eclipse.swt.custom.BusyIndicator.showWhile(Display, Runnable)
org.eclipse.jface.window.ApplicationWindow.run(boolean, boolean, IRunnableWithProgress)
org.eclipse.ui.internal.WorkbenchWindow.run(boolean, boolean, IRunnableWithProgress)
org.eclipse.ui.internal.SaveableHelper.runProgressMonitorOperation(String, IRunnableWithProgress, IRunnableContext, IShellProvider)

If this was changed to IProgressService#busyCursorWhile, then after a delay you would get a progress dialog that would allow you to cancel the operation in the other thread that is blocking you (and at least show you that something is indeed still going on).
Comment 14 Eric Moffatt CLA 2011-10-11 14:02:00 EDT
John, where would the fix to change this behavior have to be implemented ?
Comment 15 Remy Suen CLA 2011-10-11 16:07:22 EDT
(In reply to comment #14)
> John, where would the fix to change this behavior have to be implemented ?

It might be possible to just change the code in SaveableHelper to use the workbench window's IProgressService instead of using it directly as a runnable context I think.

Though this change is pretty deep so it'd probably be worth just changing it in 4.x first before considering a backport.
Comment 16 Eric Moffatt CLA 2011-10-12 13:38:50 EDT
Sounds like a good idea to me. We have to avoid any possible regressions in the 3.x stream in order to make our 'maintenance mode' statements believable.
Comment 17 Martin Robertson CLA 2012-08-20 10:48:24 EDT
Has there been any progress on this in the last 10 months? 

I have just hit this in Eclipse 3.8 (under https://bugs.eclipse.org/bugs/show_bug.cgi?id=387570) and it looks incredibly broken that a file save can make Eclipse appear to have crashed for several minutes.
Comment 18 Lars Vogel CLA 2014-07-02 04:40:02 EDT
(In reply to Johannes Rieken from comment #0)
> Build Identifier: 3.7M4
> 
> During my daily code work the Java Editor often becomes unresponsive and I
> see it waiting in the UI thread. 

I have not seens this issue with Luna (on Linux). Marking as WORKSFORME. Please reopen if you still see this issue.