View Javadoc
1   /*
2    * Copyright 2014 the original author or authors.
3    *
4    * Licensed under the Apache License, Version 2.0 (the "License");
5    * you may not use this file except in compliance with the License.
6    * You may obtain a copy of the License at
7    *
8    *      http://www.apache.org/licenses/LICENSE-2.0
9    *
10   * Unless required by applicable law or agreed to in writing, software
11   * distributed under the License is distributed on an "AS IS" BASIS,
12   * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13   * See the License for the specific language governing permissions and
14   * limitations under the License.
15   */
16  
17  package org.springframework.expression.spel;
18  
19  import org.junit.Ignore;
20  import org.junit.Test;
21  
22  import org.springframework.expression.Expression;
23  import org.springframework.expression.spel.standard.SpelCompiler;
24  
25  import static org.junit.Assert.*;
26  
27  /**
28   * Checks the speed of compiled SpEL expressions.
29   * By default these tests are marked Ignore since they can fail on a busy machine because they
30   * compare relative performance of interpreted vs compiled.
31   *
32   * @author Andy Clement
33   * @since 4.1
34   */
35  @Ignore
36  public class SpelCompilationPerformanceTests extends AbstractExpressionTests {
37  
38  	int count = 50000; // Number of evaluations that are timed in one run
39  	int iterations = 10; // Number of times to repeat 'count' evaluations (for averaging)
40  	private final static boolean noisyTests = true;
41  
42  	Expression expression;
43  
44  	public static class Payload {
45  		Two[] DR = new Two[]{new Two()};
46  
47  		public Two[] getDR() {
48  			return DR;
49  		}
50  	}
51  
52  	public static class Two {
53  		Three DRFixedSection = new Three();
54  		public Three getDRFixedSection() {
55  			return DRFixedSection;
56  		}
57  	}
58  
59  	public static class Three {
60  		double duration = 0.4d;
61  		public double getDuration() {
62  			return duration;
63  		}
64  	}
65  	
66  	@Test
67  	public void inlineLists() throws Exception {
68  		expression = parser.parseExpression("{'abcde','ijklm'}[0].substring({1,3,4}[0],{1,3,4}[1])");
69  		Object o = expression.getValue();
70  		assertEquals("bc",o);
71  		System.out.println("Performance check for SpEL expression: '{'abcde','ijklm'}[0].substring({1,3,4}[0],{1,3,4}[1])'");
72  		long stime = System.currentTimeMillis();
73  		for (int i=0;i<1000000;i++) {
74  			o = expression.getValue();
75  		}
76  		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
77  		stime = System.currentTimeMillis();
78  		for (int i=0;i<1000000;i++) {
79  			o = expression.getValue();
80  		}
81  		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
82  		stime = System.currentTimeMillis();
83  		for (int i=0;i<1000000;i++) {
84  			o = expression.getValue();
85  		}
86  		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
87  		compile(expression);
88  		System.out.println("Now compiled:");
89  		o = expression.getValue();
90  		assertEquals("bc", o);
91  		
92  		stime = System.currentTimeMillis();
93  		for (int i=0;i<1000000;i++) {
94  			o = expression.getValue();
95  		}
96  		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
97  		stime = System.currentTimeMillis();
98  		for (int i=0;i<1000000;i++) {
99  			o = expression.getValue();
100 		}
101 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
102 		stime = System.currentTimeMillis();
103 		for (int i=0;i<1000000;i++) {
104 			o = expression.getValue();
105 		}
106 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
107 	}
108 	
109 	@Test
110 	public void inlineNestedLists() throws Exception {
111 		expression = parser.parseExpression("{'abcde',{'ijklm','nopqr'}}[1][0].substring({1,3,4}[0],{1,3,4}[1])");
112 		Object o = expression.getValue();
113 		assertEquals("jk",o);
114 		System.out.println("Performance check for SpEL expression: '{'abcde','ijklm'}[0].substring({1,3,4}[0],{1,3,4}[1])'");
115 		long stime = System.currentTimeMillis();
116 		for (int i=0;i<1000000;i++) {
117 			o = expression.getValue();
118 		}
119 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
120 		stime = System.currentTimeMillis();
121 		for (int i=0;i<1000000;i++) {
122 			o = expression.getValue();
123 		}
124 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
125 		stime = System.currentTimeMillis();
126 		for (int i=0;i<1000000;i++) {
127 			o = expression.getValue();
128 		}
129 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
130 		compile(expression);
131 		System.out.println("Now compiled:");
132 		o = expression.getValue();
133 		assertEquals("jk", o);
134 		
135 		stime = System.currentTimeMillis();
136 		for (int i=0;i<1000000;i++) {
137 			o = expression.getValue();
138 		}
139 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
140 		stime = System.currentTimeMillis();
141 		for (int i=0;i<1000000;i++) {
142 			o = expression.getValue();
143 		}
144 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
145 		stime = System.currentTimeMillis();
146 		for (int i=0;i<1000000;i++) {
147 			o = expression.getValue();
148 		}
149 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
150 	}
151 
152 
153 	@Test
154 	public void stringConcatenation() throws Exception {
155 		expression = parser.parseExpression("'hello' + getWorld() + ' spring'");
156 		Greeter g = new Greeter();
157 		Object o = expression.getValue(g);
158 		assertEquals("helloworld spring", o);
159 
160 		System.out.println("Performance check for SpEL expression: 'hello' + getWorld() + ' spring'");
161 		long stime = System.currentTimeMillis();
162 		for (int i=0;i<1000000;i++) {
163 			o = expression.getValue(g);
164 		}
165 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
166 		stime = System.currentTimeMillis();
167 		for (int i=0;i<1000000;i++) {
168 			o = expression.getValue(g);
169 		}
170 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
171 		stime = System.currentTimeMillis();
172 		for (int i=0;i<1000000;i++) {
173 			o = expression.getValue(g);
174 		}
175 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
176 		compile(expression);
177 		System.out.println("Now compiled:");
178 		o = expression.getValue(g);
179 		assertEquals("helloworld spring", o);
180 		
181 		stime = System.currentTimeMillis();
182 		for (int i=0;i<1000000;i++) {
183 			o = expression.getValue(g);
184 		}
185 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
186 		stime = System.currentTimeMillis();
187 		for (int i=0;i<1000000;i++) {
188 			o = expression.getValue(g);
189 		}
190 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
191 		stime = System.currentTimeMillis();
192 		for (int i=0;i<1000000;i++) {
193 			o = expression.getValue(g);
194 		}
195 		System.out.println("One million iterations: "+(System.currentTimeMillis()-stime)+"ms");
196 	}
197 	
198 	public static class Greeter {
199 		public String getWorld() {
200 			return "world";
201 		}
202 	}
203 
204 	@Test
205 	public void complexExpressionPerformance() throws Exception {
206 		Payload payload = new Payload();
207 		Expression expression = parser.parseExpression("DR[0].DRFixedSection.duration lt 0.1");
208 		boolean b = false;
209 		long iTotal = 0,cTotal = 0;
210 
211 		// warmup
212 		for (int i=0;i<count;i++) {
213 			b = expression.getValue(payload,Boolean.TYPE);
214 		}
215 
216 		log("timing interpreted: ");
217 		for (int iter=0;iter<iterations;iter++) {
218 			long stime = System.currentTimeMillis();
219 			for (int i=0;i<count;i++) {
220 				b = expression.getValue(payload,Boolean.TYPE);
221 			}
222 			long etime = System.currentTimeMillis();
223 			long interpretedSpeed = (etime - stime);
224 			iTotal+=interpretedSpeed;
225 			log(interpretedSpeed+"ms ");
226 		}
227 		logln();
228 
229 		compile(expression);
230 		boolean bc = false;
231 		expression.getValue(payload,Boolean.TYPE);
232 		log("timing compiled: ");
233 		for (int iter=0;iter<iterations;iter++) {
234 			long stime = System.currentTimeMillis();
235 			for (int i=0;i<count;i++) {
236 				bc = expression.getValue(payload,Boolean.TYPE);
237 			}
238 			long etime = System.currentTimeMillis();
239 			long compiledSpeed = (etime - stime);
240 			cTotal+=compiledSpeed;
241 			log(compiledSpeed+"ms ");
242 		}
243 		logln();
244 
245 		reportPerformance("complex expression",iTotal, cTotal);
246 
247 		// Verify the result
248 		assertFalse(b);
249 
250 		// Verify the same result for compiled vs interpreted
251 		assertEquals(b,bc);
252 
253 		// Verify if the input changes, the result changes
254 		payload.DR[0].DRFixedSection.duration = 0.04d;
255 		bc = expression.getValue(payload,Boolean.TYPE);
256 		assertTrue(bc);
257 	}
258 
259 	public static class HW {
260 		public String hello() {
261 			return "foobar";
262 		}
263 	}
264 
265 	@Test
266 	public void compilingMethodReference() throws Exception {
267 		long interpretedTotal = 0, compiledTotal = 0;
268 		long stime,etime;
269 		String interpretedResult = null,compiledResult = null;
270 
271 		HW testdata = new HW();
272 		Expression expression = parser.parseExpression("hello()");
273 
274 		// warmup
275 		for (int i=0;i<count;i++) {
276 			interpretedResult = expression.getValue(testdata,String.class);
277 		}
278 
279 		log("timing interpreted: ");
280 		for (int iter=0;iter<iterations;iter++) {
281 			stime = System.currentTimeMillis();
282 			for (int i=0;i<count;i++) {
283 				interpretedResult = expression.getValue(testdata,String.class);
284 			}
285 			etime = System.currentTimeMillis();
286 			long interpretedSpeed = (etime - stime);
287 			interpretedTotal+=interpretedSpeed;
288 			log(interpretedSpeed+"ms ");
289 		}
290 		logln();
291 
292 		compile(expression);
293 
294 		log("timing compiled: ");
295 		expression.getValue(testdata,String.class);
296 		for (int iter=0;iter<iterations;iter++) {
297 			stime = System.currentTimeMillis();
298 			for (int i=0;i<count;i++) {
299 				compiledResult = expression.getValue(testdata,String.class);
300 			}
301 			etime = System.currentTimeMillis();
302 			long compiledSpeed = (etime - stime);
303 			compiledTotal+=compiledSpeed;
304 			log(compiledSpeed+"ms ");
305 		}
306 		logln();
307 
308 		assertEquals(interpretedResult,compiledResult);
309 		reportPerformance("method reference", interpretedTotal, compiledTotal);
310 		if (compiledTotal>=interpretedTotal) {
311 			fail("Compiled version is slower than interpreted!");
312 		}
313 	}
314 
315 
316 
317 
318 	public static class TestClass2 {
319 		public String name = "Santa";
320 		private String name2 = "foobar";
321 		public String getName2() {
322 			return name2;
323 		}
324 		public Foo foo = new Foo();
325 		public static class Foo {
326 			public Bar bar = new Bar();
327 			Bar b = new Bar();
328 			public Bar getBaz() {
329 				return b;
330 			}
331 			public Bar bay() {
332 				return b;
333 			}
334 		}
335 		public static class Bar {
336 			public String boo = "oranges";
337 		}
338 	}
339 
340 	@Test
341 	public void compilingPropertyReferenceField() throws Exception {
342 		long interpretedTotal = 0, compiledTotal = 0, stime, etime;
343 		String interpretedResult = null, compiledResult = null;
344 
345 		TestClass2 testdata = new TestClass2();
346 		Expression expression = parser.parseExpression("name");
347 
348 		// warmup
349 		for (int i=0;i<count;i++) {
350 			expression.getValue(testdata,String.class);
351 		}
352 
353 		log("timing interpreted: ");
354 		for (int iter=0;iter<iterations;iter++) {
355 			stime = System.currentTimeMillis();
356 			for (int i=0;i<count;i++) {
357 				interpretedResult = expression.getValue(testdata,String.class);
358 			}
359 			etime = System.currentTimeMillis();
360 			long interpretedSpeed = (etime - stime);
361 			interpretedTotal+=interpretedSpeed;
362 			log(interpretedSpeed+"ms ");
363 		}
364 		logln();
365 
366 		compile(expression);
367 
368 		log("timing compiled: ");
369 		expression.getValue(testdata,String.class);
370 		for (int iter=0;iter<iterations;iter++) {
371 			stime = System.currentTimeMillis();
372 			for (int i=0;i<count;i++) {
373 				compiledResult = expression.getValue(testdata,String.class);
374 			}
375 			etime = System.currentTimeMillis();
376 			long compiledSpeed = (etime - stime);
377 			compiledTotal+=compiledSpeed;
378 			log(compiledSpeed+"ms ");
379 		}
380 		logln();
381 
382 		assertEquals(interpretedResult,compiledResult);
383 		reportPerformance("property reference (field)",interpretedTotal, compiledTotal);
384 	}
385 
386 	@Test
387 	public void compilingPropertyReferenceNestedField() throws Exception {
388 		long interpretedTotal = 0, compiledTotal = 0, stime, etime;
389 		String interpretedResult = null, compiledResult = null;
390 
391 		TestClass2 testdata = new TestClass2();
392 
393 		Expression expression = parser.parseExpression("foo.bar.boo");
394 
395 		// warmup
396 		for (int i=0;i<count;i++) {
397 			expression.getValue(testdata,String.class);
398 		}
399 
400 		log("timing interpreted: ");
401 		for (int iter=0;iter<iterations;iter++) {
402 			stime = System.currentTimeMillis();
403 			for (int i=0;i<count;i++) {
404 				interpretedResult = expression.getValue(testdata,String.class);
405 			}
406 			etime = System.currentTimeMillis();
407 			long interpretedSpeed = (etime - stime);
408 			interpretedTotal+=interpretedSpeed;
409 			log(interpretedSpeed+"ms ");
410 		}
411 		logln();
412 
413 		compile(expression);
414 
415 		log("timing compiled: ");
416 		expression.getValue(testdata,String.class);
417 		for (int iter=0;iter<iterations;iter++) {
418 			stime = System.currentTimeMillis();
419 			for (int i=0;i<count;i++) {
420 				compiledResult = expression.getValue(testdata,String.class);
421 			}
422 			etime = System.currentTimeMillis();
423 			long compiledSpeed = (etime - stime);
424 			compiledTotal+=compiledSpeed;
425 			log(compiledSpeed+"ms ");
426 		}
427 		logln();
428 
429 		assertEquals(interpretedResult,compiledResult);
430 		reportPerformance("property reference (nested field)",interpretedTotal, compiledTotal);
431 	}
432 
433 	@Test
434 	public void compilingPropertyReferenceNestedMixedFieldGetter() throws Exception {
435 		long interpretedTotal = 0, compiledTotal = 0, stime, etime;
436 		String interpretedResult = null, compiledResult = null;
437 
438 		TestClass2 testdata = new TestClass2();
439 		Expression expression = parser.parseExpression("foo.baz.boo");
440 
441 		// warmup
442 		for (int i=0;i<count;i++) {
443 			expression.getValue(testdata,String.class);
444 		}
445 		log("timing interpreted: ");
446 		for (int iter=0;iter<iterations;iter++) {
447 			stime = System.currentTimeMillis();
448 			for (int i=0;i<count;i++) {
449 				interpretedResult = expression.getValue(testdata,String.class);
450 			}
451 			etime = System.currentTimeMillis();
452 			long interpretedSpeed = (etime - stime);
453 			interpretedTotal+=interpretedSpeed;
454 			log(interpretedSpeed+"ms ");
455 		}
456 		logln();
457 
458 		compile(expression);
459 
460 		log("timing compiled: ");
461 		expression.getValue(testdata,String.class);
462 		for (int iter=0;iter<iterations;iter++) {
463 			stime = System.currentTimeMillis();
464 			for (int i=0;i<count;i++) {
465 				compiledResult = expression.getValue(testdata,String.class);
466 			}
467 			etime = System.currentTimeMillis();
468 			long compiledSpeed = (etime - stime);
469 			compiledTotal+=compiledSpeed;
470 			log(compiledSpeed+"ms ");
471 		}
472 		logln();
473 
474 		assertEquals(interpretedResult,compiledResult);
475 		reportPerformance("nested property reference (mixed field/getter)",interpretedTotal, compiledTotal);
476 	}
477 
478 	@Test
479 	public void compilingNestedMixedFieldPropertyReferenceMethodReference() throws Exception {
480 		long interpretedTotal = 0, compiledTotal = 0, stime, etime;
481 		String interpretedResult = null, compiledResult = null;
482 
483 		TestClass2 testdata = new TestClass2();
484 		Expression expression = parser.parseExpression("foo.bay().boo");
485 
486 		// warmup
487 		for (int i=0;i<count;i++) {
488 			expression.getValue(testdata,String.class);
489 		}
490 
491 		log("timing interpreted: ");
492 		for (int iter=0;iter<iterations;iter++) {
493 			stime = System.currentTimeMillis();
494 			for (int i=0;i<count;i++) {
495 				interpretedResult = expression.getValue(testdata,String.class);
496 			}
497 			etime = System.currentTimeMillis();
498 			long interpretedSpeed = (etime - stime);
499 			interpretedTotal+=interpretedSpeed;
500 			log(interpretedSpeed+"ms ");
501 		}
502 		logln();
503 
504 		compile(expression);
505 
506 		log("timing compiled: ");
507 		expression.getValue(testdata,String.class);
508 		for (int iter=0;iter<iterations;iter++) {
509 			stime = System.currentTimeMillis();
510 			for (int i=0;i<count;i++) {
511 				compiledResult = expression.getValue(testdata,String.class);
512 			}
513 			etime = System.currentTimeMillis();
514 			long compiledSpeed = (etime - stime);
515 			compiledTotal+=compiledSpeed;
516 			log(compiledSpeed+"ms ");
517 
518 		}
519 		logln();
520 
521 		assertEquals(interpretedResult,compiledResult);
522 		reportPerformance("nested reference (mixed field/method)",interpretedTotal, compiledTotal);
523 	}
524 
525 	@Test
526 	public void compilingPropertyReferenceGetter() throws Exception {
527 		long interpretedTotal = 0, compiledTotal = 0, stime, etime;
528 		String interpretedResult = null, compiledResult = null;
529 
530 		TestClass2 testdata = new TestClass2();
531 		Expression expression = parser.parseExpression("name2");
532 
533 		// warmup
534 		for (int i=0;i<count;i++) {
535 			expression.getValue(testdata,String.class);
536 		}
537 
538 		log("timing interpreted: ");
539 		for (int iter=0;iter<iterations;iter++) {
540 			stime = System.currentTimeMillis();
541 			for (int i=0;i<count;i++) {
542 				interpretedResult = expression.getValue(testdata,String.class);
543 			}
544 			etime = System.currentTimeMillis();
545 			long interpretedSpeed = (etime - stime);
546 			interpretedTotal+=interpretedSpeed;
547 			log(interpretedSpeed+"ms ");
548 		}
549 		logln();
550 
551 
552 		compile(expression);
553 
554 		log("timing compiled: ");
555 		expression.getValue(testdata,String.class);
556 		for (int iter=0;iter<iterations;iter++) {
557 			stime = System.currentTimeMillis();
558 			for (int i=0;i<count;i++) {
559 				compiledResult = expression.getValue(testdata,String.class);
560 			}
561 			etime = System.currentTimeMillis();
562 			long compiledSpeed = (etime - stime);
563 			compiledTotal+=compiledSpeed;
564 			log(compiledSpeed+"ms ");
565 
566 		}
567 		logln();
568 
569 		assertEquals(interpretedResult,compiledResult);
570 
571 		reportPerformance("property reference (getter)", interpretedTotal, compiledTotal);
572 		if (compiledTotal>=interpretedTotal) {
573 			fail("Compiled version is slower than interpreted!");
574 		}
575 	}
576 
577 	// ---
578 
579 	private void reportPerformance(String title, long interpretedTotal, long compiledTotal) {
580 		double averageInterpreted = interpretedTotal/(iterations);
581 		double averageCompiled = compiledTotal/(iterations);
582 		double ratio = (averageCompiled/averageInterpreted)*100.0d;
583 		logln(">>"+title+": average for "+count+": compiled="+averageCompiled+"ms interpreted="+averageInterpreted+"ms: compiled takes "+((int)ratio)+"% of the interpreted time");
584 		if (averageCompiled>averageInterpreted) {
585 			fail("Compiled version took longer than interpreted!  CompiledSpeed=~"+averageCompiled+
586 					"ms InterpretedSpeed="+averageInterpreted+"ms");
587 		}
588 		logln();
589 	}
590 
591 	private void log(String message) {
592 		if (noisyTests) {
593 			System.out.print(message);
594 		}
595 	}
596 
597 	private void logln(String... message) {
598 		if (noisyTests) {
599 			if (message!=null && message.length>0) {
600 				System.out.println(message[0]);
601 			} else {
602 				System.out.println();
603 			}
604 		}
605 	}
606 
607 	private void compile(Expression expression) {
608 		assertTrue(SpelCompiler.compile(expression));
609 	}
610 }