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: package org.netbeans.lib.profiler.server;
042:
043: import org.netbeans.lib.profiler.global.CalibrationDataFileIO;
044: import org.netbeans.lib.profiler.global.CommonConstants;
045: import org.netbeans.lib.profiler.global.Platform;
046: import org.netbeans.lib.profiler.global.ProfilingSessionStatus;
047: import org.netbeans.lib.profiler.server.system.Timers;
048: import org.netbeans.lib.profiler.wireprotocol.InternalStatsResponse;
049: import java.text.MessageFormat;
050: import java.text.NumberFormat;
051: import java.util.ResourceBundle;
052:
053: /**
054: * Functionality that allows one to measure in advance the time that standard instrumentation takes.
055: * These values can then be subtracted from the rough profiling results, giving measurements that are
056: * much more close to reality.
057: *
058: * @author Misha Dmitriev
059: * @author Ian Formanek
060: */
061: class ProfilerCalibrator extends ProfilerRuntime {
062: //~ Static fields/initializers -----------------------------------------------------------------------------------------------
063:
064: // -----
065: // I18N String constants
066: // !!! Warning - do not use ResourceBundle.getBundle here, won't work in context of direct/dynamic attach !!!
067: // Default EN messages initialized here, will be replaced by localized messages in static initializer
068: private static String CANNOT_SAVE_CALIBRATION_DATA_MSG = "Performed calibration successfully, but could not save calibration data:\n{0}"; // NOI18N
069: private static String CALIBRATION_SUCCESS_MSG = "Calibration performed successfully"; // NOI18N
070: private static String CALIBRATION_RESULTS_PREFIX = "For your reference, obtained results are as follows:"; // NOI18N
071: private static String CALIBRATION_RESULTS_MSG = "Approximate time in one methodEntry()/methodExit() call pair:\nWhen getting absolute timestamp only: {0} microseconds\nWhen getting thread CPU timestamp only: {1} microseconds\nWhen getting both timestamps: {2} microseconds\n\nApproximate time in one methodEntry()/methodExit() call pair\nin sampled instrumentation mode: {3} microseconds\n"; // NOI18N
072: private static String STARTING_CALIBRATION_MSG = "Starting calibration..."; // NOI18N
073: private static String TIMER_COUNTS_MSG = "*** timerCountsInSecond = {0}"; // NOI18N
074: private static String TIMER_VALUE_MSG = "*** sample value returned by timer = {0}"; // NOI18N
075: private static String INJECTION_CALIBRATION_MSG = "----------- Injected profiler code calibration -----------"; // NOI18N
076: private static String TIME_getCurrentTimeInCounts_MSG = "Time per each getCurrentTimeInCounts() call"; // NOI18N
077: private static String TIME_getThreadCPUTimeInNanos_MSG = "Time per each getThreadCPUTimeInNanos() call"; // NOI18N
078: private static String TIME_COUNTS_MCS_MSG = "{0} counts, {1} mcs"; // NOI18N
079: private static String TIME_SUCCESS_PAIRS_MSG = "Time per each successful methodEntry()/methodExit() pair of calls ({0}, {1})"; // NOI18N
080: private static String MINIMUM_TIME_MSG = "Minimum time: {0} counts, or {1} mcs."; // NOI18N
081: private static String INNER_OUTER_TIME_MSG = "Inner/outer time for a successful methodEntry()/methodExit() pair of calls"; // NOI18N
082: private static String INNER_TIME_MCS_MSG = "Inner time: {0} mcs."; // NOI18N
083: private static String OUTER_TIME_MCS_MSG = "Outer time: {0} mcs."; // NOI18N
084: private static String SAMPLED_TIME_MSG = "Time per each sampled instrumentation methodEntry()/methodExit() pair of calls"; // NOI18N
085: private static String REGION_TIME_MSG = "Time per each codeRegionEntry()/codeRegionExit() pair of calls"; // NOI18N
086: // -----
087:
088: static {
089: ResourceBundle messages = ProfilerServer
090: .getProfilerServerResourceBundle();
091:
092: if (messages != null) {
093: CANNOT_SAVE_CALIBRATION_DATA_MSG = messages
094: .getString("ProfilerCalibrator_CannotSaveCalibrationDataMsg"); // NOI18N
095: CALIBRATION_SUCCESS_MSG = messages
096: .getString("ProfilerCalibrator_CalibrationSuccessMsg"); // NOI18N
097: CALIBRATION_RESULTS_PREFIX = messages
098: .getString("ProfilerCalibrator_CalibrationResultsPrefix"); // NOI18N
099: CALIBRATION_RESULTS_MSG = messages
100: .getString("ProfilerCalibrator_CalibrationResultsMsg"); // NOI18N
101: STARTING_CALIBRATION_MSG = messages
102: .getString("ProfilerCalibrator_StartingCalibrationMsg"); // NOI18N
103: TIMER_COUNTS_MSG = messages
104: .getString("ProfilerCalibrator_TimerCountsMsg"); // NOI18N
105: TIMER_VALUE_MSG = messages
106: .getString("ProfilerCalibrator_TimerValueMsg"); // NOI18N
107: INJECTION_CALIBRATION_MSG = messages
108: .getString("ProfilerCalibrator_InjectionCalibrationMsg"); // NOI18N
109: TIME_getCurrentTimeInCounts_MSG = messages
110: .getString("ProfilerCalibrator_TimeGetCurrentTimeInCountsMsg"); // NOI18N
111: TIME_getThreadCPUTimeInNanos_MSG = messages
112: .getString("ProfilerCalibrator_TimeGetThreadCPUTimeInNanosMsg"); // NOI18N
113: TIME_COUNTS_MCS_MSG = messages
114: .getString("ProfilerCalibrator_TimeCountsMcsMsg"); // NOI18N
115: TIME_SUCCESS_PAIRS_MSG = messages
116: .getString("ProfilerCalibrator_TimeSuccessPairsMsg"); // NOI18N
117: MINIMUM_TIME_MSG = messages
118: .getString("ProfilerCalibrator_MinimumTimeMsg"); // NOI18N
119: INNER_OUTER_TIME_MSG = messages
120: .getString("ProfilerCalibrator_InnerOuterTimeMsg"); // NOI18N
121: INNER_TIME_MCS_MSG = messages
122: .getString("ProfilerCalibrator_InnerTimeMcsMsg"); // NOI18N
123: OUTER_TIME_MCS_MSG = messages
124: .getString("ProfilerCalibrator_OuterTimeMcsMsg"); // NOI18N
125: SAMPLED_TIME_MSG = messages
126: .getString("ProfilerCalibrator_SampledTimeMsg"); // NOI18N
127: REGION_TIME_MSG = messages
128: .getString("ProfilerCalibrator_RegionTimeMsg"); // NOI18N
129: }
130: }
131:
132: private static ProfilingSessionStatus status;
133: private static boolean printResults;
134: private static byte[] buf;
135: private static double minTimePerMethodEntryExitCallInCounts;
136: private static double minTimePerMethodEntryExitCallInMCS;
137: private static double innerTimeInCounts;
138: private static double outerTimeInCounts;
139: private static long cntInSecond;
140: private static int nCall;
141: private static int cycleWhenMinResultDetected;
142:
143: //~ Methods ------------------------------------------------------------------------------------------------------------------
144:
145: //private static double deviation; private static int nDevSamples;
146: public static void init(ProfilingSessionStatus status) {
147: ProfilerCalibrator.status = status;
148: }
149:
150: /**
151: * Main method is called in two cases:
152: * - when the user wants to perform calibration and save results on the machine where the tool is not installed,
153: * so that later remote profiling can be performed on this machine. No command line args are needed.
154: * - a backdoor usage when JF developers want to see calibration data, tune the internals etc. In that case,
155: * a special command line argument -develmode should be provided.
156: */
157: public static void main(String[] args) {
158: boolean inDevelMode;
159:
160: if ((args.length > 0) && args[0].equals("-develmode")) { // NOI18N // Development mode, see above
161: inDevelMode = true;
162: System.out.println("Loader for this class is "
163: + ProfilerCalibrator.class.getClassLoader()); // NOI18N
164: } else {
165: inDevelMode = false;
166:
167: ProfilingSessionStatus localStatus = new ProfilingSessionStatus();
168: localStatus.targetJDKVersionString = Platform
169: .getJDKVersionString();
170: localStatus.remoteProfiling = true;
171: init(localStatus);
172: }
173:
174: Timers.initialize();
175:
176: measureBCIOverhead(inDevelMode);
177:
178: if (!inDevelMode) {
179: if (!CalibrationDataFileIO.saveCalibrationData(status)) {
180: System.err.println(MessageFormat.format(
181: CANNOT_SAVE_CALIBRATION_DATA_MSG,
182: new Object[] { CalibrationDataFileIO
183: .getErrorMessage() })); // NOI18N
184: System.exit(-1);
185: }
186:
187: System.out.println(CALIBRATION_SUCCESS_MSG); // NOI18N
188: System.out.println(CALIBRATION_RESULTS_PREFIX); // NOI18N
189:
190: NumberFormat nf = NumberFormat.getInstance();
191: nf.setMaximumFractionDigits(4);
192:
193: long cntsInSec = status.timerCountsInSecond[0];
194: double m0 = (((double) status.methodEntryExitCallTime[0]) * 1000000)
195: / cntsInSec; // Expressed in microseconds
196: double m1 = (((double) status.methodEntryExitCallTime[1]) * 1000000)
197: / cntsInSec; // Ditto
198: double m2 = (((double) status.methodEntryExitCallTime[2]) * 1000000)
199: / cntsInSec; // Ditto
200: double m4 = (((double) status.methodEntryExitCallTime[4]) * 1000000)
201: / cntsInSec; // Ditto
202:
203: StringBuffer s = new StringBuffer();
204: s.append(MessageFormat.format(CALIBRATION_RESULTS_MSG,
205: new Object[] { nf.format(m0), nf.format(m1),
206: nf.format(m2), nf.format(m4) }));
207:
208: System.out.println(s.toString());
209: }
210: }
211:
212: /**
213: * In addition to calculating and optionally printing some measurements of the overhead imposed by BCI, this
214: * call, I hope, makes the impact of BCI on the target application more uniform/predictable, since it causes
215: * the VM to precompile various profiling calls.
216: */
217: public static void measureBCIOverhead(boolean printRes) {
218: printResults = printRes;
219:
220: System.out.println(STARTING_CALIBRATION_MSG);
221:
222: // Just wait for some time, to e.g. make caller threads finish their work, etc.
223: try {
224: Thread.sleep(1000);
225: } catch (Exception ex) {
226: }
227:
228: cntInSecond = Timers.getNoOfCountsInSecond();
229: printResults(MessageFormat.format(TIMER_COUNTS_MSG,
230: new Object[] { "" + cntInSecond })); // NOI18N
231: printResults(MessageFormat.format(TIMER_VALUE_MSG,
232: new Object[] { "" + Timers.getCurrentTimeInCounts() })); // NOI18N
233:
234: if (status != null) {
235: status.timerCountsInSecond = new long[2];
236: status.timerCountsInSecond[0] = cntInSecond;
237: status.timerCountsInSecond[1] = 1000000000;
238: }
239:
240: ProfilerRuntime.resetProfilerCollectors(INSTR_RECURSIVE_FULL);
241: ProfilerRuntimeCPU.setNProfiledThreadsLimit(1);
242: ProfilerRuntimeCPU.setInstrMethodsInvoked(new boolean[] { true,
243: true, true, true });
244: ProfilerRuntimeCPU.createThreadInfoForCurrentThread();
245:
246: printResults(INJECTION_CALIBRATION_MSG + "\n"); // NOI18N
247:
248: if (printResults) { // Measure and print the performance of getCurrentTimeInCounts() - for information only
249: measureTimerCall(true);
250: measureTimerCall(false);
251: }
252:
253: //deviation = 0; nDevSamples = 0;
254: nCall = -1;
255: measureMethodEntryExitCalls(); // A warmup run to make the compiler make all necessary inlines etc.
256:
257: for (nCall = 0; nCall < 4; nCall++) {
258: measureMethodEntryExitCalls(); // This knows what to count depending on nCall
259:
260: if (status != null) {
261: status.methodEntryExitCallTime[nCall] = minTimePerMethodEntryExitCallInCounts;
262: status.methodEntryExitInnerTime[nCall] = innerTimeInCounts;
263: status.methodEntryExitOuterTime[nCall] = outerTimeInCounts;
264: }
265: }
266:
267: //deviation /= nDevSamples; System.out.println("**! deviation = " + deviation);
268:
269: //if (printResults) { // For information purposes only
270: // measureUnsuccessfulMethodEntryExitCalls();
271: // measureSuccessfulMethodEntryExitCallsCalledFromInterpreted();
272: //}
273: nCall = -1;
274: measureSampledMethodEntryExitCalls(); // Again a warmup run
275: nCall = 0;
276: measureSampledMethodEntryExitCalls();
277:
278: if (status != null) {
279: status.methodEntryExitCallTime[4] = minTimePerMethodEntryExitCallInCounts;
280: status.methodEntryExitInnerTime[4] = innerTimeInCounts;
281: status.methodEntryExitOuterTime[4] = outerTimeInCounts;
282: }
283:
284: measureCodeRegionCalls();
285:
286: printResults("----------------------------------------------------------\n"); // NOI18N
287:
288: buf = null;
289: ProfilerRuntimeCPUCodeRegion.setCPUResBufSize(0);
290: ThreadInfo.setDefaultEvBufParams();
291: ProfilerRuntime.resetProfilerCollectors(INSTR_RECURSIVE_FULL);
292: ProfilerRuntime
293: .resetProfilerCollectors(INSTR_RECURSIVE_SAMPLED);
294: }
295:
296: static InternalStatsResponse getInternalStats() {
297: InternalStatsResponse r = new InternalStatsResponse();
298: r.nTotalInstrMethods = ProfilerInterface.nTotalInstrMethods;
299: r.nClassLoads = ProfilerInterface.nClassLoads;
300: r.nFirstMethodInvocations = ProfilerInterface.nFirstMethodInvocations;
301: r.nNonEmptyInstrMethodGroupResponses = ProfilerInterface.nNonEmptyInstrMethodGroupResponses;
302: r.nEmptyInstrMethodGroupResponses = ProfilerInterface.nEmptyInstrMethodGroupResponses;
303: r.nSingleMethodInstrMethodGroupResponses = ProfilerInterface.nSingleMethodInstrMethodGroupResponses;
304:
305: long cntsInSec = Timers.getNoOfCountsInSecond();
306: r.clientInstrTime = (((double) ProfilerInterface.clientInstrTime) * 1000)
307: / cntsInSec;
308: r.clientDataProcTime = (((double) ProfilerInterface.clientDataProcTime) * 1000)
309: / cntsInSec;
310:
311: if (r.nNonEmptyInstrMethodGroupResponses > 0) {
312: r.totalHotswappingTime = (((double) ProfilerInterface.totalHotswappingTime) * 1000)
313: / cntsInSec;
314: r.averageHotswappingTime = ((((double) ProfilerInterface.totalHotswappingTime) * 1000)
315: / cntsInSec / ProfilerInterface.nNonEmptyInstrMethodGroupResponses);
316: r.minHotswappingTime = (((double) ProfilerInterface.minHotswappingTime) * 1000)
317: / cntsInSec;
318: r.maxHotswappingTime = (((double) ProfilerInterface.maxHotswappingTime) * 1000)
319: / cntsInSec;
320: }
321:
322: r.methodEntryExitCallTime0 = (((double) status.methodEntryExitCallTime[0]) * 1000000)
323: / cntsInSec; // Expressed in microseconds
324: r.methodEntryExitCallTime1 = (((double) status.methodEntryExitCallTime[1]) * 1000000)
325: / cntsInSec; // Ditto
326: r.methodEntryExitCallTime2 = (((double) status.methodEntryExitCallTime[2]) * 1000000)
327: / cntsInSec; // Expressed in microseconds
328:
329: return r;
330: }
331:
332: static void resetInternalStatsCollectors() {
333: ProfilerInterface.totalHotswappingTime = 0;
334: ProfilerInterface.clientInstrTime = 0;
335: ProfilerInterface.clientDataProcTime = 0;
336: }
337:
338: private static void measureCodeRegionCalls() {
339: printResults("\n" + REGION_TIME_MSG); // NOI18N
340: ProfilerRuntimeCPUCodeRegion.setCPUResBufSize(100);
341: ProfilerRuntimeCPUCodeRegion.resetProfilerCollectors();
342:
343: int noOfInnerIterations = 50;
344:
345: for (int i = 0; i < 50; i++) {
346: long time = Timers.getCurrentTimeInCounts();
347:
348: for (int j = 0; j < noOfInnerIterations; j++) {
349: ProfilerRuntimeCPUCodeRegion.codeRegionEntry();
350: ProfilerRuntimeCPUCodeRegion.codeRegionExit();
351: ProfilerRuntimeCPUCodeRegion.codeRegionEntry();
352: ProfilerRuntimeCPUCodeRegion.codeRegionExit();
353: }
354:
355: time = Timers.getCurrentTimeInCounts() - time;
356:
357: if (printResults && ((i % 5) == 0)) {
358: double timeInCounts = (double) time
359: / (noOfInnerIterations * 2);
360: double timePerMethodInMCS = (((double) time * 1000000)
361: / cntInSecond / (noOfInnerIterations * 2));
362: printResults(MessageFormat.format(TIME_COUNTS_MCS_MSG,
363: new Object[] { "" + timeInCounts,
364: "" + timePerMethodInMCS })); // NOI18N
365: }
366: }
367: }
368:
369: private static void measureMethodEntryExitCalls() {
370: boolean absolute = false;
371: boolean threadCPU = false;
372:
373: switch (nCall) {
374: case -1:
375: case 0:
376: absolute = true;
377: threadCPU = false;
378:
379: break;
380: case 1:
381: absolute = false;
382: threadCPU = true;
383:
384: break;
385: case 2:
386: case 3:
387: absolute = true;
388: threadCPU = true;
389:
390: break;
391: }
392:
393: printResults("\n"
394: + MessageFormat.format(TIME_SUCCESS_PAIRS_MSG,
395: new Object[] { "" + absolute, "" + threadCPU })); // NOI18N
396:
397: ProfilerRuntimeCPU.setTimerTypes(absolute, threadCPU);
398:
399: // NOTE: this is, unfortunately, simply an experimentally determined number of iterations, that makes HotSpot fully inline
400: // the call when the server compiler is used. It would certainly be better to make this algorithm more adaptive, since
401: // this way it is likely to be quite sensitive to VM changes... I have also observed that for some reason on the server
402: // compiler on Windows, even after the warmup run, i.e. on nCall == 0, the measured call time does not achieve its lowest
403: // value until noOfOuterIterations is close to 200. On nCall == 1 etc. there does not seem to be such an issue. I can't
404: // explain this phenomenon yet.
405: int noOfOuterIterations = 300;
406: int noOfInnerIterations = 200;
407: int innerIterationBufferSize = (ThreadInfo.MAX_EVENT_SIZE
408: * ((noOfInnerIterations * 4) + 2) * 5) / 4;
409: ThreadInfo ti = ThreadInfo.getThreadInfo();
410:
411: // Buffer size is calculated as "required" * 5/4, which is a "safety margin"
412: if (nCall == -1) {
413: buf = new byte[2 * innerIterationBufferSize];
414: }
415:
416: ti.setEvBuf(buf);
417: ProfilerRuntime.eventBuffer = buf;
418: ProfilerRuntime.globalEvBufPosThreshold = buf.length; // To prevent event buffer dump triggering
419:
420: if (nCall != 3) { // On the last call to this method, we just calculate the new value from the same array contents
421: minTimePerMethodEntryExitCallInMCS = 100000.0;
422: minTimePerMethodEntryExitCallInCounts = 1000000;
423: cycleWhenMinResultDetected = 1;
424:
425: for (int i = 0; i < noOfOuterIterations; i++) {
426: ti.evBufPos = ((cycleWhenMinResultDetected + 1) % 2)
427: * innerIterationBufferSize;
428: ProfilerRuntimeCPUFullInstr.rootMethodEntry((char) 1);
429:
430: long time = Timers.getCurrentTimeInCounts();
431:
432: for (int j = 0; j < noOfInnerIterations; j++) {
433: ProfilerRuntimeCPUFullInstr.methodEntry((char) 2);
434: ProfilerRuntimeCPUFullInstr.methodExit((char) 2);
435: ProfilerRuntimeCPUFullInstr.methodEntry((char) 3);
436: ProfilerRuntimeCPUFullInstr.methodExit((char) 3);
437: }
438:
439: time = Timers.getCurrentTimeInCounts() - time;
440: ProfilerRuntimeCPUFullInstr.methodExit((char) 1);
441:
442: double timeInCounts = (double) time
443: / (noOfInnerIterations * 2);
444: double timeInMCS = (((double) time * 1000000)
445: / cntInSecond / (noOfInnerIterations * 2));
446:
447: // Calculate the deviation
448: //if (i > 10 && !(nCall == 0 && i < (noOfOuterIterations - 100))) {
449: // deviation += (double) Math.abs(timeInCounts - minTimePerMethodEntryExitCallInCounts) / minTimePerMethodEntryExitCallInCounts;
450: // nDevSamples++;
451: //}
452: if (timeInCounts < minTimePerMethodEntryExitCallInCounts) {
453: minTimePerMethodEntryExitCallInCounts = timeInCounts;
454: minTimePerMethodEntryExitCallInMCS = timeInMCS;
455: cycleWhenMinResultDetected = ((cycleWhenMinResultDetected + 1) % 2);
456: }
457:
458: if (printResults && ((i % 5) == 0)) {
459: printResults(MessageFormat
460: .format(TIME_COUNTS_MCS_MSG, new Object[] {
461: "" + timeInCounts, "" + timeInMCS })); // NOI18N
462: }
463: }
464:
465: printResults(MessageFormat.format(MINIMUM_TIME_MSG,
466: new Object[] {
467: "" + minTimePerMethodEntryExitCallInCounts,
468: "" + minTimePerMethodEntryExitCallInMCS })); // NOI18N
469: }
470:
471: // Now calculate the ratio of time spent in the inner part of methodEntry-methodExit pair to the time
472: // spent in the outer part of this pair.
473: printResults("\n" + INNER_OUTER_TIME_MSG); // NOI18N
474:
475: if ((nCall != 1) && (nCall != 3)) {
476: // High-precision calculation of inner and outer time when really hi-res timer is used.
477: int recordSize = 1 + 2 + 7 + ((nCall >= 2) ? 7 : 0); // Event type, method id, and 1 or 2 7-byte timestamps
478: int curPos = (cycleWhenMinResultDetected * innerIterationBufferSize)
479: + (1 * recordSize);
480:
481: // Take into account that when only one timestamp per standard event is collected, ROOT_ENTRY and ROOT_EXIT
482: // still generate two timestamps
483: if (nCall < 2) {
484: curPos += 7;
485: }
486:
487: int totalCalls = noOfInnerIterations * 4;
488: long innerTime = 0;
489: long outerTime = 0;
490: long prevTimeStamp = 0;
491: boolean inner = false;
492: int prefixEls = 1 + 2 + ((nCall == 3) ? 7 : 0); // Event type, method id, possible second time stamp
493: int suffixEls = ((nCall == 2) ? 7 : 0); // Possible second time stamp
494:
495: for (int i = 0; i < totalCalls; i++) {
496: byte eventType = buf[curPos];
497:
498: // Now that the implementation is stable, there is not much need in the following checks
499: if (inner && (eventType != CommonConstants.METHOD_EXIT)) {
500: System.out.println("Problem with inner! "
501: + (int) eventType + ", curPos = " + curPos); // NOI18N
502: } else if (!inner
503: && (eventType != CommonConstants.METHOD_ENTRY)) {
504: System.out.println("Problem with outer! "
505: + (int) eventType + ", curPos = " + curPos); // NOI18N
506: }
507:
508: curPos += prefixEls; // Omit event type, method id, and, possibly, non-relevant timestamp
509:
510: long timeStamp = (((long) buf[curPos++] & 0xFF) << 48)
511: | (((long) buf[curPos++] & 0xFF) << 40)
512: | (((long) buf[curPos++] & 0xFF) << 32)
513: | (((long) buf[curPos++] & 0xFF) << 24)
514: | (((long) buf[curPos++] & 0xFF) << 16)
515: | (((long) buf[curPos++] & 0xFF) << 8)
516: | ((long) buf[curPos++] & 0xFF);
517: long time = (i > 0) ? (timeStamp - prevTimeStamp) : 0;
518:
519: if (inner) {
520: innerTime += time;
521: } else {
522: outerTime += time;
523: }
524:
525: inner = !inner;
526: prevTimeStamp = timeStamp;
527: curPos += suffixEls;
528: }
529:
530: innerTimeInCounts = ((double) innerTime) / (totalCalls / 2);
531: outerTimeInCounts = ((double) outerTime)
532: / ((totalCalls / 2) - 1);
533: } else {
534: // Both on Windows and Solaris, thread-local time is extremely low-resolution (10 ms and 1 ms),
535: // thus our standard high-precision method won't work. Rough calculation is used instead.
536: // Can we (and does it make sense to) do better?
537: innerTimeInCounts = outerTimeInCounts = minTimePerMethodEntryExitCallInCounts / 2;
538: }
539:
540: double innerTimeInMCS = ((innerTimeInCounts * 1000000) / cntInSecond);
541: double outerTimeInMCS = ((outerTimeInCounts * 1000000) / cntInSecond);
542: printResults(MessageFormat.format(INNER_TIME_MCS_MSG,
543: new Object[] { "" + innerTimeInMCS })); // NOI18N
544: printResults(MessageFormat.format(OUTER_TIME_MCS_MSG,
545: new Object[] { "" + outerTimeInMCS })); // NOI18N
546: }
547:
548: private static void measureSampledMethodEntryExitCalls() {
549: printResults("\n" + SAMPLED_TIME_MSG); // NOI18N
550: //ProfilerRuntime.resetProfilerCollectors(INSTR_RECURSIVE_SAMPLED); THIS IS NOT NEEDED - will delete our current ThreadInfo
551:
552: int noOfOuterIterations = (nCall == -1) ? 200 : 80; // Large number to make the server compiler inline everything
553: int noOfInnerIterations = 200;
554: ThreadInfo ti = ThreadInfo.getThreadInfo();
555: ti.setEvBuf(buf);
556:
557: minTimePerMethodEntryExitCallInMCS = 100000.0;
558: minTimePerMethodEntryExitCallInCounts = 1000000;
559:
560: for (int i = 0; i < noOfOuterIterations; i++) {
561: ti.evBufPos = 0;
562: ProfilerRuntimeCPUSampledInstr.rootMethodEntry((char) 1);
563:
564: long time = Timers.getCurrentTimeInCounts();
565:
566: for (int j = 0; j < noOfInnerIterations; j++) {
567: ProfilerRuntimeCPUSampledInstr.methodEntry((char) 2);
568: ProfilerRuntimeCPUSampledInstr.methodExit((char) 2);
569: ProfilerRuntimeCPUSampledInstr.methodEntry((char) 3);
570: ProfilerRuntimeCPUSampledInstr.methodExit((char) 3);
571: ProfilerRuntimeCPUSampledInstr.methodEntry((char) 2);
572: ProfilerRuntimeCPUSampledInstr.methodExit((char) 2);
573: ProfilerRuntimeCPUSampledInstr.methodEntry((char) 3);
574: ProfilerRuntimeCPUSampledInstr.methodExit((char) 3);
575: }
576:
577: time = Timers.getCurrentTimeInCounts() - time;
578: ProfilerRuntimeCPUSampledInstr.methodExit((char) 1);
579:
580: double timeInCounts = (double) time
581: / (noOfInnerIterations * 4);
582: double timeInMCS = (((double) time * 1000000) / cntInSecond / (noOfInnerIterations * 4));
583:
584: if (timeInCounts < minTimePerMethodEntryExitCallInCounts) {
585: minTimePerMethodEntryExitCallInCounts = timeInCounts;
586: minTimePerMethodEntryExitCallInMCS = timeInMCS;
587: }
588:
589: if (printResults && ((i % 5) == 0)) {
590: System.out.println(MessageFormat.format(
591: TIME_COUNTS_MCS_MSG, new Object[] {
592: "" + timeInCounts, "" + timeInMCS })); // NOI18N
593: }
594: }
595:
596: innerTimeInCounts = outerTimeInCounts = minTimePerMethodEntryExitCallInCounts / 2;
597: }
598:
599: private static void measureTimerCall(boolean absolute) {
600: if (absolute) {
601: printResults(TIME_getCurrentTimeInCounts_MSG); // NOI18N
602: } else {
603: printResults(TIME_getThreadCPUTimeInNanos_MSG); // NOI18N
604: }
605:
606: int noOfInnerIterations = 1000;
607: long res;
608:
609: for (int i = 0; i < 50; i++) {
610: long time = Timers.getCurrentTimeInCounts();
611:
612: for (int j = 0; j < noOfInnerIterations; j++) {
613: if (absolute) {
614: res = Timers.getCurrentTimeInCounts();
615: } else {
616: res = Timers.getThreadCPUTimeInNanos();
617: }
618: }
619:
620: time = Timers.getCurrentTimeInCounts() - time;
621:
622: if (printResults && ((i % 5) == 0)) {
623: double timeInCounts = (double) time
624: / (noOfInnerIterations + 2);
625: double timePerMethodInMCS = (((double) time * 1000000)
626: / cntInSecond / (noOfInnerIterations + 2));
627: printResults(MessageFormat.format(TIME_COUNTS_MCS_MSG,
628: new Object[] { "" + timeInCounts,
629: "" + timePerMethodInMCS })); // NOI18N
630: }
631: }
632: }
633:
634: private static void printResults(String str) {
635: if (printResults) {
636: System.out.println(str);
637: }
638: }
639:
640: /** The following two methods can be used for info purposes if needed */
641: /*private static void measureUnsuccessfulMethodEntryExitCalls() {
642: printResults("\nTime per each unsuccessful methodEntry()/methodExit() pair of calls");
643: ProfilerRuntime.resetProfilerCollectors(INSTR_RECURSIVE);
644: int noOfInnerIterations = 50;
645: for (int i = 0; i < 15; i++) {
646: long time = Timers.getCurrentTimeInCounts();
647: for (int j = 0; j < noOfInnerIterations; j++) {
648: ProfilerRuntimeCPUFullInstr.methodEntry((char) 2);
649: ProfilerRuntimeCPUFullInstr.methodExit((char) 2);
650: ProfilerRuntimeCPUFullInstr.methodEntry((char) 3);
651: ProfilerRuntimeCPUFullInstr.methodExit((char) 3);
652: }
653: time = Timers.getCurrentTimeInCounts() - time;
654: if (printResults && i % 5 == 0) {
655: double timeInCounts = (double) time / (noOfInnerIterations * 2);
656: double timePerMethodInMCS = ((double) time * 1000000 / cntInSecond / (noOfInnerIterations * 2));
657: System.out.println(timeInCounts + " counts, " + timePerMethodInMCS + " mcs");
658: }
659: }
660: }
661: private static void measureSuccessfulMethodEntryExitCallsCalledFromInterpreted(boolean printResults) {
662: printResults("\nTime per successful methodEntry()/methodExit() pair when called from interpreted code");
663: ProfilerRuntime.resetProfilerCollectors(INSTR_RECURSIVE);
664: ProfilerRuntimeCPU.createThreadInfoForThread(Thread.currentThread());
665: int noOfInnerIterations = 50;
666: for (int i = 0; i < 15; i++) {
667: ProfilerRuntimeCPUFullInstr.rootMethodEntry((char) 1);
668: long time = Timers.getCurrentTimeInCounts();
669: for (int j = 0; j < noOfInnerIterations; j++) {
670: ProfilerRuntimeCPUFullInstr.methodEntry((char) 2);
671: ProfilerRuntimeCPUFullInstr.methodExit((char) 2);
672: ProfilerRuntimeCPUFullInstr.methodEntry((char) 3);
673: ProfilerRuntimeCPUFullInstr.methodExit((char) 3);
674: }
675: time = Timers.getCurrentTimeInCounts() - time;
676: ProfilerRuntimeCPUFullInstr.methodExit((char) 1);
677: if (printResults && i % 5 == 0) {
678: double timeInCounts = (double) time / (noOfInnerIterations * 2);
679: double timePerMethodInMCS = ((double) time * 1000000 / cntInSecond / (noOfInnerIterations * 2));
680: System.out.println(timeInCounts + " counts, " + timePerMethodInMCS + " mcs");
681: }
682: }
683: } ***/
684: }
|