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

Bug 336514

Summary: The performance test JavaReplaceAllTest fails on Linux machine
Product: [Eclipse Project] JDT Reporter: Deepak Azad <deepakazad>
Component: TextAssignee: Deepak Azad <deepakazad>
Status: RESOLVED FIXED QA Contact:
Severity: normal    
Priority: P2 CC: daniel_megert
Version: 3.7   
Target Milestone: 3.7 M6   
Hardware: PC   
OS: Linux   
Whiteboard:
Attachments:
Description Flags
debug code
none
debug code 1
none
proposed fix none

Description Deepak Azad CLA 2011-02-07 10:00:42 EST
Created attachment 188441 [details]
debug code

See also Bug 330353

The failure does not happen every time, but it is easy enough to reproduce - at least 1 out of 3 test runs fails. This happens only on Linux, I cannot reproduce this on windows.

Basically when I run the test, it just gets stuck at one point. To figure out where I wrote some debug code (patch attached) and this was the console output

-------------------------------------------------------
RUNS = 3
0 run
find: e
Tab
replace: x
replace all via mnemonic - keydown
replace all via mnemonic - the key
replace all via mnemonic - keyup
close the dialog.
waiting for condition
condition() : false
condition() : false
condition() : true
stopping performance meter
reverting editor
join background activities
1 run
find: e
Tab
replace: x
replace all via mnemonic - keydown
replace all via mnemonic - the key
------------------------------------------------------

While the number of runs is not fixed, but it always gets stuck at the same line - "SWTEventHelper.pressKeyChar(display, 'a');" in AbstractJavaReplaceAllTest. The screen keeps flickering, it looks like 'a' (mnemonic for 'Replace All' button) is pressed continuously. (If I manage to open a text editor and get the focus in it, 'a' is entered into it continuously)


Bug 330353 says that the following exception occured on the build server. I am not sure if the 2 problems are the same, but the one mentioned above happens quite frequently on my local machine.

Exception logged for JavaReplace*#test()
#################
junit.framework.AssertionFailedError: null
at
org.eclipse.jdt.text.tests.performance.AbstractJavaReplaceAllTest.measure(AbstractJavaReplaceAllTest.java:115)
at
org.eclipse.jdt.text.tests.performance.AbstractJavaReplaceAllTest.test(AbstractJavaReplaceAllTest.java:71)
at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
at junit.extensions.TestSetup$1.protect(TestSetup.java:23)
at junit.extensions.TestSetup.run(TestSetup.java:27)
at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
at junit.extensions.TestSetup$1.protect(TestSetup.java:23)
at junit.extensions.TestSetup.run(TestSetup.java:27)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:377)
at org.eclipse.test.EclipseTestRunner.run(EclipseTestRunner.java:210)
at org.eclipse.test.UITestApplication$2.run(UITestApplication.java:197)
at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:35)
at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:134)
at org.eclipse.swt.widgets.Display.runAsyncMessages(Display.java:3514)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3163)
at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:2640)
at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:2604)
at org.eclipse.ui.internal.Workbench.access$4(Workbench.java:2438)
at org.eclipse.ui.internal.Workbench$7.run(Workbench.java:671)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:664)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
at
org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:115)
at
org.eclipse.test.UITestApplication.runApplication(UITestApplication.java:140)
at org.eclipse.test.UITestApplication.run(UITestApplication.java:62)
at org.eclipse.test.UITestApplication.start(UITestApplication.java:212)
at
org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
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:369)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:621)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:576)
at org.eclipse.equinox.launcher.Main.run(Main.java:1409)
at org.eclipse.equinox.launcher.Main.main(Main.java:1385)
at org.eclipse.core.launcher.Main.main(Main.java:34)
################
Comment 1 Deepak Azad CLA 2011-02-08 00:39:45 EST
Created attachment 188495 [details]
debug code 1

I debugged a bit more and here is the console output for the attached debug code. Essentially the test gets stuck in SWTEventHelper.postEvent(Display, Event, boolean), right after calling "display.post(event)" (though this call succeeds and returns true)

The javadoc for display.post(event) says - "Note that this operation can fail when the operating system fails to generate the event for any reason.  For example, this can happen when there is no such key or mouse button or when the system event queue is full". 

Plus if I fiddle with the UI (to look at the console output, try to take a thread dump, or even just bring focus to the main eclipse workbench) the test becomes unstuck and I get the exception from comment 0 - at least this confirms that the test getting stuck and the exception are the same problem.

