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 package org.apache.qetest.xsl; 23 24 import java.io.File; 25 import java.io.FileInputStream; 26 import java.text.DecimalFormat; 27 import java.util.Hashtable; 28 29 import org.apache.qetest.Datalet; 30 import org.apache.qetest.Logger; 31 import org.apache.qetest.xslwrapper.TransformWrapper; 32 import org.apache.qetest.xslwrapper.TransformWrapperHelper; 33 34 /** 35 * Testlet to capture specific timing performance data. 36 * This Testlet is a cut-down version of PerfEverythingTestlet. 37 * 38 * We log out XalanC-like overall performance numbers, as well 39 * as logging out any available data from the times array returned 40 * by our transformWrapper. Note that different flavors of 41 * transformWrapper will return different sets of timings. 42 * 43 * @author Shane_Curcuru@us.ibm.com 44 * @version $Id$ 45 */ 46 public class PerfTestlet extends StylesheetTestlet 47 { 48 // Initialize our classname for TestletImpl's main() method 49 static { thisClassName = "org.apache.qetest.xsl.PerfTestlet"; } 50 51 // Initialize our defaultDatalet 52 { defaultDatalet = (Datalet)new StylesheetDatalet(); } 53 54 /** 55 * Accesor method for a brief description of this test. 56 * @return String describing what this PerfTestlet does. 57 */ getDescription()58 public String getDescription() 59 { 60 return "PerfTestlet"; 61 } 62 63 64 /** 65 * Worker method to actually perform the transform; 66 * overriden to use command line processing. 67 * 68 * Logs out applicable info; attempts to perform transformation 69 * and also prints out a <perf> element. 70 * 71 * @param datalet to test with 72 * @param transformWrapper to have perform the transform 73 * @throws allows any underlying exception to be thrown 74 */ testDatalet(StylesheetDatalet datalet, TransformWrapper transformWrapper)75 protected void testDatalet(StylesheetDatalet datalet, TransformWrapper transformWrapper) 76 throws Exception 77 { 78 // Setup: Save options from the datalet in convenience variables 79 int iterations = 5; 80 boolean runtimeGC = true; 81 long[] times = null; 82 83 // Read in necessary options from test.properties file. 84 try 85 { 86 iterations = Integer.parseInt(datalet.options.getProperty("iterations")); 87 } 88 catch (Exception e) { /* no-op, leave as default */ } 89 try 90 { 91 String gc = datalet.options.getProperty("runtimeGC"); 92 if (gc != null) 93 runtimeGC = (Boolean.valueOf(gc)).booleanValue(); 94 } 95 catch (Exception e) { /* no-op, leave as default */ } 96 97 // Setup: store various XalanC-like timing data in convenience variables 98 long warmup = 0L; // First transform. Used to load classes. 99 long singletransform = 0L; // Very first Preload end-to-end transform 100 long etoe = 0L; // First end-to-end transform during iterations 101 long avgetoe = 0L; // Average of end-to-end transforms during iterations 102 long parsexsl = 0L; // First stylesheet preprocess during iterations 103 long avgparsexsl = 0L; // Average of stylesheet preprocess during iterations 104 long unparsedxml = 0L; // First stylesheet process during iterations 105 long transxml = 0L; // Transform w/Stylesheet - NO OUTPUT 106 long transxmloutput = 0L; // Transform w/Stylesheet - OUTPUT 107 108 //logger.logMsg(Logger.TRACEMSG, "executing with: inputName=" + datalet.inputName 109 // + " xmlName=" + datalet.xmlName + " outputName=" + datalet.outputName 110 // + " goldName=" + datalet.goldName + " flavor=" + datalet.flavor 111 // + " iterations=" + iterations 112 // + " algorithim=" + getDescription()); 113 114 //@todo make various logMemory calls optional 115 logMemory(runtimeGC, false); 116 117 // Measure(warmup): JVM warm up 118 times = transformWrapper.transform(datalet.xmlName, datalet.inputName, 119 datalet.outputName); 120 warmup = times[TransformWrapper.IDX_OVERALL]; 121 logMemory(runtimeGC, false); 122 123 // Measure(singletransform): Very first Preload end-to-end transform 124 times = transformWrapper.transform(datalet.xmlName, datalet.inputName, 125 datalet.outputName); 126 singletransform = times[TransformWrapper.IDX_OVERALL]; 127 logMemory(runtimeGC, false); 128 129 // Measure(parsexsl): once: first preprocess 130 times = transformWrapper.buildStylesheet(datalet.inputName); 131 parsexsl = times[TransformWrapper.IDX_OVERALL]; 132 logMemory(runtimeGC, false); 133 134 // Measure(unparsedxml): once: first process 135 times = transformWrapper.transformWithStylesheet(datalet.xmlName, datalet.outputName); 136 unparsedxml = times[TransformWrapper.IDX_OVERALL]; 137 logMemory(runtimeGC, false); 138 139 for (int ctr = 1; ctr <= iterations; ctr++) 140 { 141 // Measure(avgparsexsl): average preprocess 142 times = transformWrapper.buildStylesheet(datalet.inputName); 143 avgparsexsl += times[TransformWrapper.IDX_OVERALL]; 144 logMemory(runtimeGC, false); 145 146 // Measure(avgunparsedxml): getTransformer + xmlRead + transform 147 times = transformWrapper.transformWithStylesheet(datalet.xmlName, datalet.outputName); 148 transxml += times[TransformWrapper.IDX_TRANSFORM]; 149 logMemory(runtimeGC, false); 150 151 // Measure(avgunparsedxml): getTransformer + xmlRead + transform + resultWrite 152 times = transformWrapper.transformWithStylesheet(datalet.xmlName, datalet.outputName); 153 transxmloutput += times[TransformWrapper.IDX_OVERALL]; 154 logMemory(runtimeGC, false); 155 156 } 157 158 // Measure(etoe): once: first full process 159 times = transformWrapper.transform(datalet.xmlName, datalet.inputName, datalet.outputName); 160 etoe = times[TransformWrapper.IDX_OVERALL]; 161 logMemory(runtimeGC, false); 162 163 // Aggregate all specific timing data returned by TransformWrappers 164 // note that different flavors of wrappers will be able 165 // to report different kinds of times 166 // This data is separate from the XalanC-like data above 167 //@todo determine which data is best to store 168 long[] storedTimes = TransformWrapperHelper.getTimeArray(); 169 long[] storedCounts = TransformWrapperHelper.getTimeArray(); 170 for (int ctr = 1; ctr <= iterations; ctr++) 171 { 172 // Measure(avgetoe): average full process 173 times = transformWrapper.transform(datalet.xmlName, datalet.inputName, datalet.outputName); 174 avgetoe += times[TransformWrapper.IDX_OVERALL]; 175 aggregateTimes(times, storedTimes, storedCounts); 176 logMemory(runtimeGC, false); 177 } 178 179 Hashtable attrs = new Hashtable(); 180 // BOTH: Log all specific timing data returned by TransformWrappers 181 logAggregateTimes(attrs, storedTimes, storedCounts); 182 183 // ASLO: Log special XalanC-like performance element with our timing 184 // UniqRunid is an Id that our TestDriver normally sets 185 // with some unique code, so that results analysis 186 // stylesheets can compare different test runs 187 attrs.put("UniqRunid", datalet.options.getProperty("runId", "runId;none")); 188 // processor is the 'flavor' of processor we're testing 189 attrs.put("processor", transformWrapper.getDescription()); 190 // idref is the individual filename 191 attrs.put("idref", (new File(datalet.inputName)).getName()); 192 // inputName is the actual name we gave to the processor 193 attrs.put("inputName", datalet.inputName); 194 attrs.put("iterations", new Integer(iterations)); 195 attrs.put("warmup", new Long(warmup)); 196 attrs.put("singletransform", new Long(singletransform)); // Very first Preload end-to-end transform 197 attrs.put("etoe", new Long(etoe)); // First end-to-end transform during iterations 198 // Note that avgetoe should match logTimes()'s OVERALL value 199 attrs.put("avgetoe", new Long(avgetoe / iterations)); // Average of end-to-end transforms during iterations 200 attrs.put("parsexsl", new Long(parsexsl)); // First stylesheet preprocess during iterations 201 attrs.put("avgparsexsl", new Long(avgparsexsl / iterations)); // Average of stylesheet preprocess during iterations 202 attrs.put("unparsedxml", new Long(unparsedxml)); // First stylesheet process during iterations 203 attrs.put("transxml", new Long(transxml / iterations)); // Average of stylesheet process during iterations 204 205 // Additional metrics for data throughput 206 File fIn = new File(datalet.inputName); 207 long btIn = iterations * fIn.length(); 208 attrs.put("BytesIn", new Long(btIn)); 209 210 // Due to unknown reasons the output needs to be filtered through a FileInputStream to get it's size. 211 File fOut = new File(datalet.outputName); 212 FileInputStream fOutStrm = new FileInputStream(fOut); 213 214 int len = fOutStrm.available(); 215 long btOut = iterations * fOut.length(); 216 attrs.put("BytesOut", new Long(btOut)); 217 fOutStrm.close(); 218 219 // I've added additional measurments. DP calculated KBs as ((Ki+Ko)/2)/sec. 220 // I now calculate it with the following (Ki+K0)/sec 221 222 // Calculate TRANSFORM thruput (Kb/sec). Based on DataPower; does NOT file I/O 223 double KBtdp = (double)(1000 * (btIn + btOut)) / (double)(1024 * 2 * transxml); 224 DecimalFormat fmt = new DecimalFormat("####.##"); 225 StringBuffer x = new StringBuffer( fmt.format(KBtdp)); 226 attrs.put("KBtdp", x); 227 228 // Calculate OVERALL thruput (Kb/sec). Based on DataPower; does include file I/O 229 double KBtsdp = (double)(1000 * (btIn + btOut)) / (double)(1024 * 2 * transxmloutput); 230 //DecimalFormat fmt = new DecimalFormat("####.##"); 231 x = new StringBuffer(fmt.format(KBtsdp)); 232 attrs.put("KBtsdp", x); 233 234 // Calculate TRANSFORM thruput (Kb/sec). Based on ped; does NOT file I/O 235 double KBtPD = (double)(1000 * (btIn + btOut)) / (double)(1024 * transxml); 236 //DecimalFormat fmt = new DecimalFormat("####.##"); 237 x = new StringBuffer(fmt.format(KBtPD)); 238 attrs.put("KBtPD", x); 239 240 // Calculate OVERALL thruput (Kb/sec). Based on ped; does include file I/O 241 double KBtsPD = (double)(1000 * (btIn + btOut)) / (double)(1024 * transxmloutput); 242 //DecimalFormat fmt = new DecimalFormat("####.##"); 243 x = new StringBuffer(fmt.format(KBtsPD)); 244 attrs.put("KBtsPD", x); 245 246 logger.logElement(Logger.STATUSMSG, "perf", attrs, fIn.getName()); 247 } 248 249 /** 250 * Worker method: optionally reports Runtime.totalMemory/freeMemory; 251 * optionally first calls .gc() to force garbage collection. 252 * @param doGC: call .gc() or not first 253 * @param doLog: log out memory stats or not 254 */ logMemory(boolean doGC, boolean doLog)255 protected void logMemory(boolean doGC, boolean doLog) 256 { 257 if (doGC) 258 { 259 Runtime.getRuntime().gc(); 260 //System.out.print("."); 261 } 262 if (doLog) 263 { 264 logger.logStatistic(Logger.STATUSMSG, Runtime.getRuntime().freeMemory(), 0, "UMem;freeMemory"); 265 logger.logStatistic(Logger.STATUSMSG, Runtime.getRuntime().totalMemory(), 0, "UMem;totalMemory"); 266 } 267 } 268 269 /** 270 * Worker method: aggregate timing arrays and keep counters. 271 * @param newTimes new timing data to add to storedTimes 272 * @param storedTimes incremented from newTimes 273 * @param countTimes number of time slots actually incremented; 274 * i.e. TIME_UNUSED ones are not incremented 275 */ aggregateTimes(long[] newTimes, long[] storedTimes, long[] countTimes)276 protected void aggregateTimes(long[] newTimes, long[] storedTimes, long[] countTimes) 277 { 278 // Note assumption in this class that all are same len 279 for (int i = 0; i < storedTimes.length; i++) 280 { 281 // Only aggregate items that have actual timing data 282 if (TransformWrapper.TIME_UNUSED != newTimes[i]) 283 { 284 // Be sure to start from 0 if we haven't been hit before 285 if (TransformWrapper.TIME_UNUSED == storedTimes[i]) 286 { 287 // Start counting the time data for this slot 288 storedTimes[i] = newTimes[i]; 289 // Start counter for this slot 290 countTimes[i] = 1; 291 } 292 else 293 { 294 // Aggregate the time data for this slot 295 storedTimes[i] += newTimes[i]; 296 // Increment counter for this slot 297 countTimes[i]++; 298 } 299 } 300 } 301 } 302 303 /** 304 * Worker method: log aggregate timing arrays and keep counters. 305 * @param storedTimes to log out 306 * @param countTimes number of time slots actually incremented 307 */ logAggregateTimes(Hashtable attrs, long[] storedTimes, long[] countTimes)308 protected void logAggregateTimes(Hashtable attrs, long[] storedTimes, long[] countTimes) 309 { 310 for (int i = 0; i < storedTimes.length; i++) 311 { 312 // Only log items that have actual timing data 313 if (TransformWrapper.TIME_UNUSED != storedTimes[i]) 314 { 315 attrs.put(TransformWrapperHelper.getTimeArrayDesc(i), 316 new Long(storedTimes[i] / countTimes[i])); 317 } 318 } 319 } 320 } // end of class PerfTestlet 321 322