[bpel-dev] Re: Plug-in loading

[Michal Chmielewski <michal.chmielewski@xxxxxxxxxx>]

Bruno Wassermann wrote:

Michal, 

Where do you notice the delay? How do you reproduce that? 
  

Well, since I have the validator plug-in which is not yet checked in ... because it is not yet nearly useful ... it's kinda hard to duplicate this.

But I took your advice and profiled it using TPTP directly in Eclipse  .... in essence, here is the scoop and the pretty printed HTML output of profiling is attached for the methods of interest.

The validator plugin had a dependency on all the other plugins as it turned out. In the initial primodial invocation it had to load dependent classes and on that initial invocation it had to loop in 1161 classes (look at the attached trace1.html file below). This trace shows the method validateBPEL() which invokes a bunch of methods listed in the table. You can see that loadClassInternal() was called 1161 times and it had the longest cumulative wall time (31+ sec, mind you this is with the profiler running, so wall time will be longer).

In the trace2.html file, you will see that the number of the calls to loadClassInternal() has been reduced to 113 as I had removed the dependency of the validator plugin on the the org.eclipse.bpel.ui plugin. So this simply means that about 1000 classes do not get needlessly loaded. There are other bottlenecks on the very first invocation still, but at least I have reduced one and shown that there is some direct relationship to the first invocation being slow and class loading.

In trace3.html you can see how is the BPEL Resource reading done on the first invocation - 90% of the time is spent in getResource(), so this includes the reading of the file and all the loadClassInternal() calls are in here.

The attachment trace4.html records the 2nd validation invocation (when everything has been bootstrapped, ie all classes loaded). You can see there is no calls to loadClassInternal() at all. The wall time for the validateBPEL() method is 1.74 seconds, versus 24 seconds in trace2.html.

Finally, in trace5.html the call to read the BPEL source using EMF is also insignificant - the getResource() method takes only 0.18 seconds of wall time vs. 6.36 seconds before (on the first run, look at trace3.html)

So based on this, I think there is some initial hit when the plugin is activated and when it has to slurp all the classes from whatever jar files are in the dependencies. On subsequent invocations this problem is not there.

Similar thing happens in the editor plugin (the UI plugin) - first invocation takes a while, subsequent openings of a BPEL process file are very quick.

My comment on the call had to do with plugins having their own class loader. So the validator plugin has it's own, the ui plugin has it's own, etc. Code not seen before has to be slurped in using that plugin's class loader. I was hoping that there was a mechanism like Tomcat has, where there is a class loader chain - each web app has its own class loader which has the tomcat loader as a parent (so shared code is only loaded once).

My apologies in case I just misunderstood the problem, but to quickly ensure
that the delay is actually caused by loading this particular plug-in, would
it make sense to load it from some other point in the code (write some
plug-in just for that)? Just to check that once this plug-in has been
loaded, the experienced delay does not occur anymore where experienced
before? Or is this complete rubbish?

-- Bruno




______________________________________________
Bruno Wassermann 
           
Research Fellow                
                               
University College London      Tel: +44 (0)20 7679 0369 (Direct Dial)
Dept. of Computer Science      Fax: +44 (0)20 7387 1397
Gower Street		       
London WC1E 6BT                http://www.cs.ucl.ac.uk/staff/B.Wassermann
United Kingdom 
______________________________________________
  

  

-- 
Michal Chmielewski, CMTS, Oracle Corp, 
W:650-506-5952 / M:408-209-9321 

"Manuals ?! What manuals ? Son, it's Unix, you just gotta know." 

>Calls	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Cumulative CPU Time (seconds)
1	validateBPEL(java.util.Map, org.eclipse.core.runtime.IProgressMonitor, org.eclipse.core.resources.IFile) void		Builder	org.eclipse.bpel.validator	0.006806	0.006806	19.901335	13.078125

<Invoked by	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Calls	Cumulative CPU Time (seconds)
1	build(int, java.util.Map, org.eclipse.core.runtime.IProgressMonitor) org.eclipse.core.resources.IProject[]		Builder	org.eclipse.bpel.validator	0.001448	0.001448	19.915708	1	13.078125

