Community
Participate
Working Groups
The core headless startup test had a major regression introduced somewhere between I20090224 and N20090305. We need to track down the cause of this.
From more careful analysis of results, the regression actually appeared between N20090205-2000 and I20090210-0950. There was a brief improvement in I20090224 and then it was back again. There were some problems with the I20090224 build, so I think the real regression came earlier. I'm reviewing changes between those two builds to see if I can narrow down the cause.
The only significant change that matches the numbers so far is the introduction of Equinox DS: bug 253926. However I have been measuring DS startup and it only takes about 30ms for me. There may be something peculiar to the test environment that makes it take longer.
DS spawns a background thread to do component resolution. Even though DS look like it starts fast, perhaps this thread is slowing down the rest of the startup.
I downloaded the test framework, and ran the test both with and without DS in the SDK. It shows an average 47ms slowdown with ds enabled (discarding two runs that were inconsistent). This doesn't account for the roughly 500ms slowdown introduced in 20090210 With DS: Elapsed Process: 984ms Elapsed Process: 1.01s Elapsed Process: 984ms Elapsed Process: 984ms Elapsed Process: 984ms CPU Time: 1.11s CPU Time: 1.14s CPU Time: 1.11s CPU Time: 1.12s CPU Time: 1.16s Without DS: Elapsed Process: 937ms Elapsed Process: 937ms Elapsed Process: 937ms Elapsed Process: 921ms Elapsed Process: 937ms CPU Time: 1.05s CPU Time: 1.06s CPU Time: 1.09s CPU Time: 1.06s CPU Time: 1.09s
John, when the test framework can you use a .options file (with the -debug <trace fiel> options) for tracing? If so it would be interesting to capture the console output from each run with the following trace enabled: org.eclipse.osgi/profile/startup=true
I can set the trace option, but I haven't yet found a way to capture stdout to see the result. If we moved to using DebugTrace it would be easier to capture the output.
You can also set the following option to write the profile data out to. It should append to the file each run. org.eclipse.osgi/defaultprofile/logfilename=/develop/trace.out
Created attachment 131165 [details] Performance trace output on I20090401
Created attachment 131174 [details] Performance trace output on I20090401 Previous was from first run. This one is from a second run.
Created attachment 131177 [details] Performance trace output on 3.5M5
There are some definite differences here: simpleconfigurator startup: M5: 31ms I20090401: 235ms Equinox ds: M5: 0ms (didn't exist) I20090401: 31ms But from this 235ms slowdown it ends up being only about 100ms slower, so some of the lost time is made up later. Simpleconfigurator looks like a promising place to start deeper investigation.
We tracked down and solved part of this regression in bug 271621.
The big regression from 3.4 has finally been fixed, and we are back down near the baseline numbers. We still see a regresion of 100-150ms depending on the build. This can be attributed to the general decay of this test because it is sensitive to the number of plugins in the system, the size of the plug-in registry, etc. There is also a small regression due to the introduction of Equinox DS that we accept given the benefits it provides. Profiling on the latest builds, the vast majority of time is taken by class loading, so there is very little opportunity for further improvements here.
Verified for M7 with I20090430-2300 results
