More and more companies are adopting cloud solutions and virtual desktop infrastructure (VDI) which can lead to startup time issues with Eclipse based applications like IBM Developer for z/OS (IDz).
I will try to list here some common issues and solutions as well as tips to troubleshoot the problem.
The 3 main phases
There are 3 main phases during Eclipse “startup” which usually have quite different reasons for being slow:
- Startup of java.exe and before splash screen
- between splash screen and workspace selection
- after workspace selection until workbench is usable
By default many IBM Eclipse products use javaw.exe instead of java.exe so you don’t see the first command window. You just see that it takes a long time before the splash screen appears. You will see below how to make it visible by using java.exe instead of javaw.exe.
Common problems and solutions
Slow startup phase |
Possible solution |
Before the splash screen |
- Check your real-time virus scanner configuration and exclude jar files.
Antivirus exclusion
- Add Java option
-Xshareclasses:cacheDir= to your eclipse.ini to target a persistent and well performing network drive for the JVM class cache. Default is in the user home directory, something like C:\Users\MYUSER\AppData\Local\javasharedresources
|
Before workspace selection |
Eclipse OSGI is probably running an unexpected reconciliation.
|
After workspace selection |
Use -data option to target a persistent and well performing network drive. |
See Eclipse runtime options for more information.
Your eclipse.ini will then looks like:
... -install C:/Program Files/IBM/SDP -configuration I:/rdz-start/ -vmargs -Xquickstart ... -Xshareclasses:name=IBMSDP_%u,cacheDir=I:/javashrcls ... -Declipse.home.location="C:/Users/johndoe/AppData/Local/.../pkgid1234/.../ProgramFilesX64/IBM/SDP"
|
What if eclipse.ini is protected and readonly?
If you have no permission to modify eclipse.ini, you can still indicate another one on the command line by using parameter --launcher.ini, like for example:
"C:\Program Files\IBM\IDZ15\eclipse.exe" --launcher.ini
I:/idz-start/eclipse.ini |
Antivirus exclusion
When IDz is slow to show the splash screen or to run even though it does not seem to consume any CPU then a possible cause is that IDz is waiting on the antivirus to finish scanning jar files or configuration files from the workspace.
Depending on how the anti-virus works, the problem can be random like being slow on startup but only after a reboot of the machine or an operation/menu being slow only the first time,...
The problem can usually be solved by adding exclusion to the antivirus scanner.
The following directories are known for causing performance degradation if they are scanned:
- IDz installation directories like for example
c:\Program Files\IBM and c:\Program Files\IBMShared where most of the jar files are located. Check with Inst/allation Manager for the exact location of your shared and installation directories.
- user workspace like
c:\workspaces\wrk1
- user home directory for the Eclipse OSGI configuration if the user is not administrator of his machine, like
C:\Users\JohnDoe\.eclipse\org.eclipse.platform_4.6.3_1991667125_win32_win32_x86_64\configuration . When the user is administrator, IDz uses the configuration folder under [installation dir]\configuration . But when a user is not administrator or has no write permission on the default configuration directory then Eclipse will create a new configuration under his home directory.You will have to check with your operating system provider where the home directory is located.
|
To finalize this list, you need to take into consideration:
- how the anti-virus works: what is scanned and when and how to exclude directories (you may need to contact your anti-virus provider on that)
- the operating system, regional language settings, hypervisor environment, ... which can for example change the location of the user home directory
- where IDz has been installed
- if you accept to not scan these directories (you may need to discuss it with your security team)
|
How to troubleshoot slow startup
The steps are:
Enable Eclipse debug traces
Create a file named .options (in c:\temp for example) with the following content:
# Prints out start level service debug information
org.eclipse.osgi/debug/startlevel=true
# Prints out timing information for bundle activation
org.eclipse.osgi/debug/bundleTime=true
# Debug the loading of message bundles
org.eclipse.osgi/debug/messageBundles=true
# monitor bundle activation
org.eclipse.osgi/monitor/activation=true
org.eclipse.equinox.p2.core/debug=true
org.eclipse.equinox.p2.core/reconciler=true
org.eclipse.equinox.p2.core/publisher=true
|
Enable JVM traces in eclipse.ini:
Unfortunately, the OSGI trace entries do not have a timestamp… so it can be useful to add the -Xtrace option in bold below to your eclipse.ini and use java.exe instead of javaw.exe
-vm jdk/jre/bin/java.exe -startup plugins/org.eclipse.equinox.launcher_1.3.0.v20140415-2008.jar –launcher.library plugins/org.eclipse.equinox.launcher.win32.win32.x86_64_1.1.200.v20150204-1316 -install C:/Program Files/IBM/SDP14 -vmargs -Xquickstart -Xms100m -Xmx1024m -Xmnx64m -Xgcpolicy:gencon -Xscmx96m -Xshareclasses:name=IBMSDP14_%u -XX:MaxPermSize=512M -Xnolinenumbers -Xcompressedrefs -Xtrace:none,maximal=mt,output=c:\temp\jvmtrc.log,trigger={method{org/eclipse/core/runtime/internal/adaptor/EclipseAppLauncher.runApplication,jstacktrace},method{org/eclipse/equinox/internal/p2/reconciler/dropins/Activator.start,jstacktrace},method{org/eclipse/equinox/launcher/Main.main,jstacktrace},method{org/eclipse/ui/internal/ide/application/IDEApplication.promptForWorkspace,jstacktrace}},stackdepth=1
|
Traces are created in output=c:\temp\jvmtrc.log
Start Eclipse in debug mode
You will need to start eclipseC.exe instead of eclipse.exe with option -debug and -consoleLog
For example:
"C:\Program Files\IBM\SDP14\eclipsec.exe" -debug c:\temp\.options -consoleLog > c:\temp\startup.log 2>&1
|
What products/plugins are installed and being started?
When you start an Eclipse “product” like IDz, it does not mean that you start “only” IDz.
You start everything that is installed on this same workbench/shell but under the branding of product IDz (meaning splash screen, default perspective,…).
I often hear “IDz startup is slow” just because the IDz icon is being clicked on but actually it starts every products installed “shell shared” with IDz like Enterprise Workflow Management, eGit, Data Studio, CICS Explorer, and any other third party products, debugger,…
To know what you have really started, go to menu Help > about > Installation Details and click on tab Configuration.
You will then see most of the paths being used (OSGI, user home,…) and all the plugins/features loaded:
org.eclipse.* will be Eclipse plugins
com.ibm.* will be IBM plugins
other packages will be third party plugins
Examples of IBM products/plugins:
com.ibm.datastudio.consolidated.licensing (1.0.400.v20150716_0751) "IBM Data Studio" [Starting] com.ibm.pdtools.common.component.core (14.0.17.v20170515-1506) "Problem Determination Tools for z/OS" [Active] com.ibm.rational.developer.systemz.product (14.0.1015.v20170624_0301) "IBM Developer for z Systems" [Active] com.ibm.team.concert (3.1.1200.v20151110_0208) "Rational Team Concert" [Active] |
Analyze the logs
OSGI traces
What you do not want to find are traces like “[reconciler] Performing reconciliation.”
Under normal circumstances, you want to see reconciliation happening during:
- First time the user launches Eclipse
- When new plugins have been installed or upgraded
Below are some key entries to look for in the OSGI trace file (c:\temp\startup.log in this example):
Entry |
Starting org.eclipse.equinox.simpleconfigurator_1.1.0.v20131217-1203 [3] End starting org.eclipse.equinox.simpleconfigurator_1.1.0.v20131217-1203 [3] 118962 |
Explanation |
Created by org.eclipse.osgi.internal.framework.BundleContextImpl start = System.currentTimeMillis(); Debug.println("Starting " + bundle); Debug.println("End starting " + bundle + " " + (System.currentTimeMillis() - start));
Indicate the plugin started in 118962 milliseconds |
Entry |
Starting application: 354211 |
Explanation |
Created by org/eclipse/core/runtime/internal/adaptor/EclipseAppLauncher.runApplication() and indicates the elapse time between start and current in milliseconds. String timeString = equinoxConfig.getConfiguration("eclipse.startTime"); long time = timeString == null ? 0L : Long.parseLong(timeString); Debug.println("Starting application: " + (System.currentTimeMillis() - time));
Workspace selection should happen shortly after this entry. |
Entry |
StartLevel: changing bundle StartLevel: resuming bundle; |
Explanation |
Created by org.eclipse.osgi.container.ModuleContainer
“changing bundle” happens during -clean or when starting Eclipse the first time and OSGI config is being built/rebuilt |
Entry |
[p2] Tue May 30 03:14:19 PDT 2017 - [Start Level: Equinox Container: 80b1686c-2045-0017-177b-d1f592d8e972] [reconciler] Cached timestamp file empty. [p2] Tue May 30 03:14:19 PDT 2017 - [Start Level: Equinox Container: 80b1686c-2045-0017-177b-d1f592d8e972] [reconciler] Performing reconciliation. |
Explanation |
Created by org.eclipse.equinox.internal.p2.reconciler.dropins.ProfileSynchronizer.isUpToDate()
P2 has started |
JVM Traces
The JVM trace file can be formatted using command:
"C:\Program Files\IBM\SDP14\jdk\jre\bin\java.exe" com.ibm.jvm.TraceFormat C:\temp\jvmtrc.log C:\temp\jvmtrc.formatted.log
and the output looks like:
Trace file header: JVM start time: 13:36:14.200000000
Trace Formatted Data
Time (UTC) Thread ID Tracepoint ID Type Tracepoint Data 13:36:14.758548889 *0x0000000002330500 mt.3 Entry >org/eclipse/equinox/launcher/Main.main([Ljava/lang/String;)V bytecode static method 13:36:14.758554407 0x0000000002330500 j9trc_aux.0 Event jstacktrace: 13:36:14.758566210 0x0000000002330500 j9trc_aux.1 Event [1] org.eclipse.equinox.launcher.Main.main (Bytecode PC: 0) 13:36:21.533760790 *0x000000000263a600 mt.0 Entry >org/eclipse/equinox/internal/p2/reconciler/dropins/Activator.start(Lorg/osgi/framework/BundleContext;)V bytecode method, this = 0xfccead60 13:36:21.533770149 0x000000000263a600 j9trc_aux.0 Event jstacktrace: 13:36:21.533782162 0x000000000263a600 j9trc_aux.1 Event [1] org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start (Bytecode PC: 0) 13:36:21.549168878 0x000000000263a600 mt.6 Exit <org/eclipse/equinox/internal/p2/reconciler/dropins/Activator.start(Lorg/osgi/framework/BundleContext;)V bytecode method 13:36:21.651251152 *0x0000000002330500 mt.0 Entry >org/eclipse/core/runtime/internal/adaptor/EclipseAppLauncher.runApplication(Ljava/lang/Object;)Ljava/lang/Object; bytecode method, this = 0xfcf20ba8 13:36:21.651262676 0x0000000002330500 j9trc_aux.0 Event jstacktrace: 13:36:21.651271476 0x0000000002330500 j9trc_aux.1 Event [1] org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication (Bytecode PC: 0) 13:36:22.141296968 0x0000000002330500 mt.0 Entry >org/eclipse/ui/internal/ide/application/IDEApplication.promptForWorkspace(Lorg/eclipse/swt/widgets/Shell;Lorg/eclipse/ui/internal/ide/ChooseWorkspaceData;Z)Ljava/net/URL; bytecode method, this = 0xfd4a4d68 13:36:22.141318759 0x0000000002330500 j9trc_aux.0 Event jstacktrace: 13:36:22.141328048 0x0000000002330500 j9trc_aux.1 Event [1] org.eclipse.ui.internal.ide.application.IDEApplication.promptForWorkspace (Bytecode PC: 0) 13:36:24.108059854 0x0000000002330500 mt.6 Exit <org/eclipse/ui/internal/ide/application/IDEApplication.promptForWorkspace(Lorg/eclipse/swt/widgets/Shell;Lorg/eclipse/ui/internal/ide/ChooseWorkspaceData;Z)Ljava/net/URL; bytecode method 13:36:24.723034921 0x0000000002330500 mt.6 Exit <org/eclipse/core/runtime/internal/adaptor/EclipseAppLauncher.runApplication(Ljava/lang/Object;)Ljava/lang/Object; bytecode method 13:36:26.088397751 *0x000000000263a600 dg.262 Debug ***** Thread termination - trace purged ***** |
Entries to look for are the reconcilier startup and workspace prompt.