Invokes	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	<Calls	Cumulative CPU Time (seconds)
15	loadClassInternal(java.lang.String) java.lang.Class		ClassLoader	java.lang	31.440151	0.027080	31.441327	1161	3.125000
13	checkPackageAccess(java.lang.Class, java.security.ProtectionDomain) void		ClassLoader	java.lang	0.028305	0.000044	0.028305	643	0.000000
1	getName() java.lang.String		Class	java.lang	0.000786	0.000004	0.000786	180	0.000000
7	getAdapter(java.lang.Object, java.lang.Class) java.lang.Object		AdapterManager	org.eclipse.core.internal.runtime	0.031464	0.000197	0.237526	160	0.187500
15	addLast(java.lang.Object) void		LinkedList	java.util	0.003645	0.000023	0.003645	156	0.015625
1	getAdapterManager() org.eclipse.core.runtime.IAdapterManager		Platform	org.eclipse.core.runtime	0.003146	0.000020	0.003146	154	0.015625
16	hasNext() boolean		LinkedList$ListItr	java.util	0.000225	0.000002	0.000225	147	0.015625
2	LinkedList()		LinkedList	java.util	0.003471	0.000029	0.003471	119	0.000000
15	next() java.lang.Object		LinkedList$ListItr	java.util	0.000559	0.000005	0.000559	111	0.000000
1	getClass() java.lang.Class		Object	java.lang	0.000185	0.000002	0.000185	74	0.000000
3	setUserData(java.lang.String, java.lang.Object, org.w3c.dom.UserDataHandler) java.lang.Object		NodeImpl	org.apache.xerces.dom	0.010344	0.000144	0.010344	72	0.000000
15	children() java.util.List		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.008560	0.000190	0.038319	45	0.046875
1	iterator() java.util.Iterator		AbstractSequentialList	java.util	0.001370	0.000036	0.001370	38	0.000000
15	getProblems() org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.000220	0.000007	0.000653	31	0.000000
15	nodeValidator() org.eclipse.bpel.validator.model.INodeValidator		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.000353	0.000016	0.752018	22	0.343750
6	setAttribute(java.lang.String, boolean) void		Marker	org.eclipse.core.internal.resources	0.053996	0.003000	0.053996	18	0.046875
15	validate(org.eclipse.bpel.validator.model.INode, org.eclipse.bpel.validator.model.IModelQuery) org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.002712	0.000170	18.388257	16	12.765625
15	removeFirst() java.lang.Object		LinkedList	java.util	0.000114	0.000008	0.000114	15	0.000000
15	hasValidated() boolean		Validator	org.eclipse.bpel.validator.model	0.000024	0.000002	0.000024	15	0.000000
6	addAll(int, java.util.Collection) boolean		LinkedList	java.util	0.000290	0.000048	0.000290	6	0.000000
6	hasNext() boolean		EContentsEList$FeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000112	0.000019	0.000201	6	0.000000
5	next() java.lang.Object		EContentsEList$FeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000316	0.000063	0.000577	5	0.000000
1	BPELReader()		BPELReader	org.eclipse.bpel.ui.util	0.000015	0.000005	0.000015	3	0.000000
1	ResourceSetImpl()		ResourceSetImpl	org.eclipse.emf.ecore.resource.impl	0.000088	0.000044	0.000088	2	0.000000
1	add(java.lang.Object) boolean		LinkedList	java.util	0.000022	0.000022	0.000022	1	0.000000
1	iterator() java.util.Iterator		EContentsEList	org.eclipse.emf.ecore.util	0.000045	0.000045	0.000045	1	0.000000
1	-clinit-()		ModelQuery	org.eclipse.bpel.validator	0.000052	0.000052	0.000093	1	0.000000
1	eContents() org.eclipse.emf.common.util.EList		BasicEObjectImpl	org.eclipse.emf.ecore.impl	0.000008	0.000008	0.000008	1	0.000000
1	read(org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.ui.util	0.000122	0.000122	0.539190	1	0.343750
1	ModelQuery(org.eclipse.wst.wsdl.WSDLElement)		ModelQuery	org.eclipse.bpel.validator	0.000182	0.000182	0.028963	1	0.000000

>Calls	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Cumulative CPU Time (seconds)
1	validateBPEL(java.util.Map, org.eclipse.core.runtime.IProgressMonitor, org.eclipse.core.resources.IFile) void		Builder	org.eclipse.bpel.validator	0.010884	0.010884	24.887718	16.812500

>Invoked by	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Calls	Cumulative CPU Time (seconds)
1	build(int, java.util.Map, org.eclipse.core.runtime.IProgressMonitor) org.eclipse.core.resources.IProject[]		Builder	org.eclipse.bpel.validator	0.001842	0.001842	24.902443	1	16.828125

Invokes	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	<Calls	Cumulative CPU Time (seconds)
1	getName() java.lang.String		Class	java.lang	0.000675	0.000004	0.000675	180	0.000000
7	getAdapter(java.lang.Object, java.lang.Class) java.lang.Object		AdapterManager	org.eclipse.core.internal.runtime	0.047635	0.000298	0.256479	160	0.187500
15	addLast(java.lang.Object) void		LinkedList	java.util	0.003649	0.000023	0.003649	156	0.000000
1	getAdapterManager() org.eclipse.core.runtime.IAdapterManager		Platform	org.eclipse.core.runtime	0.003444	0.000022	0.003444	154	0.000000
16	hasNext() boolean		LinkedList$ListItr	java.util	0.000222	0.000002	0.000222	147	0.000000
2	LinkedList()		LinkedList	java.util	0.003418	0.000029	0.003418	119	0.000000
17	loadClassInternal(java.lang.String) java.lang.Class		ClassLoader	java.lang	0.926660	0.008201	0.926660	113	0.203125
15	next() java.lang.Object		LinkedList$ListItr	java.util	0.000630	0.000006	0.000630	111	0.000000
12	checkPackageAccess(java.lang.Class, java.security.ProtectionDomain) void		ClassLoader	java.lang	0.004194	0.000047	0.004194	90	0.000000
1	getClass() java.lang.Class		Object	java.lang	0.000175	0.000002	0.000175	73	0.000000
15	children() java.util.List		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.009510	0.000211	0.038942	45	0.015625
1	iterator() java.util.Iterator		AbstractSequentialList	java.util	0.016741	0.000441	0.016741	38	0.000000
3	setUserData(java.lang.String, java.lang.Object, org.w3c.dom.UserDataHandler) java.lang.Object		NodeImpl	org.apache.xerces.dom	0.002959	0.000090	0.002959	33	0.000000
15	getProblems() org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.000229	0.000007	0.000656	31	0.000000
15	nodeValidator() org.eclipse.bpel.validator.model.INodeValidator		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.000334	0.000015	3.085932	22	0.343750
6	setAttribute(java.lang.String, boolean) void		Marker	org.eclipse.core.internal.resources	0.051856	0.002881	0.051856	18	0.046875
15	validate(org.eclipse.bpel.validator.model.INode, org.eclipse.bpel.validator.model.IModelQuery) org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.002784	0.000174	14.434272	16	12.140625
15	hasValidated() boolean		Validator	org.eclipse.bpel.validator.model	0.000023	0.000002	0.000023	15	0.000000
15	removeFirst() java.lang.Object		LinkedList	java.util	0.000102	0.000007	0.000102	15	0.000000
6	addAll(int, java.util.Collection) boolean		LinkedList	java.util	0.000291	0.000048	0.000291	6	0.000000
5	hasNext() boolean		EContentsEList$FeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000215	0.000043	0.000215	5	0.000000
4	next() java.lang.Object		EContentsEList$FeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000784	0.000196	0.000784	4	0.000000
1	ModelQuery(org.eclipse.wst.wsdl.WSDLElement)		ModelQuery	org.eclipse.bpel.validator	0.000193	0.000193	0.059028	1	0.000000
1	add(java.lang.Object) boolean		LinkedList	java.util	0.000021	0.000021	0.000021	1	0.000000
1	read(org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.001888	0.001888	7.088202	1	4.625000
1	eContents() org.eclipse.emf.common.util.EList		BasicEObjectImpl	org.eclipse.emf.ecore.impl	0.003627	0.003627	0.003627	1	0.015625
1	BPELReader()		BPELReader	org.eclipse.bpel.validator	0.000011	0.000011	0.000011	1	0.000000
1	iterator() java.util.Iterator		EContentsEList	org.eclipse.emf.ecore.util	0.011142	0.011142	0.011142	1	0.000000
1	-clinit-()		ModelQuery	org.eclipse.bpel.validator	0.000052	0.000052	0.000092	1	0.000000
1	ResourceSetImpl()		ResourceSetImpl	org.eclipse.emf.ecore.resource.impl	0.000074	0.000074	0.000074	1	0.000000

>Calls	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Cumulative CPU Time (seconds)
1	read(org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.001888	0.001888	7.088202	4.625000

>Invoked by	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Calls	Cumulative CPU Time (seconds)
1	validateBPEL(java.util.Map, org.eclipse.core.runtime.IProgressMonitor, org.eclipse.core.resources.IFile) void		Builder	org.eclipse.bpel.validator	0.010884	0.010884	24.887718	1	16.812500

Invokes	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	<Calls	Cumulative CPU Time (seconds)
3	loadClassInternal(java.lang.String) java.lang.Class		ClassLoader	java.lang	0.926660	0.008201	0.926660	113	0.203125
3	checkPackageAccess(java.lang.Class, java.security.ProtectionDomain) void		ClassLoader	java.lang	0.004194	0.000047	0.004194	90	0.000000
1	createPlatformResourceURI(java.lang.String) org.eclipse.emf.common.util.URI		URI	org.eclipse.emf.common.util	0.005047	0.002524	0.005047	2	0.000000
1	toString() java.lang.String		Path	org.eclipse.core.runtime	0.000108	0.000054	0.000108	2	0.000000
1	getResource(org.eclipse.emf.common.util.URI, boolean) org.eclipse.emf.ecore.resource.Resource		ResourceSetImpl	org.eclipse.emf.ecore.resource.impl	6.367492	6.367492	6.367492	1	4.093750
1	-clinit-()		EcorePackage	org.eclipse.emf.ecore	0.700101	0.700101	0.700101	1	0.531250
1	eAdapters() org.eclipse.emf.common.util.EList		EObjectImpl	org.eclipse.emf.ecore.impl	0.000039	0.000039	0.000039	1	0.000000
1	read(org.eclipse.emf.ecore.resource.Resource, org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.000922	0.000922	0.008950	1	0.000000

>Calls	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Cumulative CPU Time (seconds)
1	validateBPEL(java.util.Map, org.eclipse.core.runtime.IProgressMonitor, org.eclipse.core.resources.IFile) void		Builder	org.eclipse.bpel.validator	0.003847	0.003847	1.747172	0.843750

>Invoked by	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Calls	Cumulative CPU Time (seconds)
1	build(int, java.util.Map, org.eclipse.core.runtime.IProgressMonitor) org.eclipse.core.resources.IProject[]		Builder	org.eclipse.bpel.validator	0.001004	0.001004	1.767325	1	0.859375

Invokes	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	<Calls	Cumulative CPU Time (seconds)
1	getName() java.lang.String		Class	java.lang	0.000269	0.000001	0.000269	180	0.000000
7	getAdapter(java.lang.Object, java.lang.Class) java.lang.Object		AdapterManager	org.eclipse.core.internal.runtime	0.016060	0.000100	0.151635	160	0.140625
15	addLast(java.lang.Object) void		LinkedList	java.util	0.008724	0.000056	0.008724	156	0.015625
1	getAdapterManager() org.eclipse.core.runtime.IAdapterManager		Platform	org.eclipse.core.runtime	0.002978	0.000019	0.002978	154	0.015625
16	hasNext() boolean		LinkedList$ListItr	java.util	0.000230	0.000002	0.000230	147	0.000000
2	LinkedList()		LinkedList	java.util	0.026144	0.000220	0.026144	119	0.031250
15	next() java.lang.Object		LinkedList$ListItr	java.util	0.000549	0.000005	0.000549	111	0.000000
1	getClass() java.lang.Class		Object	java.lang	0.000144	0.000002	0.000144	68	0.000000
15	children() java.util.List		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.007821	0.000174	0.047314	45	0.062500
1	iterator() java.util.Iterator		AbstractSequentialList	java.util	0.006629	0.000174	0.006629	38	0.000000
3	setUserData(java.lang.String, java.lang.Object, org.w3c.dom.UserDataHandler) java.lang.Object		NodeImpl	org.apache.xerces.dom	0.008218	0.000249	0.008218	33	0.015625
15	getProblems() org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.000258	0.000008	0.000658	31	0.000000
15	nodeValidator() org.eclipse.bpel.validator.model.INodeValidator		DOMNodeAdapter	org.eclipse.bpel.validator.adapters	0.000260	0.000012	0.047409	22	0.031250
6	setAttribute(java.lang.String, boolean) void		Marker	org.eclipse.core.internal.resources	0.020768	0.001154	0.020768	18	0.015625
15	validate(org.eclipse.bpel.validator.model.INode, org.eclipse.bpel.validator.model.IModelQuery) org.eclipse.bpel.validator.model.IProblem[]		Validator	org.eclipse.bpel.validator.model	0.002209	0.000138	1.398122	16	0.625000
15	hasValidated() boolean		Validator	org.eclipse.bpel.validator.model	0.000021	0.000001	0.000021	15	0.000000
15	removeFirst() java.lang.Object		LinkedList	java.util	0.000100	0.000007	0.000100	15	0.000000
10	isIncluded(org.eclipse.emf.ecore.EStructuralFeature) boolean		EContentsEList$FeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000012	0.000001	0.000012	10	0.000000
10	eIsSet(org.eclipse.emf.ecore.EStructuralFeature) boolean		ProcessImpl	org.eclipse.bpel.model.impl	0.000022	0.000002	0.000022	10	0.000000
6	addAll(int, java.util.Collection) boolean		LinkedList	java.util	0.000258	0.000043	0.000258	6	0.000000
5	resolve() boolean		EContentsEList$ResolvingFeatureIteratorImpl	org.eclipse.emf.ecore.util	0.000006	0.000001	0.000006	5	0.000000
4	eGet(org.eclipse.emf.ecore.EStructuralFeature, boolean) java.lang.Object		ProcessImpl	org.eclipse.bpel.model.impl	0.000011	0.000003	0.000011	4	0.000000
1	read(org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.001603	0.001603	0.193486	1	0.171875
1	ResourceSetImpl()		ResourceSetImpl	org.eclipse.emf.ecore.resource.impl	0.000052	0.000052	0.000052	1	0.000000
1	ModelQuery(org.eclipse.wst.wsdl.WSDLElement)		ModelQuery	org.eclipse.bpel.validator	0.000085	0.000085	0.000103	1	0.000000
1	add(java.lang.Object) boolean		LinkedList	java.util	0.000019	0.000019	0.000019	1	0.000000
1	BPELReader()		BPELReader	org.eclipse.bpel.validator	0.000002	0.000002	0.000002	1	0.000000
1	eContents() org.eclipse.emf.common.util.EList		BasicEObjectImpl	org.eclipse.emf.ecore.impl	0.000235	0.000235	0.000235	1	0.000000
1	newListIterator() java.util.ListIterator		EContentsEList	org.eclipse.emf.ecore.util	0.000054	0.000054	0.000054	1	0.000000

>Calls	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Cumulative CPU Time (seconds)
1	read(org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.001603	0.001603	0.193486	0.171875

>Invoked by	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	Calls	Cumulative CPU Time (seconds)
1	validateBPEL(java.util.Map, org.eclipse.core.runtime.IProgressMonitor, org.eclipse.core.resources.IFile) void		Builder	org.eclipse.bpel.validator	0.003847	0.003847	1.747172	1	0.843750

Invokes	Method		Class	Package	Base Time (seconds)	Average Base Time (seconds)	Cumulative Time (seconds)	<Calls	Cumulative CPU Time (seconds)
1	toString() java.lang.String		Path	org.eclipse.core.runtime	0.000106	0.000053	0.000106	2	0.000000
1	createPlatformResourceURI(java.lang.String) org.eclipse.emf.common.util.URI		URI	org.eclipse.emf.common.util	0.003383	0.001691	0.003383	2	0.015625
1	eAdapters() org.eclipse.emf.common.util.EList		EObjectImpl	org.eclipse.emf.ecore.impl	0.000003	0.000003	0.000003	1	0.000000
1	getResource(org.eclipse.emf.common.util.URI, boolean) org.eclipse.emf.ecore.resource.Resource		ResourceSetImpl	org.eclipse.emf.ecore.resource.impl	0.187662	0.187662	0.187662	1	0.156250
1	read(org.eclipse.emf.ecore.resource.Resource, org.eclipse.core.resources.IFile, org.eclipse.emf.ecore.resource.ResourceSet) void		BPELReader	org.eclipse.bpel.validator	0.000245	0.000245	0.002515	1	0.000000