1 /* 2 * Licensed to the Apache Software Foundation (ASF) under one 3 * or more contributor license agreements. See the NOTICE file 4 * distributed with this work for additional information 5 * regarding copyright ownership. The ASF licenses this file 6 * to you under the Apache License, Version 2.0 (the "License"); 7 * you may not use this file except in compliance with the License. 8 * You may obtain a copy of the License at 9 * 10 * http://www.apache.org/licenses/LICENSE-2.0 11 * 12 * Unless required by applicable law or agreed to in writing, software 13 * distributed under the License is distributed on an "AS IS" BASIS, 14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 15 * See the License for the specific language governing permissions and 16 * limitations under the License. 17 */ 18 /* 19 * $Id$ 20 */ 21 22 /* 23 * 24 * PerfEverythingTestlet.java 25 * 26 */ 27 package org.apache.qetest.xsl; 28 import java.io.File; 29 import java.io.PrintWriter; 30 import java.io.StringWriter; 31 import java.util.Hashtable; 32 33 import org.apache.qetest.CheckService; 34 import org.apache.qetest.Datalet; 35 import org.apache.qetest.Logger; 36 import org.apache.qetest.TestletImpl; 37 import org.apache.qetest.xslwrapper.TransformWrapper; 38 import org.apache.qetest.xslwrapper.TransformWrapperFactory; 39 40 /** 41 * Testlet to capture specific timing performance data. 42 * This Testlet attempts to mirror what one of our Xalan-C 43 * performance tests does, at least as well as we can compare 44 * Java processing to the C processing model. 45 * Note that as a standalone Testlet, this class does waaaay too 46 * much stuff: Testlets should really be smaller test algorithims 47 * than here. However for performance measurements and reporting 48 * purposes, we really need to do it all here. 49 * 50 * @author Shane_Curcuru@lotus.com 51 * @version $Id$ 52 */ 53 public class PerfEverythingTestlet extends TestletImpl 54 { 55 // Initialize our classname for TestletImpl's main() method 56 static { thisClassName = "org.apache.qetest.xsl.PerfEverythingTestlet"; } 57 58 // Initialize our defaultDatalet 59 { defaultDatalet = (Datalet)new StylesheetDatalet(); } 60 61 /** 62 * Accesor method for a brief description of this test. 63 * 64 * @return String describing what this PerfEverythingTestlet does. 65 */ getDescription()66 public String getDescription() 67 { 68 return "PerfEverythingTestlet: processes supplied file in multiple ways over multiple iterations and logs timing data"; 69 } 70 71 72 /** 73 * Run this PerfEverythingTestlet: execute it's test and return. 74 * This algorithim processes the supplied file in several 75 * different ways: 76 * <ul> 77 * <li>Run one full end-to-end transform and log timing 78 * (a 'preload' process: note that results may vary for this 79 * timing depending on whether you run this Testlet standalone 80 * or if you're using StylesheetTestletDriver to run it, due at 81 * least to classloading issues, if nothing else)</li> 82 * <li>Preprocess the stylesheet once and log timing</li> 83 * <li>Process that preprocessed stylesheet once and log timing</li> 84 * <li>Loop iterations times and preprocess the stylesheet, 85 * then do a transform with it, and log each time</li> 86 * <li>Loop iterations times and do a full end-to-end transform 87 * and log each time</li> 88 * </ul> 89 * We (optionally) call Runtime.gc() after every use of the 90 * processor, and log out memory statistics here and there. 91 * 92 * Note that if any error happens during the execution, we 93 * simply log the error and return: in this case, a <perf> 94 * element will <b>not</b> be output at all. 95 * 96 * @param Datalet to use as data point for the test. 97 */ execute(Datalet d)98 public void execute(Datalet d) 99 { 100 StylesheetDatalet datalet = null; 101 try 102 { 103 datalet = (StylesheetDatalet)d; 104 105 } 106 catch (ClassCastException e) 107 { 108 logger.checkErr("Incorrect Datalet type provided, threw:" + e.toString()); 109 return; 110 } 111 logger.logMsg(Logger.STATUSMSG, "About to test: " 112 + (null == datalet.inputName 113 ? datalet.xmlName 114 : datalet.inputName)); 115 116 // Cleanup outName only if asked to - delete the file on disk 117 if ("true".equalsIgnoreCase(datalet.options.getProperty("deleteOutFile"))) 118 { 119 try 120 { 121 File outFile = new File(datalet.outputName); 122 boolean btmp = outFile.delete(); 123 logger.logMsg(Logger.TRACEMSG, "Deleting OutFile of::" + datalet.outputName 124 + " status: " + btmp); 125 } 126 catch (SecurityException se) 127 { 128 logger.logMsg(Logger.WARNINGMSG, "Deleting OutFile of::" + datalet.outputName 129 + " threw: " + se.toString()); 130 // But continue anyways... 131 } 132 } 133 134 // Setup: Save options from the datalet in convenience variables 135 int iterations = 10; 136 boolean preload = true; 137 boolean runtimeGC = false; 138 try 139 { 140 iterations = Integer.parseInt(datalet.options.getProperty("iterations")); 141 } 142 catch (Exception e) { /* no-op, leave as default */ } 143 try 144 { 145 preload = (new Boolean(datalet.options.getProperty("preload"))).booleanValue(); 146 } 147 catch (Exception e) { /* no-op, leave as default */ } 148 try 149 { 150 runtimeGC = (new Boolean(datalet.options.getProperty("runtimeGC"))).booleanValue(); 151 } 152 catch (Exception e) { /* no-op, leave as default */ } 153 154 // Setup: store various timing data in convenience variables 155 long singletransform = 0L; // Very first Preload end-to-end transform 156 long etoe = 0L; // First end-to-end transform during iterations 157 long avgetoe = 0L; // Average of end-to-end transforms during iterations 158 long parsexsl = 0L; // First stylesheet preprocess during iterations 159 long avgparsexsl = 0L; // Average of stylesheet preprocess during iterations 160 long unparsedxml = 0L; // First stylesheet process during iterations 161 long avgunparsedxml = 0L;// Average of stylesheet process during iterations 162 163 // Create a new TransformWrapper of appropriate flavor 164 // null arg is unused liaison for TransformWrapper 165 //@todo allow user to pass in pre-created 166 // TransformWrapper so we don't have lots of objects 167 // created and destroyed for every file 168 TransformWrapper transformWrapper = null; 169 try 170 { 171 transformWrapper = TransformWrapperFactory.newWrapper(datalet.flavor); 172 transformWrapper.newProcessor(null); 173 } 174 catch (Throwable t) 175 { 176 logThrowable(t, getDescription() + " newWrapper/newProcessor threw"); 177 logger.checkErr(getDescription() + " newWrapper/newProcessor threw: " + t.toString()); 178 return; 179 } 180 181 // Test our supplied file in multiple ways, logging performance data 182 try 183 { 184 // Store local copies of XSL, XML references to avoid 185 // potential for changing datalet 186 String inputName = datalet.inputName; 187 String xmlName = datalet.xmlName; 188 189 logger.logMsg(Logger.TRACEMSG, "executing with: inputName=" + inputName 190 + " xmlName=" + xmlName + " outputName=" + datalet.outputName 191 + " goldName=" + datalet.goldName + " flavor=" + datalet.flavor 192 + " iterations=" + iterations + " preload=" + preload 193 + " algorithim=" + getDescription()); 194 195 //@todo make various logMemory calls optional 196 logMemory(runtimeGC, true); 197 198 // Measure(singletransform): Very first Preload end-to-end transform 199 long[] times = null; 200 times = transformWrapper.transform(xmlName, inputName, 201 datalet.outputName); 202 singletransform = times[TransformWrapper.IDX_OVERALL]; 203 logMemory(runtimeGC, false); 204 205 // Measure(parsexsl): once: first preprocess 206 times = transformWrapper.buildStylesheet(inputName); 207 parsexsl = times[TransformWrapper.IDX_OVERALL]; 208 logMemory(runtimeGC, false); 209 210 // Measure(unparsedxml): once: first process 211 times = transformWrapper.transformWithStylesheet(xmlName, datalet.outputName); 212 unparsedxml = times[TransformWrapper.IDX_OVERALL]; 213 logMemory(runtimeGC, false); 214 215 for (int ctr = 1; ctr <= iterations; ctr++) 216 { 217 // Measure(avgparsexsl): average preprocess 218 times = transformWrapper.buildStylesheet(inputName); 219 avgparsexsl += times[TransformWrapper.IDX_OVERALL]; 220 logMemory(runtimeGC, false); 221 222 // Measure(avgunparsedxml): average process 223 times = transformWrapper.transformWithStylesheet(xmlName, datalet.outputName); 224 avgunparsedxml += times[TransformWrapper.IDX_OVERALL]; 225 logMemory(runtimeGC, false); 226 } 227 228 // Measure(etoe): once: first full process 229 times = transformWrapper.transform(xmlName, inputName, datalet.outputName); 230 etoe = times[TransformWrapper.IDX_OVERALL]; 231 logMemory(runtimeGC, true); 232 233 for (int ctr = 1; ctr <= iterations; ctr++) 234 { 235 // Measure(avgetoe): average full process 236 times = transformWrapper.transform(xmlName, inputName, datalet.outputName); 237 avgetoe += times[TransformWrapper.IDX_OVERALL]; 238 logMemory(runtimeGC, false); 239 } 240 241 // Log special performance element with our timing 242 Hashtable attrs = new Hashtable(); 243 // UniqRunid is an Id that our TestDriver normally sets 244 // with some unique code, so that results analysis 245 // stylesheets can compare different test runs 246 attrs.put("UniqRunid", datalet.options.getProperty("runId", "runId;none")); 247 // processor is the 'flavor' of processor we're testing 248 attrs.put("processor", transformWrapper.getDescription()); 249 // idref is the individual filename 250 attrs.put("idref", (new File(datalet.inputName)).getName()); 251 // inputName is the actual name we gave to the processor 252 attrs.put("inputName", inputName); 253 attrs.put("iterations", new Integer(iterations)); 254 attrs.put("singletransform", new Long(singletransform)); // Very first Preload end-to-end transform 255 attrs.put("etoe", new Long(etoe)); // First end-to-end transform during iterations 256 attrs.put("avgetoe", new Long(avgetoe / iterations)); // Average of end-to-end transforms during iterations 257 attrs.put("parsexsl", new Long(parsexsl)); // First stylesheet preprocess during iterations 258 attrs.put("avgparsexsl", new Long(avgparsexsl / iterations)); // Average of stylesheet preprocess during iterations 259 attrs.put("unparsedxml", new Long(unparsedxml)); // First stylesheet process during iterations 260 attrs.put("avgunparsedxml", new Long(avgunparsedxml / iterations)); // Average of stylesheet process during iterations 261 262 logger.logElement(Logger.STATUSMSG, "perf", attrs, "PItr;"); 263 264 // If we get here, attempt to validate the contents of 265 // the last outputFile created 266 CheckService fileChecker = (CheckService)datalet.options.get("fileCheckerImpl"); 267 // Supply default value 268 if (null == fileChecker) 269 fileChecker = new XHTFileCheckService(); 270 if (Logger.PASS_RESULT 271 != fileChecker.check(logger, 272 new File(datalet.outputName), 273 new File(datalet.goldName), 274 getDescription() + ", " + datalet.getDescription()) 275 ) 276 logger.logMsg(Logger.WARNINGMSG, "Failure reason: " + fileChecker.getExtendedInfo()); 277 } 278 // try...catch around entire performance operation 279 catch (Throwable t) 280 { 281 java.io.StringWriter sw = new java.io.StringWriter(); 282 java.io.PrintWriter pw = new java.io.PrintWriter(sw); 283 t.printStackTrace(pw); 284 logger.logArbitrary(Logger.ERRORMSG, sw.toString()); 285 logger.checkErr("PerfEverythingTestlet with:" + datalet.inputName 286 + " threw: " + t.toString()); 287 return; 288 } 289 290 //@todo Should we attempt to cleanup anything else here? 291 // We've had problems running this testlet over large 292 // files, so I'm looking for ways to reduce the impact 293 // this test code has on the JVM 294 } 295 296 297 /** 298 * Worker method: optionally reports Runtime.totalMemory/freeMemory; 299 * optionally first calls .gc() to force garbage collection. 300 * @param doGC: call .gc() or not first 301 * @param doLog: log out memory stats or not 302 */ logMemory(boolean doGC, boolean doLog)303 protected void logMemory(boolean doGC, boolean doLog) 304 { 305 if (doGC) 306 { 307 Runtime.getRuntime().gc(); 308 } 309 if (doLog) 310 { 311 logger.logStatistic(Logger.STATUSMSG, Runtime.getRuntime().freeMemory(), 0, "UMem;freeMemory"); 312 logger.logStatistic(Logger.STATUSMSG, Runtime.getRuntime().totalMemory(), 0, "UMem;totalMemory"); 313 } 314 } 315 316 317 /** 318 * Logs out throwable.toString() and stack trace to our Logger. 319 * //@todo Copied from Reporter; should probably be moved into Logger. 320 * @param throwable thrown throwable/exception to log out. 321 * @param msg description of the throwable. 322 */ logThrowable(Throwable throwable, String msg)323 protected void logThrowable(Throwable throwable, String msg) 324 { 325 StringWriter sWriter = new StringWriter(); 326 sWriter.write(msg + "\n"); 327 328 PrintWriter pWriter = new PrintWriter(sWriter); 329 throwable.printStackTrace(pWriter); 330 331 logger.logArbitrary(Logger.STATUSMSG, sWriter.toString()); 332 } 333 } // end of class PerfEverythingTestlet 334 335