Bugzilla – Full Text Bug Listing
| Summary: | [reconciler] Second startup after update also slow | ||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [Eclipse Project] Equinox | Reporter: | Gary Karasiuk <karasiuk> | ||||||||||||
| Component: | p2 | Assignee: | DJ Houghton <dj.houghton> | ||||||||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||||||||
| Severity: | major | ||||||||||||||
| Priority: | P3 | CC: | john.arthorne, krzysztof.daniel, natalia.bartol, pascal, pwebster, rtaniwa, tjwatson | ||||||||||||
| Version: | 3.6 | ||||||||||||||
| Target Milestone: | 3.6.1 | ||||||||||||||
| Hardware: | PC | ||||||||||||||
| OS: | Windows XP | ||||||||||||||
| Whiteboard: | |||||||||||||||
| Bug Depends on: | |||||||||||||||
| Bug Blocks: | 314939, 317519 | ||||||||||||||
| Attachments: |
|
||||||||||||||
|
Description
Gary Karasiuk
I added some code to FileOutStream to print a stack trace when the platform.xml was opened. Here are the results from the first startup. You can see that the platform.xml file is changed twice. The number in the exception is System.currentTimeMillis()
java.lang.RuntimeException: Accessing platform.xml at 1274446349500
at java.io.FileOutputStream.<init>(Unknown Source)
at java.io.FileOutputStream.<init>(Unknown Source)
at org.eclipse.equinox.internal.p2.update.ConfigurationWriter.save(Unknown Source)
at org.eclipse.equinox.internal.p2.update.ConfigurationIO.write(Unknown Source)
at org.eclipse.equinox.internal.p2.update.Configuration.save(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.PlatformXmlListener.synchronizeConfiguration(Unknown Sourc
e)
at org.eclipse.equinox.internal.p2.reconciler.dropins.PlatformXmlListener.stopPoll(Unknown Source)
at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.stopPoll(Unknown Source)
at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.poll(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.watchConfiguration(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Unknown Source)
at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(Unknown Source)
at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(Unknown Source)
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(Unknown Source)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(Unknown Source)
java.lang.RuntimeException: Accessing platform.xml at 1274446363062
at java.io.FileOutputStream.<init>(Unknown Source)
at java.io.FileOutputStream.<init>(Unknown Source)
at org.eclipse.equinox.internal.p2.update.ConfigurationWriter.save(Unknown Source)
at org.eclipse.equinox.internal.p2.update.ConfigurationIO.write(Unknown Source)
at org.eclipse.equinox.internal.p2.update.Configuration.save(Unknown Source)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.PlatformConfigurationWrapper.save(Unknown Source)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.savePlatformConfigurationWrapper(Unknown
Source)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.commit(Unknown Source)
at org.eclipse.equinox.internal.p2.engine.EngineSession.commit(Unknown Source)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Unknown Source)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.executePlan(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.synchronize(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.synchronize(Unknown Source)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(Unknown Source)
at java.security.AccessController.doPrivileged(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(Unknown Source)
at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Unknown Source)
at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(Unknown Source)
at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(Unknown Source)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(Unknown Source)
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(Unknown Source)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(Unknown Source)
Interesting. The reconciler bundle activator is supposed to re-read the timestamps and then cache them at the end of doing all its work. (In reply to comment #1) I think the double opening of the platform.xml file that I posted in the previous comment is a bit of an anomaly. The more common pattern is just a single opening, but with still the second startup being slow and still with the platform.xml timestamps not matching. java.lang.RuntimeException: Accessing platform.xml at 1274447986578 at java.io.FileOutputStream.<init>(Unknown Source) at java.io.FileOutputStream.<init>(Unknown Source) at org.eclipse.equinox.internal.p2.update.ConfigurationWriter.save(Unknown Source) at org.eclipse.equinox.internal.p2.update.ConfigurationIO.write(Unknown Source) at org.eclipse.equinox.internal.p2.update.Configuration.save(Unknown Source) at org.eclipse.equinox.internal.p2.touchpoint.eclipse.PlatformConfigurationWrapper.save(Unknown Source) at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.savePlatformConfigurationWrapper(Unknown Source) at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.commit(Unknown Source) at org.eclipse.equinox.internal.p2.engine.EngineSession.commit(Unknown Source) at org.eclipse.equinox.internal.p2.engine.Engine.perform(Unknown Source) at org.eclipse.equinox.internal.p2.engine.Engine.perform(Unknown Source) at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.executePlan(Unknown Source) at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.synchronize(Unknown Source) at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.synchronize(Unknown Source) at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Unknown Source) at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(Unknown Source) at java.security.AccessController.doPrivileged(Unknown Source) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(Unknown Source) at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(Unknown Source) at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(Unknown Source) at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(Unknown Source) at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Unknown Source) at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source) at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(Unknown Source) at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(Unknown Source) at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(Unknown Source) at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(Unknown Source) at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(Unknown Source) at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(Unknown Source) I think it has to do when we find a feature in the dropins and then add it to the platform.xml file. Will continue investigation. (In reply to comment #4) Hi John/DJ, Any updates on this? No, yesterday was a holiday here. I performed a test where I only used Eclipse, i.e. I did not use our adopting product. I used the 3.6RC2 driver. I am seeing the same slow code path taken for the second startup. The org.eclipse.equinox.internal.p2.reconciler.dropins.Activator#isUpToDate() method is returning false during the second startup. I think the reason that this was not noticed in the Eclipse only case, is that the "slow" code path, isn't slow when only the Eclipse platform is installed. Could you do further analysis and see why we are entering this slow path? Which one of the short-circuiting check is failing? (In reply to comment #8) > Could you do further analysis and see why we are entering this slow path? Which > one of the short-circuiting check is failing? It is the timestamp check on the platform.xml file. (In reply to comment #7) > I am seeing the same slow code path taken for the second startup. The > org.eclipse.equinox.internal.p2.reconciler.dropins.Activator#isUpToDate() > method is returning false during the second startup. Can you describe the scenario you are testing here? Are you doing an install, update, or uninstall? Are you installing features or just plugins? Just one or a large number, etc. I collided with John's comment on providing the steps to reproduce ... I tried to reproduce by simply placing a single bundle in the dropins folder but the check to org.eclipse.equinox.internal.p2.reconciler.dropins.Activator#isUpToDate() is returning true as expected for me on the second start after adding a single bundle to the dropins folder. (In reply to comment #10) > Can you describe the scenario you are testing here? Are you doing an install, > update, or uninstall? Are you installing features or just plugins? Just one or > a large number, etc. 1) Start with Eclipse 3.6 RC2 2) Start it/stop it. 3) Add one feature and two bundles to the dropins/eclipse folder. 4) start/stop 5) start/stop Sometimes I vary step 3, but the numbers are always small, i.e. two features, a fragment and four bundles. (In reply to comment #11) For all my testing I didn't try loose bundles, it was always features AND bundles. Also, I used a remote debugger to verify the code path, so that I could start the product "normally", rather than in -dev mode. Having a feature is likely to be the key since it will cause the platform.xml to be modified. I think I found the problem .... it is the finalizer thread. The platform.xml file isn't being closed when you think it is, but rather it is being closed when the FileOutputSteam instance is finalized.
I added some tracing to the FileOutputStream and here is what I seeing during the next two startups:
D:\eclipse\36-target\eclipse>eclipsec.exe -data \ws\36-target\play
java.lang.RuntimeException: File D:\eclipse\36-target\eclipse\configuration\org.eclipse.update\platform.xml is being opened by thread 14 at
1274869938578
at java.io.FileOutputStream.<init>(FileOutputStream.java:170)
at java.io.FileOutputStream.<init>(FileOutputStream.java:132)
at org.eclipse.equinox.internal.p2.update.ConfigurationWriter.save(ConfigurationWriter.java:35)
at org.eclipse.equinox.internal.p2.update.ConfigurationIO.write(ConfigurationIO.java:69)
at org.eclipse.equinox.internal.p2.update.Configuration.save(Configuration.java:46)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.PlatformConfigurationWrapper.save(PlatformConfigurationWrapper.java:236)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.savePlatformConfigurationWrapper(EclipseTouchpoint.java:78)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.commit(EclipseTouchpoint.java:144)
at org.eclipse.equinox.internal.p2.engine.EngineSession.commit(EngineSession.java:123)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Engine.java:91)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Engine.java:44)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.executePlan(ProfileSynchronizer.java:567)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.synchronize(ProfileSynchronizer.java:124)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.synchronize(Activator.java:410)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Activator.java:164)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:783)
at java.security.AccessController.doPrivileged(AccessController.java:251)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:774)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:755)
at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:370)
at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:374)
at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1067)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:561)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:546)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:459)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:440)
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:227)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:337)
java.lang.RuntimeException: File platform.xml is being closed in thread 14 at 1274869938593
at java.io.FileOutputStream.close(FileOutputStream.java:298)
at java.io.FilterOutputStream.close(FilterOutputStream.java:155)
at sun.nio.cs.StreamEncoder$CharsetSE.implClose(StreamEncoder.java:442)
at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:171)
at java.io.OutputStreamWriter.close(OutputStreamWriter.java:271)
at java.io.PrintWriter.close(PrintWriter.java:307)
at org.eclipse.equinox.internal.p2.update.ConfigurationWriter.save(ConfigurationWriter.java:67)
at org.eclipse.equinox.internal.p2.update.ConfigurationIO.write(ConfigurationIO.java:69)
at org.eclipse.equinox.internal.p2.update.Configuration.save(Configuration.java:46)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.PlatformConfigurationWrapper.save(PlatformConfigurationWrapper.java:236)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.savePlatformConfigurationWrapper(EclipseTouchpoint.java:78)
at org.eclipse.equinox.internal.p2.touchpoint.eclipse.EclipseTouchpoint.commit(EclipseTouchpoint.java:144)
at org.eclipse.equinox.internal.p2.engine.EngineSession.commit(EngineSession.java:123)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Engine.java:91)
at org.eclipse.equinox.internal.p2.engine.Engine.perform(Engine.java:44)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.executePlan(ProfileSynchronizer.java:567)
at org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.synchronize(ProfileSynchronizer.java:124)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.synchronize(Activator.java:410)
at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Activator.java:164)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:783)
at java.security.AccessController.doPrivileged(AccessController.java:251)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:774)
at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:755)
at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:370)
at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:374)
at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1067)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:561)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:546)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:459)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:243)
at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:440)
at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:227)
at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:337)
Now: 1274869938625, file last mod: 1274869938625java.lang.RuntimeException: File platform.xml is being closed in thread 21 at 1274869939140
at java.io.FileOutputStream.close(FileOutputStream.java:298)
at java.io.FileOutputStream.finalize(FileOutputStream.java:358)
at java.lang.J9VMInternals.runFinalize(J9VMInternals.java:412)
D:\eclipse\36-target\eclipse>eclipsec.exe -data \ws\36-target\play
File: D:\eclipse\36-target\eclipse\configuration\org.eclipse.update\platform.xml last modified: 1274869939968 does not equal timestamp: 1274
869938625
(In reply to comment #15) Here are the key lines in comment 15: 1) File platform.xml is being closed in thread 14 at 1274869938593 -- This is when the ConfigurationWriter starts closing the file. 2) File platform.xml is being closed in thread 21 at 1274869939140 -- This is when the finalizer starts closing the file. (0.547 seconds later). 3) This is the platform.xml timestamp that is stored in the timestamp cache. 1274869938625 -- this is 32ms after 1), but that is because I need to get the time before Java calls the OS to close the file. 4) The OS timestamp on the platform.xml file is 1274869939968 (which is 828ms after 2)) hmm, I did some more testing on the effects of doing a double close, in my tests the second close didn't effect the file timestamp. Here is what I did: 1) created a new FileOutputStream and wrote a byte to it. -- I observed that the file was created and it had a current timestamp. (It also had a length of 1). I also saw that the file was owned by the Java process. 2) closed the FileOutputStream -- I observed that the file timestamp was updated. I saw that the file was no longer owned by the Java process. 3) closed the FileOutputStream a second time -- nothing appeared to change. The file timestamp stayed the same as it was in 2). Created attachment 169978 [details]
all the OS events that touch the platform.xml file
I did a trace using a tool called procmon of all the events that involved the platform.xml file.
Maybe they will help shed some light on why this file is changing
(In reply to comment #18) A line that caught my eye was 139: ReplaceIfExists: False, FileName: D:\eclipse\36-target\eclipse\configuration\org.eclipse.update\history\1274876152468.xml I'm not sure how to read this line, or which way the rename is going, but if we are moving this file around that could effect the timestamp. Since my double close investigation didn't pan out, I have a new theory. I think that this line in PlatformConfiguration#save(URL) is causing the trouble: cfigTmp.setLastModified(config.getDate().getTime()); Maybe someone who is more familiar with this code can take a look, but I can't see how the config.getDate() ever gets set from the timestamp of the current platform.xml file. To me it looks like it is getting a new timestamp, and hence when the file is renamed to platform.xml it has a new timestamp. org.eclipse.update.internal.configurator.Configuration has two fields date and lastModified. It seems like they represent the same thing, but are not being synchronized properly. For example the configuration parser uses setLastModified(long lastModified) but this doesn't change the date and then later on we get the "old" date: cfigTmp.setLastModified(config.getDate().getTime()); I wonder if this is the problem? Gary, thanks for the investigation. The code that you are referring to is in the old Update Manager code and isn't (shouldn't) being called in our case. It should only be called if there are things being installed via the Update Manager UI or old command-line operations. The platform.xml file (which is modeled by the Configuration object) does have a timestamp in it but I believe p2 only looks at the java.io.File timestamp when taking it into consideration for being up-to-date. (In reply to comment #22) I think it is being called :-) Here is the stack trace: Thread [main] (Suspended (breakpoint at line 1223 in File)) File.renameTo(File) line: 1223 PlatformConfiguration.save(URL) line: 635 PlatformConfiguration.save() line: 574 PlatformConfiguration.startup(URL, Location) line: 714 ConfigurationActivator.getPlatformConfiguration(URL, Location) line: 404 ConfigurationActivator.initialize() line: 136 ConfigurationActivator.start(BundleContext) line: 69 BundleContextImpl$1.run() line: 783 AccessController.doPrivileged(PrivilegedExceptionAction<T>) line: 251 BundleContextImpl.startActivator(BundleActivator) line: 774 BundleContextImpl.start() line: 755 BundleHost.startWorker(int) line: 370 BundleHost(AbstractBundle).start(int) line: 284 SecureAction.start(Bundle, int) line: 417 BundleLoader.setLazyTrigger() line: 265 EclipseLazyStarter.postFindLocalClass(String, Class, ClasspathManager) line: 106 ClasspathManager.findLocalClass(String) line: 453 DefaultClassLoader.findLocalClass(String) line: 216 BundleLoader.findLocalClass(String) line: 393 BundleLoader.findClassInternal(String, boolean, ClassLoader) line: 469 BundleLoader.findClass(String, boolean) line: 422 BundleLoader.findClass(String) line: 410 DefaultClassLoader.loadClass(String, boolean) line: 107 DefaultClassLoader(ClassLoader).loadClass(String) line: 618 BundleLoader.loadClass(String) line: 338 BundleHost.loadClass(String, boolean) line: 232 BundleHost(AbstractBundle).loadClass(String) line: 1197 ServiceComponent.createInstance() line: 457 ServiceComponentProp.createInstance() line: 254 ServiceComponentProp.build(Bundle, Object, boolean) line: 315 InstanceProcess.buildComponent(Bundle, ServiceComponentProp, Object, boolean) line: 580 ServiceReg.getService(Bundle, ServiceRegistration) line: 53 ServiceUse$1.run() line: 120 AccessController.doPrivileged(PrivilegedAction<T>) line: 202 ServiceUse.getService() line: 118 ServiceRegistrationImpl.getService(BundleContextImpl) line: 447 ServiceRegistry.getService(BundleContextImpl, ServiceReferenceImpl) line: 430 BundleContextImpl.getService(ServiceReference) line: 667 ServiceTracker.addingService(ServiceReference) line: 442 ServiceTracker$Tracked.customizerAdding(Object, Object) line: 896 ServiceTracker$Tracked(AbstractTracked).trackAdding(Object, Object) line: 261 ServiceTracker$Tracked(AbstractTracked).trackInitial() line: 184 ServiceTracker.open(boolean) line: 339 ServiceTracker.open() line: 273 InternalPlatform.getBundleGroupProviders() line: 223 Platform.getBundleGroupProviders() line: 1261 IDEWorkbenchPlugin.getFeatureInfos() line: 281 WorkbenchActionBuilder.makeFeatureDependentActions(IWorkbenchWindow) line: 1178 WorkbenchActionBuilder.makeActions(IWorkbenchWindow) line: 1001 WorkbenchActionBuilder(ActionBarAdvisor).fillActionBars(int) line: 147 WorkbenchActionBuilder.fillActionBars(int) line: 335 WorkbenchWindow.fillActionBars(int) line: 3527 WorkbenchWindow.<init>(int) line: 414 Workbench3xImplementation.createWorkbenchWindow(int) line: 31 Workbench.newWorkbenchWindow() line: 1874 Workbench.access$14(Workbench) line: 1872 Workbench$63.runWithException() line: 3588 Workbench$63(StartupThreading$StartupRunnable).run() line: 31 RunnableLock.run() line: 35 UISynchronizer(Synchronizer).runAsyncMessages(boolean) line: 134 Display.runAsyncMessages(boolean) line: 4041 Display.readAndDispatch() line: 3660 IDEWorkbenchAdvisor(WorkbenchAdvisor).openWindows() line: 803 Workbench$31.runWithException() line: 1566 Workbench$31(StartupThreading$StartupRunnable).run() line: 31 RunnableLock.run() line: 35 UISynchronizer(Synchronizer).runAsyncMessages(boolean) line: 134 Display.runAsyncMessages(boolean) line: 4041 Display.readAndDispatch() line: 3660 Workbench.runUI() line: 2537 Workbench.access$4(Workbench) line: 2427 Workbench$7.run() line: 670 Realm.runWithDefault(Realm, Runnable) line: 332 Workbench.createAndRunWorkbench(Display, WorkbenchAdvisor) line: 663 PlatformUI.createAndRunWorkbench(Display, WorkbenchAdvisor) line: 149 IDEApplication.start(IApplicationContext) line: 115 EclipseAppHandle.run(Object) line: 196 EclipseAppLauncher.runApplication(Object) line: 110 EclipseAppLauncher.start(Object) line: 79 EclipseStarter.run(Object) line: 369 EclipseStarter.run(String[], Runnable) line: 179 NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method] NativeMethodAccessorImpl.invoke(Object, Object[]) line: 48 DelegatingMethodAccessorImpl.invoke(Object, Object[]) line: 37 Method.invoke(Object, Object...) line: 600 Main.invokeFramework(String[], URL[]) line: 619 Main.basicRun(String[]) line: 574 Main.run(String[]) line: 1407 The stack trace in comment 23 came from simply starting eclipse (after adding a feature and bundle to the dropins) with this command: eclipsec.exe -data \ws\36-target\play albeit I added the following lines to the eclipse.ini (but that shouldn't make a difference): -Xdebug -Xrunjdwp:transport=dt_socket,server=y,suspend=y,address=1044 Again, as near as I can tell, the problem timestamp is being set with this line: cfigTmp.setLastModified(config.getDate().getTime()); as I couldn't find any place where config#date was being set correctly. I reproduced problem by myself and I confirm that problem occurs when a feature is installed/uninstalled what modifies platform.xml and causes new history file to be created in org.eclipse.update\history. After platform.xml has been changed currentPlatformConfiguration.config.isDirty is true in PlatformConfiguration.startup(), so save(URL url) is called. In PlatformConfiguration#save(URL url) files are switched and renamed: Description form source code: // Do safe i/o: // - backup current config, by moving it to the history folder // - write new config to platform.xml.tmp file // - rename the temp file to platform.xml When xml history file is created, platform.xml is touched and this new timestamp is not cached. Created attachment 170064 [details]
A patch for your consideration.
Comment on attachment 170064 [details]
A patch for your consideration.
whoops left a debugging line in the patch
Created attachment 170065 [details]
A patch for your consideration.
Created attachment 170180 [details]
Timestamp patch for platform.xml
Gary, your patch helps with avoiding reconciliation during second startup, but as a side effect platform.xml backup in history is not created, so there will be no possibility to revert configuration.
I think that what we really need here is to keep platform.xml modification timestamp the same as is written to cache.timestamps. This timestamp is correct before backup file is created. When files are switched and renamed this timestamp is moved forward due to file modification (actually platform.xml is created as completely new file).
Here is a patch that keeps the platform.xml timestamp and sets it back to platform.xml when backup operation is completed. This solves second startup issue.
It seems like a bug that update.configurator is writing this file at all (or at least it's not optimal). I presume update is just writing the exact same platform.xml contents out again, so we should be able to optimize this to avoid writing it altogether in this case. Trying to fix file timestamps manually often fails because different operating systems and file systems may have different timestamp granularity and the end result may not be the same. Note that java.io.File#setLastModified specifies that it may truncate the passed value, so we may end up with a different value even when attempting to make the file appear unchanged. Can you attach a patch of the features/plug-ins that you are using to replicate this problem? I am unable to replicate it with the simple feature/plug-in that I am using. Thanks. Created attachment 170280 [details]
patch
Thanks again for your investigation into this. I received features and bundles from Gary and was able to reproduce this locally.
The problem is in the eclipse touchpoint code... we read the config timestamp (embedded in the XML) as we should but we should be updating it before we write it out. (the old Update Manager does this in PlatformConfiguration#saveAsXML)
It is a pretty small patch, can we get this into 3.6 please? DJ's patch works good and prevents org.eclipse.update.configurator.PlatfomConfiguration from calling reconcile() and rewriting platform.xml. But it also disables creating backup files in history folder. Shouldn't we then create backup file when platform.xml in written in org.eclipse.equinox.p2.touchpoint.eclipse.ConfigurationWriter? Natalia, there are 2 separate issues here. 1). Sometimes when p2 installs features and updates the platform.xml file, the Update Manager performs a reconciliation on startup and re-writes that file which then causes the p2 reconciler to re-reconcile on second startup. This is fixed by the attached patch. 2). When you install features via p2 the Update Manager's history.xml file isn't updated. The scenario that is broken (I believe) is if you install via p2 and then want to rollback via Update Manager. It is unclear whether or not this is an interesting use case, we will need to define exactly how far we want to go with the interoperability between p2 and UM. If you feel this is important then feel free to open a new bug report with details, although given that we will be removing the Update Manager bundles altogether soon in a future release, this issue may not be addressed. (In reply to comment #34) > It is a pretty small patch, can we get this into 3.6 please? Given the ongoing discussion and the sensitivity in this area I don't think it is a good idea to rush this into 3.6. Opened bug 314939 to track potential release/patch into 3.4.2+. Released patch to r36x maintenance stream. Closing. |