0001: /*
0002: * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS HEADER.
0003: *
0004: * Copyright 1997-2007 Sun Microsystems, Inc. All rights reserved.
0005: *
0006: * The contents of this file are subject to the terms of either the GNU
0007: * General Public License Version 2 only ("GPL") or the Common
0008: * Development and Distribution License("CDDL") (collectively, the
0009: * "License"). You may not use this file except in compliance with the
0010: * License. You can obtain a copy of the License at
0011: * http://www.netbeans.org/cddl-gplv2.html
0012: * or nbbuild/licenses/CDDL-GPL-2-CP. See the License for the
0013: * specific language governing permissions and limitations under the
0014: * License. When distributing the software, include this License Header
0015: * Notice in each file and include the License file at
0016: * nbbuild/licenses/CDDL-GPL-2-CP. Sun designates this
0017: * particular file as subject to the "Classpath" exception as provided
0018: * by Sun in the GPL Version 2 section of the License file that
0019: * accompanied this code. If applicable, add the following below the
0020: * License Header, with the fields enclosed by brackets [] replaced by
0021: * your own identifying information:
0022: * "Portions Copyrighted [year] [name of copyright owner]"
0023: *
0024: * Contributor(s):
0025: * The Original Software is NetBeans. The Initial Developer of the Original
0026: * Software is Sun Microsystems, Inc. Portions Copyright 1997-2006 Sun
0027: * Microsystems, Inc. All Rights Reserved.
0028: *
0029: * If you wish your version of this file to be governed by only the CDDL
0030: * or only the GPL Version 2, indicate your decision by adding
0031: * "[Contributor] elects to include this software in this distribution
0032: * under the [CDDL or GPL Version 2] license." If you do not indicate a
0033: * single choice of license, a recipient has the option to distribute
0034: * your version of this file under either the CDDL, the GPL Version 2 or
0035: * to extend the choice of license to its licensees as provided above.
0036: * However, if you add GPL Version 2 code and therefore, elected the GPL
0037: * Version 2 license, then the option applies only if the new code is
0038: * made subject to such option by the copyright holder.
0039: */
0040:
0041: package org.netbeans.lib.profiler.results.cpu;
0042:
0043: import org.netbeans.lib.profiler.ProfilerClient;
0044: import org.netbeans.lib.profiler.TargetAppRunner;
0045: import org.netbeans.lib.profiler.client.ProfilingPointsProcessor;
0046: import org.netbeans.lib.profiler.global.CommonConstants;
0047: import org.netbeans.lib.profiler.global.InstrumentationFilter;
0048: import org.netbeans.lib.profiler.global.TransactionalSupport;
0049: import org.netbeans.lib.profiler.results.BaseCallGraphBuilder;
0050: import org.netbeans.lib.profiler.results.RuntimeCCTNode;
0051: import org.netbeans.lib.profiler.results.cpu.cct.CPUCCTNodeFactory;
0052: import org.netbeans.lib.profiler.results.cpu.cct.RuntimeCPUCCTNodeVisitorAdaptor;
0053: import org.netbeans.lib.profiler.results.cpu.cct.nodes.CategoryCPUCCTNode;
0054: import org.netbeans.lib.profiler.results.cpu.cct.nodes.MethodCPUCCTNode;
0055: import org.netbeans.lib.profiler.results.cpu.cct.nodes.RuntimeCPUCCTNode;
0056: import org.netbeans.lib.profiler.results.cpu.cct.nodes.ServletRequestCPUCCTNode;
0057: import org.netbeans.lib.profiler.results.cpu.cct.nodes.SimpleCPUCCTNode;
0058: import org.netbeans.lib.profiler.results.cpu.cct.nodes.ThreadCPUCCTNode;
0059: import org.netbeans.lib.profiler.results.cpu.cct.nodes.TimedCPUCCTNode;
0060: import org.netbeans.lib.profiler.results.cpu.marking.Mark;
0061: import org.netbeans.lib.profiler.results.cpu.marking.MarkingEngine;
0062: import java.util.ArrayList;
0063: import java.util.List;
0064: import java.util.logging.Level;
0065:
0066: /**
0067: * @author Tomas Hurka
0068: * @author Misha Dmitriev
0069: * @author Jaroslav Bachorik
0070: */
0071: public class CPUCallGraphBuilder extends BaseCallGraphBuilder implements
0072: CPUProfilingResultListener, CPUCCTProvider {
0073: //~ Inner Classes ------------------------------------------------------------------------------------------------------------
0074:
0075: // -------------------------------------- Thread representation class -------------------------------------------
0076: static class ThreadInfo {
0077: //~ Static fields/initializers -------------------------------------------------------------------------------------------
0078:
0079: // The following variable is used to record the "compensation" value, a difference between the timestamp at the
0080: // moment user hits "get results" and the timestamp for the method entry into the top stack method. To present
0081: // results consistenly, we add this value to the TimedCPUCCTNode for the top-stack method. However, when
0082: // processing of data is resumed, we need to subtract this value back from that node.
0083: // this is effectively the self time for the last invocation of the top method on stack - if we would not keep
0084: // it separately, it would not be reported
0085: // private long diffAtGetResultsMoment; // diff between last methodEntry and current moment timestamp -
0086: // we will have to compensate for the processing time
0087: static ThreadInfo[] threadInfos;
0088: static String[] threadNames;
0089: static String[] threadClassNames; // Used just for user presentation
0090: static int threadInfosLastIdx;
0091: private static TransactionalSupport transaction = new TransactionalSupport();
0092:
0093: static {
0094: reset();
0095: }
0096:
0097: //~ Instance fields ------------------------------------------------------------------------------------------------------
0098:
0099: TimedCPUCCTNode[] stack; // Simulated stack for this thread - stack starting at root method
0100: // (or a pseudo node if multiple root methods are called within the thread)
0101: int inRoot; // flag indicating this thread is in a root method initiated code
0102: int stackTopIdx; // Index of the stack top element
0103: final int threadId;
0104: TimedCPUCCTNode comboNodeDst;
0105: TimedCPUCCTNode comboNodeSrc;
0106: int totalNNodes; // total number of call tree nodes for this thread
0107: long lastCallIndex = -1;
0108: long rootGrossTimeAbs;
0109: long rootGrossTimeThreadCPU; // Accumulated absolute and thread CPU gross time for the root method
0110: // - blackout data subtracted, calibration data not
0111: long rootMethodEntryTimeAbs;
0112: long rootMethodEntryTimeThreadCPU; // Absoute and thread CPU entry timestamps for the root method.
0113:
0114: // The xxx0 part is used when only absolute or thread CPU time data is collected.
0115: // Both xxx0 and xx1 parts are used when both timestamps are collected.
0116: long topMethodEntryTime0;
0117: long topMethodEntryTime1; // Entry (or "re-entry" upon return from the callee) time for the topmost method
0118: long totalNInv; // total number of invocations within the entire call tree for this thread
0119:
0120: //~ Constructors ---------------------------------------------------------------------------------------------------------
0121:
0122: /**
0123: * See the comment to diffAtGetResultsMoment field
0124: */
0125:
0126: // private void applyDiffAtGetResultsMoment() {
0127: // commented out - see issue http://www.netbeans.org/issues/show_bug.cgi?id=67197
0128: /* if (stackTopIdx == -1 || (stack[0].methodId == 0 && stackTopIdx == 0)) {
0129: return;
0130: }
0131: // We are executing the top-stack method, possibly for long time.
0132: // Add a time and +1 invocation??? for it to the call graph
0133: long time0 = status.dumpAbsTimeStamp;
0134: System.err.println("Apply diff at get results time0: "+time0);
0135: System.err.println("Apply diff at get results last methodEntry: "+stack[stackTopIdx].netTime0);
0136: if (time0 > topMethodEntryTime0) {
0137: long diffInCounts = time0 - topMethodEntryTime0;
0138: if (stack[stackTopIdx].lastSleepOrWaitTimeStamp == 0) {
0139: // the top method on stack was running at the get results time, add the diff to the real time
0140: stack[stackTopIdx].netTime0 += diffInCounts;
0141: System.err.println("Apply diff netTime0");
0142: } else {
0143: // the top method on stack was waiting at the get results time, add the diff to the wait time
0144: stack[stackTopIdx].waitTime0 += diffInCounts;
0145: System.err.println("Apply diff waitTime0");
0146: }
0147: diffAtGetResultsMoment = diffInCounts;
0148: System.err.println("Apply diff at get results diffInCounts: "+diffInCounts);
0149: } */
0150:
0151: // }
0152: /**
0153: * See the comment to diffAtGetResultsMoment field. When we resume data processing for the given thread,
0154: * we need to undo the effect of diffAtGetResultsMoment.
0155: */
0156:
0157: // private static synchronized void undoDiffAtGetResultsMomentForAllThreads() {
0158: // commented out - see issue http://www.netbeans.org/issues/show_bug.cgi?id=67197
0159: /* if (threadInfos == null) {
0160: return;
0161: }
0162: for (int i = 0; i < threadInfos.length; i++) {
0163: ThreadInfo ti = threadInfos[i];
0164: if (ti == null || ti.stackTopIdx == -1) {
0165: continue;
0166: }
0167: if (ti.stack[ti.stackTopIdx].lastSleepOrWaitTimeStamp == 0) {
0168: ti.stack[ti.stackTopIdx].netTime0 -= ti.diffAtGetResultsMoment;
0169: } else {
0170: ti.stack[ti.stackTopIdx].waitTime0 -= ti.diffAtGetResultsMoment;
0171: }
0172: ti.diffAtGetResultsMoment = 0;
0173: }*/
0174:
0175: // }
0176: private ThreadInfo(int threadId) {
0177: stack = new TimedCPUCCTNode[40];
0178: stackTopIdx = -1;
0179: inRoot = 0;
0180: this .threadId = threadId;
0181: }
0182:
0183: //~ Methods --------------------------------------------------------------------------------------------------------------
0184:
0185: static boolean isEmpty() {
0186: if ((threadInfos == null) || (threadInfos.length == 0)) {
0187: return true;
0188: }
0189:
0190: for (int i = 0; i < threadInfos.length; i++) {
0191: if ((threadInfos[i] != null)
0192: && (threadInfos[i].stack != null)
0193: && (threadInfos[i].stack[0] != null)
0194: && (threadInfos[i].stack[0].getChildren() != null)
0195: && (threadInfos[i].stack[0].getChildren()
0196: .size() > 0)) {
0197: return false;
0198: }
0199: }
0200:
0201: return true;
0202: }
0203:
0204: /**
0205: * Synchronization in this and previous method is to avoid counting semi-initialized threads when the user
0206: * clicks "Get results" and the summary info about all tracked threads is calculated.
0207: */
0208: static synchronized String[] getThreadNames() {
0209: return threadNames;
0210: }
0211:
0212: static void beginTrans(boolean mutable) {
0213: transaction.beginTrans(mutable);
0214: }
0215:
0216: static boolean beginTrans(boolean mutable, boolean failEarly) {
0217: return transaction.beginTrans(mutable, failEarly);
0218: }
0219:
0220: static void endTrans() {
0221: transaction.endTrans();
0222: }
0223:
0224: static synchronized void newThreadInfo(int threadId,
0225: String threadName, String threadClassName) {
0226: if ((threadId > threadInfosLastIdx)
0227: || (threadInfos == null)) {
0228: int newLen = threadId + 1;
0229: ThreadInfo[] newInfos = new ThreadInfo[newLen];
0230: String[] newNames = new String[newLen];
0231: String[] newClassNames = new String[newLen];
0232:
0233: if (threadInfos != null) {
0234: System.arraycopy(threadInfos, 0, newInfos, 0,
0235: threadInfos.length);
0236: System.arraycopy(threadNames, 0, newNames, 0,
0237: threadNames.length);
0238: System.arraycopy(threadClassNames, 0,
0239: newClassNames, 0, threadNames.length);
0240: }
0241:
0242: threadInfos = newInfos;
0243: threadNames = newNames;
0244: threadClassNames = newClassNames;
0245: threadInfosLastIdx = threadId;
0246: }
0247:
0248: threadInfos[threadId] = new ThreadInfo(threadId);
0249: threadNames[threadId] = threadName;
0250: threadClassNames[threadId] = threadClassName;
0251: }
0252:
0253: static void reset() {
0254: beginTrans(true);
0255:
0256: try {
0257: threadInfos = null;
0258: threadNames = null;
0259: threadInfosLastIdx = -1;
0260: } finally {
0261: endTrans();
0262: }
0263: }
0264:
0265: boolean isInRoot() {
0266: return inRoot > 0;
0267: }
0268:
0269: TimedCPUCCTNode peek() {
0270: synchronized (stack) {
0271: return (stackTopIdx > -1) ? stack[stackTopIdx] : null;
0272: }
0273: }
0274:
0275: TimedCPUCCTNode pop() {
0276: TimedCPUCCTNode node = null;
0277:
0278: synchronized (stack) {
0279: if (stackTopIdx >= 0) {
0280: node = stack[stackTopIdx];
0281: stack[stackTopIdx] = null;
0282: stackTopIdx--;
0283: }
0284:
0285: return node;
0286: }
0287: }
0288:
0289: void push(TimedCPUCCTNode node) {
0290: synchronized (stack) {
0291: stackTopIdx++;
0292:
0293: if (stackTopIdx >= stack.length) {
0294: increaseStack();
0295: }
0296:
0297: stack[stackTopIdx] = node;
0298: node.addNCalls(1);
0299: totalNInv++;
0300: }
0301: }
0302:
0303: private void increaseStack() {
0304: TimedCPUCCTNode[] newStack = new TimedCPUCCTNode[stack.length * 2];
0305: System.arraycopy(stack, 0, newStack, 0, stack.length);
0306: stack = newStack;
0307: }
0308: }
0309:
0310: private class DebugInfoCollector extends
0311: RuntimeCPUCCTNodeVisitorAdaptor {
0312: //~ Instance fields ------------------------------------------------------------------------------------------------------
0313:
0314: private StringBuffer buffer = new StringBuffer();
0315:
0316: //~ Constructors ---------------------------------------------------------------------------------------------------------
0317:
0318: public DebugInfoCollector() {
0319: }
0320:
0321: //~ Methods --------------------------------------------------------------------------------------------------------------
0322:
0323: public StringBuffer getBuffer() {
0324: return buffer;
0325: }
0326:
0327: public synchronized String getInfo(RuntimeCPUCCTNode node) {
0328: buffer = new StringBuffer();
0329: node.accept(this );
0330:
0331: return buffer.toString();
0332: }
0333:
0334: public void visit(MethodCPUCCTNode node) {
0335: buffer.append(debugMethod(node.getMethodId()));
0336: }
0337:
0338: public void visit(ServletRequestCPUCCTNode node) {
0339: buffer.append("Boundary"); // NOI18N
0340: }
0341:
0342: public void visit(ThreadCPUCCTNode node) {
0343: buffer.append("threadId = ").append(node.getThreadId()); // NOI18N
0344: }
0345:
0346: public void visit(CategoryCPUCCTNode node) {
0347: buffer.append("Category ").append(node.getMark()); // NOI18N
0348: }
0349:
0350: public void visit(SimpleCPUCCTNode node) {
0351: }
0352: }
0353:
0354: //~ Instance fields ----------------------------------------------------------------------------------------------------------
0355:
0356: private CPUCCTNodeFactory factory;
0357: private DebugInfoCollector debugCollector = null;
0358: private InstrumentationFilter instrFilter;
0359: private boolean stackIntegrityViolationReported;
0360: private long delta;
0361:
0362: //~ Methods ------------------------------------------------------------------------------------------------------------------
0363:
0364: public CPUCCTContainer[] createPresentationCCTs(
0365: CPUResultsSnapshot cpuSnapshot) {
0366: ThreadInfo.beginTrans(false);
0367:
0368: try {
0369: // process the ThreadInfo data structure to create a CCT presentation
0370: String[] threadNames = ThreadInfo.getThreadNames();
0371:
0372: // There is a chance that the data has not been initialized yet
0373: if (threadNames == null) {
0374: return null;
0375: }
0376:
0377: int len = threadNames.length;
0378:
0379: if (len == 0) {
0380: return null;
0381: }
0382:
0383: List ccts = new ArrayList(len);
0384:
0385: int threadId = 0;
0386:
0387: for (int i = 0; i < len; i++) {
0388: ThreadInfo ti = ThreadInfo.threadInfos[i];
0389:
0390: if ((ti == null) || (ti.stack[0] == null)) {
0391: continue; // Can happen if thread just created, but nothing has been executed on its behalf yet
0392: }
0393:
0394: // Fix the problem with inconsistent thread times that otherwise will occur for e.g. threads sitting in wait()
0395: // for long enough time when "get results" is pressed
0396: /* not in use any longer
0397: ti.applyDiffAtGetResultsMoment();
0398: */
0399: double[] activeTimes = calculateThreadActiveTimes(ti);
0400:
0401: TimedCPUCCTNode rootNode = ti.stack[0];
0402:
0403: CPUCCTContainer cct = new CPUCCTContainer(rootNode,
0404: cpuSnapshot, status, instrFilter,
0405: ti.totalNNodes, activeTimes, threadId++,
0406: threadNames[i]);
0407:
0408: if ((cct.rootNode != null)
0409: && (cct.rootNode.getNChildren() > 0)) {
0410: ccts.add(cct);
0411: }
0412: }
0413:
0414: return (CPUCCTContainer[]) ccts
0415: .toArray(new CPUCCTContainer[ccts.size()]);
0416: } finally {
0417: ThreadInfo.endTrans();
0418: }
0419: }
0420:
0421: public void methodEntry(final int methodId, final int threadId,
0422: final int methodType, final long timeStamp0,
0423: final long timeStamp1) {
0424: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0425: return;
0426: }
0427:
0428: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0429:
0430: if (ti == null) {
0431: return;
0432: }
0433:
0434: switch (methodType) {
0435: case METHODTYPE_NORMAL: {
0436: plainMethodEntry(methodId, ti, timeStamp0, timeStamp1);
0437:
0438: break;
0439: }
0440: case METHODTYPE_ROOT: {
0441: rootMethodEntry(methodId, ti, timeStamp0, timeStamp1);
0442:
0443: break;
0444: }
0445: case METHODTYPE_MARKER: {
0446: markerMethodEntry(methodId, ti, timeStamp0, timeStamp1);
0447:
0448: break;
0449: }
0450: }
0451:
0452: batchNotEmpty = true;
0453: }
0454:
0455: public void methodEntryUnstamped(final int methodId,
0456: final int threadId, final int methodType) {
0457: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0458: return;
0459: }
0460:
0461: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0462:
0463: if (ti == null) {
0464: return;
0465: }
0466:
0467: switch (methodType) {
0468: case METHODTYPE_NORMAL: {
0469: plainMethodEntry(methodId, ti);
0470:
0471: break;
0472: }
0473: case METHODTYPE_MARKER: {
0474: markerMethodEntry(methodId, ti);
0475:
0476: break;
0477: }
0478: }
0479:
0480: batchNotEmpty = true;
0481: }
0482:
0483: public void methodExit(final int methodId, final int threadId,
0484: final int methodType, final long timeStamp0,
0485: final long timeStamp1) {
0486: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0487: return;
0488: }
0489:
0490: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0491:
0492: if (ti == null) {
0493: return;
0494: }
0495:
0496: TimedCPUCCTNode oldNode = null;
0497:
0498: switch (methodType) {
0499: case METHODTYPE_MARKER:
0500: case METHODTYPE_NORMAL: {
0501: oldNode = plainMethodExit(methodId, ti, timeStamp0,
0502: timeStamp1);
0503:
0504: break;
0505: }
0506: case METHODTYPE_ROOT: {
0507: oldNode = rootMethodExit(methodId, ti, timeStamp0,
0508: timeStamp1);
0509:
0510: break;
0511: }
0512: }
0513:
0514: if (oldNode != null) {
0515: TimedCPUCCTNode oneMoreNode = ti.peek();
0516:
0517: // category must go with a method node; so close them together
0518: if ((oneMoreNode != null)
0519: && (oneMoreNode instanceof CategoryCPUCCTNode || oneMoreNode instanceof ServletRequestCPUCCTNode)) {
0520: // oneMoreNode.addNCalls(oldNode.getNCalls());
0521: // oneMoreNode.addNetTime0(oldNode.getNetTime0());
0522: // oneMoreNode.addNetTime1(oldNode.getNetTime1());
0523: // oneMoreNode.addSleepTime0(oldNode.getSleepTime0());
0524: // oneMoreNode.addWaitTime0(oldNode.getWaitTime0());
0525: ti.pop();
0526: }
0527: }
0528:
0529: batchNotEmpty = true;
0530: }
0531:
0532: public void methodExitUnstamped(final int methodId,
0533: final int threadId, final int methodType) {
0534: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0535: return;
0536: }
0537:
0538: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0539:
0540: if (ti == null) {
0541: return;
0542: }
0543:
0544: TimedCPUCCTNode oldNode = null;
0545:
0546: switch (methodType) {
0547: case METHODTYPE_MARKER:
0548: case METHODTYPE_NORMAL: {
0549: oldNode = plainMethodExit(methodId, ti);
0550:
0551: break;
0552: }
0553: }
0554:
0555: if (oldNode != null) {
0556: TimedCPUCCTNode oneMoreNode = ti.peek();
0557:
0558: // category must go with a method node; so close them together
0559: if ((oneMoreNode != null)
0560: && (oneMoreNode instanceof CategoryCPUCCTNode || oneMoreNode instanceof ServletRequestCPUCCTNode)) {
0561: // oneMoreNode.addNCalls(oldNode.getNCalls());
0562: // oneMoreNode.addNetTime0(oldNode.getNetTime0());
0563: // oneMoreNode.addNetTime1(oldNode.getNetTime1());
0564: // oneMoreNode.addSleepTime0(oldNode.getSleepTime0());
0565: // oneMoreNode.addWaitTime0(oldNode.getWaitTime0());
0566: ti.pop();
0567: }
0568: }
0569:
0570: batchNotEmpty = true;
0571: }
0572:
0573: public void monitorEntry(final int threadId, final long timeStamp0,
0574: final long timeStamp1) {
0575: waitEntry(threadId, timeStamp0, timeStamp1);
0576: batchNotEmpty = true;
0577: }
0578:
0579: public void monitorExit(final int threadId, final long timeStamp0,
0580: final long timeStamp1) {
0581: waitEntry(threadId, timeStamp0, timeStamp1);
0582: batchNotEmpty = true;
0583: }
0584:
0585: public void newThread(final int threadId, final String threadName,
0586: final String threadClassName) {
0587: if (!isReady()) {
0588: return;
0589: }
0590:
0591: LOGGER.finest("New thread creation for thread id = " + threadId // NOI18N
0592: + ", name = " + threadName // NOI18N
0593: );
0594:
0595: ThreadInfo.newThreadInfo(threadId, threadName, threadClassName);
0596: batchNotEmpty = true;
0597: }
0598:
0599: public void servletRequest(final int threadId,
0600: final int requestType, final String servletPath,
0601: final int sessionId) {
0602: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0603:
0604: if (ti == null) {
0605: return;
0606: }
0607:
0608: TimedCPUCCTNode curNode = ti.peek();
0609:
0610: if (curNode == null) {
0611: curNode = factory.createThreadNode(threadId);
0612: ti.totalNNodes++;
0613: ti.push(curNode);
0614: ti.totalNInv--;
0615: }
0616:
0617: ServletRequestCPUCCTNode servletNode = ServletRequestCPUCCTNode.Locator
0618: .locate(requestType, servletPath, curNode.getChildren());
0619:
0620: if (servletNode == null) {
0621: servletNode = factory.createServletRequestNode(requestType,
0622: servletPath);
0623: curNode.attachNodeAsChild(servletNode);
0624: }
0625:
0626: ti.push(servletNode);
0627: }
0628:
0629: public void sleepEntry(final int threadId, long timeStamp0,
0630: long timeStamp1) {
0631: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0632: return;
0633: }
0634:
0635: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0636: TimedCPUCCTNode curNode = ti.stack[ti.stackTopIdx];
0637:
0638: if (LOGGER.isLoggable(Level.FINEST)) {
0639: LOGGER.finest("ENTRY SLEEP: " + debugNode(curNode) // NOI18N
0640: + ", time: " + timeStamp0 // NOI18N
0641: + ", delta: " + (timeStamp0 - delta) // NOI18N
0642: + ", ti: " + ti // NOI18N
0643: );
0644: delta = timeStamp0;
0645: }
0646:
0647: long diff = timeStamp0 - ti.topMethodEntryTime0;
0648:
0649: if (diff > 0) {
0650: curNode.addNetTime0(diff);
0651: } else {
0652: timeStamp0 = ti.topMethodEntryTime0;
0653: }
0654:
0655: ti.topMethodEntryTime0 = timeStamp0;
0656:
0657: curNode.setLastWaitOrSleepStamp(timeStamp0);
0658: batchNotEmpty = true;
0659: }
0660:
0661: public void sleepExit(final int threadId, final long timeStamp0,
0662: final long timeStamp1) {
0663: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0664: return;
0665: }
0666:
0667: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0668: TimedCPUCCTNode curNode = ti.stack[ti.stackTopIdx];
0669:
0670: long lastSleep = timeStamp0 - curNode.getLastWaitOrSleepStamp();
0671:
0672: if (LOGGER.isLoggable(Level.FINEST)) {
0673: LOGGER.finest("EXIT SLEEP: " + debugNode(curNode) // NOI18N
0674: + ", time: " + timeStamp0 // NOI18N
0675: + ", delta: " + (timeStamp0 - delta) // NOI18N
0676: + ", slept: " + lastSleep // NOI18N
0677: + ", ti: " + ti // NOI18N
0678: );
0679: delta = timeStamp0;
0680: lastSleep = 0;
0681: }
0682:
0683: curNode.setLastWaitOrSleepStamp(0);
0684: curNode.addSleepTime0(lastSleep);
0685:
0686: // move start timer for current method, so that the time spent sleeping is ignored
0687: if ((timeStamp0 - ti.topMethodEntryTime0) > 0) {
0688: ti.topMethodEntryTime0 = timeStamp0;
0689: }
0690:
0691: batchNotEmpty = true;
0692: }
0693:
0694: public void threadsResume(final long timeStamp0,
0695: final long timeStamp1) {
0696: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0697: return;
0698: }
0699:
0700: ThreadInfo[] tis = ThreadInfo.threadInfos;
0701:
0702: for (int i = 0; i < tis.length; i++) {
0703: ThreadInfo ti = tis[i];
0704:
0705: if ((ti == null) || (ti.stackTopIdx < 0)) {
0706: continue;
0707: }
0708:
0709: ti.topMethodEntryTime0 = timeStamp0;
0710:
0711: if (status.collectingTwoTimeStamps()) {
0712: ti.topMethodEntryTime1 = timeStamp1;
0713: }
0714:
0715: if (status.collectingTwoTimeStamps()) {
0716: ti.rootMethodEntryTimeAbs = timeStamp0;
0717: ti.rootMethodEntryTimeThreadCPU = timeStamp1;
0718: } else {
0719: ti.rootMethodEntryTimeAbs = timeStamp0;
0720:
0721: // rootMethodEntryTimeThreadCPU can remain the same - thread was suspended and time wasn't increasing
0722: }
0723: }
0724:
0725: batchNotEmpty = true;
0726: }
0727:
0728: public void threadsSuspend(final long timeStamp0,
0729: final long timeStamp1) {
0730: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0731: return;
0732: }
0733:
0734: ThreadInfo[] tis = ThreadInfo.threadInfos;
0735:
0736: for (int i = 0; i < tis.length; i++) {
0737: ThreadInfo ti = tis[i];
0738:
0739: if ((ti == null) || (ti.stackTopIdx < 0)) {
0740: continue;
0741: }
0742:
0743: TimedCPUCCTNode curNode = ti.stack[ti.stackTopIdx];
0744:
0745: long diff = timeStamp0 - ti.topMethodEntryTime0;
0746:
0747: if (diff > 0) {
0748: curNode.addNetTime0(diff);
0749: }
0750:
0751: if (status.collectingTwoTimeStamps()) {
0752: ti.rootGrossTimeAbs += (timeStamp0 - ti.rootMethodEntryTimeAbs);
0753: diff = timeStamp1 - ti.topMethodEntryTime1;
0754:
0755: if (diff > 0) {
0756: curNode.addNetTime1(diff);
0757: }
0758:
0759: ti.rootGrossTimeThreadCPU += (timeStamp1 - ti.rootMethodEntryTimeThreadCPU);
0760: } else { // Collecting only absolute timestamps
0761: ti.rootGrossTimeAbs += (timeStamp0 - ti.rootMethodEntryTimeAbs);
0762:
0763: // Shouldn't do anything with rootGrossTimeThreadCPU, since while thread is suspended,
0764: // thread CPU time is stopped
0765: }
0766: }
0767:
0768: batchNotEmpty = true;
0769: }
0770:
0771: /**
0772: * Called when the TA is suspended waiting for the tool to process the buffer
0773: */
0774: public void timeAdjust(final int threadId, final long timeDiff0,
0775: final long timeDiff1) {
0776: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0777: return;
0778: }
0779:
0780: final ProfilingPointsProcessor ppp = TargetAppRunner
0781: .getDefault().getProfilingPointsProcessor();
0782: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0783:
0784: // In this case, time stamps are actually time adjustments.
0785: // timeStamp0 is always abosolute and timeStamp1 is always thread CPU.
0786: ti.rootMethodEntryTimeAbs += timeDiff0;
0787: ti.rootMethodEntryTimeThreadCPU += timeDiff1;
0788: ti.topMethodEntryTime0 += timeDiff0;
0789:
0790: if (status.collectingTwoTimeStamps()) {
0791: ti.topMethodEntryTime1 += timeDiff1;
0792: }
0793:
0794: afterBatchCommands.add(new Runnable() {
0795: public void run() {
0796: ppp.timeAdjust(threadId, timeDiff0, timeDiff1);
0797: }
0798: });
0799: batchNotEmpty = true;
0800: }
0801:
0802: public void waitEntry(final int threadId, long timeStamp0,
0803: long timeStamp1) {
0804: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0805: return;
0806: }
0807:
0808: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0809: TimedCPUCCTNode curNode = ti.stack[ti.stackTopIdx];
0810:
0811: if (LOGGER.isLoggable(Level.FINEST)) {
0812: LOGGER.finest("ENTRY WAIT: " + debugNode(curNode) // NOI18N
0813: + ", time: " + timeStamp0 // NOI18N
0814: + ", delta: " + (timeStamp0 - delta) // NOI18N
0815: + ", ti: " + ti // NOI18N
0816: );
0817: delta = timeStamp0;
0818: LOGGER.finest(dumpStack(ti));
0819: }
0820:
0821: long diff = timeStamp0 - ti.topMethodEntryTime0;
0822:
0823: if (diff > 0) {
0824: curNode.addNetTime0(diff);
0825: } else {
0826: timeStamp0 = ti.topMethodEntryTime0;
0827: }
0828:
0829: ti.topMethodEntryTime0 = timeStamp0;
0830:
0831: curNode.setLastWaitOrSleepStamp(timeStamp0);
0832: batchNotEmpty = true;
0833: }
0834:
0835: public void waitExit(final int threadId, final long timeStamp0,
0836: final long timeStamp1) {
0837: if (!isReady() || (ThreadInfo.threadInfos == null)) {
0838: return;
0839: }
0840:
0841: ThreadInfo ti = ThreadInfo.threadInfos[threadId];
0842: TimedCPUCCTNode curNode = ti.stack[ti.stackTopIdx];
0843:
0844: long lastWait = timeStamp0 - curNode.getLastWaitOrSleepStamp();
0845: curNode.setLastWaitOrSleepStamp(0);
0846: curNode.addWaitTime0(lastWait);
0847:
0848: if (LOGGER.isLoggable(Level.FINEST)) {
0849: LOGGER.finest("EXIT WAIT: " + debugNode(curNode) // NOI18N
0850: + ", time: " + timeStamp0 // NOI18N
0851: + ", delta: " + (timeStamp0 - delta) // NOI18N
0852: + ", waited: " + lastWait // NOI18N
0853: + ", ti: " + ti // NOI18N
0854: );
0855: delta = timeStamp0;
0856: LOGGER.finest(dumpStack(ti));
0857: }
0858:
0859: // move start timer for current method, so that the time spent waiting is ignored
0860: if ((timeStamp0 - ti.topMethodEntryTime0) > 0) {
0861: ti.topMethodEntryTime0 = timeStamp0;
0862: }
0863:
0864: batchNotEmpty = true;
0865: }
0866:
0867: /**
0868: * For each monitored thread, returns the current absolute and thread-local CPU time. Returned thread-local time
0869: * may be just -1, indicating that it can't be reliably calculated for the given thread (at this moment or at all).
0870: */
0871: protected long[][] getAllThreadsActiveTimes() {
0872: int len = ThreadInfo.getThreadNames().length;
0873: long[][] res = new long[2][len];
0874:
0875: for (int i = 0; i < len; i++) {
0876: ThreadInfo ti = ThreadInfo.threadInfos[i];
0877: double[] times = calculateThreadActiveTimes(ti);
0878:
0879: res[0][i] = (long) (((times[0] - times[2]) * 1000) / status.timerCountsInSecond[0]);
0880: res[1][i] = (times[1] != -1) ? (long) (((times[1] - times[3]) * 1000) / status.timerCountsInSecond[1])
0881: : (-1);
0882: }
0883:
0884: return res;
0885: }
0886:
0887: protected RuntimeCCTNode getAppRootNode() {
0888: if (ThreadInfo.isEmpty()) {
0889: return null;
0890: }
0891:
0892: RuntimeCPUCCTNode appNode = null;
0893:
0894: ThreadInfo.beginTrans(false);
0895:
0896: try {
0897: appNode = new SimpleCPUCCTNode(true);
0898:
0899: int len = (ThreadInfo.getThreadNames() != null) ? ThreadInfo
0900: .getThreadNames().length
0901: : 0;
0902:
0903: for (int i = 0; i < len; i++) {
0904: ThreadInfo ti = ThreadInfo.threadInfos[i];
0905:
0906: if ((ti == null) || (ti.stack[0] == null)) {
0907: continue;
0908: }
0909:
0910: appNode.attachNodeAsChild(ti.stack[0]);
0911: }
0912: } finally {
0913: ThreadInfo.endTrans();
0914: }
0915:
0916: return appNode;
0917: }
0918:
0919: //----------------------------- Calculation of supporting numeric data ---------------------------
0920:
0921: /**
0922: * For the given thread, calculate the following values (not all may be available, depending on the active timers and
0923: * the current thread state (inside or outside the profiled call graph):
0924: * absolute gross time, thread CPU gross time, time spent in instrumentation code in absolute counts, same time in
0925: * thread-local time counts.
0926: * The values are assigned to the relevant fields of cgm parameter (if it's not null), and returned as an array of
0927: * doubles.
0928: * NOTE THAT setMethodEntryExitTimesGivenCollectedTimeStampsKinds() SHOULD BE CALLED ONCE BEFORE CALLING THIS METHOD!
0929: */
0930: double[] calculateThreadActiveTimes(ThreadInfo ti) {
0931: TimedCPUCCTNode rootNode = ti.stack[0];
0932:
0933: if (rootNode == null) {
0934: // May happen if thread just created, but nothing ran its behalf yet
0935: return new double[] { 0, 0, 0, 0 };
0936: }
0937:
0938: // Now calculate and return gross times for the whole call subgraph.
0939: // Note that absolute time is provided irrespective of the timers (absolute only, thread CPU only, or both) used
0940: // for methods.
0941: // Correct thread CPU time can be provided only if either thread CPU timer is used, or if execution is currently
0942: // not within the call graph.
0943: // If we can't provide a correct thread CPU time, we set cgm.wholeGraphGrossTimeThreadCPU to a negative value,
0944: // indicating that this time should not be displayed at all.
0945: long rootGrossTimeAbs = ti.rootGrossTimeAbs;
0946:
0947: // System.err.println("\n*** CPUCallGraphBuilder: rootGrossTimeAbs = "
0948: // + rootGrossTimeAbs + ", totalNInv = " + ti.totalNInv); // NOI18N
0949: if (ti.stackTopIdx != -1) {
0950: long time0 = status.dumpAbsTimeStamp;
0951:
0952: if (ti.topMethodEntryTime0 > time0) {
0953: time0 = ti.topMethodEntryTime0;
0954: }
0955:
0956: rootGrossTimeAbs += (time0 - ti.rootMethodEntryTimeAbs);
0957:
0958: //System.err.println("*** dumpAbsTimeStamp = " + status.dumpAbsTimeStamp + ", ti.topMethodEntryTime0 = "
0959: // + ti.topMethodEntryTime0 + "ti.rootMethodEntryTimeAbs = " + ti.rootMethodEntryTimeAbs); // NOI18N
0960: //System.err.println("*** Adjusted rootGrossTimeAbs = " + rootGrossTimeAbs); // NOI18N
0961: }
0962:
0963: //System.err.println("*** rootGrossTimeAbs in ms = "
0964: // + ((double) rootGrossTimeAbs) * 1000 / status.timerCountsInSecond[0]); // NOI18N
0965: long rootGrossTimeCPU = ti.rootGrossTimeThreadCPU;
0966:
0967: //System.err.println("*** ti.rootGrossTimeThreadCPU = "
0968: // + ti.rootGrossTimeThreadCPU + ", totalNInv = " + ti.totalNInv); // NOI18N
0969: if (ti.stackTopIdx != -1) {
0970: if (status.collectingTwoTimeStamps()) {
0971: rootGrossTimeCPU += (ti.topMethodEntryTime1 - ti.rootMethodEntryTimeThreadCPU);
0972:
0973: //System.err.println("*** ti.topMethodEntryTime1 = " + ti.topMethodEntryTime1
0974: // + ", ti.rootMethodEntryTimeThreadCPU = " + ti.rootMethodEntryTimeThreadCPU);
0975: //System.err.println("*** adjustment for CPU time = "
0976: // + (ti.topMethodEntryTime1 - ti.rootMethodEntryTimeThreadCPU)); // NOI18N
0977: } else {
0978: rootGrossTimeCPU = -1;
0979: }
0980: }
0981:
0982: //System.err.println("*** Adjusted rootGrossTimeCPU = " + rootGrossTimeCPU + ", in ms = "
0983: // + ((double) rootGrossTimeCPU) * 1000 / status.timerCountsInSecond[1]); // NOI18N
0984: int nRootInv = rootNode.getNCalls();
0985: double timeInInjectedCodeInAbsCounts;
0986: double timeInInjectedCodeInThreadCPUCounts = 0;
0987: // Calculate timeInInjectedCodeInAbsCounts.
0988: timeInInjectedCodeInAbsCounts = TimingAdjusterOld.getDefault(
0989: status).delta(nRootInv,
0990: (int) (ti.totalNInv - nRootInv), false);
0991:
0992: //System.err.println("*** timeInInjectedCodeInAbsCounts = " + timeInInjectedCodeInAbsCounts + ", in ms = "
0993: // + ((double) timeInInjectedCodeInAbsCounts) * 1000 / status.timerCountsInSecond[0]); // NOI18N
0994:
0995: // Now calculate timeInInjectedCodeInThreadCPUCounts
0996: if (status.collectingTwoTimeStamps()) {
0997: timeInInjectedCodeInThreadCPUCounts = TimingAdjusterOld
0998: .getDefault(status).delta(nRootInv,
0999: (int) (ti.totalNInv - nRootInv), true);
1000: } else { // Same calculation whether we have absoluteTimerOn == true or not
1001: // Just convert the known time into thread CPU time units
1002: timeInInjectedCodeInThreadCPUCounts = (timeInInjectedCodeInAbsCounts * status.timerCountsInSecond[1])
1003: / status.timerCountsInSecond[0];
1004: ;
1005: }
1006:
1007: //System.err.println("*** timeInInjectedCodeInThreadCPUCounts = " + timeInInjectedCodeInThreadCPUCounts); // NOI18N
1008: return new double[] { (double) rootGrossTimeAbs,
1009: (double) rootGrossTimeCPU,
1010: timeInInjectedCodeInAbsCounts,
1011: timeInInjectedCodeInThreadCPUCounts };
1012: }
1013:
1014: protected void doBatchStart() {
1015: ThreadInfo.beginTrans(true);
1016: }
1017:
1018: protected void doBatchStop() {
1019: ThreadInfo.endTrans();
1020: }
1021:
1022: protected void doReset() {
1023: boolean threadLocked = ThreadInfo.beginTrans(true, true);
1024:
1025: if (threadLocked) { // ignore request for reset received durin an ongoing active transaction
1026:
1027: try {
1028: ThreadInfo.reset();
1029: } finally {
1030: ThreadInfo.endTrans();
1031: }
1032: }
1033: }
1034:
1035: protected void doShutdown() {
1036: ThreadInfo.reset();
1037: factory = null;
1038: instrFilter = null;
1039: }
1040:
1041: protected void doStartup(ProfilerClient profilerClient) {
1042: instrFilter = profilerClient.getSettings()
1043: .getInstrumentationFilter();
1044: factory = new CPUCCTNodeFactory(status
1045: .collectingTwoTimeStamps());
1046:
1047: profilerClient.registerCPUCCTProvider(this );
1048: }
1049:
1050: private synchronized DebugInfoCollector getDebugCollector() {
1051: if (debugCollector == null) {
1052: debugCollector = new DebugInfoCollector();
1053: }
1054:
1055: return debugCollector;
1056: }
1057:
1058: private boolean isReady() {
1059: return (status != null) && (factory != null)
1060: && (instrFilter != null);
1061: }
1062:
1063: private String debugMethod(int methodId) {
1064: StringBuffer buffer = new StringBuffer();
1065: status.beginTrans(false);
1066:
1067: try {
1068: buffer.append(status.getInstrMethodClasses()[methodId])
1069: .append('.').append(
1070: status.getInstrMethodNames()[methodId]); // NOI18N
1071: buffer.append(status.getInstrMethodSignatures()[methodId])
1072: .append(" (methodId = ").append(methodId).append(
1073: ')'); // NOI18N
1074: } finally {
1075: status.endTrans();
1076: }
1077:
1078: return buffer.toString();
1079: }
1080:
1081: private String debugNode(RuntimeCPUCCTNode node) {
1082: return getDebugCollector().getInfo(node);
1083: }
1084:
1085: private String dumpStack(ThreadInfo ti) {
1086: StringBuffer buffer = new StringBuffer();
1087: buffer.append("*** Thread stack dump:\n"); // NOI18N
1088:
1089: for (int i = ti.stackTopIdx; i >= 0; i--) {
1090: DebugInfoCollector collector = new DebugInfoCollector();
1091: TimedCPUCCTNode frame = ti.stack[i];
1092: frame.accept(collector);
1093: buffer.append(collector.getInfo(frame)).append('\n'); // NOI18N
1094: }
1095:
1096: return buffer.toString();
1097: }
1098:
1099: private TimedCPUCCTNode markerMethodEntry(final int methodId,
1100: final ThreadInfo ti, long timeStamp0, long timeStamp1,
1101: boolean stamped) {
1102: MarkingEngine engine = MarkingEngine.getDefault();
1103: Mark mark = engine.getMarker().getMark(methodId, status);
1104:
1105: if (LOGGER.isLoggable(Level.FINEST)) {
1106: LOGGER.finest("MarkerMEntry"
1107: + ((!stamped) ? "(unstamped)" : "")
1108: + " for tId = "
1109: + (int) ti.threadId // NOI18N
1110: + ", time: "
1111: + timeStamp0 // NOI18N
1112: + ", method: "
1113: + debugMethod(methodId) // NOI18N
1114: + ", inRoot: "
1115: + ti.rootMethodEntryTimeAbs // NOI18N
1116: + ", rootEntryTimeThread: "
1117: + ti.rootMethodEntryTimeThreadCPU);
1118: }
1119:
1120: TimedCPUCCTNode curNode = ti.peek();
1121:
1122: if (curNode == null) {
1123: TimedCPUCCTNode rootNode = factory
1124: .createThreadNode(ti.threadId);
1125: ti.totalNNodes++;
1126: ti.push(rootNode);
1127: ti.totalNInv--;
1128:
1129: if (!mark.isDefault) {
1130: curNode = factory.createCategory(mark);
1131: rootNode.attachNodeAsChild(curNode);
1132: ti.totalNNodes++;
1133: ti.push(curNode);
1134: rootNode = curNode;
1135: }
1136:
1137: curNode = factory.createMethodNode(methodId);
1138: rootNode.attachNodeAsChild(curNode);
1139: ti.totalNNodes++;
1140: ti.push(curNode);
1141:
1142: ti.topMethodEntryTime0 = timeStamp0;
1143:
1144: if (status.collectingTwoTimeStamps()) {
1145: ti.topMethodEntryTime1 = timeStamp1;
1146: }
1147: } else {
1148: if (stamped) {
1149: long diff = timeStamp0 - ti.topMethodEntryTime0;
1150:
1151: if (diff > 0) {
1152: curNode.addNetTime0(diff);
1153: } else {
1154: timeStamp0 = ti.topMethodEntryTime0;
1155: }
1156:
1157: ti.topMethodEntryTime0 = timeStamp0;
1158:
1159: if (status.collectingTwoTimeStamps()) {
1160: diff = timeStamp1 - ti.topMethodEntryTime1;
1161:
1162: if (diff > 0) {
1163: curNode.addNetTime1(diff);
1164: } else {
1165: timeStamp1 = ti.topMethodEntryTime1;
1166: }
1167:
1168: ti.topMethodEntryTime1 = timeStamp1;
1169: }
1170: }
1171:
1172: TimedCPUCCTNode calleeNode;
1173:
1174: if (!mark.isDefault) {
1175: // try to locate the category node; or create a new node for the category
1176: calleeNode = CategoryCPUCCTNode.Locator.locate(mark,
1177: curNode.getChildren());
1178:
1179: if (calleeNode == null) {
1180: calleeNode = factory.createCategory(mark);
1181: curNode.attachNodeAsChild(calleeNode);
1182: ti.totalNNodes++;
1183: }
1184:
1185: ti.push(calleeNode);
1186: curNode = calleeNode;
1187: }
1188:
1189: // Now find the appropriate callee in this node or create one
1190: calleeNode = MethodCPUCCTNode.Locator.locate(methodId,
1191: curNode.getChildren());
1192:
1193: if (calleeNode == null) {
1194: calleeNode = factory.createMethodNode(methodId);
1195: curNode.attachNodeAsChild(calleeNode);
1196: ti.totalNNodes++;
1197: }
1198:
1199: ti.push(calleeNode);
1200: curNode = calleeNode; // make the callee node be the current one
1201: }
1202:
1203: // curNode.setMarkID(categoryId);
1204: if (!ti.isInRoot()) { // not within root method CCT
1205: curNode.setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1206:
1207: if (stamped) { // stamped marker method called before any root method; must set rootMethodEntryTimes
1208: // Be careful - with MARKER_ENTRY and MARKER_EXIT events, unlike with others, timeStamp0 is *always* absolute time,
1209: // and timeStamp1 is *always* thread CPU time
1210: ti.rootMethodEntryTimeAbs = timeStamp0;
1211: ti.rootMethodEntryTimeThreadCPU = timeStamp1;
1212: ti.topMethodEntryTime0 = timeStamp0;
1213:
1214: if (status.collectingTwoTimeStamps()) {
1215: ti.topMethodEntryTime1 = timeStamp1;
1216: }
1217: }
1218: } else {
1219: String jvmClassName = status.getInstrMethodClasses()[((MethodCPUCCTNode) curNode)
1220: .getMethodId()].replace('.', '/'); // NOI18N
1221: ProfilerClient client = getClient();
1222:
1223: if (client != null) {
1224: if (!client.getSettings().getInstrumentationFilter()
1225: .passesFilter(jvmClassName)) {
1226: curNode
1227: .setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1228: }
1229: } else {
1230: curNode.setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1231: }
1232: }
1233:
1234: return curNode;
1235: }
1236:
1237: private TimedCPUCCTNode markerMethodEntry(final int methodId,
1238: final ThreadInfo ti, long timeStamp0, long timeStamp1) {
1239: return markerMethodEntry(methodId, ti, timeStamp0, timeStamp1,
1240: true);
1241: }
1242:
1243: private TimedCPUCCTNode markerMethodEntry(final int methodId,
1244: final ThreadInfo ti) {
1245: return markerMethodEntry(methodId, ti, 0, 0, false);
1246: }
1247:
1248: private TimedCPUCCTNode plainMethodEntry(final int methodId,
1249: final ThreadInfo ti, long timeStamp0, long timeStamp1,
1250: boolean stamped) {
1251: if (LOGGER.isLoggable(Level.FINEST)) {
1252: if (LOGGER.isLoggable(Level.FINEST)) {
1253: LOGGER.finest("MethodEntry "
1254: + ((!stamped) ? "(unstamped)" : "")
1255: + " for tId = " + (int) ti.threadId // NOI18N
1256: + ", time: " + timeStamp0 // NOI18N
1257: + ", delta: " + (timeStamp0 - delta) // NOI18N
1258: + ", method: " + debugMethod(methodId) // NOI18N
1259: );
1260: }
1261: }
1262:
1263: TimedCPUCCTNode curNode = ti.peek();
1264:
1265: if (stamped) {
1266: long diff = timeStamp0 - ti.topMethodEntryTime0;
1267:
1268: if (diff > 0) {
1269: curNode.addNetTime0(diff);
1270: } else {
1271: timeStamp0 = ti.topMethodEntryTime0;
1272: }
1273:
1274: ti.topMethodEntryTime0 = timeStamp0;
1275:
1276: if (status.collectingTwoTimeStamps()) {
1277: diff = timeStamp1 - ti.topMethodEntryTime1;
1278:
1279: if (diff > 0) {
1280: curNode.addNetTime1(diff);
1281: } else {
1282: timeStamp1 = ti.topMethodEntryTime1;
1283: }
1284:
1285: ti.topMethodEntryTime1 = timeStamp1;
1286: }
1287: }
1288:
1289: // Now find the appropriate callee in this node or create one
1290: MethodCPUCCTNode methodNode = MethodCPUCCTNode.Locator.locate(
1291: methodId, curNode.getChildren());
1292:
1293: if (methodNode != null) {
1294: ti.push(methodNode);
1295:
1296: return methodNode;
1297: }
1298:
1299: // Appropriate sub-node not found, or there are no sub-nodes yet - create one
1300: methodNode = factory.createMethodNode(methodId);
1301: curNode.attachNodeAsChild(methodNode);
1302:
1303: curNode = methodNode;
1304:
1305: ti.totalNNodes++;
1306: ti.push(curNode);
1307:
1308: if (!ti.isInRoot()) {
1309: String jvmClassName = status.getInstrMethodClasses()[((MethodCPUCCTNode) curNode)
1310: .getMethodId()].replace('.', '/');
1311: ProfilerClient client = getClient();
1312:
1313: if (client != null) {
1314: if (!client.getSettings().getInstrumentationFilter()
1315: .passesFilter(jvmClassName)) {
1316: curNode
1317: .setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1318: }
1319: } else {
1320: curNode.setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1321: }
1322: }
1323:
1324: return curNode;
1325: }
1326:
1327: private TimedCPUCCTNode plainMethodEntry(final int methodId,
1328: final ThreadInfo ti, long timeStamp0, long timeStamp1) {
1329: return plainMethodEntry(methodId, ti, timeStamp0, timeStamp1,
1330: true);
1331: }
1332:
1333: private TimedCPUCCTNode plainMethodEntry(final int methodId,
1334: final ThreadInfo ti) {
1335: return plainMethodEntry(methodId, ti, 0, 0, false);
1336: }
1337:
1338: private TimedCPUCCTNode plainMethodExit(final int methodId,
1339: final ThreadInfo ti, long timeStamp0, long timeStamp1,
1340: boolean stamped) {
1341: if (LOGGER.isLoggable(Level.FINEST)) {
1342: LOGGER.finest("MethodExit"
1343: + ((!stamped) ? "(unstamped)" : "") + ": "
1344: + debugMethod(methodId) // NOI18N
1345: + ", time: " + timeStamp0 // NOI18N
1346: + ", delta: " + (timeStamp0 - delta) // NOI18N
1347: + ", ti: " + ti // NOI18N
1348: );
1349: delta = timeStamp0;
1350: }
1351:
1352: TimedCPUCCTNode curNode = ti.peek();
1353:
1354: if (curNode == null) {
1355: LOGGER
1356: .severe(CommonConstants.ENGINE_WARNING
1357: + "critical: stack integrity violation on method exit.\n" // NOI18N
1358: + "*** methodId on simulated stack top is unidentifiable\n"); // NOI18N
1359:
1360: return null;
1361: }
1362:
1363: if (!(curNode instanceof MethodCPUCCTNode)) {
1364: LOGGER
1365: .severe(CommonConstants.ENGINE_WARNING
1366: + "critical: stack integrity violation on method exit.\n" // NOI18N
1367: + "*** methodId on simulated stack top is unidentifiable\n"); // NOI18N
1368:
1369: return null;
1370: }
1371:
1372: MethodCPUCCTNode methodNode = (MethodCPUCCTNode) curNode;
1373:
1374: if (methodId != methodNode.getMethodId()) {
1375: StringBuffer message = new StringBuffer();
1376: message
1377: .append(CommonConstants.ENGINE_WARNING)
1378: .append(
1379: "critical: stack integrity violation on method exit.\n"); // NOI18N
1380: message.append("*** methodId on simulated stack top: ")
1381: .append((int) methodNode.getMethodId()); // NOI18N
1382: message.append(", received methodId (should match) = ")
1383: .append((int) methodId).append('\n'); // NOI18N
1384: message.append("received method debug: ").append(
1385: debugMethod(methodId)).append('\n'); // NOI18N
1386: message.append(CommonConstants.PLEASE_REPORT_PROBLEM);
1387:
1388: if ((status != null)
1389: && (status.getInstrMethodClasses() != null)
1390: && !stackIntegrityViolationReported) {
1391: message.append(dumpStack(ti));
1392: stackIntegrityViolationReported = true;
1393: }
1394:
1395: message.append('\n'); // NOI18N
1396: LOGGER.severe(message.toString());
1397:
1398: return null;
1399: }
1400:
1401: // Timer's coarse granularities etc. may occasionally cause this issue. FIXME: maybe need a warning, though not
1402: // every time this happens, but probably rather in the end of run, so that the problem could then be investigated.
1403: if (stamped) {
1404: long diff = timeStamp0 - ti.topMethodEntryTime0;
1405:
1406: if (diff > 0) {
1407: curNode.addNetTime0(diff);
1408: } else {
1409: timeStamp0 = ti.topMethodEntryTime0;
1410: }
1411:
1412: if (status.collectingTwoTimeStamps()) {
1413: diff = timeStamp1 - ti.topMethodEntryTime1;
1414:
1415: if (diff > 0) {
1416: curNode.addNetTime1(diff);
1417: } else {
1418: timeStamp1 = ti.topMethodEntryTime1;
1419: }
1420: }
1421: }
1422:
1423: TimedCPUCCTNode oldNode = ti.pop();
1424:
1425: // if ((ti.stackTopIdx < 0 || ti.stack[ti.stackTopIdx].getMethodId() == 0) && checkStack) {
1426: // System.err.println(ENGINE_WARNING + "critical: stack state on methodExit is like at rootMethodExit"); // NOI18N
1427: // System.err.println(PLEASE_REPORT_PROBLEM);
1428: // }
1429: // Resume the net time for the caller
1430: if (stamped) {
1431: ti.topMethodEntryTime0 = timeStamp0;
1432:
1433: if (status.collectingTwoTimeStamps()) {
1434: ti.topMethodEntryTime1 = timeStamp1;
1435: }
1436: }
1437:
1438: return oldNode;
1439: }
1440:
1441: private TimedCPUCCTNode plainMethodExit(final int methodId,
1442: final ThreadInfo ti, long timeStamp0, long timeStamp1) {
1443: return plainMethodExit(methodId, ti, timeStamp0, timeStamp1,
1444: true);
1445: }
1446:
1447: private TimedCPUCCTNode plainMethodExit(final int methodId,
1448: final ThreadInfo ti) {
1449: return plainMethodExit(methodId, ti, 0, 0, false);
1450: }
1451:
1452: private TimedCPUCCTNode rootMethodEntry(final int methodId,
1453: final ThreadInfo ti, final long timeStamp0,
1454: final long timeStamp1) {
1455: if (LOGGER.isLoggable(Level.FINEST)) {
1456: LOGGER.finest("RootMEntry for tId = " + (int) ti.threadId // NOI18N
1457: + ", time: " + timeStamp0 // NOI18N
1458: + ", method: " + debugMethod(methodId) // NOI18N
1459: );
1460: }
1461:
1462: MarkingEngine engine = MarkingEngine.getDefault();
1463: Mark mark = engine.getMarker().getMark(methodId, status);
1464:
1465: TimedCPUCCTNode curNode = ti.peek();
1466:
1467: if (ti.isInRoot()) {
1468: StringBuffer buffer = new StringBuffer();
1469: buffer
1470: .append(CommonConstants.ENGINE_WARNING)
1471: .append(
1472: "critical: at root method entry thread stack is not at 0 - should not happen!\n"); // NOI18N
1473: buffer.append("*** thread = ").append(
1474: ThreadInfo.threadNames[ti.threadId]); // NOI18N
1475: buffer.append(", ti.stackTopIdx = ").append(ti.stackTopIdx); // NOI18N
1476:
1477: if (curNode != null) {
1478: buffer.append(", curNode = " + curNode).append('\n'); // NOI18N
1479: }
1480:
1481: buffer.append(CommonConstants.PLEASE_REPORT_PROBLEM);
1482: LOGGER.severe(buffer.toString());
1483: }
1484:
1485: if (curNode == null) { // no node on stack
1486:
1487: TimedCPUCCTNode rootNode = factory
1488: .createThreadNode(ti.threadId); // create a new thread node
1489: ti.totalNNodes++;
1490: ti.push(rootNode); // and place it on the stack
1491: ti.totalNInv--;
1492:
1493: if (!mark.isDefault) {
1494: curNode = factory.createCategory(mark);
1495: rootNode.attachNodeAsChild(curNode);
1496: ti.totalNNodes++;
1497: ti.push(curNode);
1498: rootNode = curNode;
1499: }
1500:
1501: curNode = factory.createMethodNode(methodId); // now create the root method node
1502: rootNode.attachNodeAsChild(curNode); // and attach it to the previously created thread node
1503: ti.totalNNodes++;
1504: } else {
1505: TimedCPUCCTNode calleeNode;
1506:
1507: if (!mark.isDefault) {
1508: // try to locate the category node; or create a new node for the category
1509: calleeNode = CategoryCPUCCTNode.Locator.locate(mark,
1510: curNode.getChildren());
1511:
1512: if (calleeNode == null) {
1513: calleeNode = factory.createCategory(mark);
1514: curNode.attachNodeAsChild(calleeNode);
1515: ti.totalNNodes++;
1516: }
1517:
1518: ti.push(calleeNode);
1519: curNode = calleeNode;
1520: }
1521:
1522: calleeNode = MethodCPUCCTNode.Locator.locate(methodId,
1523: curNode.getChildren());
1524:
1525: if (calleeNode == null) {
1526: calleeNode = factory.createMethodNode(methodId);
1527: curNode.attachNodeAsChild(calleeNode);
1528: ti.totalNNodes++;
1529: }
1530:
1531: curNode = calleeNode;
1532: }
1533:
1534: ti.push(curNode); // make the new node the current one
1535: // curNode.setMarkID(categoryId);
1536:
1537: // Be careful - with ROOT_ENTRY and ROOT_EXIT events, unlike with others, timeStamp0 is *always* absolute time,
1538: // and timeStamp1 is *always* thread CPU time
1539: ti.rootMethodEntryTimeAbs = timeStamp0;
1540: ti.rootMethodEntryTimeThreadCPU = timeStamp1;
1541: ti.topMethodEntryTime0 = timeStamp0;
1542:
1543: if (status.collectingTwoTimeStamps()) {
1544: ti.topMethodEntryTime1 = timeStamp1;
1545: }
1546:
1547: ti.inRoot++;
1548:
1549: // String jvmClassName = status.getInstrMethodClasses()[((MethodCPUCCTNode)curNode).getMethodId()].replace('.', '/');
1550: // ProfilerClient client = getClient();
1551: // if (client != null) {
1552: // if (!client.getSettings().getInstrumentationFilter().passesFilter(jvmClassName)) {
1553: // curNode.setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1554: // }
1555: // } else {
1556: // curNode.setFilteredStatus(TimedCPUCCTNode.FILTERED_YES);
1557: // }
1558: return curNode;
1559: }
1560:
1561: private TimedCPUCCTNode rootMethodExit(final int methodId,
1562: final ThreadInfo ti, long timeStamp0, long timeStamp1) {
1563: if (LOGGER.isLoggable(Level.FINEST)) {
1564: LOGGER.finest("RootMExit for tId = " + (int) ti.threadId // NOI18N
1565: + ", time: " + timeStamp0 // NOI18N
1566: + ", delta: " + (timeStamp0 - delta) // NOI18N
1567: + ", method: " + debugMethod(methodId) // NOI18N
1568: );
1569: delta = timeStamp0;
1570: }
1571:
1572: TimedCPUCCTNode curNode = ti.peek();
1573:
1574: if (curNode == null) {
1575: LOGGER
1576: .severe(CommonConstants.ENGINE_WARNING
1577: + "critical: stack integrity violation on root method exit.\n" // NOI18N
1578: + "*** methodId on simulated stack top is unidentifiable\n"); // NOI18N
1579:
1580: return null;
1581: }
1582:
1583: if (!(curNode instanceof MethodCPUCCTNode)) {
1584: LOGGER
1585: .severe(CommonConstants.ENGINE_WARNING
1586: + "critical: stack integrity violation on root method exit.\n" // NOI18N
1587: + "*** methodId on simulated stack top is unidentifiable\n"); // NOI18N
1588:
1589: return null;
1590: }
1591:
1592: MethodCPUCCTNode methodNode = (MethodCPUCCTNode) curNode;
1593:
1594: if (methodId != methodNode.getMethodId()) {
1595: StringBuffer message = new StringBuffer();
1596: message
1597: .append(CommonConstants.ENGINE_WARNING)
1598: .append(
1599: "critical: stack integrity violation on root thod exit.\n"); // NOI18N
1600: message.append("*** methodId on simulated stack top: ")
1601: .append((int) methodNode.getMethodId())
1602: .append('\n'); // NOI18N
1603: message.append(", received methodId (should match) = ")
1604: .append((int) methodId).append('\n'); // NOI18N
1605: message.append("received method debug: ").append(
1606: debugMethod(methodId)).append('\n'); // NOI18N
1607: message.append(CommonConstants.PLEASE_REPORT_PROBLEM);
1608:
1609: if ((status != null)
1610: && (status.getInstrMethodClasses() != null)
1611: && !stackIntegrityViolationReported) {
1612: message.append(dumpStack(ti));
1613: stackIntegrityViolationReported = true;
1614: }
1615:
1616: message.append('\n'); // NOI18N
1617: LOGGER.severe(message.toString());
1618:
1619: return null;
1620: }
1621:
1622: // Be careful - with ROOT_ENTRY and ROOT_EXIT events, unlike with others, timeStamp0 is *always* absolute time,
1623: // and timeStamp1 is *always* thread CPU time
1624: long diff = timeStamp0 - ti.topMethodEntryTime0;
1625:
1626: if (diff > 0) {
1627: curNode.addNetTime0(diff);
1628: } else {
1629: timeStamp0 = ti.topMethodEntryTime0;
1630: }
1631:
1632: if (status.collectingTwoTimeStamps()) {
1633: diff = timeStamp1 - ti.topMethodEntryTime1;
1634:
1635: if (diff > 0) {
1636: curNode.addNetTime1(diff);
1637: } else {
1638: timeStamp1 = ti.topMethodEntryTime1;
1639: }
1640: }
1641:
1642: ti.inRoot--;
1643:
1644: TimedCPUCCTNode oldNode = ti.pop();
1645:
1646: if (ti.isInRoot()) { // We are actually exiting a non-root invocation of the root method
1647: ti.topMethodEntryTime0 = timeStamp0;
1648:
1649: if (status.collectingTwoTimeStamps()) {
1650: ti.topMethodEntryTime1 = timeStamp1;
1651: }
1652: } else {
1653: ti.rootGrossTimeAbs += (timeStamp0 - ti.rootMethodEntryTimeAbs);
1654: ti.rootGrossTimeThreadCPU += (timeStamp1 - ti.rootMethodEntryTimeThreadCPU);
1655: ti.rootMethodEntryTimeAbs = 0;
1656: ti.rootMethodEntryTimeThreadCPU = 0;
1657: }
1658:
1659: return oldNode;
1660: }
1661: }
|