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.server.system.Threads;
044: import org.netbeans.lib.profiler.server.system.Timers;
045:
046: /**
047: * This class contains the actual methods for sampled instrumentation recursive CPU profiling, calls to which are injected
048: * into the target application (TA) bytecodes when they are instrumented.
049: *
050: * methodEntry: if taking timestamp (in new sampling slot), time is charged to method being left
051: * methodExit: if taking timestamp (in new sampling slot), time is charged to method being exited
052: *
053: * @author Tomas Hurka
054: * @author Misha Dmitriev
055: */
056: public class ProfilerRuntimeCPUSampledInstr extends ProfilerRuntimeCPU {
057: //~ Inner Classes ------------------------------------------------------------------------------------------------------------
058:
059: //------------------------------------------- Support classes --------------------------------------------------
060:
061: /** A thread that periodically sets the sample flag for worker threads */
062: static class SamplingThread extends Thread {
063: //~ Static fields/initializers -------------------------------------------------------------------------------------------
064:
065: private static final boolean isSolaris = System.getProperty(
066: "os.name").startsWith("Sun"); // NOI18N
067: private static final boolean isLinux = System.getProperty(
068: "os.name").startsWith("Linux"); // NOI18N
069: private static final boolean isUnix = isSolaris || isLinux;
070: private static final int VIOLATION_THRESHOLD = 10;
071: private static final boolean DEBUG = false;
072:
073: //~ Instance fields ------------------------------------------------------------------------------------------------------
074:
075: private boolean terminated;
076: private int count;
077:
078: //~ Methods --------------------------------------------------------------------------------------------------------------
079:
080: public void run() {
081: if (isSolaris) {
082: samplingInterval *= 1000000; // Convert into nanos - the Solaris hires timer resolution
083: } else if (isLinux) {
084: samplingInterval *= 1000; // Convert into microseconds - the Linux hires timer resolution
085: }
086:
087: int adjustedSamplingInterval = samplingInterval;
088: int upperBound = (samplingInterval * 5) / 4;
089: int lowerBound = samplingInterval / 10;
090: int violationCount = VIOLATION_THRESHOLD;
091:
092: long startTime = Timers.getCurrentTimeInCounts();
093:
094: while (!terminated) {
095: if (!isUnix) {
096: try {
097: Thread.sleep(samplingInterval);
098: } catch (InterruptedException ex) { /* Should not happen */
099: }
100: } else { // Solaris and Linux
101:
102: long time = Timers.getCurrentTimeInCounts();
103: // On Solaris, the resolution of Thread.sleep(), which boils down to the select(3C) system call, seems to be
104: // around 20 ms. So we have to use our own call, which eventually calls nanosleep() and takes an argument in nanos.
105: // On Linux (at least version 7.3 + patches, which I tried), nanosleep() seems to have a 20 ms resolution (or even
106: // give 20 ms no matter what?), which is a documented bug (see 'man nanosleep'). Well, maybe it improves in future...
107: Timers.osSleep(adjustedSamplingInterval);
108: time = Timers.getCurrentTimeInCounts() - time;
109:
110: if ((time > upperBound)
111: && (adjustedSamplingInterval > lowerBound)) {
112: if (violationCount > 0) {
113: violationCount--;
114: } else {
115: adjustedSamplingInterval = (adjustedSamplingInterval * 95) / 100;
116: violationCount = VIOLATION_THRESHOLD;
117: }
118: }
119: }
120:
121: ThreadInfo.setSampleDueForAllThreads();
122:
123: if (DEBUG) {
124: count++;
125: }
126: }
127:
128: if (DEBUG && isUnix) {
129: long time = ((Timers.getCurrentTimeInCounts() - startTime) * 1000)
130: / Timers.getNoOfCountsInSecond();
131: System.out
132: .println("JFluid sampling thread: elapsed time: "
133: + time
134: + " ms, avg interval: "
135: + (((double) time) / count)
136: + "ms, adjusted interval: "
137: + adjustedSamplingInterval
138: + " OS units"); // NOI18N
139: }
140: }
141:
142: public void terminate() {
143: terminated = true;
144:
145: try {
146: Thread.sleep(100);
147: } catch (InterruptedException ex) { /* Should not happen */
148: }
149: }
150: }
151:
152: //~ Static fields/initializers -----------------------------------------------------------------------------------------------
153:
154: protected static int samplingInterval = 10;
155: protected static SamplingThread st;
156:
157: //~ Methods ------------------------------------------------------------------------------------------------------------------
158:
159: public static void setSamplingInterval(int v) {
160: samplingInterval = v;
161: }
162:
163: public static void enableProfiling(boolean v) {
164: if (v) {
165: createNewDataStructures();
166: ProfilerRuntimeCPU.enableProfiling(v);
167: } else {
168: ProfilerRuntimeCPU.enableProfiling(v);
169: clearDataStructures();
170: }
171: }
172:
173: // ---------------------------------- Profile Data Acquisition --------------------------------------
174: /** Called upon entry into a special root method used for */
175: public static void markerMethodEntry(char methodId) {
176: if (recursiveInstrumentationDisabled) {
177: return; // See the comment at the recursiveInstrumentationDisabled variable declaration
178: }
179:
180: ThreadInfo ti = ThreadInfo.getThreadInfo();
181:
182: if (ti.inProfilingRuntimeMethod > 0) {
183: return;
184: }
185:
186: //if (instrMethodClasses != null && methodId < instrMethodClasses.length) System.out.println("++++++Marker methodEntry for " + instrMethodClasses[methodId] + "." + instrMethodNames[methodId] + ", thread = " + Thread.currentThread());
187: //else System.out.println("++++++Marker methodEntry for methodId = " + (int)methodId + ", thread = " + Thread.currentThread());
188: if (!ti.isInitialized()) {
189: if ((nProfiledThreadsAllowed > 0)
190: && !ThreadInfo
191: .isCurrentThreadProfilerServerThread()) {
192: ti.initialize();
193: ti.useEventBuffer();
194:
195: synchronized (eventBuffer) { // Make this happen atomically wrt. other operations on eventBuffer, such as reset collectors
196: nProfiledThreadsAllowed--;
197: ti.inProfilingRuntimeMethod++;
198: ti.inCallGraph = true;
199: writeThreadCreationEvent(ti);
200: }
201: } else {
202: return;
203: }
204: } else {
205: ti.inProfilingRuntimeMethod++;
206: ti.inCallGraph = true;
207: }
208:
209: // This is to bypass what seems to be a compiler bug (at least C1 on Windows): when methodId > 64K/2 is passed here
210: // using our instrumentation's sipush command at the call site, it's treated here as a signed integer. Thus without
211: // the below fix we can get e.g. an ArrayIndexOutOfBoundsException(-32768) when methodId == 32768 (***)
212: methodId = (char) ((int) methodId);
213:
214: // DO NOT perform instrumentation of its immediate callees
215: if (!instrMethodInvoked[methodId]) {
216: instrMethodInvoked[methodId] = true;
217: }
218:
219: ti.stackDepth++; //= 1; // This is the logical stack depth
220:
221: if (ti.stackDepth > 1) {
222: if (!ti.sampleDue) {
223: writeUnstampedEvent(MARKER_ENTRY_UNSTAMPED, ti,
224: methodId);
225: } else {
226: writeTimeStampedEvent(MARKER_ENTRY, ti, methodId);
227: ti.sampleDue = false;
228: }
229: } else {
230: writeTimeStampedEvent(MARKER_ENTRY, ti, methodId);
231: }
232:
233: ti.inProfilingRuntimeMethod--;
234: }
235:
236: /** Called upon exit from the marker method. */
237: public static void markerMethodExit(char methodId) {
238: if (recursiveInstrumentationDisabled) {
239: return;
240: }
241:
242: ThreadInfo ti = ThreadInfo.getThreadInfo();
243:
244: if (ti.isInitialized() && ti.inCallGraph) { // ti == null may happen if instrumentation has been removed or data collectors reset
245:
246: if (ti.inProfilingRuntimeMethod > 0) {
247: return;
248: }
249:
250: if (ti.rootMethodStackDepth > 0) {
251: methodExit(methodId);
252: } else {
253: ti.inProfilingRuntimeMethod++;
254:
255: //System.out.println("------markerMethodExit for " + instrMethodClasses[methodId] + "." + instrMethodNames[methodId] + ", depth = " + ti.stackDepth + ", id = " + (int) methodId);
256: ti.stackDepth--;
257:
258: if (ti.stackDepth < 1) {
259: ti.inCallGraph = false; // We are exiting the marker method of our call subgraph
260: writeTimeStampedEvent(MARKER_EXIT, ti, methodId);
261: } else {
262: if (!ti.sampleDue) {
263: writeUnstampedEvent(MARKER_EXIT_UNSTAMPED, ti,
264: methodId);
265: } else {
266: writeTimeStampedEvent(MARKER_EXIT, ti, methodId);
267: ti.sampleDue = false;
268: }
269: }
270:
271: ti.inProfilingRuntimeMethod--;
272: }
273: }
274: }
275:
276: /** Called upon entry into a non-root target application method */
277: public static void methodEntry(char methodId) {
278: if (recursiveInstrumentationDisabled) {
279: return; // See the comment at the recursiveInstrumentationDisabled variable declaration
280: }
281:
282: ThreadInfo ti = ThreadInfo.getThreadInfo();
283:
284: if (ti.isInitialized() && ti.inCallGraph
285: && (ti.rootMethodStackDepth > 0)) {
286: if (ti.inProfilingRuntimeMethod > 0) {
287: return;
288: }
289:
290: ti.inProfilingRuntimeMethod++;
291: //System.out.println("++++++methodEntry, depth = " + ti.stackDepth + ", id = " + (int) methodId);
292:
293: // See comment marked with (***)
294: methodId = (char) ((int) methodId);
295:
296: // Now check if it's the first invocation of this method, and if so, perform instrumentation of nearest callees
297: if (!instrMethodInvoked[methodId]) {
298: long absTimeStamp = Timers.getCurrentTimeInCounts();
299: long threadTimeStamp = Timers.getThreadCPUTimeInNanos();
300: externalActionsHandler
301: .handleFirstTimeMethodInvoke(methodId);
302: instrMethodInvoked[methodId] = true; // Mark this method as invoked
303: writeAdjustTimeEvent(ti, absTimeStamp, threadTimeStamp);
304: }
305:
306: ti.stackDepth++;
307:
308: if (!ti.sampleDue) {
309: if (methodId <= MAX_METHOD_ID_FOR_COMPACT_FORMAT) {
310: writeCompactEvent(
311: ti,
312: (char) (METHOD_ENTRY_COMPACT_MASK | methodId));
313: } else {
314: writeUnstampedEvent(METHOD_ENTRY_UNSTAMPED, ti,
315: methodId);
316: }
317: } else {
318: writeTimeStampedEvent(METHOD_ENTRY, ti, methodId);
319: ti.sampleDue = false;
320: }
321:
322: ti.inProfilingRuntimeMethod--;
323: }
324: }
325:
326: /** Called upon exit from the method. */
327: public static void methodExit(char methodId) {
328: if (recursiveInstrumentationDisabled) {
329: return; // See the comment at the recursiveInstrumentationDisabled variable declaration
330: }
331:
332: ThreadInfo ti = ThreadInfo.getThreadInfo();
333:
334: if (ti.isInitialized() && ti.inCallGraph
335: && (ti.rootMethodStackDepth > 0)) { // ti == null may happen if instrumentation has been removed or data collectors reset
336:
337: if (ti.inProfilingRuntimeMethod > 0) {
338: return;
339: }
340:
341: ti.inProfilingRuntimeMethod++;
342:
343: //System.out.println("------methodExit, depth = " + ti.stackDepth + ", id = " + (int) methodId);
344: if (ti.rootMethodStackDepth == ti.stackDepth) {
345: ti.rootMethodStackDepth = 0;
346: }
347:
348: ti.stackDepth--;
349:
350: if (ti.stackDepth < 1) {
351: ti.inCallGraph = false; // We are exiting the root method of our call subgraph
352: writeTimeStampedEvent(ROOT_EXIT, ti, methodId);
353: } else {
354: if (!ti.sampleDue) {
355: // short path: not taking time stamp
356:
357: // See comment marked with (***)
358: methodId = (char) ((int) methodId);
359:
360: if (methodId <= MAX_METHOD_ID_FOR_COMPACT_FORMAT) {
361: writeCompactEvent(
362: ti,
363: (char) (METHOD_EXIT_COMPACT_MASK | methodId));
364: } else {
365: writeUnstampedEvent(METHOD_EXIT_UNSTAMPED, ti,
366: methodId);
367: }
368: } else {
369: writeTimeStampedEvent(METHOD_EXIT, ti, methodId);
370: ti.sampleDue = false;
371: }
372: }
373:
374: ti.inProfilingRuntimeMethod--;
375: }
376: }
377:
378: /** Called upon entry into a root target application method */
379: public static void rootMethodEntry(char methodId) {
380: if (recursiveInstrumentationDisabled) {
381: return; // See the comment at the recursiveInstrumentationDisabled variable declaration
382: }
383:
384: ThreadInfo ti = ThreadInfo.getThreadInfo();
385:
386: if (ti.inProfilingRuntimeMethod > 0) {
387: return;
388: }
389:
390: ProfilerServer.notifyClientOnResultsAvailability();
391:
392: if (ti.isInitialized() && !ti.inCallGraph
393: && (ti.stackDepth > 0)) {
394: ti.inCallGraph = true;
395: methodEntry(methodId);
396: ti.inCallGraph = false;
397:
398: return;
399: }
400:
401: if ((ti != null) && ti.inCallGraph
402: && (ti.rootMethodStackDepth > 0)) {
403: methodEntry(methodId);
404: } else { // Entered the root method from outside this call subgraph
405: //if (instrMethodClasses != null && methodId < instrMethodClasses.length) System.out.println("++++++Root methodEntry for " + instrMethodClasses[methodId] + "." + instrMethodNames[methodId] + ", thread = " + Thread.currentThread());
406: //else System.out.println("++++++Root methodEntry for methodId = " + (int)methodId + ", thread = " + Thread.currentThread());
407:
408: if (!ti.isInitialized()) {
409: if ((nProfiledThreadsAllowed > 0)
410: && !ThreadInfo
411: .isCurrentThreadProfilerServerThread()) {
412: ti.initialize();
413: ti.useEventBuffer();
414:
415: synchronized (eventBuffer) { // Make this happen atomically wrt. other operations on eventBuffer, such as reset collectors
416: nProfiledThreadsAllowed--;
417: ti.inProfilingRuntimeMethod++;
418:
419: if (!ProfilerServer
420: .startProfilingPointsActive()) {
421: ti.inCallGraph = true;
422: }
423:
424: writeThreadCreationEvent(ti);
425: }
426: } else {
427: return;
428: }
429: } else {
430: if (ti.stackDepth > 0) {
431: ti.rootMethodStackDepth = ti.stackDepth + 1;
432: methodEntry(methodId);
433:
434: return;
435: } else {
436: ti.inProfilingRuntimeMethod++;
437:
438: if (!ProfilerServer.startProfilingPointsActive()) {
439: ti.inCallGraph = true;
440: }
441: }
442: }
443:
444: // This is to bypass what seems to be a compiler bug (at least C1 on Windows): when methodId > 64K/2 is passed here
445: // using our instrumentation's sipush command at the call site, it's treated here as a signed integer. Thus without
446: // the below fix we can get e.g. an ArrayIndexOutOfBoundsException(-32768) when methodId == 32768 (***)
447: methodId = (char) ((int) methodId);
448:
449: // Check if it's the first invocation of this method, and if so, perform instrumentation of its immediate callees
450: if (!instrMethodInvoked[methodId]) {
451: externalActionsHandler
452: .handleFirstTimeMethodInvoke(methodId);
453: instrMethodInvoked[methodId] = true;
454: }
455:
456: ti.stackDepth++; //= 1; // This is the logical stack depth
457: writeTimeStampedEvent(ROOT_ENTRY, ti, methodId);
458: ti.rootMethodStackDepth = ti.stackDepth;
459: ti.inProfilingRuntimeMethod--;
460: }
461: }
462:
463: protected static void clearDataStructures() {
464: ProfilerRuntimeCPU.clearDataStructures();
465:
466: if (st != null) {
467: st.terminate();
468: }
469: }
470:
471: protected static void createNewDataStructures() {
472: ProfilerRuntimeCPU.createNewDataStructures();
473: st = new SamplingThread();
474: st.setPriority(Thread.MAX_PRIORITY);
475: Threads.recordAdditionalProfilerOwnThread(st);
476: st.start();
477: }
478:
479: // ---------------------------------- Writing profiler events --------------------------------------
480:
481: // In order to optimize usage of the event buffer, we exploit the facts that:
482: // (1) We have just a handful of different events, and thus their normal codes are small numbers, that need a few bits.
483: // (2) We rarely instrument more than a few thousand methods, so out of 16 bits of char methodId the upper two are usually unused
484: // (3) Just two events, method entry and method exit, happen ~3 orders of magnitude more often than others.
485: // (4) When performing sampled instrumentation profiling, most of method entry/exit events don't have a timestamp.
486: // Given all these observations, we can encode unstamped method entry/exit events with method id <= MAX_METHOD_ID_FOR_COMPACT_FORMAT
487: // (equal to 0x3FFF, i.e. not using the upper two bits) as just a single char. The uppermost bit determines if the char
488: // corresponds to a full event stored in the compact format, or to just an event code. The second bit from the top determines
489: // the actual event - method entry or method exit. Subsequent bits are the method id.
490:
491: /** Write a two-byte event, such as unstamped method entry/exit in compact format. */
492: static void writeCompactEvent(ThreadInfo ti, char event) {
493: // if (printEvents) System.out.println("*** Writing compact event " + (int) event);
494: ti.evBuf[ti.evBufPos++] = (byte) ((event >> 8) & 0xFF);
495: ti.evBuf[ti.evBufPos++] = (byte) ((event) & 0xFF);
496:
497: if (ti.evBufPos > ThreadInfo.evBufPosThreshold) {
498: copyLocalBuffer(ti);
499: }
500: }
501:
502: /** Write an unstamped event, such as method entry/exit for a method whose id is > MAX_METHOD_ID_FOR_COMPACT_FORMAT */
503: static void writeUnstampedEvent(byte eventType, ThreadInfo ti,
504: char methodId) {
505: // if (printEvents) System.out.println("*** Writing unstamped event " + (int) eventType + ", metodId = " + (int)methodId);
506: byte[] evBuf = ti.evBuf;
507: int curPos = ti.evBufPos; // It's important to use a local copy for evBufPos, so that evBufPos is at event boundary at any moment
508: evBuf[curPos++] = eventType;
509: evBuf[curPos++] = (byte) ((methodId >> 8) & 0xFF);
510: evBuf[curPos++] = (byte) ((methodId) & 0xFF);
511: ti.evBufPos = curPos;
512:
513: if (curPos > ThreadInfo.evBufPosThreshold) {
514: copyLocalBuffer(ti);
515: }
516: }
517: }
|