Console output
-----------------------------------------------------------------------------
waitForCondition 1
waitForCondition 2
waitForCondition 3- about to drive event queue
waitForCondition 4- driven event queue
waitForCondition 5
waitForCondition 1
waitForCondition 2
waitForCondition 3- about to drive event queue
waitForCondition 4- driven event queue
waitForCondition 5
waitForCondition 1
waitForCondition 2
waitForCondition 3- about to drive event queue
waitForCondition 4- driven event queue
waitForCondition 5
waitForCondition 6
STARTING WAITER
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
WOKEN UP
RUNS = 3
0 run
find: e
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
key up
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
Tab
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace: x
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
key up
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace all via mnemonic - keydown
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace all via mnemonic - the key
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
key up
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace all via mnemonic - keyup
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
close the dialog.
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
waiting for condition
waitForCondition 1
condition() : true
stopping performance meter
reverting editor
join background activities
waitForCondition 1
waitForCondition 2
waitForCondition 3- about to drive event queue
waitForCondition 4- driven event queue
waitForCondition 5
waitForCondition 1
waitForCondition 2
waitForCondition 3- about to drive event queue
waitForCondition 4- driven event queue
waitForCondition 5
waitForCondition 6
STARTING WAITER
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
about to sleep
display SLEEP
WOKEN UP
1 run
find: e
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
key up
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
Tab
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace: x
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
key up
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace all via mnemonic - keydown
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
replace all via mnemonic - the key
key down
posting event
ABOUT TO WAIT FOR CONDITION
waitForCondition 1
post condition : true
-----------------------------------------------------------------------------
Comment 2 Deepak Azad CLA 2011-02-14 04:54:33 EST
Created attachment 188882 [details]
proposed fix
Comment 3 Deepak Azad CLA 2011-02-14 04:58:48 EST
Same reasons as Bug 330353 comment 9.
Comment 4 Deepak Azad CLA 2011-02-14 08:12:54 EST
Fixed in HEAD.

Performance numbers are not affected

*Without fix*
Scenario 'org.eclipse.jdt.text.tests.performance.JavaReplaceAllTest#test()' (average over 3 samples):
  Used Java Heap:        -5.43M         (95% in [-41.84M, 30.97M])     Measurable effect: 33.85M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6400)
  Working Set:            9.36M         (95% in [-12.17M, 30.89M])     Measurable effect: 20.02M (2.3 SDs) (required sample size for an effect of 5% of mean: 5485)
  Committed:              6.94M         (95% in [-19.84M, 33.72M])     Measurable effect: 24.9M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6400)
  Working Set Peak:        7.8M         (95% in [-13.58M, 29.17M])     Measurable effect: 19.87M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6401)
  Elapsed Process:         781ms        (95% in [714ms, 847ms])        Measurable effect: 62ms (2.3 SDs) (required sample size for an effect of 5% of mean: 8)
  Kernel time:              52ms        (95% in [-29ms, 133ms])        Measurable effect: 76ms (2.3 SDs) (required sample size for an effect of 5% of mean: 2564)
  Page Faults:            2.61K         (95% in [-3.24K, 8.46K])       Measurable effect: 5.44K (2.3 SDs) (required sample size for an effect of 5% of mean: 5223)
  CPU Time:                911ms        (95% in [816ms, 1.01s])        Measurable effect: 88ms (2.3 SDs) (required sample size for an effect of 5% of mean: 12)
  GDI Objects:              -9          (95% in [-9, -9])             


*With fix*
Scenario 'org.eclipse.jdt.text.tests.performance.JavaReplaceAllTest#test()' (average over 3 samples):
  Used Java Heap:        -3.51M         (95% in [-14.96M, 7.93M])      Measurable effect: 10.64M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6401)
  Working Set:            1.46M         (95% in [-5.46M, 8.39M])       Measurable effect: 6.44M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6401)
  Committed:              1.78M         (95% in [-15.89M, 19.45M])     Measurable effect: 16.43M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6400)
  Working Set Peak:     494.67K         (95% in [-1.6M, 2.56M])        Measurable effect: 1.93M (2.3 SDs) (required sample size for an effect of 5% of stdev: 6400)
  Elapsed Process:         791ms        (95% in [769ms, 813ms])        Measurable effect: 20ms (2.3 SDs)
  Kernel time:              52ms        (95% in [30ms, 73ms])          Measurable effect: 20ms (2.3 SDs) (required sample size for an effect of 5% of mean: 178)
  Page Faults:             655          (95% in [-2.02K, 3.34K])       Measurable effect: 2.49K (2.3 SDs) (required sample size for an effect of 5% of stdev: 6400)
  CPU Time:                901ms        (95% in [843ms, 959ms])        Measurable effect: 53ms (2.3 SDs) (required sample size for an effect of 5% of mean: 5)
  GDI Objects:              -9          (95% in [-9, -9])
Comment 5 Dani Megert CLA 2011-02-14 08:22:36 EST
.
Comment 6 Deepak Azad CLA 2011-03-07 06:05:07 EST
Fix backported to 'perf_36x' and released.