001: /*
002: * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS HEADER.
003: *
004: * Copyright 1997-2007 Sun Microsystems, Inc. All rights reserved.
005: *
006: * The contents of this file are subject to the terms of either the GNU
007: * General Public License Version 2 only ("GPL") or the Common
008: * Development and Distribution License("CDDL") (collectively, the
009: * "License"). You may not use this file except in compliance with the
010: * License. You can obtain a copy of the License at
011: * http://www.netbeans.org/cddl-gplv2.html
012: * or nbbuild/licenses/CDDL-GPL-2-CP. See the License for the
013: * specific language governing permissions and limitations under the
014: * License. When distributing the software, include this License Header
015: * Notice in each file and include the License file at
016: * nbbuild/licenses/CDDL-GPL-2-CP. Sun designates this
017: * particular file as subject to the "Classpath" exception as provided
018: * by Sun in the GPL Version 2 section of the License file that
019: * accompanied this code. If applicable, add the following below the
020: * License Header, with the fields enclosed by brackets [] replaced by
021: * your own identifying information:
022: * "Portions Copyrighted [year] [name of copyright owner]"
023: *
024: * Contributor(s):
025: * The Original Software is NetBeans. The Initial Developer of the Original
026: * Software is Sun Microsystems, Inc. Portions Copyright 1997-2006 Sun
027: * Microsystems, Inc. All Rights Reserved.
028: *
029: * If you wish your version of this file to be governed by only the CDDL
030: * or only the GPL Version 2, indicate your decision by adding
031: * "[Contributor] elects to include this software in this distribution
032: * under the [CDDL or GPL Version 2] license." If you do not indicate a
033: * single choice of license, a recipient has the option to distribute
034: * your version of this file under either the CDDL, the GPL Version 2 or
035: * to extend the choice of license to its licensees as provided above.
036: * However, if you add GPL Version 2 code and therefore, elected the GPL
037: * Version 2 license, then the option applies only if the new code is
038: * made subject to such option by the copyright holder.
039: */
040:
041: /*
042: * CPUTestCase.java
043: *
044: * Created on July 19, 2005, 5:20 PM
045: *
046: * To change this template, choose Tools | Options and locate the template under
047: * the Source Creation and Management node. Right-click the template and choose
048: * Open. You can then make changes to the template in the Source Editor.
049: */
050: package org.netbeans.lib.profiler.tests.jfluid.cpu;
051:
052: import org.netbeans.lib.profiler.ProfilerEngineSettings;
053: import org.netbeans.lib.profiler.TargetAppRunner;
054: import org.netbeans.lib.profiler.global.CommonConstants;
055: import org.netbeans.lib.profiler.results.EventBufferResultsProvider;
056: import org.netbeans.lib.profiler.results.ProfilingResultsDispatcher;
057: import org.netbeans.lib.profiler.results.RuntimeCCTNode;
058: import org.netbeans.lib.profiler.results.cpu.CPUCCTProvider;
059: import org.netbeans.lib.profiler.results.cpu.CPUCallGraphBuilder;
060: import org.netbeans.lib.profiler.results.cpu.CPUResultsSnapshot;
061: import org.netbeans.lib.profiler.results.cpu.FlatProfileBuilder;
062: import org.netbeans.lib.profiler.results.cpu.FlatProfileContainer;
063: import org.netbeans.lib.profiler.results.cpu.FlatProfileContainerFree;
064: import org.netbeans.lib.profiler.tests.jfluid.*;
065: import org.netbeans.lib.profiler.tests.jfluid.utils.*;
066: import org.netbeans.lib.profiler.utils.StringUtils;
067: import java.text.NumberFormat;
068: import java.util.*;
069:
070: /**
071: *
072: * @author ehucka
073: */
074: public abstract class CPUTestCase extends CommonProfilerTestCase {
075: //~ Inner Classes ------------------------------------------------------------------------------------------------------------
076:
077: class Measured {
078: //~ Instance fields ------------------------------------------------------------------------------------------------------
079:
080: public int invocations = 0;
081: public long time = 0;
082:
083: //~ Methods --------------------------------------------------------------------------------------------------------------
084:
085: public void setInvocations(int invc) {
086: this .invocations = invc;
087: }
088:
089: public void setTime(long time) {
090: this .time = time;
091: }
092: }
093:
094: private class CPUResultListener implements CPUCCTProvider.Listener {
095: //~ Instance fields ------------------------------------------------------------------------------------------------------
096:
097: private final Object resultsLock = new Object();
098: private boolean hasResults = false;
099:
100: //~ Methods --------------------------------------------------------------------------------------------------------------
101:
102: public void cctEstablished(RuntimeCCTNode appRootNode) {
103: synchronized (resultsLock) {
104: hasResults = true;
105: resultsLock.notify();
106: }
107: }
108:
109: public void cctReset() {
110: synchronized (resultsLock) {
111: hasResults = false;
112: resultsLock.notify();
113: }
114: }
115:
116: public boolean wait4results(long timeout) {
117: synchronized (resultsLock) {
118: if (!hasResults) {
119: try {
120: resultsLock.wait(timeout);
121: } catch (InterruptedException e) {
122: }
123: }
124:
125: return hasResults;
126: }
127: }
128: }
129:
130: //~ Static fields/initializers -----------------------------------------------------------------------------------------------
131:
132: static int ALL_INV_ERROR_METHOD = 0;
133: static int LAST_INV_ERROR_METHOD = 1;
134:
135: //~ Instance fields ----------------------------------------------------------------------------------------------------------
136:
137: NumberFormat percentFormat;
138:
139: //~ Constructors -------------------------------------------------------------------------------------------------------------
140:
141: /**
142: * Creates a new instance of CPUTestCase
143: */
144: public CPUTestCase(String name) {
145: super (name);
146: percentFormat = NumberFormat.getPercentInstance();
147: percentFormat.setMaximumFractionDigits(1);
148: percentFormat.setMinimumFractionDigits(0);
149: }
150:
151: //~ Methods ------------------------------------------------------------------------------------------------------------------
152:
153: public int getALL_INV_ERROR_METHOD() {
154: return ALL_INV_ERROR_METHOD;
155: }
156:
157: protected double getError(int invocations, long mctime,
158: long idealtime) {
159: double ideal = idealtime * invocations * 1000.0;
160:
161: return Math.abs(ideal - mctime) / 1000;
162: }
163:
164: protected void checkCPUResults(FlatProfileContainer fpc,
165: HashMap methods, String[] measuredMethodsFilter) {
166: double percent = 0.0;
167:
168: for (int row = 0; row < fpc.getNRows(); row++) {
169: percent += fpc.getPercentAtRow(row);
170:
171: for (int mets = 0; mets < measuredMethodsFilter.length; mets++) {
172: if (fpc.getMethodNameAtRow(row).startsWith(
173: measuredMethodsFilter[mets])) {
174: Measured m = (Measured) (methods.get(fpc
175: .getMethodNameAtRow(row)));
176:
177: if (m == null) {
178: m = new Measured();
179: m.time = fpc.getTimeInMcs0AtRow(row);
180: m.invocations = fpc.getNInvocationsAtRow(row);
181: methods.put(fpc.getMethodNameAtRow(row), m);
182: } else {
183: long tm = m.time;
184: int inv = m.invocations;
185: m.setTime(fpc.getTimeInMcs0AtRow(row));
186: m.setInvocations(fpc.getNInvocationsAtRow(row));
187:
188: if ((tm > m.time) || (inv > m.invocations)) {
189: log("\n!!!Decreasing values: method "
190: + fpc.getMethodNameAtRow(row)
191: + " current time " + m.time
192: + " invocations " + m.invocations
193: + " but was time=" + tm
194: + " invocations=" + inv + "\n");
195: assertFalse(
196: "Unacceptable results - decresing values (issue 65187)",
197: true);
198: }
199: }
200: }
201: }
202: }
203:
204: if (Math.abs(percent - 100.0) > 0.1) {
205: log("\n!!!Sum of percents is not 100% - " + percent + "\n");
206:
207: for (int row = 0; row < fpc.getNRows(); row++) {
208: log(fpc.getMethodIdAtRow(row)
209: + " "
210: + percentFormat
211: .format(fpc.getPercentAtRow(row) / 100)
212: + " %");
213: }
214:
215: assertFalse(
216: "Unacceptable results - sum of percents != 100",
217: true);
218: }
219: }
220:
221: protected void checkCPUResults(FlatProfileContainer fpc,
222: String[] methodsNames, long[] idealTimes,
223: double diffMillis, String[] refMethods,
224: ArrayList refMethodsList, int errorMethod) {
225: double[] errors = new double[methodsNames.length];
226: int[] nInv = new int[methodsNames.length];
227: long[] times = new long[methodsNames.length];
228:
229: for (int row = 0; row < fpc.getNRows(); row++) {
230: for (int mets = 0; mets < methodsNames.length; mets++) {
231: if (fpc.getMethodNameAtRow(row).equals(
232: methodsNames[mets])) {
233: nInv[mets] = fpc.getNInvocationsAtRow(row);
234: times[mets] = fpc.getTimeInMcs0AtRow(row);
235: errors[mets] = getError(nInv[mets], times[mets],
236: idealTimes[mets]);
237: }
238: }
239:
240: if (refMethods != null) {
241: for (int mets = 0; mets < refMethods.length; mets++) {
242: String mname = fpc.getMethodNameAtRow(row);
243:
244: if (mname.startsWith(refMethods[mets])
245: && !refMethodsList.contains(mname)) {
246: refMethodsList.add(mname);
247: }
248: }
249: }
250: }
251:
252: double best = diffMillis / 4.0;
253: int bestcount = 0;
254: boolean bigdifference = false;
255:
256: for (int cntr = 0; cntr < errors.length; cntr++) {
257: if (errors[cntr] <= best) {
258: bestcount++;
259: }
260:
261: bigdifference |= (errors[cntr] > diffMillis);
262: }
263:
264: boolean accepted = !bigdifference
265: || ((bestcount * 1.0) >= (errors.length * 0.5));
266: logFractions(errors, nInv, times, idealTimes, methodsNames);
267: log("");
268:
269: if (!accepted) {
270: log("\nRESULTS WITH BIG DIFFERENCES - differences are greater than given tolerance: "
271: + diffMillis + " ms");
272: log("Best count " + bestcount + " errors.length "
273: + errors.length);
274: }
275:
276: //assertTrue("Not acceptable results - big differences", accepted);
277: }
278:
279: protected ProfilerEngineSettings initCpuTest(String projectName,
280: String mainClass) {
281: return initCpuTest(projectName, mainClass, null);
282: }
283:
284: protected ProfilerEngineSettings initCpuTest(String projectName,
285: String mainClass, String[][] rootMethods) {
286: //System.setProperty("org.netbeans.lib.profiler.wireprotocol.WireIO", "true");
287: ProfilerEngineSettings settings = initTest(projectName,
288: mainClass, rootMethods);
289: //defaults
290: settings.setCPUProfilingType(CommonConstants.CPU_INSTR_FULL);
291: settings.setInstrScheme(CommonConstants.INSTRSCHEME_LAZY);
292: settings.setInstrumentEmptyMethods(false);
293: settings.setInstrumentGetterSetterMethods(false);
294: settings.setInstrumentMethodInvoke(true);
295: settings.setInstrumentSpawnedThreads(rootMethods != null);
296: settings.setExcludeWaitTime(true);
297:
298: // addJVMArgs(settings, "-Dorg.netbeans.lib.profiler.wireprotocol.WireIO=true");
299: //addJVMArgs(settings, "-Dorg.netbeans.lib.profiler.server.ProfilerServer=true");
300: // if (rootMethods == null) {
301: // addJVMArgs(settings, "-Dorg.netbeans.lib.profiler.server.ProfilerServer=true");
302: // }
303: settings.setThreadCPUTimerOn(false);
304:
305: return settings;
306: }
307:
308: protected void logFractions(double[] errors, int[] inv,
309: long[] times, long[] ideals, String[] methods) {
310: log(complete("Error[ms]", 10) + complete("Invocs", 10)
311: + complete("Time[ms]", 10) + complete("Ideal[ms]", 10)
312: + "Method");
313:
314: for (int i = 0; i < errors.length; i++) {
315: log(complete(String.valueOf(errors[i]), 9)
316: + " "
317: + complete(String.valueOf(inv[i]), 9)
318: + " "
319: + complete(StringUtils.mcsTimeToString(times[i]), 9)
320: + " "
321: + complete(String.valueOf(ideals[i] * inv[i]), 9)
322: + " " + methods[i]);
323: }
324: }
325:
326: protected void logInstrumented(TargetAppRunner runner)
327: throws Exception {
328: CPUResultsSnapshot snapshot = runner.getProfilerClient()
329: .getCPUProfilingResultsSnapshot();
330: String[] mets = snapshot.getInstrMethodNames();
331: log("Instrumented methods:");
332:
333: for (int i = 0; i < mets.length; i++) {
334: log(mets[i]);
335: }
336: }
337:
338: /**
339: * checks results after the profiled app is finished
340: */
341: protected void startCPUTest(ProfilerEngineSettings settings,
342: String[] measuredMethods, long[] idealTimes,
343: double diffMillis, String[] displayMethodsFilter,
344: int errorMethod) {
345: CPUCallGraphBuilder builder = new CPUCallGraphBuilder();
346:
347: assertTrue(builder != null);
348:
349: //create runner
350: TargetAppRunner runner = new TargetAppRunner(settings,
351: new TestProfilerAppHandler(this ),
352: new TestProfilingPointsProcessor());
353: runner.addProfilingEventListener(Utils
354: .createProfilingListener(this ));
355:
356: ProfilingResultsDispatcher.getDefault().addListener(builder);
357:
358: CPUResultListener resultListener = new CPUResultListener();
359: builder.addListener(resultListener);
360:
361: FlatProfileBuilder flattener = new FlatProfileBuilder();
362: builder.addListener(flattener);
363: flattener.setContext(runner.getProfilerClient());
364:
365: EventBufferResultsProvider.getDefault().startup(
366: runner.getProfilerClient());
367:
368: builder.startup(runner.getProfilerClient());
369:
370: try {
371: runner.readSavedCalibrationData();
372:
373: Process p = startTargetVM(runner);
374: assertNotNull("Target JVM is not started", p);
375: bindStreams(p);
376: runner.connectToStartedVMAndStartTA();
377:
378: runner.getProfilerClient()
379: .initiateRecursiveCPUProfInstrumentation(
380: settings.getInstrumentationRootMethods());
381:
382: waitForStatus(STATUS_RUNNING);
383: assertTrue("runner is not running", runner
384: .targetAppIsRunning());
385:
386: ArrayList methods = new ArrayList();
387:
388: waitForStatus(STATUS_APP_FINISHED);
389:
390: if (runner.targetJVMIsAlive()) {
391: log("Get results: " + System.currentTimeMillis());
392: assertTrue("Results do not exist - issue 65185.",
393: runner.getProfilerClient().cpuResultsExist());
394:
395: boolean gotResults = false;
396: int retryCounter = 4;
397:
398: do {
399: // just wait for the results to appear - forceObtainedResultsDump() has been alread called by ProfilerClient on shutdown
400: // runner.getProfilerClient().forceObtainedResultsDump();
401: gotResults = resultListener.wait4results(2500);
402: } while (!gotResults && (--retryCounter > 0));
403:
404: assertTrue(
405: "Results are not available after 10 seconds.",
406: gotResults);
407: log("obtaining results "
408: + String.valueOf(System.currentTimeMillis()));
409:
410: //logInstrumented(runner);
411: FlatProfileContainerFree fpc = null;
412: int retry = 5;
413:
414: while ((fpc == null) && (--retry > 0)) {
415: fpc = (FlatProfileContainerFree) flattener
416: .createFlatProfile();
417: Thread.sleep(500);
418: }
419:
420: fpc.filterOriginalData(new String[] { "" },
421: CommonConstants.FILTER_CONTAINS, 0.0D);
422: checkCPUResults(fpc, measuredMethods, idealTimes,
423: diffMillis, displayMethodsFilter, methods,
424: errorMethod);
425: }
426:
427: setStatus(STATUS_MEASURED);
428:
429: if (methods.size() > 0) {
430: Collections.sort(methods);
431:
432: for (int mets = 0; mets < methods.size(); mets++) {
433: ref(methods.get(mets));
434: }
435: }
436: } catch (Exception ex) {
437: log(ex);
438: assertTrue("Exception thrown: " + ex.getMessage(), false);
439: } finally {
440: ProfilingResultsDispatcher.getDefault().pause(true);
441: builder.shutdown();
442: flattener.setContext(null);
443: builder.removeListener(flattener);
444: builder.removeListener(resultListener);
445: ProfilingResultsDispatcher.getDefault().removeListener(
446: builder);
447: finalizeTest(runner);
448: }
449: }
450:
451: /**
452: * check reulsts periodicaly - live results
453: */
454: protected void startCPUTest(ProfilerEngineSettings settings,
455: String[] measuredMethodsFilter, long checkDelay,
456: long maxDelay) {
457: CPUCallGraphBuilder builder = new CPUCallGraphBuilder();
458:
459: assertTrue(builder != null);
460:
461: //create runner
462: TargetAppRunner runner = new TargetAppRunner(settings,
463: new TestProfilerAppHandler(this ),
464: new TestProfilingPointsProcessor());
465: runner.addProfilingEventListener(Utils
466: .createProfilingListener(this ));
467:
468: ProfilingResultsDispatcher.getDefault().addListener(builder);
469:
470: CPUResultListener resultListener = new CPUResultListener();
471: builder.addListener(resultListener);
472:
473: FlatProfileBuilder flattener = new FlatProfileBuilder();
474: builder.addListener(flattener);
475: flattener.setContext(runner.getProfilerClient());
476:
477: EventBufferResultsProvider.getDefault().startup(
478: runner.getProfilerClient());
479:
480: builder.startup(runner.getProfilerClient());
481:
482: try {
483: runner.readSavedCalibrationData();
484:
485: // runner.getProfilerClient().initiateRecursiveCPUProfInstrumentation(settings.getInstrumentationRootMethods());
486: Process p = startTargetVM(runner);
487: assertNotNull("Target JVM is not started", p);
488: bindStreams(p);
489:
490: runner.connectToStartedVMAndStartTA();
491:
492: runner.getProfilerClient()
493: .initiateRecursiveCPUProfInstrumentation(
494: settings.getInstrumentationRootMethods());
495:
496: waitForStatus(STATUS_RUNNING);
497: assertTrue("runner is not running", runner
498: .targetAppIsRunning());
499: waitForStatus(STATUS_RESULTS_AVAILABLE
500: | STATUS_APP_FINISHED);
501: assertTrue("ResultsAvailable was not called - issue 69084",
502: isStatus(STATUS_RESULTS_AVAILABLE));
503:
504: HashMap methods = new HashMap(128);
505: long alltime = 0;
506: long time = System.currentTimeMillis();
507: long oldtime = time - checkDelay;
508:
509: while (!isStatus(STATUS_APP_FINISHED)
510: && !isStatus(STATUS_ERROR) && (alltime < maxDelay)) {
511: if ((time - oldtime) < (2 * checkDelay)) {
512: Thread.sleep((2 * checkDelay) - (time - oldtime));
513: }
514:
515: if (!isStatus(STATUS_LIVERESULTS_AVAILABLE)) {
516: waitForStatus(STATUS_LIVERESULTS_AVAILABLE,
517: checkDelay / 2);
518: }
519:
520: if (runner.targetJVMIsAlive()
521: && isStatus(STATUS_LIVERESULTS_AVAILABLE)) {
522: assertTrue("Results do not exist - issue 65185.",
523: runner.getProfilerClient()
524: .cpuResultsExist());
525: log("Get Results: " + System.currentTimeMillis());
526:
527: // runner.getProfilerClient().forceObtainedResultsDump();
528: // assertTrue("Results do not exist on the server - issue 65185.", runner.getProfilerClient().cpuResultsExist());
529: boolean gotResults = false;
530: int retryCounter = 2;
531:
532: do {
533: runner.getProfilerClient()
534: .forceObtainedResultsDump();
535: gotResults = resultListener.wait4results(2500);
536: } while (!gotResults && (--retryCounter > 0));
537:
538: assertTrue(
539: "CallGraphBuilder: Results do not exist.",
540: gotResults);
541: log("Results obtained "
542: + String
543: .valueOf(System.currentTimeMillis()));
544:
545: //logInstrumented(runner);
546: FlatProfileContainerFree fpc = null;
547: int retry = 5;
548:
549: while ((fpc == null) && (--retry > 0)) {
550: fpc = (FlatProfileContainerFree) flattener
551: .createFlatProfile();
552: Thread.sleep(500);
553: }
554:
555: fpc.filterOriginalData(new String[] { "" },
556: CommonConstants.FILTER_CONTAINS, 0.0D);
557: fpc.sortBy(FlatProfileContainer.SORT_BY_TIME, true);
558: checkCPUResults(fpc, methods, measuredMethodsFilter);
559: }
560:
561: alltime += (System.currentTimeMillis() - time);
562: oldtime = time;
563: time = System.currentTimeMillis();
564: }
565:
566: if (methods.size() == 0) {
567: assertTrue(
568: "Results were not on the server - issue 65185",
569: false);
570: }
571: } catch (Exception ex) {
572: log(ex);
573: assertTrue("Exception thrown: " + ex.getMessage(), false);
574: } finally {
575: ProfilingResultsDispatcher.getDefault().pause(true);
576: builder.shutdown();
577: flattener.setContext(null);
578: builder.removeListener(flattener);
579: builder.removeListener(resultListener);
580: ProfilingResultsDispatcher.getDefault().removeListener(
581: builder);
582: finalizeTest(runner);
583: }
584: }
585: }
|