View Javadoc

1   /**
2    * 
3    */
4   package pt.digitalis.sampleApp.iss;
5   
6   import java.io.File;
7   import java.util.Properties;
8   
9   import pt.digitalis.iss.ISS;
10  import pt.digitalis.iss.ISSManager;
11  import pt.digitalis.iss.ProcessResults;
12  import pt.digitalis.log.ILogWrapper;
13  import pt.digitalis.log.LogLevel;
14  import pt.digitalis.log.LogWrapperLog4JImpl;
15  import pt.digitalis.sampleApp.util.Utilities;
16  import pt.digitalis.sampleApp.util.stats.Series;
17  import pt.digitalis.sampleApp.util.stats.StatsGenerator;
18  
19  /**
20   * @author Pedro Viegas <a
21   *         href="mailto:pviegas@digitalis.pt">pviegas@digitalis.pt</a>
22   * @created Aug 5, 2007
23   * 
24   */
25  public class ISSPerformanceTester {
26  
27  	/** The log level that all tests will use */
28  	final static LogLevel TEST_LOG_LEVEL = LogLevel.INFO;
29  
30  	/** the Logger for test output */
31  	static private ILogWrapper logger = new LogWrapperLog4JImpl(
32  			"Performance tester");
33  
34  	/** Cooldown factor. Number of seconds to pause between tests */
35  	static private int cooldown_factor = 3;
36  
37  	/** Number of processes to launch */
38  	static private int total_processes = 600;
39  
40  	/** Interactions for first process and minimal value */
41  	static private int iteractions_start = 1000;
42  
43  	/** Max interactions for all process */
44  	static private int max_iteractions = 10000;
45  
46  	/** Interactions increment for each new process */
47  	static private int iteractions_increment = 100;
48  
49  	/** Array that will keep all the generated Processes */
50  	static private BaseWriterProcess[] processes;
51  
52  	/** Array that will keep all the generated process threads */
53  	static private myProcessCaller[] myProcessCallers;
54  
55  	/** Test types to run... */
56  	private enum TestType {
57  		/** ISS Managed execution */
58  		ISS_MANAGED,
59  		/** Sequential process execution */
60  		SEQUENTIAL,
61  		/** Threaded process execution - Parallel */
62  		THREADED
63  	}
64  
65  	/**
66  	 * Initialize all necessary objects for the test
67  	 * 
68  	 * @param description
69  	 *            The description for this test
70  	 * @param processClazz
71  	 *            the class to instantiate
72  	 * 
73  	 * @return a ISS for process execution
74  	 * 
75  	 * @throws IllegalAccessException
76  	 *             when the processClazz is not a BaseWriterProcess class
77  	 * @throws InstantiationException
78  	 *             when the processClazz is not a BaseWriterProcess class
79  	 */
80  	static private ISS init(String description, Class<?> processClazz)
81  			throws InstantiationException, IllegalAccessException {
82  
83  		BaseWriterProcess process;
84  		long start;
85  		long elapsedTime;
86  		ProcessResults results;
87  
88  		logger.info("");
89  		logger.info("Starting " + description + "...");
90  		logger
91  				.info("----------------------------------------------------------------------------");
92  		logger.info("");
93  		logger.debug(Utilities.logMemoryMessage());
94  
95  		if (cooldown_factor > 0) {
96  			try {
97  
98  				logger.info("Waiting " + cooldown_factor
99  						+ " seconds to cool down running processes...");
100 				Thread.sleep(cooldown_factor * 1000);
101 			} catch (InterruptedException e) {
102 				logger.warn(e);
103 			}
104 		}
105 
106 		ISSManager.setLogger(logger);
107 
108 		/*
109 		 * A tunned configuration for the intended load
110 		 */
111 		Properties tunnedConfig = new Properties();
112 		// Populate them
113 		tunnedConfig.setProperty("PerformanceTester.stats.numberOfGroups", "4");
114 		tunnedConfig.setProperty("PerformanceTester.stats.elementsPerGroup",
115 				"10");
116 		tunnedConfig.setProperty(
117 				"PerformanceTester.iss.asynchronicityThreshold", "5");
118 		tunnedConfig.setProperty("PerformanceTester.iss.minimumThreshold", "1");
119 		tunnedConfig.setProperty("PerformanceTester.iss.maximumThreshold", "5");
120 		tunnedConfig.setProperty("PerformanceTester.iss.maximumActiveWorkers",
121 				"5");
122 		tunnedConfig.setProperty("PerformanceTester.iss.minimumExecutionTime",
123 				"85");
124 		tunnedConfig.setProperty("PerformanceTester.iss.maximumExecutionTime",
125 				"200");
126 
127 		ISS testISS = ISSManager.getISS("PerformanceTester", tunnedConfig);
128 		testISS.setStatisticsDumpEnabled(false);
129 
130 		logger.debug("Got the ISS instance");
131 
132 		// Testing the minimal interactions process execution without any load
133 		process = (BaseWriterProcess) processClazz.newInstance();
134 		process.init(iteractions_start, 9999);
135 
136 		start = System.currentTimeMillis();
137 		results = process.execute();
138 		elapsedTime = System.currentTimeMillis() - start;
139 
140 		logger.debug("Minimal interactions process ["
141 				+ results.getResult("lines") + "]: " + elapsedTime + "ms");
142 
143 		// Testing the maximal interactions process execution without any load
144 		process = (BaseWriterProcess) processClazz.newInstance();
145 		process.init(max_iteractions, 9999);
146 
147 		start = System.currentTimeMillis();
148 		results = process.execute();
149 		elapsedTime = System.currentTimeMillis() - start;
150 
151 		logger.debug("Maximal interactions process ["
152 				+ results.getResult("lines") + "]: " + elapsedTime + "ms");
153 
154 		return testISS;
155 	}
156 
157 	/**
158 	 * Cleanup method for the test
159 	 * 
160 	 * @param processClazz
161 	 *            the class to instantiate
162 	 */
163 	static private void end(Class<?> processClazz) {
164 
165 		logger.info("");
166 		logger.debug(Utilities.logMemoryMessage() + " - Cleaning up....");
167 
168 		processes = null;
169 		myProcessCallers = null;
170 
171 		Runtime.getRuntime().gc();
172 		logger.debug(Utilities.logMemoryMessage()
173 				+ " - After Garbage Collector....");
174 
175 		if (processClazz == WriterProcessFileImpl.class) {
176 			logger.debug("Deleting the created output files from disk...");
177 
178 			File dir = new File(".");
179 			String patt = "ProcessOutputFile";
180 
181 			String[] files = dir.list();
182 
183 			for (String fileName : files) {
184 
185 				File n = new File(fileName);
186 
187 				if (n.isFile() && fileName.indexOf(patt) != -1) {
188 					// Is a file and one of the output files we've created
189 
190 					if (n.delete())
191 						logger.debug(n.getPath() + " deleted...");
192 					else
193 						logger.error("Couldn't delete " + n.getPath() + "!");
194 				}
195 			}
196 		}
197 
198 		logger.debug("Test ended.");
199 	}
200 
201 	/**
202 	 * Executes all processes
203 	 * 
204 	 * @param incrementLoad
205 	 *            true increments load on each new execution
206 	 * @param testType
207 	 *            the type of test to run
208 	 * @param processClazz
209 	 *            the class to instantiate
210 	 * 
211 	 * @return the execution times in a Series object
212 	 * 
213 	 * @throws IllegalAccessException
214 	 *             when the processClazz is not a BaseWriterProcess class
215 	 * @throws InstantiationException
216 	 *             when the processClazz is not a BaseWriterProcess class
217 	 */
218 	static public Series ExecuteProcesses(boolean incrementLoad,
219 			TestType testType, Class<?> processClazz)
220 			throws InstantiationException, IllegalAccessException {
221 
222 		long start;
223 		double elapsedTime;
224 		String testTitle;
225 		ISS theISS;
226 		long[] executionTimes = new long[total_processes];
227 
228 		processes = null;
229 		myProcessCallers = null;
230 
231 		if (testType == TestType.ISS_MANAGED)
232 			testTitle = "ISS Managed: ";
233 		else if (testType == TestType.THREADED)
234 			testTitle = "Threaded: ";
235 		else
236 			testTitle = "Sequential: ";
237 
238 		testTitle += (incrementLoad ? "IncrementingLoad" : "EqualLoad")
239 				+ " test - " + processClazz.getSimpleName();
240 
241 		theISS = init(testTitle, processClazz);
242 
243 		// Initialize process/thread arrays
244 		if (testType == TestType.SEQUENTIAL)
245 			processes = new BaseWriterProcess[total_processes];
246 		else
247 			myProcessCallers = new myProcessCaller[total_processes];
248 
249 		// Discart the ISS manager if not needed
250 		if (testType != TestType.ISS_MANAGED)
251 			theISS = null;
252 
253 		logger.info("Starting executing processes...");
254 
255 		// Init processes
256 
257 		int currentInteractions = iteractions_start;
258 		long totalLines = 0;
259 		int totalErrors = 0;
260 
261 		BaseWriterProcess process;
262 		ProcessResults results;
263 
264 		start = System.currentTimeMillis();
265 
266 		try {
267 			for (int i = 0; i < total_processes; ++i) {
268 
269 				// Init the execution time with a error execution value. If the
270 				// process never executes the initial 0s would be interpreted
271 				// with an instantaneous execution.
272 				executionTimes[i] = -1;
273 
274 				if (incrementLoad && (currentInteractions < max_iteractions))
275 					currentInteractions += iteractions_increment;
276 
277 				process = (BaseWriterProcess) processClazz.newInstance();
278 				process.init(currentInteractions, i);
279 
280 				if (testType == TestType.SEQUENTIAL) {
281 
282 					// In sequential mode execute directly the operation
283 
284 					processes[i] = process;
285 					results = processes[i].execute();
286 
287 					executionTimes[i] = process.getEndTime() - start;
288 
289 					totalLines += (Long) results.getResult("lines");
290 
291 					if ((i > 0) && (i % 50 == 0))
292 						logger.info(Utilities.logMemoryMessage() + " - " + i
293 								+ " processes in "
294 								+ ((System.currentTimeMillis() - start) / 1000)
295 								+ "s");
296 
297 					processes[i] = null;
298 
299 				} else {
300 
301 					// In threaded or ISS managed mode delegate to a new Thread
302 					// the
303 					// execution
304 
305 					myProcessCallers[i] = new myProcessCaller(process, theISS,
306 							String.valueOf(i));
307 					myProcessCallers[i].start();
308 				}
309 			}
310 
311 			// In non sequential mode we have to monitor the process now!
312 			if (testType != TestType.SEQUENTIAL) {
313 				elapsedTime = System.currentTimeMillis() - start;
314 
315 				logger.info(Utilities.logMemoryMessage()
316 						+ " - Processes launched in... " + elapsedTime / 1000
317 						+ "s");
318 
319 				// Monitoring processes and discarting executed ones
320 				for (int i = 0; i < total_processes; ++i) {
321 
322 					try {
323 						myProcessCallers[i].join();
324 
325 						if (myProcessCallers[i].getResults() != null) {
326 
327 							process = (BaseWriterProcess) myProcessCallers[i]
328 									.getTheProcess();
329 
330 							executionTimes[i] = process.getEndTime() - start;
331 
332 							process = null;
333 
334 							totalLines += (Long) myProcessCallers[i]
335 									.getResults().getResult("lines");
336 
337 						} else
338 							totalErrors++;
339 
340 					} catch (InterruptedException e) {
341 						logger.error(e);
342 					}
343 
344 					if ((i > 0) && (i % 50 == 0)) {
345 						logger.info(Utilities.logMemoryMessage() + " - " + i
346 								+ " processes in "
347 								+ ((System.currentTimeMillis() - start) / 1000)
348 								+ "s");
349 					}
350 
351 					myProcessCallers[i] = null;
352 				}
353 			}
354 
355 			logger.info(Utilities.logMemoryMessage() + " - Executed "
356 					+ total_processes + " processes in "
357 					+ ((System.currentTimeMillis() - start) / 1000)
358 					+ " seconds");
359 
360 			elapsedTime = System.currentTimeMillis() - start;
361 
362 			logger.debug("Wrote " + totalLines + " lines in " + elapsedTime
363 					/ 1000 + "s");
364 
365 			if (totalErrors > 0)
366 				logger.debug("(with " + totalErrors
367 						+ " failed process executions!)");
368 		} catch (OutOfMemoryError e) {
369 			logger
370 					.error("Current test case has failed with out of memory. Cleaning up and exiting.");
371 
372 		} finally {
373 			end(processClazz);
374 		}
375 
376 		return new Series(testTitle, executionTimes);
377 
378 	}
379 
380 	/**
381 	 * Performs the performance tests
382 	 * 
383 	 * @param args
384 	 *            pass ["quick"] for a quick run
385 	 * @throws InstantiationException
386 	 * @throws IllegalAccessException
387 	 */
388 	static public void main(String[] args) throws InstantiationException,
389 			IllegalAccessException {
390 
391 		// Quick mode, used for the JUnit call
392 		if (args != null && args.length > 0 && "quick".equals(args[0])) {
393 			cooldown_factor = 0;
394 			total_processes = 100;
395 			max_iteractions = 1000;
396 			iteractions_start = 10;
397 			iteractions_increment = 10;
398 		}
399 		
400 		long [] nullArray = new long[1];
401 		nullArray[0] = 0;
402 
403 		Class<?> testerClass = WriterProcessFileImpl.class;
404 
405 		logger.setLevel(TEST_LOG_LEVEL);
406 
407 		// Equal load section
408 		StatsGenerator stats = new StatsGenerator(logger);
409 
410 		stats
411 				.addSerie(ExecuteProcesses(false, TestType.SEQUENTIAL,
412 						testerClass));
413 		stats.addSerie(ExecuteProcesses(false, TestType.ISS_MANAGED,
414 				testerClass));
415 		stats.addSerie(ExecuteProcesses(false, TestType.THREADED, testerClass));
416 
417 		stats.printAsciiChart();
418 		stats.buildChartData(100);
419 		stats.exportToExcel("iss_equalLoad.xls");
420 		stats.createChartAsPNG("iss_equalLoad.png");
421 
422 		// Incremental load section
423 		StatsGenerator statsWithISS = new StatsGenerator(logger);
424 		Series serie;
425 
426 		stats = new StatsGenerator(logger);
427 
428 		serie = ExecuteProcesses(true, TestType.SEQUENTIAL, testerClass);
429 		stats.addSerie(serie);
430 		statsWithISS.addSerie(serie);
431 
432 		serie = ExecuteProcesses(true, TestType.ISS_MANAGED, testerClass);
433 		stats.addSerie(serie.getName(), nullArray);
434 		statsWithISS.addSerie(serie);
435 
436 		serie = ExecuteProcesses(true, TestType.THREADED, testerClass);
437 		stats.addSerie(serie);
438 		statsWithISS.addSerie(serie);
439 
440 		statsWithISS.printAsciiChart();
441 		stats.buildChartData(100);
442 		stats.exportToExcel("iss_incrementalLoad.xls");
443 		stats.createChartAsPNG("iss_incrementalLoadWithoutISS.png");
444 
445 		statsWithISS.buildChartData(100);
446 		statsWithISS.createChartAsPNG("iss_incrementalLoadWithISS.png");
447 	}
448 }