Method and system for SMP profiling using synchronized or nonsynchronized metric variables with support across multiple systems

[0002] This application is a related to the following copending and commonly assigned applications entitled “SYSTEM AND METHOD FOR PROVIDING TRACE INFORMATION REDUCTION”, U.S. application Ser. No. 08/989,725, filed on Dec. 12, 1997, currently pending now U.S. Pat. No. 6,055,492, “A METHOD AND APPARATUS FOR STRUCTURED PROFILING OF DATA PROCESSING SYSTEMS AND APPLICATIONS”, U.S. application Ser. No. 09/052,329, filed on Mar. 31, 1998, now U.S. Pat. No. 6,003,872, “A METHOD AND APPARATUS FOR STRUCTURED MEMORY ANALYSIS OF DATA PROCESSING SYSTEMS AND APPLICATIONS”, U.S. application Ser. No. 09/052,331, filed on Mar. 31, 1998, now U.S. Pat. No. 6,158,024, and “METHOD AND APPARATUS FOR PROFILING PROCESSES IN A DATA PROCESSING SYSTEM”, U.S. application Ser. No. 09/177,031, filed on Oct. 22, 1998, now U.S. Pat. No. 6,311,325, “PROCESS AND SYSTEM FOR MERGING TRACE DATA FOR PRIMARILY INTERPRETED METHODS”, U.S. application Ser. No. 09/343,439, filed on Jun. 30, 1999; “METHOD AND SYSTEM FOR MERGING EVENT-BASED DATA AND SAMPLED DATA INTO POSTPROCESSED TRACE OUTPUT”, U.S. application Ser. No. 09/343,438, filed Jun. 30, 1999; “METHOD AND SYSTEM FOR APPORTIONING CHANGES IN METRIC VARIABLES IN AN SYMMETRIC MULTIPROCESSOR (SMP) ENVIRONMENT”, U.S. application Ser. No. 09/612,340 filed Jul. 6, 2000 “METHOD AND SYSTEM FOR SHADOW HEAP MEMORY LEAK DETECTION AND OTHER HEAP ANALYSIS IN AN OBJECT-ORIENTED ENVIRONMENT DURING REAL-TIME TRACE PROCESSING”, U.S. application Ser. No. 09/589,798 filed Jun. 8, 2000; “METHOD AND SYSTEM FOR TRACING PROFILING INFORMATION IN AN APPLICATION USING PER THREAD METRIC VARIABLES WITH REUSED KERNEL THREADS”, U.S. application Ser. No. 09/612,349, filed Jul. 6. 2000; and “METHOD AND SYSTEM FOR TRACING PROFILING INFORMATION USING PER THREAD METRIC VARIABLES WITH REUSED KERNEL THREADS”, U.S. application Ser. No. 09/612,350 filed Jul. 6, 2000

[0003] 1. Technical Field

[0004] The present invention relates to an improved data processing system and, in particular, to a method and apparatus for optimizing performance in a data processing system. Still more particularly, the present invention provides a method and apparatus for a software program development tool for enhancing performance of a software program through software profiling.

[0005] 2. Description of Related Art

[0006] In analyzing and enhancing performance of a data processing system and the applications executing within the data processing system, it is helpful to know which software modules within a data processing system are using system resources. Effective management and enhancement of data processing systems requires knowing how and when various system resources are being used. Performance tools are used to monitor and examine a data processing system to determine resource consumption as various software applications are executing within the data processing system. For example, a performance tool may identify the most frequently executed modules and instructions in a data processing system, or may identify those modules, which allocate the largest amount of memory or perform the most I/O requests. Hardware performance tools may be built into the system or added at a later point in time. Software performance tools also are useful in data processing systems, such as personal computer systems, which typically do not contain many, if any, built-in hardware performance tools.

[0007] One known software performance tool is a trace tool. A trace tool may use more than one technique to provide trace information that indicates execution flows for an executing program. One technique keeps track of particular sequences of instructions by logging certain events as they occur, so-called event-based profiling technique. For example, a trace tool may log every entry into, and every exit from, a module, subroutine, method, function, or system component. Alternately, a trace tool may log the requester and the amounts of memory allocated for each memory allocation request. Typically, a time-stamped record is produced for each such event. Corresponding pairs of records similar to entry-exit records also are used to trace execution of arbitrary code segments, starting and completing I/O or data transmission, and for many other events of interest.

[0008] In order to improve performance of code generated by various families of computers, it is often necessary to determine where time is being spent by the processor in executing code, such efforts being commonly known in the computer processing arts as locating “hot spots.” Ideally, one would like to isolate such hot spots at the instruction and/or source line of code level in order to focus attention on areas, which might benefit most from improvements to the code.

[0009] Another trace technique involves periodically sampling a program's execution flows to identify certain locations in the program in which the program appears to spend large amounts of time. This technique is based on the idea of periodically interrupting the application or data processing system execution at regular intervals, so-called sample-based profiling. At each interruption, information is recorded for a predetermined length of time or for a predetermined number of events of interest. For example, the program counter of the currently executing thread, which is a process that is part of the larger program being profiled, may be recorded during the intervals. These values may be resolved against a load map and symbol table information for the data processing system at post-processing time, and a profile of where the time is being spent may be obtained from this analysis.

[0010] For example, isolating such hot spots to the instruction level permits compiler writers to find significant areas of suboptimal code generation at which they may thus focus their efforts to improve code generation efficiency. Another potential use of instruction level detail is to provide guidance to the designer of future systems. Such designers employ profiling tools to find characteristic code sequences and/or single instructions that require optimization for the available software for a given type of hardware.

[0011] Profiling information consists of two primary types of profiling metric variables, those which are updated based on a discrete event and those which are updated based on a non-discrete event. When profiling discrete metric variables, the value of the metric variable must be gathered from the component receiving the event. If profiling includes gather profiling information at the processor level, the value of discrete metric variable must be obtained from the processor. That value may be used to compute the change in the value of a metric variable that should be attributed to the process or method running on a specific processor. A change in the value of a non-discrete metric variable, on the other hand, does not rely on the occurrence of a discrete event. The value continues to update at a predetermined rate regardless of what events transpire during updating. However, the value of one processor's non-discrete metric variable may be different from the value of another processor's metric variable. For example, some symmetric multiprocessor (SMP) systems may not have synchronized clocks in which each processor has an identical value for the timing metric variable. Conversely, other SMP systems allow processor clocks that start synchronized to drift. Therefore, even though each processor may start with an identical value for a metric variable, the values may drift apart and become non-synchronized. Thus, the values of the non-synchronized metric variables must also be obtained from the individual processor receiving the event.

[0012] Generally, the values of metric variables are not considered to be synchronized between individual systems or machines. Therefore, a similar synchronization problem occur between a plurality of systems as occurs between processors within a single system. In addition, rarely are the values of metric variables in separate systems ever synchronized. Thus, the values of non-discrete metric variables must be obtained from the individual processor and system having the event even though the actual value of the non-discrete metric variable does not rely on the event for updating.

[0013] Therefore, it would be advantageous to provide a system in which accurate profiling information could be maintained globally for a plurality of processors rather than at the processor level. Further, it would be advantageous to provide a means to synchronize the value of metric variables between systems rather than at the system level.

[0014] A method and system for tracing profiling information using synchronized or non-synchronized metric variables with support across multiple systems using a global value of a metric variable. In one embodiment the value of non-discrete metric variables are synchronized at the processor level. When the profiler requests metric information for the non-discrete metric variables, the operating system kernel obtains the global metric value rather than a per-processor metric value for each processor. More particularly, if trace records are written, the change in the value of non-discrete metric variables can be derived from a single, global, value of the last metric variable which is set each time a record is processed. In another embodiment, the value of non-discrete metric variables are synchronized at the system level. In that case if trace records are written, the change in the value of non-discrete metric variables can be derived from a single value of the last metric variable which held for all synchronized systems and is set each time a record is processed for any system.

[0015] The novel features believed characteristic of the invention are set forth in the appended claims. The invention itself, however, as well as a preferred mode of use, further objectives and advantages thereof, will best be understood by reference to the following detailed description of an illustrative embodiment when read in conjunction with the accompanying drawings, wherein:

[0016] FIG. 1 is an illustration depicting a distributed data processing system in which the present invention may be implemented;

[0017] FIGS. 2A-B are block diagrams depicting a data processing system in which the present invention may be implemented;

[0018] FIG. 3A is a block diagram depicting the relationship of software components operating within a computer system that may implement the present invention;

[0019] FIG. 3B is a block diagram depicting a Java virtual machine in accordance with a preferred embodiment of the present invention;

[0020] FIG. 4 is a block diagram depicting components used to profile processes in a data processing system;

[0021] FIG. 5 is an illustration depicting various phases in profiling the active processes in an operating system;

[0022] FIG. 6 is a flowchart depicting a process used by a trace program for generating trace records from processes executing on a data processing system;

[0023] FIG. 7 is a flowchart depicting a process used in a system interrupt handler trace hook;

[0024] FIG. 8 is a diagram depicting the call stack containing stack frames;

[0025] FIG. 9 is an illustration depicting a call stack sample;

[0026] FIG. 10A is a diagram depicting a program execution sequence along with the state of the call stack at each function entry/exit point;

[0027] FIG. 10B is a diagram depicting a particular timer based sampling of the execution flow depicted in FIG. 10A;

[0028] FIGS. 10C-D are time charts providing an example of the types of time for which the profiling tool accounts;

[0029] FIG. 11A is a diagram depicting a tree structure generated from sampling a call stack;

[0030] FIG. 11B is a diagram depicting an event tree, which reflects call stacks observed during system execution;

[0031] FIG. 12 is a table depicting a call stack tree;

[0032] FIG. 13 is a flow chart depicting a method for building a call stack tree using a trace text file as input;

[0033] FIG. 14 is a flow chart depicting a method for building a call stack tree dynamically as tracing is taking place during system execution;

[0034] FIG. 15A is a flowchart depicting a process for creating a call stack tree structure from call stack unwind records in a trace file;

[0035] FIG. 15B is a flowchart depicting a process for identifying functions from an address obtained during sampling;

[0036] FIG. 16 is a diagram depicting a record generated using the processes of the present invention;

[0037] FIG. 17 is a diagram depicting another type of report that may be produced to show the calling structure between routines shown in FIG. 12;

[0038] FIG. 18 is a table depicting a report generated from a trace file containing both event-based profiling information (method entry/exits) and sample-based profiling information (stack unwinds);

[0039] FIG. 19 is a table depicting major codes and minor codes that may be employed to instrument modules for profiling;

[0040] FIG. 20 is a blocked diagram that depicts a relationship to a profiler and other software components in multiple data processing systems capable of accurately tracking synchronized or nonsynchronized metric variables with support across multiple systems, in accordance with a preferred embodiment of the present invention;

[0041] FIGS. 21A and 21B is a flowchart that depicts writing a trace record to a single buffer and to individual processor's buffers, respectively, in accordance with a preferred embodiment of the present invention;

[0042] FIGS. 22A through 22D are diagrams of trace record contents are presented based on event type and kernel buffer allocation in accordance with a preferred embodiment of the present invention;

[0043] FIGS. 23A and 23B flowcharts depicting a generic process for writing a trace record in accordance with a preferred embodiment of the present invention;

[0044] FIG. 24 is a diagram depicting a trace file written from a single trace buffer in accordance with a preferred embodiment of the present invention;

[0045] FIG. 24B is a diagram depicting a plurality of trace files written from individual processor trace buffers in accordance with a preferred embodiment of the present invention;

[0046] FIG. 24C is a diagram illustrating a postprocessing table for tracking the variables necessary for tracking profiling information in a non-synchronized system, in accordance with a preferred embodiment of the present invention;

[0047] FIG. 24D is a diagram depicting a profiling tree structure in accordance with a preferred embodiment of the present invention;

[0048] FIGS. 25A-25C is a flowcharts depicting a process for postprocessing trace records having nonsynchronized metric variables in accordance with a preferred embodiment of the present invention;

[0049] FIG. 26, a diagram illustrating a postprocessing table for tracking the variables necessary for tracking profiling information in a synchronized system, in accordance with a preferred embodiment of the present invention; and

[0050] FIGS. 27A-27C, flowcharts depicting a process for postprocessing trace records having synchronized metric variables in accordance with a preferred embodiment of the present invention.

[0051] With reference now to the figures, and in particular with reference to FIG. 1, a pictorial representation of a distributed data processing system in which the present invention may be implemented is depicted.

[0052] Distributed data processing system 100 is a network of computers in which the present invention may be implemented. Distributed data processing system 100 contains a network 102, which is the medium used to provide communications links between various devices and computers connected together within distributed data processing system 100. Network 102 may include permanent connections, such as wire or fiber optic cables, or temporary connections made through telephone connections.

[0053] In the depicted example, a server 104 is connected to network 102 along with storage unit 106. In addition, clients 108, 110, and 112 also are connected to a network 102. These clients 108, 110, and 112 may be, for example, personal computers or network computers. For i-purposes of this application, a network computer is any computer, coupled to a network, which receives a program or other application from another computer coupled to the network. In the depicted example, server 104 provides data, such as boot files, operating system images, and applications to clients 108-112. Clients 108, 110, and 112 are clients to server 104. Distributed data processing system 100 may include additional servers, clients, and other devices not shown. In the depicted example, distributed data processing system 100 is the Internet with network 102 representing a worldwide collection of networks and gateways that use the TCP/IP suite of protocols to communicate with one another. At the heart of the Internet is a backbone of high-speed data communication lines between major nodes or host computers, consisting of thousands of commercial, government, educational, and other computer systems, that route data and messages. Of course, distributed data processing system 100 also may be implemented as a number of different types of networks, such as, for example, an Intranet or a local area network.

[0054] FIG. 1 is intended as an example, and not as an architectural limitation for the processes of the present invention.

[0055] With reference now to FIG. 2A, a block diagram of a data processing system which may be implemented as a server, such as server 104 in FIG. 1, is depicted in accordance to the present invention. Data processing system 200 may be a symmetric multiprocessor (SMP) system including a plurality of processors 202 and 204 connected to system bus 206. Alternatively, a single processor system may be employed. Also connected to system bus 206 is memory controller/cache 208, which provides an interface to local memory 209. I/O Bus Bridge 210 is connected to system bus 206 and provides an interface to I/O bus 212. Memory controller/cache 208 and I/O Bus Bridge 210 may be integrated as depicted.

[0056] Peripheral component interconnect (PCI) bus bridge 214 connected to I/O bus 212 provides an interface to PCI local bus 216. A modem 218 may be connected to PCI local bus 216. Typical PCI bus implementations will support four PCI expansion slots or add-in connectors. Communications links to network computers 108-112 in FIG. 1 may be provided through modem 218 and network adapter 220 connected to PCI local bus 216 through add-in boards.

[0057] Additional PCI bus bridges 222 and 224 provide interfaces for additional PCI buses 226 and 228, from which additional modems or network adapters may be supported. In this manner, server 200 allows connections to multiple network computers. A memory mapped graphics adapter 230 and hard disk 232 may also be connected to I/O bus 212 as depicted, either directly or indirectly.

[0058] Those of ordinary skill in the art will appreciate that the hardware depicted in FIG. 2A may vary. For example, other peripheral devices, such as optical disk drive and the like also may be used in addition or in place of the hardware depicted. The depicted example is not meant to imply architectural limitations with respect to the present invention.

[0059] The data processing system depicted in FIG. 2A may be, for example, an IBM RISC/System 6000 system, a product of International Business Machines Corporation in Armonk, N.Y., running the Advanced Interactive Executive (AIX) operating system.

[0060] With reference now to FIG. 2B, a block diagram of a data processing system in which the present invention may be implemented is illustrated. Data processing system 250 is an example of a client computer. Data processing system 250 employs a peripheral component interconnect (PCI) local bus architecture. Although the depicted example employs a PCI bus, other bus architectures such as Micro Channel and ISA may be used. Processor 252 and main memory 254 are connected to PCI local bus 256 through PCI Bridge 258. PCI Bridge 258 also may include an integrated memory-controller and cache memory for processor 252. Additional connections to PCI local bus 256 may be made through direct component interconnection or through add-in boards. In the depicted example, local area network (LAN) adapter 260, SCSI host bus adapter 262, and expansion bus interface 264 are connected to PCI local bus 256 by direct component connection. In contrast, audio adapter 266, graphics adapter 268, and audio/video adapter (A/V) 269 are connected to PCI local bus 266 by add-in boards inserted into expansion slots. Expansion bus interface 264 provides a connection for a keyboard and mouse iadapter 270, modem 272, and additional memory 274. SCSI host bus adapter 262 provides a connection for hard disk drive 276, tape drive 278, and CD-ROM 280 in the depicted example. Typical PCI local bus implementations will support three or four PCI expansion slots or add-in connectors.

[0061] An operating system runs on processor 252 and is used to coordinate and provide control of various components within data processing system 250 in FIG. 2B. The operating system may be a commercially available operating system such as JavaOS for Business™ or OS/2™, which are available from International Business Machines Corporations™. JavaOS is loaded from a server on a network to a network client and supports Java programs and applets. A couple of characteristics of JavaOS that are favorable for performing traces with stack unwinds, as described below, are that JavaOS does not support paging or virtual memory. An object-oriented programming system such as Java may run in conjunction with the operating system and may provide calls to the operating system from Java programs or applications executing on data processing system 250. Instructions for the operating system, the object-oriented operating system, and applications or programs are located on storage devices, such as hard disk drive 276 and may be loaded into main memory 254 for execution by processor 252. Hard disk drives are often absent and memory is constrained when data processing system 250 is used as a network client.

[0062] Those of ordinary skill in the art will appreciate that the hardware in FIG. 2B may vary depending on the implementation. For example, other peripheral devices, such as optical disk drives and the like may be used in addition to or in place of the hardware depicted in FIG. 2B. The depicted example is not meant to imply architectural limitations with respect to the present invention. For example, the processes of the present invention may be applied to a multiprocessor data processing system.

[0063] The present invention provides a process and system for profiling software applications. Although the present invention may operate on a variety of computer platforms and operating systems, it may also operate within a Java runtime environment. Hence, the present invention may operate in conjunction with a Java virtual machine (JVM) yet within the boundaries of a Jvm as defined by Java standard specifications. In order to provide a context for the present invention, portions of the operation of a Jvm according to Java specifications are herein described.

[0064] With reference now to FIG. 3A, a block diagram illustrates the relationship of software components operating within a computer system that may implement the present invention. Java-based system 300 contains platform specific operating system 302 that provides hardware and system support to software executing on a specific hardware platform. Jvm 304 is one software application that may execute in conjunction with the operating system. Jvm 304 provides a Java run-time environment with the ability to execute Java application or applet 306, which is a program, servlet, or software component written in the Java programming language. The computer system in which Jvm 304 operates may be similar to data processing system 200 or computer 100 described above. However, Jvm 304 may be implemented in dedicated hardware on a so-called Java chip, Java-on-silicon, or Java processor with an embedded picoJava core.

[0065] At the center of a Java run-time environment is the Jvm, which supports all aspects of Java's environment, including its architecture, security features, mobility across networks, and platform independence.

[0066] The Jvm is a virtual computer, i.e. a computer that is specified abstractly. The specification defines certain features that every Jvm must implement, with some range of design choices that may depend upon the platform on which the Jvm is designed to execute. For example, all Jvms must execute Java bytecodes and may use a range of techniques to execute the instructions represented by the bytecodes. A Jvm may be implemented completely in software or somewhat in hardware. This flexibility allows different Jvms to be designed for mainframe computers and PDAs.

[0067] The Jvm is the name of a virtual computer component that actually executes Java programs. Java programs are not run directly by the central processor but instead by the Jvm, which is itself a piece of software running on the processor. The Jvm allows Java programs to be executed on a different platform as opposed to only the one platform for which the code was compiled. Java programs are compiled for the Jvm. In this manner, Java is able to support applications for many types of data processing systems, which may contain a variety of central processing units and operating systems architectures. To enable a Java application to execute on different types of data processing systems, a compiler typically generates an architecture-neutral file format. The compiled code is executable on many processors, given the presence of the Java run-time system. The Java compiler generates bytecode instructions that are nonspecific to a particular computer architecture. A bytecode is a machine independent-code generated by the Java compiler and executed by a Java interpreter. A Java interpreter is part of the Jvm that alternately decodes and interprets a bytecode or bytecodes. These bytecode instructions are designed to be easy to interpret on any computer and easily translated on the fly into native machine code. Byte codes may be translated into native code by a just-in-time compiler or JIT.

[0068] A Jvm must load class files and execute the bytecodes within them. The Jvm contains a class loader, which loads class files from an application and the class files from the Java application programming interfaces (APIs), which are needed by the application. The execution engine that executes the bytecodes may vary across platforms and implementations.

[0069] One type of software-based execution engine is a just-in-time compiler. With this type of execution, the bytecodes of a method are compiled to native machine code upon successful fulfillment of some type of criteria for jitting a method. The native machine code for the method is then cached and reused upon the next invocation of the method. The execution engine may also be implemented in hardware and embedded on a chip so that the Java bytecodes are executed natively. Jvms usually interpret bytecodes, but Jvms may also use other techniques, such as just-in-time compiling, to execute bytecodes.

[0070] Interpreting code provides an additional benefit. Rather than instrumenting the Java source code, the interpreter may be instrumented. Trace data may be generated via selected events and timers through the instrumented interpreter without modifying the source code. Profile instrumentation is discussed in more detail further below.

[0071] When an application is executed on a Jvm that is implemented in software on a platform-specific operating system, a Java application may interact with the host operating system by invoking native methods. A Java method is written in the Java language, compiled to bytecodes, and stored in class files. A native method is written in some other language and compiled to the native machine code of a particular processor. Native methods are stored in a dynamically linked library whose exact form is platform specific.

[0072] With reference now to FIG. 3B, a block diagram of a Jvm is depicted in accordance with a preferred embodiment of the present invention. Jvm 350 includes a class loader subsystem 352, which is a mechanism for loading types, such as classes and interfaces, given fully qualified names. Jvm 350 also contains runtime data areas 354, execution engine 356, native method interface 358, and memory management 374. Execution engine 356 is a mechanism for executing instructions contained in the methods of classes loaded by class loader subsystem 352. Execution engine 356 may be, for example, Java interpreter 362 or just-in-time compiler 360. Native method interface 358 allows access to resources in the underlying operating system. Native method interface 358 may be, for example, a Java native interface. Runtime data areas 354 contain native method stacks 364, Java stacks 366, PC registers 368, method area 370, and heap 372. These different data areas represent the organization of memory needed by Jvm 350 to execute a program.

[0073] Java stacks 366 are used to store the state of Java method invocations. When a new thread is launched, the Jvm creates a new Java stack for the thread. The Jvm performs only two operations directly on Java stacks: it pushes and pops frames. A thread's Java stack stores the state of Java method invocations for the thread. The state of a Java method invocation includes its local variables, the parameters with which it was invoked, its return value, if any, and intermediate calculations. Java stacks are composed of stack frames. A stack frame contains the state of a single Java method invocation. When a thread invokes a method, the Jvm pushes a new frame onto the Java stack of the thread. When the method completes, the Jvm pops the frame for that method and discards it. The Jvm does not have any registers for holding intermediate values; any Java instruction that requires or produces an intermediate value uses the stack for holding the intermediate values. In this manner, the Java instruction set is well defined for a variety of platform architectures.

[0074] PC registers 368 are used to indicate the next instruction to be executed. Each instantiated thread gets its own PC register (program counter) and Java stack. If the thread is executing a Jvm method, the value of the PC register indicates the next instruction to execute. If the thread is executing a native method, then the contents of the PC register are undefined. Native method stacks 364 store the state of invocations of native methods. The state of native method invocations is stored in an implementation-dependent way in native method stacks, registers, or other implementation-dependent memory areas. In some Jvm implementations, native method stacks 364 and Java stacks 366 are combined.

[0075] Method area 370 contains class data while heap 372 contains all instantiated objects. The Jvm specification strictly defines data types and operations. Most JVMs choose to have one method area and one heap, each of which are shared by all threads running inside the JVM. When the Jvm loads a class file, it parses information about a type from the binary data contained in the class file. It places this type information into the method area. Each time a class instance or array is created, the memory for the new object is allocated from heap 372. Jvm 350 includes an instruction that allocates memory space within the memory for heap 372 but includes no instruction for freeing that space within the memory. Memory management 374 in the depicted example manages memory space within the memory allocated to heap 370. Memory management 374 may include a garbage collector, which automatically reclaims memory used by objects that are no longer referenced. Additionally, a garbage collector also may move objects to reduce heap fragmentation.

[0076] The processes within the following figures provide an overall perspective of the many processes employed within the present invention: processes that generate event-based profiling information in the form of specific types of records in a trace file; processes that generate sample-based profiling information in the form of specific types of records in a trace file; processes that read the trace records to generate more useful information to be placed into profile reports; and

[0077] processes that generate the profile reports for the user of the profiling utility.

[0078] With reference now to FIG. 4, a block diagram depicts components used to profile processes in a data processing system. A trace program 400 is used to profile processes 402. Trace program 400 may be used to record data upon the execution of a hook, which is a specialized piece of code at a specific location in a routine or program in which other routines may be connected. Trace hooks are typically inserted for the purpose of debugging, performance analysis, or enhancing functionality. These trace hooks are employed to send trace data to trace program 400, which stores the trace data in buffer 404. The trace data in buffer 404 may be stored in a file for post-processing. With Java operating systems, the present invention employs trace hooks that aid in identifying methods that may be used in processes 402. In addition, since classes may be loaded and unloaded, these changes may also be identified using trace data. This is especially relevant with “network client” data processing systems, such as those that may operate under JavaOS, since classes and jitted methods may be loaded and unloaded more frequently due to the constrained memory and role as a network client.

[0079] With reference now to FIG. 5, a diagram depicts various phases in profiling the processes active in an operating system. Subject to memory constraints, the generated trace output may be as long and as detailed as the analyst requires for the purpose of profiling a particular program.

[0080] An initialization phase 500 is used to capture the state of the client machine at the time tracing is initiated. This trace initialization data includes trace records that identify all existing threads, all loaded classes, and all methods for the loaded classes. Records from trace data captured from hooks are written to indicate thread switches, interrupts, and loading and unloading of classes and jitted methods. Any class, which is loaded, has trace records that indicate the name of the class and its methods. In the depicted example, four byte IDs are used as identifiers for threads, classes, and methods. These IDs are associated with names output in the records. A record is written to indicate when all of the start up information has been written.

[0081] Next, during the profiling phase 502, trace records are written to a trace buffer or file. Trace records may originate from two types of profiling actions-event-based profiling and sample-based profiling. In the present invention, the trace file may have a combination of event-based records, such as those that may originate from a trace hook executed in response to a particular type of event, e.g., a method entry or method exit, and sample-based records, such as those that may originate from a stack walking function executed in response to a timer interrupt, e.g., a stack unwind record, also called a call stack record.

[0082] For example, the following process may occur during the profiling phase if the user of the profiling utility has requested sample-based profiling information. Each time a particular type of timer interrupt occurs, a trace record is written, which indicates the system program counter. This system program counter may be used to identify the routine that is interrupted. In the depicted example, a timer interrupt is used to initiate gathering of trace data. Of course, other types of interrupts may be used other than timer interrupts.

[0083] Interrupts based on a programmed performance monitor event or other types of periodic events may be employed.

[0084] In the post-processing phase 504, the data collected in the buffer is sent to a file for post-processing. In one configuration, the file may be sent to a server, which determines the profile for the processes on the client machine. Of course, depending on available resources, the post-processing also may be performed on the client machine. In post-processing phase 504, B-trees and/or hash tables may be employed to maintain names associated with the records in the trace file to be processed. A hash table employs hashing to convert an identifier or a key, meaningful to a user, into a value for the location of the corresponding data in the table. While processing trace records, the B-trees and/or hash tables are updated to reflect the current state of the client machine, including newly loaded jitted code or unloaded code. Also, in the post-processing phase 504, each trace record is processed in a serial manner. As soon as the indicator is encountered and all of the startup information has been processed, event-based trace records from trace hooks and sample-based trace records from timer interrupts are then processed. Timer interrupt information from the timer interrupt records are resolved with existing hash tables. In addition, this information identifies the thread and function being executed. The data is stored in hash tables with a count identifying the number of timer tick occurrences associated with each way of looking at the data. After all of the trace records are processed, the information is formatted for output in the form of a report.

[0085] Alternatively, trace information may be processed on the fly so that trace data structures are maintained during the profiling phase. In other words, while a profiling function, such as a timer interrupt, is executing, rather than (or in addition to) writing trace records to a buffer or file, the trace record information is processed to construct and maintain any appropriate data structures.

[0086] For example, during the processing of a timer interrupt during the profiling phase, a determination could be made as to whether the code being interrupted is being interpreted by the Java interpreter. If the code being interrupted is interpreted, the method ID of the method being interpreted may be placed in the trace record. In addition, the name of the method may be obtained and placed in the appropriate B-tree. Once the profiling phase has completed, the data structures may contain all the information necessary for generating a profile report without the need for post-processing of the trace file.

[0087] With reference now to FIG. 6, a flowchart depicts a process used by a trace program for generating trace records from processes executing on a data processing system. FIG. 6 provides further detail concerning the generation of trace records that were not described with respect to FIG. 5.

[0088] Trace records may be produced by the execution of small pieces of code called “hooks”. Hooks may be inserted in various ways into the code executed by processes, including statically (source code) and dynamically (through modification of a loaded executable). This process is employed after trace hooks have already been inserted into the process or processes of interest. The process begins by allocating a buffer (step 600), such as buffer 404 in FIG. 4. Next, in the depicted example, trace hooks are turned on (step 602), and tracing of the processes on the system begins (step 604). Trace data is received from the processes of interest (step 606). This type of tracing may be performed during phases 500 and/or 502. This trace data is stored as trace records in the buffer (step 608). A determination is made as to whether tracing has finished (step 610). Tracing finishes when the trace buffer has been filled or the user stops tracing via a command and requests that the buffer contents be sent to file. If tracing has not finished, the process returns to step 606 as described above.

[0089] Otherwise, when tracing is finished, the buffer contents are sent to a file for post-processing (step 612). A report is then generated in post-processing (step 614) with the process terminating thereafter.

[0090] Although the depicted example uses post-processing to analyze the trace records, the processes of the present invention may be used to process trace information in real-time depending on the implementation.

[0091] With reference now to FIG. 7, a flowchart depicts a process that may be used during an interrupt handler trace hook.

[0092] The process begins by obtaining a program counter and an interrupted thread ID (steps 700-701). Typically, the program counter is available in one of the saved program stack areas. Thereafter, a determination is made as to whether the code being interrupted is interpreted code (step 702). This determination may be made by determining whether the program counter is within an address range for the interpreter used to interpret bytecodes. If the code being interrupted is interpreted, a method block address is obtained for the code being interpreted (step 704). A trace record is then written (step 706). The trace record is written by sending the trace information to a trace program, such as trace program 400, which generates trace records for post-processing in the depicted example. This trace record is referred to as an interrupt record, or an interrupt hook.

[0093] This type of trace may be performed during phase 502. Alternatively, a similar process, i.e. determining whether code that was interrupted is interpreted code, may occur during post-processing of a trace file.

[0094] In addition to event-based profiling, a set of processes may be employed to obtain sample-based profiling information. As applications execute, the applications may be periodically interrupted in order to obtain information about the current runtime environment. This information may be written to a buffer or file for post-processing, or the information may be processed on the fly into data structures representing an ongoing history of the runtime environment. FIGS. 8 and 9 describe sample-based profiling in more detail.

[0095] A sample-based profiler obtains information from the stack of an interrupted thread. The thread is interrupted by a timer interrupt presently available in many operating systems. The user of the trace facility selects either the program counter option or the stack unwind option, which may be accomplished by enabling one major code or another major code, as described further below. This timer interrupt is employed to sample information from a call stack. By walking back up the call stack, a complete call stack can be obtained for analysis. A “stack walk” may also be described as a “stack unwind”, and the process of “walking the stack” may also be described as “unwinding the stack”. Each of these terms illustrates a different metaphor for the process. The process can be described as “walking” as the process must obtain and process the stack frames step-by-step. The process may also be described as “unwinding” as the process must obtain and process the stack frames that point to one another, and these pointers and their information must be “unwound” through many pointer dereferences.

[0096] The stack unwind follows the sequence of functions/method calls at the time of the interrupt. A call stack is an ordered list of routines plus offsets within routines (i.e. modules, functions, methods, etc.) that have been entered during execution of a program. For example, if routine A calls routine B, and then routine B calls routine C, while the processor is executing instructions in routine C, the call stack is ABC. When control returns from routine C back to routine B, the call stack is AB. For more compact presentation and ease of interpretation within a generated report, the names of the routines are presented without any information about offsets. Offsets could be used for more detailed analysis of the execution of a program, however, offsets are not considered further herein.

[0097] Thus, during timer interrupt processing or at post-processing, the generated sample-based profile information reflects a sampling of call stacks, not just leaves of the possible call stacks, as in some program counter sampling techniques. A leaf is a node at the end of a branch, i.e. a node that has no descendants. A descendant is a child of a parent node, and a leaf is a node that has no children.

[0098] With reference now to FIG. 8, a diagram depicts the call stack containing stack frames. A “stack” is a region of reserved memory in which a program or programs store status data, such as procedure and function call addresses, passed parameters, and sometimes local variables. A “stack frame” is a portion of a thread's stack that represents local storage (arguments, return addresses, return values, and local variables) for a single function invocation. Every active thread of execution has a portion of system memory allocated for its stack space. A thread's stack consists of sequences of stack frames. The set of frames on a thread's stack represent the state of execution of that thread at any time. Since stack frames are typically interlinked (e.g., each stack frame points to the previous stack frame), it is often possible to trace back up the sequence of stack frames and develop the “call stack”. A call stack represents all not-yet-completed function calls—in other words, it reflects the function invocation sequence at any point in time. Call stack 800 includes information identifying the routine that is currently running, the routine that invoked it, and so on all the way up to the main program. Call stack 800 includes a number of stack frames 802, 804, 806, and 808. In the depicted example, stack frame 802 is at the top of call stack 800, while stack frame 808 is located at the bottom of call stack 800. The top of the call stack is also referred to as the “root”. The timer interrupt (found in most operating systems) is modified to obtain the program counter value (pcv) of the interrupted thread, together with the pointer to the currently active stack frame for that thread. In the Intel architecture, this is typically represented by the contents of registers: EIP (program counter) and EBP (pointer to stack frame). By accessing the currently active stack frame, it is possible to take advantage of the (typical) stack frame linkage convention in order to chain all of the frames together. Part of the standard linkage convention also dictates that the function return address be placed just above the invoked-function's stack frame; this can be used to ascertain the address for the invoked function. While this discussion employs an Intel-based architecture, this example is not a restriction. Most architectures employ linkage conventions that can be similarly navigated by a modified profiling interrupt handler.

[0099] When a timer interrupt occurs, the first parameter acquired is the program counter value. The next value is the pointer to the top of the current stack frame for the interrupted thread. In the depicted example, this value would point to EBP 808ain stack frame 808. In turn, EBP 808apoints to EBP 806ain stack frame 806, which in turn points to EBP 804ain stack frame 804. In turn, this EBP points to EBP 802ain stack frame 802. Within stack frames 802-808 are EIPs 802b-808b, which identify the calling routine's return address. The routines may be identified from these addresses. Thus, routines are defined by collecting all of the return addresses by walking up or backwards through the stack.

[0100] With reference now to the FIG. 9, an illustration of a call stack is depicted. A call stack, such as call stack 900 is obtained by walking the call stack. A call stack is obtained each time a periodic event, such as, for example, a timer interrupt occurs. These call stacks may be stored as call stack unwind trace records within the trace file for post-processing or may be processed on-the-fly while the program continues to execute. In the depicted example, call stack 900 contains a pid 902, which is the process identifier, and a tid 904, which is the thread identifier. Call stack 900 also contains addresses addr1906, addr2908 . . . addrN 910. In this example, addr1906 represents the value of the program counter at the time of the interrupt. This address occurs somewhere within the scope of the interrupted function. addr2908 represents an address within the process that called the function that was interrupted. For Intel-processor-based data processing systems, it represents the return address for that call; decrementing that value by 4 results in the address of the actual call, also known as the call-site. This corresponds with EIP 808bin FIG. 8; addrN 910 is the top of the call stack (EIP 802b). The call stack that would be returned if the timer interrupt interrupted the thread whose call stack state is depicted in FIG. 8 would consist of: a pid, which is the process id of the interrupted thread; a tid, which is the thread id for the interrupted thread; a pcv, which is a program counter value (not shown on FIG. 8) for the interrupted thread;

[0101] EIP 808b; EIP 806b; EIP 804b; and EIP 802b. In terms of FIG. 9, pcv=addr1, EIP 808b=addr2, EIP 806b=addr3, EIP 804b=addr4, EIP 802b=addr5.

[0102] With reference now to FIG. 10A, a diagram of a program execution sequence along with the state of the call stack at each function entry/exit point is provided. The illustration shows entries and exits occurring at regular time intervals, but this is only a simplification for the illustration. If each function (A, B, C, and X in the figure) were instrumented with entry/exit event hooks, then complete accounting of the time spent within and below each function would be readily obtained. Note in FIG. 10A that at time 0, the executing thread is in routine C. The call stack at time 0 is C. At time 1, routine C calls routine A, and the call stack becomes CA and so on. It should be noted that the call stack in FIG. 10A is a reconstructed call stack that is generated by processing the event-based trace records in a trace file to follow such events as method entries and method exits.

[0103] The accounting technique and data structure is described in more detail further below. Unfortunately, this type of instrumentation can be expensive, can introduce bias, and in some cases, can be hard to apply. Sample-based profiling, by sampling the program's call stack, helps to alleviate the performance bias (and other complications) that entry/exit hooks produce. Consider FIG. 10B, in which the same program is executed but is being sampled on a regular basis (in the example, the interrupt occurs at a frequency equivalent to two timestamp values). Each sample includes a snapshot of the interrupted thread's call stack. Not all call stack combinations are seen with this technique (note that routine X does not show up at all in the set of call stack samples in FIG. 10B). This is an acceptable limitation of sampling. The idea is that with an appropriate sampling rate (e.g., 30-1000 times per second), the call stacks in which most of the time is spent will be identified. Although some call stacks are omitted, it is a minor issue provided these call stacks are combinations for which little time is consumed.

[0104] In the event-based traces, there is a fundamental assumption that the traces contain information about routine entries and matching routine exits. Often, entry-exit pairs are nested in the traces because routines call other routines. Time spent (or memory consumed) between entry into a routine and exit from the same routine is attributed to that routine, but a user of a profiling tool may want to distinguish between time spent directly in a routine and time spent in other routines that it calls.

[0105] FIG. 10C shows an example of the manner in which time may be expended by two routines: a program's “main” calls routine A at time “t” equal to zero; routine A computes for 1 ms and then calls routine B; routine B computes for 8 ms and then returns to routine A; routine A computes for 1 ms and then returns to “main”. From the point of view of “main”, routine A took 10 ms to execute, but most of that time was spent executing instructions in routine B and was not spent executing instructions within routine A. This is a useful piece of information for a person attempting to optimize the example program. In addition, if routine B is called from many places in the program, it might be useful to know how much of the time spent in routine B was on behalf of (or when called by) routine A and how much of the time was on behalf of other routines.

[0106] A fundamental concept in the output provided by the methods described herein is the call stack. The call stack consists of the routine that is currently running, the routine that invoked it, and so on all the way up to main. A profiler may add a higher, thread level with the pid/tid (the process IDs and thread IDs). In any case, an attempt is made to follow the trace event records, such as method entries and exits, as shown in FIG. 10A, to reconstruct the structure of the call stack frames while the program was executing at various times during the trace.

[0107] The post-processing of a trace file may result in a report consisting of three kinds of time spent in a routine, such as routine A: (1) base time—the time spent executing code in routine A itself; (2) cumulative time (or “cum time” for short)—the time spent executing in routine A plus all the time spent executing every routine that routine A calls (and all the routines they call, etc.); and (3) wall-clock time or elapsed time. This type of timing information may be obtained from event-based trace records as these records have timestamp information for each record.

[0108] A routine's cum time is the sum of all the time spent executing the routine plus the time spent executing any other routine while that routine is below it on the call stack. In the example above in FIG. 10C, routine A's base time is 2 ms, and its cum time is 10 ms. Routine B's base time is 8 ms, and its cum time is also 8 ms because it does not call any other routines. It should be noted that cum time may not be generated if a call stack tree is being generated on the fly—cum time may only be computed after the fact during the post-processing phase of a profile utility. For wall-clock or elapsed time, if while routine B was running, the system fielded an interrupt or suspended this thread to run another thread, or if routine B blocked waiting on a lock or I/O, then routine B and all the entries above routine B on the call stack accumulate elapsed time but not base or cum time. Base and cum time are unaffected by interrupts, dispatching, or blocking.

[0109] Base time only increases while a routine is running, and cum time only increases while the routine or a routine below it on the call stack is running.

[0110] In the example in FIG. 10C, routine A's elapsed time is the same as its cum time—10 ms. Changing the example slightly, suppose there was a 1 ms interrupt in the middle of B, as shown in FIG. 10D. Routine A's base and cum time are unchanged at 2 ms and 10 ms, but its elapsed time is now 11 ms.

[0111] Although base time, cum time and elapsed time were defined in terms of processor time spent in routines, sample based profiling is useful for attributing consumption of almost any system resource to a set of routines, as described in more detail below with respect to FIG. 11B. Referring to FIG. 10C again, if routine A initiated two disk I/O's, and then routine B initiated three more I/O's when called by routine A, routine A's “base I/O's” are two and routine A's “cum I/O's” are five. “Elapsed I/O's” would be all I/O's, including those by other threads and processes, which occurred between entry to routine A and exit from routine A. More general definitions for the accounting concepts during profiling would be the following: base—the amount of the tracked system resource consumed directly by this routine; cum—the amount of the tracked system resource consumed by this routine and all routines below it on the call stack; elapsed—the total amount of the tracked system resource consumed (by any routine) between entry to this routine and exit from the routine.

[0112] As noted above, FIGS. 10A-10D describe the process by which a reconstructed call stack may be generated by processing the event-based trace records in a trace file by following such events as method entries and method exits. Hence, although FIGS. 11A-14 describe call stack trees that may be applicable to processing sample-based trace records, the description below for generating or reconstructing call stacks and call stack trees in FIGS. 11A-14 is mainly directed to the processing of event-based trace records. With reference now to FIG. 11A, a diagram depicts a tree structure generated from trace data. This figure illustrates a call stack tree 1100 in which each node in tree structure 1100 represents a function entry point. Additionally, in each node in tree structure 1100, a number of statistics are recorded. In the depicted example, each node, nodes 1102-1108, contains an address (addr), a base time (BASE), cumulative time (CUM) and parent and children pointers. As noted above, this type of timing information may be obtained from event-based trace records as these records have timestamp information for each record. The address represents a function entry point. The base time represents the amount of time consumed directly by this thread executing this function.

[0113] The cumulative time is the amount of time consumed by this thread executing this function and all functions below it on the call stack. In the depicted example, pointers are included for each node. One pointer is a parent pointer, a pointer to the node's parent. Each node also contains a pointer to each child of the node.

[0114] Those of ordinary skill in the art will appreciate that tree structure 1100 may be implemented in a variety of ways and that many different types of statistics may be maintained at the nodes other than those in the depicted example.

[0115] The call stack is developed from looking back at all return addresses. These return addresses will resolve within the bodies of those functions. This information allows for accounting discrimination between distinct invocations of the same function. In other words, if function X has 2 distinct calls to function A, the time associated with those calls can be accounted for separately. However, most reports would not make this distinction.

[0116] With reference now to FIG. 11B, a call stack tree which reflects call stacks observed during a specific example of system execution will now be described. At each node in the tree, several statistics are recorded. In the example shown in FIG. 11B, the statistics are time-based statistics. The particular statistics shown include the number of distinct times the call stack is produced, the sum of the time spent in the call stack, the total time spent in the call stack plus the time in those call stacks invoked from this call stack (referred to as cumulative time), and the number of instances of this routine above this instance (indicating depth of recursion).

[0117] For example, at node 1152 in FIG. 11B, the call stack is CAB, and the statistics kept for this node are 2:3:4:1. Note that call stack CAB is first produced at time 2 in FIG. 10A, and is exited at time 3. Call stack CAB is produced again at time 4, and is exited at time 7. Thus, the first statistic indicates that this particular call stack, CAB, is produced twice in the trace. The second statistic indicates that call stack CAB exists for three units of time (at time 2, time 4, and time 6). The third statistic indicates the cumulative amount of time spent in call stack CAB and those call stacks invoked from call stack CAB (i.e., those call stacks having CAB as a prefix, in this case CABB). The cumulative time in the example shown in FIG. 11B is four units of time. Finally, the recursion depth of call stack CAB is one, as none of the three routines present in the call stack have been recursively entered.

[0118] Those skilled in the art will appreciate that the tree structure depicted in FIG. 11B may be implemented in a variety of ways, and a variety of different types of statistics may be maintained at each node. In the described embodiment, each node in the tree contains data and pointers. The data include the name of the routine at that node, and the four statistics discussed above. Of course, many other types of statistical information may be stored at each node. In the described embodiment, the pointers for each node include a pointer to the node's parent, a pointer to the first child of the node (i.e. the left-most child), a pointer to the next sibling of the node, and a pointer to the next instance of a given routine in the tree. For example, in FIG. 11B, node 1154 would contain a parent pointer to node 1156, a first child pointer to node 1158, a next sibling pointer equal to NULL (note that node 1154 does not have a next sibling), and a next instance pointer to node 1162. Those skilled in the art will appreciate that other pointers may be stored to make subsequent analysis more efficient. In addition, other structural elements, such as tables for the properties of a routine that are invariant across instances (e.g., the routine's name), may also be stored.

[0119] The type of performance information and statistics maintained at each node are not constrained to time-based performance statistics. The present invention may be used to present many types of trace information in a compact manner, which supports performance queries. For example, rather than keeping statistics regarding time, tracing may be used to track the number of Java bytecodes executed in each method (i.e., routine) called. The tree structure of the present invention would then contain statistics regarding bytecodes executed rather than time. In particular, the quantities recorded in the second and third categories would reflect the number of bytecodes executed rather than the amount of time spent in each method.

[0120] Tracing may also be used to track memory allocation and deallocation. Every time a routine creates an object, a trace record could be generated. The tree structure of the present invention would then be used to efficiently store and retrieve information regarding memory allocation. Each node would represent the number of method calls, the amount of memory allocated within a method, the amount of memory allocated by methods called by the method, and the number of methods above this instance (i.e., the measure of recursion). Those skilled in the art will appreciate that the tree structure of the present invention may be used to represent a variety of performance data in a manner which is very compact, and allows a wide variety of performance queries to be performed.

[0121] The tree structure shown in FIG. 11B depicts one way in which data may be pictorially presented to a user. The same data may also be presented to a user in tabular form as shown in FIG. 12.

[0122] With reference now to FIG. 12, a call stack tree presented as a table will now be described. Note that FIG. 12 contains a routine, pt_pidtid, which is the main process/thread, which calls routine C. Table 12 includes columns of data for Level 1230, RL 1232, Calls 1234, Base 1236, Cum 1238, and Indent 1240. Level 1230 is the tree level (counting from the root as level 0) of the node. RL 1232 is the recursion level. Calls 1234 is the number of occurrences of this particular call stack, i.e., the number of times this distinct call stack configuration occurs. Base 1236 is the total observed time in the particular call stack, i.e., the total time that the stack had exactly these routines on the stack. Cum 1238 is the total time in the particular call stack plus deeper levels below it. Indent 1240 depicts the level of the tree in an indented manner. From this type of call stack configuration information, it is possible to infer each unique call stack configuration, how many times the call stack configuration occurred, and how long it persisted on the stack. This type of information also provides the dynamic structure of a program, as it is possible to see which routine called which other routine.

[0123] However, there is no notion of time-order in the call stack tree. It cannot be inferred that routines at a certain level were called before or after other routines on the same level.

[0124] The pictorial view of the call stack tree, as illustrated in FIG. 11B, may be built dynamically or built statically using a trace text file or binary file as input. FIG. 13 depicts a flow chart of a method for building a call stack tree using a trace text file as input. In FIG. 13, the call stack tree is built to illustrate module entry and exit points.

[0125] With reference now to FIG. 13, it is first determined if there are more trace records in the trace text file (step 1350). If so, several pieces of data are obtained from the trace record, including the time, whether the event is an enter or an exit, and the module name (step 1352). Next, the last time increment is attributed to the current node in the tree (step 1354). A check is made to determine if the trace record is an enter or an exit record (step 1356). If it is an exit record, the tree is traversed to the parent (using the parent pointer), and the current tree node is set equal to the parent node (step 1358). If the trace record is an enter record, a check is made to determine if the module is already a child node of the current tree node (step 1360). If not, a new node is created for the module and it is attached to the tree below the current tree node (step 1362). The tree is then traversed to the module's node, and the current tree node is set equal to the module node (step 1364). The number of calls to the current tree node is then incremented (step 1366). This process is repeated for each trace record in the trace output file, until there are no more trace records to parse (step 1350).

[0126] With reference now to FIG. 14, a flow chart depicts a method for building a call stack tree dynamically as tracing is taking place during system execution. In FIG. 14, as an event is logged, it is added to the tree in real time. Preferably, a call stack tree is maintained for each thread. The call stack tree reflects the call stacks recorded to date, and a current tree node field indicates the current location in a particular tree. When an event occurs (step 1470), the thread ID is obtained (step 1471). The time, type of event (i.e., in this case, whether the event is a method entry or exit), the name of the module (i.e., method), location of the thread's call stack, and location of the thread's “current tree node” are then obtained (step 1472). The last time increment is attributed to the current tree node (step 1474). A check is made to determine if the trace event is an enter or an exit event (step 1476). If it is an exit event, the tree is traversed to the parent (using the parent pointer), and the current tree node is set equal to the parent node (step 1478). At this point, the tree can be dynamically pruned in order to reduce the amount of memory dedicated to its maintenance (step 1479). Pruning is discussed in more detail below. If the trace event is an enter event, a check is made to determine if the module is already a child node of the current tree node (step 1480). If not, a new node is created for the module, and it is attached to the tree below the current tree node (step 1482). The tree is then traversed to the module's node, and the current tree node is set equal to the module node (step 1484). The number of calls to the current tree node is then incremented (step 1486). Control is then passed back to the executing module, and the dynamic tracing/reduction program waits for the next event to occur (step 1488).

[0127] One of the advantages of using the dynamic tracing/reduction technique described in FIG. 14 is its enablement of long-term system trace collection with a finite memory buffer. Very detailed performance profiles may be obtained without the expense of an “infinite” trace buffer. Coupled with dynamic pruning, the method depicted in FIG. 14 can support a fixed-buffer-size trace mechanism.

[0128] The use of dynamic tracing and reduction (and dynamic pruning in some cases) is especially useful in profiling the performance characteristics of long running programs. In the case of long running programs, a finite trace buffer can severely impact the amount of useful trace information that may be collected and analyzed. By using dynamic tracing and reduction (and perhaps dynamic pruning), an accurate and informative performance profile may be obtained for a long running program.

[0129] Many long-running applications reach a type of steady-state, where every possible routine and call stack is present in the tree and updating statistics. Thus, trace data can be recorded and stored for such applications indefinitely within the constraints of a bounded memory requirement using dynamic pruning.

[0130] Pruning has value in reducing the memory requirement for those situations in which the call stacks are actually unbounded. For example, unbounded call stacks are produced by applications that load and run other applications.

[0131] Pruning can be performed in many ways, and a variety of pruning criteria is possible. For example, pruning decisions may be based on the amount of cumulative time attributed to a subtree. Note that pruning may be disabled unless the amount of memory dedicated to maintaining the call stack exceeds some limit. As an exit event is encountered (such as step 1478 in FIG. 14), the cumulative time associated with the current node is compared with the cumulative time associated with the parent node. If the ratio of these two cumulative times does not exceed a pruning threshold (e.g., 0.1), then the current node and all of its descendants are removed from the tree. The algorithm to build the tree proceeds as before by traversing to the parent, and changing the current node to the parent.

[0132] Many variations of the above pruning mechanism are possible. For example, the pruning threshold can be raised or lowered to regulate the level of pruning from very aggressive to none. More global techniques are also possible, including a periodic sweep of the entire call stack tree, removing all subtrees whose individual cumulative times are not a significant fraction of their parent node's cumulative times.

[0133] Data reduction allows analysis programs to easily and quickly answer many questions regarding how computing time was spent within the traced program. This information may be gathered by “walking the tree” and accumulating the data stored at various nodes within the call stack tree, from which it can be determined the amount of time spent strictly within routine A, the total amount of time spent in routine A and in the routines called by routine A either directly or indirectly, etc.

[0134] With reference now to FIG. 15A, a flowchart depicts a process for creating a call stack tree structure from call stack unwind records in a trace file. FIGS. 10A-14 above primarily showed the processes involved in generating a call stack tree from event-based trace records, which show events such as method entries and method exits. These types of trace records allow a call stack to be generated, usually during a postprocessing phase of the profile tool or utility. Using timer interrupts, a profiling function may walk an active call stack to generate a call stack unwind trace record. FIG. 15A describes a process for combining the information in a call stack unwind trace record into a call stack tree. The call stack tree may have been previously constructed from other call stack unwind trace records or from event-based trace records according to the methods described in FIGS. 10A-14.

[0135] The process begins by reading a call stack unwind record (step 1500). This step processes the call stack information in the record to determine what routines are or were executing when the timer interrupt occurs or occurred, depending on whether the call stack unwind record is being processed on-the-fly or is being postprocessed. A sample-based profiling function avoids, through the call stack unwind, the need for adding additional instructions to the program, which affects the performance and time spent in routines. Next, the tree structure for this process/thread (pid, tid) is located (step 1502). Then, the pointer (PTR) is set to the root of this tree structure by setting PTR=root(pid, tid) (step 1504). The index is set equal to N, which is the number of entries in the call stack (step 1506).

[0136] A determination is made as to whether the index is equal to zero (step 1508). If the index is equal to zero, the process then returns to determine whether additional call stack unwind trace records are present for processing (step 1510). If additional call stack unwind trace records are present, the process then returns to step 1500 to read another call stack unwind trace record. Otherwise, the process terminates.

[0137] On the other hand, if the index is not equal to zero, the process then sets sample_address equal to the call_stack_address [index] (step 1512). The B-tree is then used to lookup the address to get a routine name (step 1513). Next, a determination is made as to whether PTR.child.name for any child of PTR is equal to the looked-up routine name (step 1514). In other words, this step determines whether the routine name has ever been seen at this level in the tree structure. If the address has never been seen at this level in the tree structure, a new child of PTR is created and the PTR.child.name is set equal to the routine name, the variable PTR.child.BASE for the node is set equal to zero, and the variable PTR.child .CUM for the node is set equal to zero (step 1516). Thereafter, the cumulative time for the node is incremented by incrementing the variable PTR.child.CUM (step 1518). The process also proceeds to step 1518 from step 1514 if the address has been seen at this level. In the case of sample-based trace records, the “cumulative” time represents the number of times that this particular call stack configuration has been processed.

[0138] Next, a determination is made as to whether the sample address, sample_address, is equal the last address in the call stack sample, call_stack_address [1] (step 1520). If the sample address is equal to the address being processed, the base time for the node is incremented by incrementing the variable PTR.child.BASE (step 1522). The pointer PTR is then set equal to the child (step 1524), and the index is decremented (step 1526) with the process then returning to step 1508 as previously described. With reference again to step 1520, if the sample address is not equal to the address being processed, the process then proceeds to step 1524. In the depicted example in FIG. 15A, the process is used to process call stack unwind records recorded during execution of a program. The illustrated process also may be implemented to dynamically process call stack unwind records during execution of a program. For example, step 1510 may be modified to wait until the next timer interrupt occurs and then continue to loop back to step 1510 at the next interrupt.

[0139] The addresses obtained during sampling are used to identify functions. The functions are identified by mapping these addresses into functions.

[0140] With reference now to FIG. 15B, a flowchart depicts a process for identifying functions from an address obtained during sampling. The process begins by reading a program counter value that is obtained during sampling of the call stack (step 1550). A determination is made as to whether the end of file has been reached (step 1552). If the end of the file has not been reached, the program counter value is looked up in a global map (step 1554). A global map in the depicted example is a map of system and per process symbols that are generated from system loader information and application, library, and system symbol tables. A process plus function id is obtained from the global map in response to looking up the program counter value (step 1556). Thereafter, the process returns to step 1550. The function information may be used in generating reports, such as those described below. The process in FIG. 15B also may be used during execution of a program that is sampled.

[0141] With reference now to FIG. 16, a diagram of a record generated using the processes of present invention is depicted. Each routine in record 1600 is listed separately, along with information regarding the routine in FIG. 16. For example, Calls column 1602 lists the number of times each routine has been called. BASE column SAC contains the total time spent in the routine, while CUM column 1606 includes the cumulative time spent in the routine and all routines called by the routine. Name column 1608 contains the name of the routine. With reference now to FIG. 17, a diagram of another type of report that may be produced is depicted. The report depicted in FIG. 17 illustrates much of the same information found in FIG. 16, but in a slightly different format. As with FIG. 16, diagram 1700 includes information on calls, base time, and cumulative time.

[0142] FIG. 17 shows a sample-based trace output containing times spent within various routines as measured in microseconds. FIG. 17 contains one stanza (delimited by horizontal lines) for each routine that appears in the sample-based trace output. The stanza contains information about the routine itself on the line labeled “Self”, about who called it on lines labeled “Parent”, and about who the routine called on lines labeled “Child”. The stanzas are in order of cum time.

[0143] The third stanza is about routine A, as indicated by the line beginning with “Self.” The numbers on the “Self” line of this stanza show that routine A was called three times in this trace, once by routine C and twice by routine B. In the profile terminology, routines C and B are (immediate) parents of routine A. Routine A is a child of routines C and B. All the numbers on the “Parent” rows of the second stanza are breakdowns of routine A's corresponding numbers. Three microseconds of the seven microsecond total base time spent in A was when it was called by routine C, and three microseconds when it was first called by routine B, and another one microsecond when it was called by routine B for a second time. Likewise, in this example, half of routine A's fourteen microsecond cum time was spent on behalf of each parent.

[0144] Looking now at the second stanza, we see that routine C called routine B and routine A once each. All the numbers on “Child” rows are subsets of numbers from the child's profile. For example, of the three calls to routine A in this trace, one was by routine C; of routine A's seven microsecond total base time, three microseconds were while it was called directly by routine C; of routine A's fourteen microsecond cum time, seven microseconds was on behalf of routine C. Notice that these same numbers are the first row of the third stanza, where routine C is listed as one of routine A's parents.

[0145] The four relationships that are true of each stanza are summarized at the top of FIG. 17. First, the sum of the numbers in the Calls column for parents equals the number of calls on the self row. Second, the sum of the numbers in the Base column for parents equals Self's base. Third, the sum of the numbers in the Cum column for parents equals Self's Cum. These first three invariants are true because these characteristics are the definition of Parent; collectively they are supposed to account for all of Self's activities. Fourth, the Cum in the Child rows accounts for all of Self's Cum except for its own Base.

[0146] Program sampling contains information from the call stack and provides a profile, reflecting the sampling of an entire call stack, not just the leaves. Furthermore, the sample-based profiling technique may also be applied to other types of stacks. For example, with Java programs, a large amount of time is spent in a routine called the “interpreter”. If only the call stack was examined, the profile would not reveal much useful information. Since the interpreter also tracks information in its own stack, e.g., a Java stack (with its own linkage conventions), the process can be used to walk up the Java stack to obtain the calling sequence from the perspective of the interpreted Java program.

[0147] With reference now to FIG. 18, a figure depicts a report generated from a trace file containing both event-based profiling information (method entry/exits) and sample-based profiling information (stack unwinds). FIG. 18 is similar to FIG. 12, in which a call stack tree is presented as a report, except that FIG. 18 contains embedded stack walking information. Call stack tree 1800 contains two stack unwinds generated within the time period represented by the total of 342 ticks. Stack unwind identifier 1802 denotes the beginning of stack unwind information 1806, with the names of routines that are indented to the right containing the stack information that the stack walking process was able to discern. Stack unwind identifier 1804 denotes the beginning of stack unwind information 1808. In this example, “J:” identifies an interpreted Java method and “F:” identifies a native function, such as a native function within JavaOS. A call from a Java method to a native method is via “ExecuteJava.” Hence, at the point at which the stack walking process reaches a stack frame for an “ExecuteJava,” it cannot proceed any further up the stack as the stack frames are discontinued. The process for creating a tree containing both event-based nodes and sample-based nodes is described in more detail further below. In this case, identifiers 1802 and 1804 also denote the major code associated with the stack unwind.

[0148] With reference now to FIG. 19, a table depicts major codes and minor codes that may be employed to instrument software modules for profiling. In order to facilitate the merging of event-based profiling information and sample-based profiling information, a set of codes may be used to turn on and off various types of profiling functions.

[0149] For example, as shown in FIG. 19, the minor code for a stack unwind is designated as 0×7fffffff, which may be used for two different purposes. The first purpose, denoted with a major code of 0×40, is for a stack unwind during a timer interrupt. When this information is output into a trace file, the stack information that appears within the file will have been coded so that the stack information is analyzed as sample-based profiling information. The second purpose, denoted with a major code of 0×41, is for a stack unwind in an instrumented routine. This stack information could then be post-processed as event-based profiling information.

[0150] Other examples in the table show a profile or major code purpose of tracing jitted methods with a major code value of 0×50. Tracing of jitted methods may be distinguished based on the minor code that indicates method invocation or method exit. In contrast, a major code of 0×30 indicates a profiling purpose of instrumenting interpreted methods, while the minor code again indicates, with the same values, method invocation or method exit.

[0151] Referring back to FIG. 18, the connection can be made between the use of major and minor codes, the instrumentation of code, and the post-processing of profile information. In the generated report shown in FIG. 18, the stack unwind identifiers can be seen to be equal to 0×40, which, according to the table in FIG. 19, is a stack unwind generated in response to a timer interrupt. This type of stack unwind may have occurred in response to a regular interrupt that was created in order to generate a sampled profile of the executing software.

[0152] As noted in the last column of the table in FIG. 19, by using a utility that places a hook into a software module to be profiled, a stack unwind may be instrumented into a routine. If so, the output for this type of stack unwind will be designated with a major code of 0×41.

[0153] As discussed above, kernel threads are sometimes reused by the Jvm. When an operating system kernel reuses a kernel thread for a current Java thread, in cannot be known for certain whether the value of the kernel thread's metrics should be attributed to the current Java thread in its entirety. A portion of the change in the value of an accumulated metric for the reused kernel thread may be attributable to a previous Java thread. Therefore, when a profiler calls for the change in a value of an accumulated kernel thread metric variable, the value returned to the profiler might be too high because metrics for the kernel thread were accumulated for other Java threads. Profiling information for a Java thread, which gets its metric variable values from a reused kernel thread, is unreliable unless a means for apportioning the value of the change in a metric for a reused kernel thread ID between Java threads.

[0154] With reference now to FIG. 20, a block diagram that depicts a relationship to a profiler and other software components in multiple data processing systems capable of accurately tracking synchronized or nonsynchronized metric variables with support across multiple systems, in accordance with a preferred embodiment of the present invention. FIG. 20 depicts two systems, machine 2000 and machine 2050, each machine supports a uniprocessor system or a symmetric multiprocessing (SMP). In machine 2000, operating system kernel 2001 provides native support for the execution of programs and applications, such as Jvm 2002 in the data processing system. Jvm 2002 executes Java programs, possibly compiling the program via a just-in-time (JIT) compiler 2003. As Java applications execute, objects are allocated in a heap and the Jvm maintains heap information concerning the objects, such as, heap 1960 shown in FIG. 19. Profiler 2008 accepts events from Jvm 2002 instrumentation through Jvm profiling interface (JVMPI) 2006, and returns the information as required by the Jvm. Preferably, the profiler 2008 is a set of native runtime DLLs (dynamic link libraries) supported by operating system kernel 2000. Profiler 2008 generates tree structure, trace output, et cetera (not shown), as necessary to produce a runtime profile to an application developer monitoring the execution of a profiled program.

[0155] In accordance with a preferred embodiment of the present invention, operating system kernel 2001 allocates memory space for event buffer 2030, which contains space for trace records generated by operating system kernel 2001. Jvm 2002 utilizes operating system kernel 2001 for processing support. Operating system kernel 2001 controls one or more processors for processing threads for Jvm 2002. In the depicted example, operating r system kernel 2001 controls four SMP processors, P₀2020-P_n2028, in machine 2000. Each time operating system kernel 2001 receives an event, it gets a value for the metric variables on the processor having the event and writes a trace record describing the event to the single event buffer 2030, the event record will be described in detail below. One method for apportioning changes in the value of metric variables for profiling information is disclosed by Levine et al. in “METHOD AND SYSTEM FOR APPORTIONING CHANGES IN METRIC VARIABLES IN AN SYMMETRIC MULTIPROCESSOR (SMP) ENVIRONMENT”, U.S. application Ser. No. 09/612,340, Attorney Docket No. AUS990853US1 filed Jul. 6, 2000, which is incorporated by reference herein in its entirety.

[0156] In the depicted example, a value of a metric variable may be classified as either a discrete or non-discrete. Discrete metrics differ from non-discrete metrics in the way that their values accumulate. The accumulated value of a discrete metric is based on the occurrence of discrete, quantifiable events such as the consumption of a resource. For example, the value of a metric variable representing object allocations is a measure of discrete object allocation resources that are consumed by a specific processor. The value of a discrete metric accumulates only in response to a resource being consumed, in the example above, when objects are actually being allocated for a thread running on processor. At the processor level, the rate of change in the value of a discrete metric depends on the rate at which the resource is being consumed on a specific processor. It is therefore impossible to synchronize per-processor values for a discrete metric between individual processors because the rate of consumption of the resource varies from one processor to the next, depending on the specific thread being processed.

[0157] On the other hand, the value of a non-discrete metric is not based on the occurrence of any discrete event. The value of a non-discrete metric accumulates regardless whether a resource is actually being consumed on a processor or not. Additionally, the value of a metric variable accumulates on one processor at approximately the same rate as on another, however slight variations may exist due to, for example, differences in clock outputs between processors. Therefore, it is possible to synchronize the values of a non-discrete metric variable on one processor with another processor by neglecting the slight rate variation between the processors.

[0158] Examples of discrete metrics include count of object allocations and deallocations, number of bytes allocated and deallocated and accumulated time values, such as capturing 32 bit time values from a 64 bit clock source. An example of a non-discrete metric variable is time of day.

[0159] Machine 2050 is similar to machine 2000 except that machine 2050 maintains separated trace buffers, P₀buffer 2080-P_nBuffer 2088, for each processor P₀2070-P_n2078. Trace record files 2060-2068 are written from these buffers. Alternatively, a single trace file could be implemented that contains all the trace records from the separated trace buffers by organizing the trace records within the file by processor. For instance, the location of a particular processor's trace records within a file might be identified in the file header.

[0160] Finally, note that machines 2000 and 2050 are synchronized via metric synchronization cards 2040 and 2090. A typical metric synchronization card implementation would support one monotonically increasing synchronized metric which increments at the card connection frequency. Another implementation involves a common memory for updating synchronized metrics shared between machines. Individually, each card provides source for global values of a metric variable for all processors in the respective machine. By maintaining a global non-discrete metric variable in a single location within the system, the operating system kernel could retrieve the global metric variable value from a single buffer for any processor receiving an event. The operating system kernel is thereby relieved of the task of accessing separate locations for metric variable values for each processor. Event records which include the value of the global metric variable can then be postprocessed without maintaining a separate value for the last metric variable, PLastCum (M,p), for each processor. A postprocessor computes a global last metric variable and uses that value to calculate the change in a metric variable for all processors that are actively running a thread.

[0161] Taken together, metric synchronization cards 2040 and 2090 synchronize the value of global metric variable across a plurality of systems. Each time a processor receives an event, that processor's operating system kernel retrieves the global metric variable value from a single buffer within the system. Event records for all synchronized systems can be postprocessed by a single postprocessor without maintaining a separate last metric variable value for each processor in every system.

[0162] With respect to FIGS. 21A and 21B, flowcharts that depict writing a trace record to a single buffer and to individual processor's buffers, respectively, in accordance with a preferred embodiment of the present invention. The process begins with the operating system kernel allocating a single kernel buffer (trace buffer) for trace data (step 2102). Next, trace hooks, including dispatch hooks, are turned on (step 2104). In the single trace buffer case, dispatch hooks include processor ID and thread ID (PID/TID). Tracing then commences (step 2106) and the operating system kernel receives trace data (step 2108). The operating system kernel stores the trace data in the single trace buffer (step 2110). The trace data included in each event record stored in the single trace buffer comprises at least metric information, event type information and a processor ID and/or PID/TID. The process for writing a trace record to a single trace buffer is now complete.

[0163] FIG. 21B is a flowchart depicting a process for writing trace records into individual processor's buffers. The process begins with the operating system allocating a kernel buffer for each processor's trace data (step 2152). Next, the trace hooks, including dispatch hooks, are turned on (step 2154). In this case, the dispatch hooks include only PID/TID information to be written to a unique kernel buffer for each processor. Tracing is then started (step 2156) and the operating system kernel receives trace data (step 2158). In this case, the operating system kernel stores the trace data associated with each processor in the kernel buffer allocated for that processor. Trace data for the individual processor's buffer case includes at least metric data and event type information.

[0164] With respect to FIGS. 22A through 22D, diagrams of trace record contents are presented based on event type and kernel buffer allocation in accordance with a preferred embodiment of the present invention. Trace records generated from metric events will be passed to at least one trace file for postprocessing. In the postprocessing phase, the change in the value of a metric variable, for processor (p), Delta (M,p), will be computed and applied to the method running on processor (p). Therefore, the minimum information needed for this computation is the accumulated value of a metric variable for the processor, PCum (M,p) and information related to the event type on a specific processor (p). However, processor ID need not always be included in the trace record if the PID/TID is included.

[0165] With respect to FIG. 22A, a diagram of a dispatch trace record for a single buffer is presented in accordance with a preferred embodiment of the present invention. In response to a dispatch event, the identity of the old processor (Pold) is obtained from the last trace record for the process and thread (PID/TID). Similarly, the change in the value of the metric variable, Delta (M,p), may be calculated by the difference in the value of the accumulated metric variable for the present trace record and the last trace record for the process and thread (PID/TID). The current method to which Delta (M,p) must be applied is known from the last method entry. Therefore, a dispatch trace record for a single buffer need only contain a value for the accumulated metric variable, PID/TID information and the identity of the new processor (P_new) to which the process and thread (PID/TID) is dispatched.

[0166] Turning now to FIG. 22B, a diagram of a method entry or exit trace record for a single buffer is presented in accordance with a preferred embodiment of the present invention. Here again, the change in the value of the accumulated metric variable is calculated by the difference in the value of the accumulated metric variable in the present trace record in the last trace record for the process and thread (PID/TID). In this case, the processor ID may be given directly in the event information or the PID/TID may be included in the trace record. Therefore, a trace record for a method entry/exit recorded to a single buffer must include the value of the accumulated metric variable for the processor (p), PCum (M,p), event type information which includes method information concerning the entering or exit method, and information for recovering the processor ID. This information may be in the form of PID/TID information or instead the event type information may include the processor ID.

[0167] Because each of the trace record examples depicted above will be written to a single buffer, the trace record must include the processor ID directly or indirectly by including PID/TID information with which the processor ID may be derived. However, in the case of individual processor buffers, the processor ID may be derived from the specific kernel buffer containing the trace record. Thus, the trace record may be abbreviated by not containing the processor ID.

[0168] With respect to FIG. 22C, a diagram depicting a dispatch trace record for an individual processor's buffer in accordance with a preferred embodiment of the present invention. Once again, the change in the value of the accumulated metric variable for processor (p), may be calculated by finding the difference in the value of the accumulated metric variable between the present trace record and the last trace record in the file for the current process and thread (PID/TID). However, in this case, the thread dispatch will cause the trace record to be written to the new processor's (P_new) trace buffer. The previous trace record for PID/TID will be held in the old processor's (P_old) trace buffer. The new processor (P_new) can be identified by the processor's trace file in which the current record exists. Therefore, the event type information need not contain the identity of the new processor (p_new) In the case of the dispatch trace record written to an individual processor buffer, the individual trace record must include PID/TID, event type information and the value of the accumulated metric variable, PCum (M,p).

[0169] Turning now to FIG. 22D, a diagram illustrating a trace record for a method entry/exit event written to an individual processor buffer in accordance with a preferred embodiment of the present invention. In this case, the process and thread (PID/TID) have been previously dispatched to the processor (p) so the processor ID does not change. Therefore, the change in the value of the metric variable for processor (p), Delta (M,p), may be calculated by the difference in the value of the accumulated metric variable for the processor (p) in the current trace record and the last trace record in the processor's trace file. Because the processor ID is known and neither the processor ID nor the PID/TID have changed, the trace record need not include any processor ID information. The trace record for a metric entry/exit stored in an individual processor's trace buffer need only include event type information which identifies the method which is entering or exiting and the value of the accumulated metric variable for processor (p), PCum (M,p).

[0170] With respect to FIG. 23A and 23B, flowcharts depicting a generic process for writing a trace record in accordance with a preferred embodiment of the present invention. In this example, trace records may be written to either a single buffer or to individual processor buffers, and included in each trace record is metric variables which may be either discrete or non-discrete.

[0171] Additionally, non-discrete metric variables may be synchronized for all processors on the machine or, in fact, across a plurality of machines. The process begins with the operating system kernel receiving trace parameters from a trace hook (step 2302). Trace parameters include information which may be used in determining whether the metric variable is discrete or non-discrete and for determining if a non-discrete metric variable is synchronized. A check is made to determine whether all metrics are discrete (step 2304). Any metric variable (M) contains a plurality of individual metric variables (m₀, m₁,m₂. . . m_k). Individual metrics (m) may be discrete or non-discrete or a combination. If any individual metrics (m) are non-discrete, they must be checked for synchronization (step 2306). In absence of any non-discrete synchronized metrics, the operating system kernel gets PCum (M,p) for the processor processing the current thread (step 2308). Turning to step 2306, if on the other hand, an individual non-discrete metric is synchronized, then the operating system obtains the synchronized value of the accumulated metric variable, PCum (M) for any processor processing a thread having that particular individual metric (step 2310). The metric variable Pcum (M) is a global metric variable, which is maintained for all processors. By synchronizing the value of the accumulated metric variables across a machine, or across several machines, only a global metric variable must be maintained. Next, a check is made to determine if any discrete metric variables are being tracked (step 2320). If any discrete metrics are being tracked, the operating system gets the value of the accumulated metric variable for processor (p), PCum (M,p), for the processor (step 2322). Additionally, the process would flow directly to step 2322 from step 2304 if determined at step 2304 that all metrics were discrete. The process then flows to step 2324 where the event type is checked.

[0172] Returning to step 2320, if no discrete metrics are being tracked, the process flows again to step 2324 where the event type is checked. If the event is a thread dispatch event, the operating system kernel writes trace information for the event which includes the value of the accumulated metric variable for the processor (p), PCum (M,p), event type information and PID/TID to processor (p)'s trace buffer. Alternatively, if only a single trace buffer is being used, the operating system kernel writes the value of the accumulated metric variable for processor (p), PCum (M,p), event type information, including the processor ID and PID/TID (step 2330).

[0173] Returning to step 2324, if a thread dispatch event had not been received, then a method entry/exit must have occurred. In that case, the profiler passes the method entry/exit event information to the operating system which will be included in the event type information (step 2326). Finally, the operating system kernel writes trace information either to a processor's trace buffer or a single trace buffer (step 2328). If the operating system kernel is writing to an individual processor's trace buffer, then the trace information includes the event type information, including the method ID, and the value of the accumulated metric variable for processor (p), PCum (M,p). If the operating system kernel is writing to a single trace buffer, trace information must include event type information, including method ID, accumulated value of the metric variable for processor (p), PCum (M,p), and either PID/TID or the processor ID in the event type information.

[0174] Once trace information has been written into a trace buffer or buffers, the contents of each trace buffer can be written to a trace file.

[0175] FIG. 24A is a diagram depicting a trace file written from a single trace buffer in accordance with a preferred embodiment of the present invention. Initially, the file header will include the machine ID. The trace information contained in each record in the trace file will include trace information as described with respect to FIGS. 22A and 22B above.

[0176] With respect to FIG. 24B, a diagram depicting a plurality of trace files written from individual processor trace buffers in accordance with a preferred embodiment of the present invention. In this case, each file header includes not only the machine ID, but also the processor ID from which the trace buffer was written. Alternatively, the trace files for individual trace buffers could be merged into a single file by demarcating the extent of each processor's trace records. The trace information contained in each record in the individual trace files will include trace information as described above with respect to FIGS. 22C and 22D.

[0177] With reference to FIG. 24C, a diagram depicting a postprocessing table for tracking the variables necessary for tracking profiling information in a non-synchronized system, in accordance with a preferred embodiment of the present invention. During postprocessing, the postprocessor allocates memory space for a postprocessing table for maintaining the current values for the thread node identifier 2420, for the thread running on each processor (processor (p₀) 2412-processor (p_n) 2418)(using process and thread identifiers PID/TID 2420-PID/TID 2428). Additionally, the postprocessing table is used by the postprocessor for tracking the PLastCum values 2430 for the metric values running on each processor (processor (p₀) 2412-processor (p_n) 2418) (PLastCum (M,p₀) 2432-PLastCum (M,p_n) 2438. Only with thread node identifier 2420 and LastCum value 2430, can the postprocessor calculate the change of the value of the metric variable for each processor (p_n), Delta (M,p), and apply it to the proper method.

[0178] With reference to FIG. 24D, a diagram depicting a profiling tree structure in accordance with a preferred embodiment of the present invention. The depicted tree structure is used whether the metrics being tracked are synchronized or non-synchronized. The postprocessor allocates memory space in its own buffer for a profiling tree structure. A tree structure may contain a plurality of thread tree structures such as thread tree structure 2480. In the depicted example, the tree structure consists of a top node, thread node 2482 and five method nodes, nodes 2482-2490. Each thread node is identified by the PID/TID identifiers which are maintained in the post processing table. In each node in the tree structure, a number of statistics or metric variable values are recorded. In the depicted example, each node, nodes 2480-2490, contain at least a base metric variable (Base (M)), a place for cumulative metric variable (Cum (M)), which is calculated as requested and parent and children pointers. All thread nodes, such as thread node 2480 contain additional information including a node pointer to the current method node that is being processed, which may point to a method node or may point back to the thread node itself.

[0179] Method nodes, such as method nodes 2482-2090, may alternatively contain an address that represents a function entry point, of course the thread node, depicted in the figure as node 2480, will not have such an address. As discussed above with respect to FIG. 11, the metric information may be obtained from event-based trace records. The base metric variable in the node represents the amount of each tracked metric consumed directly by the thread executing this function. The cumulative metric variable is the amount of each metric consumed by the thread executing this function and all functions below it on the call stack. This is typically calculated at postprocessing time or in response to a report generation request. In the depicted example, node pointers are included for each node. One pointer is a parent pointer, a pointer to the node's parent. Each node also contains a pointer to each child of the node. Those of ordinary skill in the art will appreciate that the tree structure may be implemented in a variety of ways and that many different types of statistics may be maintained at the nodes other than those in the depicted example.

[0180] With respect to FIGS. 25A-25C, a flowchart depicting a process for postprocessing trace records having nonsynchronized metric variables in accordance with a preferred embodiment of the present invention. In this process, the trace records include nonsynchronized metric variables which are individually received for each processor by the operating system kernel. Therefore, the value of the change in the metric variable must be calculated for each processor's metric event and individually applied to the method running on that processor. The process begins by checking the file for another trace record (step 2502). If at any time another trace record does not exist in the file, the process ends. If, however, the trace record does exist, the postprocessor reads the raw trace record (step 2504). A postprocessing step may be included that converts separately recorded trace records to a single buffer format or converts trace records recorded to a single buffer to a multiple buffer format.

[0181] As discussed above, trace records maybe written to a single file for each system or to a single file for each processor in each system. In the case of postprocessing non-synchronized metric variables, a postprocessor can process one file at a time or may instead process a plurality of files simultaneously. In the simultaneous processing case, the postprocessor may retrieve trace records for any file because a postprocessing table is maintained for each system which has processor specific variables for each system. Before any computations can be made, the identity of the processor to which the trace record relates must be identified. The processor ID can be determined from either the trace record, directly or indirectly, or the trace record file header (step 2506).

[0182] As previously discussed, a dispatch trace record from a single trace buffer will contain PID/TID information. The postprocessor can determine the processor ID from the postprocessing table with the PID/TID. If the trace record is a method entry or exit from a single trace buffer, the trace record will include either the PID/TID or the processor ID in the event type information. Alternatively, if the trace record is from a trace file written from an individual processor's trace buffer, the processor ID will be contained in the trace record file header.

[0183] A determination is then made as to whether the event is a dispatch event or a method entry/exit event (step 2508). If the event is a dispatch event, the process flows to FIG. 25B where the postprocessing table is checked for an entry for the value of the last accumulated metric variable, PLastCum (M,p), for processor (p) (step 2512). If an entry does not exist for processor (p), then the postprocessor must only update the postprocessing table information for processor (p) without calculating the value of the change in the metric variable, Delta (M,p), because the postprocessing table had not previously been used for processor (p). The postprocessor enters PID/TID from the event type information of the trace record in the postprocessing table for processor (p) (step 2512). The postprocessor then sets the value of the last accumulated metric variable, PLastCum (M,p), held in the postprocessing table for processor (p), to the value of the accumulated metric variable for the processor, PCum (M,p) (step 2514). The postprocessor gets the value of the accumulated metric variable for processor (p), PCum (M,p), from the trace record. The value of the last accumulated metric variable, PLastCum (M,p), is set by:

[0184] PLastCum (M,p)=PCum (M,p)

[0185] Initial postprocessing a dispatch trace record is now complete.

[0186] Turning to step 2512, if the postprocessing table contains an entry for the last accumulated metric variable, PLastCum (M,p), for processor (p), then the value of the change in the accumulated metric variable for processor (p), Delta (M,p), may be calculated and applied to the method running on processor (p). Initially the postprocessor gets PLastCum (M,p) and PID/TID from the table for processor (p) (step 2520). The postprocessor then calculates the value of the change in the accumulated metric variable, Delta (M,p), by finding the difference between the value of the accumulated metric variable for processor (p), PCum (M,p), from the trace record and the value of the last accumulated metric variable for processor (p), PLastCum (M,p), read from the postprocessing table (step 2522). The value of the change in the metric variable, Delta (M,p) is calculated by:

[0187] Delta (M)=PCum (M,p)−PLastCum (M,p)

[0188] Next, the postprocessor gets the node pointer to the current method node from the PID/TID thread node (step 2524). The PID/TID entry in the postprocessing table for processor (p) identifies the current thread node in the tree structure for the thread running on processor (p). The thread node contains a node pointer to the current method node running on processor (p), which may point to the thread node itself. The postprocessor then updates the value of the base metric variable, Base (M) with the value of the change of the metric variable, Delta (M) (step 2526). The metric variable Base (M) is updated by:

[0189] Base (M)+=Delta (M)

[0190] Finally, the postprocessor enters the value of PID/TID from the trace record in the postprocessing table for processor (p), and deletes any other occurrence of the identical value of PID/TID from the trace record in the postprocessing table (step 2514). The postprocessor sets the value of the last accumulated metric variable for processor (p), PLastCum (M,p), to the value of the accumulated metric variable, PCum (M,p), from the trace record (step 2516). The value of the last accumulated metric variable, PLastCum (M,p), is set by:

[0191] PLastCum (M,p)=PCum (M,p)

[0192] Postprocessing a dispatch trace record on an idle processor is now complete.

[0193] Returning now to step 2508, if the trace record describes a method entry/exit event, the process flows to FIG. 25C, where the postprocessing table is initially checked for an entry for the value of the last accumulated metric variable for processor (p), PLastCum (M,p) (step 2530). If a PLastCum (M,p) entry is not present in the postprocessing table, then the postprocessing table has not been used to calculate the value of the change in the metric variable, Delta (M,p), for processor (p). In that case, the postprocessor gets the value of the accumulated metric variable for processor (p), PCum (M,p), from the trace record (step 2542). The postprocessor then sets the value of the entry of the last accumulated metric variable, PLastCum (M,p), for processor (p) in the postprocessing table to the value of the accumulated metric variable for processor (p), PCum (M,p) (step 2544). The metric variable PLastCum (M,p) is updated by:

[0194] PLastCum (M,p)=PCum (M,p)

[0195] The postprocessor then gets the new method ID and/or PID/TID from the event type information in the trace record and enters the PID/TID in the postprocessing table for processor (p) (2546). The postprocessor then determines whether a node currently exists in the tree structure for the new method and/or new PID/TID thread node (step 2548). If a node does not exist in the tree structure for either the new method or the new PID/TID thread node, the postprocessor creates the appropriate node in the tree structure (step 2550). Once a node exists for the current thread, the node pointer to the current method node held in the PID/TID thread node is changed to the current method node for thread PID/TID processed on processor (p) (step 2552). The node pointer to the current method node held in the PID/TID thread node may point to itself. Returning to step 2548, if a node currently exists in the tree structure for the new method and/or the new PID/TID thread node, the process flows directly to step 2552 without creating a new node in the tree structure. The process for updating the postprocessing table (and possibly the tree structure) for processor (p) is now complete.

[0196] Returning to step 2530, if the postprocessing table contains an entry value for the last accumulative metric variable, PLastCum (M,p) for processor (p), then the value of the base metric variable, Base (M), may be updated for the method currently running on processor (p). Initially the postprocessor gets the value of the accumulated metric variable for processor (p), PCum (M,p), from the trace record (step 2532). The values of the last accumulated metric variable, PLastCum (M,p) and PID/TID are read from the postprocessing table (step 2534). The postprocessor then calculates the value of the change in the metric variable, Delta (M) from the difference of the value of the accumulated metric variable for processor (p), PCum (M,p), and the value of the last accumulated metric variable for processor (p), PLastCum (M,p) (step 2536). The metric variable Delta (M) is calculated by:

[0197] Delta (M)=PCum (M,p)−PLastCum (M,p)

[0198] The postprocessor then gets the node pointer to the current node method from the PID/TID thread node (step 2538). The node pointer may point to the PID/TID thread node itself. Using the node pointer to the current method node, the value of the base metric variable, Base (M), is updated with the value of the change in the metric variable, Delta (M) (step 2540). The metric variable Base (M) is updated by:

[0199] Base (M)+=Delta (M)

[0200] The postprocessor then sets the value of the entry of the last accumulated metric variable, PLastCum (M,p), for processor (p) in the postprocessing table to the value of the accumulated metric variable for processor (p), PCum (M,p) (step 2544). The metric variable PLastCum (M,p) is updated by:

[0201] PLastCum (M,p)=PCum (M,p)

[0202] The postprocessor then gets the new method ID and/or PID/TID from the event type information in the trace record and enters the PID/TID in the postprocessing table for processor (p) (2546). The postprocessor then determines whether a node currently exists in the tree structure for the new method and/or new PID/TID thread node (step 2548). If a node does not exist in the tree structure for either the new method or the new PID/TID thread node, the postprocessor creates the appropriate node in the tree structure (step 2550). Once a node exists for the current thread, the node pointer to the current method node held in the PID/TID thread node is changed to the current method node for thread PID/TID processed on processor (p) (step 2552). The node pointer to the current method node held in the PID/TID thread node may point to itself. Returning to step 2548, if a node currently exists in the tree structure for the new method and/or the new PID/TID thread node, the process flows directly to step 2552 without creating a new node in the tree structure. The process for updating the base metric variable for the current method and the postprocessing table (and possibly the tree structure) for processor (p) using non-synchronized metric variables is now complete.

[0203] Although the example used to describe the preferred embodiment of the present invention postprocesses trace records, the trace information may instead be processed in realtime. Levine et al. describe realtime processing of profiling information in a SMP system in “METHOD AND SYSTEM FOR APPORTIONING CHANGES IN METRIC VARIABLES IN AN SYMMETRIC MULTIPROCESSOR (SMP) ENVIRONMENT”, U.S. application Ser. No. 09/612,340, Attorney Docket No. AUS990853US1, filed July 6, 2000. U.S. application Ser. No. 09/612,340 discloses two approaches for processing trace information in realtime, an application level approach and kernel level approach. Using the application level approach, the profiling application is modified to maintain the variables from the postprocessing table described in FIG. 24C above and then the profiling tree structure is generated as described by Attorney Docket No. AUS990853US 1 and here within. Alternatively, an operating system kernel is used for profiling trace information by first modifying the kernel with the functionality for constructing a profiling tree structure. The operating system kernel then tracks the variables from the postprocessing table described in FIG. 24C above. The above application level approach is supplemented for reusable thread kernels by Levine et al. in “METHOD AND SYSTEM FOR TRACING PROFILING INFORMATION IN AN APPLICATION USING PER THREAD METRIC VARIABLES WITH REUSED KERNEL THREADS”, U.S. application Ser. No. 09/612,349 filed Jul. 6, 2000 which is incorporated by reference herein in its entirety. Additionally, the above kernel level approach is supplemented for reusable thread kernels by Levine et al. in “METHOD AND SYSTEM FOR TRACING PROFILING INFORMATION USING PER THREAD METRIC VARIABLES WITH REUSED KERNEL THREADS”, U.S. application Ser. No. 09/612,350, Attorney Docket No. AUS000057US1, filed Jul. 6, 2000, which is also incorporated by reference herein in its entirety.

[0204] With reference to FIG. 26, a diagram illustrates a postprocessing table for tracking the variables necessary for processing profiling information in a synchronized system, in accordance with a preferred embodiment of the present invention. The postprocessing table for processing synchronized metric variables is identical to the postprocessing table depicted in FIG. 24C with the exception of the LastCum value column. When postprocessing trace records having synchronized metric variables, the postprocessor maintains the current values for the thread node identifier 2620, for the thread running on each processor (processor (p₀) 2612-processor (P_n) 2618) (using process and thread identifiers PID/TID 2620-PID/TID 2628). However, rather than tracking individual values for the last accumulated metric variable for each processor, PLastCum (M,p), the postprocessor needs only to allocate buffer space for a single global variable, PLastCum (M) 2630. In contrast to the above described method where the value of the change in a metric variable, Delta (M), is calculated for only the active thread running on the processor that generated the trace record, here each time a value of the change in a metric variable, Delta (M), is calculated it is applied to all thread nodes for the active thread running on any processor, regardless of whether the processor generated the current trace record.

[0205] A separate post processing table must be constructed for each system or a single postprocessing table may be constructed for postprocessing trace record files from multiple systems if the individual processor entries are identified by unique system.

[0206] With respect to FIGS. 27A-27C, a flowchart depicts a process for postprocessing trace records having synchronized metric variables in accordance with a preferred embodiment of the present invention. This process is similar in many respects to the process discussed above with respect to FIGS. 25A-25C, therefore, only the differences between the processes will be discussed in detail. Here, the trace records include synchronized metric variables which are obtained from a global metric variable which is maintained for all processors. In this case, when the trace records are postprocessed only a single, global, value of the last accumulated metric variable is maintained for all non-discrete metric variables for all processors on all machines. Therefore, each time a trace record is processed and the value of the last accumulated metric variable is updated, the base metric variables for each active thread's method or thread node running on any processor is updated. Therefore, the postprocessor need not track a value for each processor's last accumulated metric variable, only a global last metric variable which is set each time a trace record is processed.

[0207] The process begins by checking the file for another trace record (step 2702). If at any time another trace record does not exist in the file, the process ends. If, however, the trace record does exist, the postprocessor reads the raw trace record (step 2704).

[0208] Again, trace records maybe written to a single file for each system or a single file for each processor, for each system. The source of all accumulated metric variables which are written into each trace record is a global value of the accumulated metric variable, PCum (M), rather than the value of the metric variable for processor (p), PCum (M,p) as is used for non-synchronized metric variables.

[0209] Accordingly, the postprocessor need only maintain only one value for the last accumulated metric variable, a global value, for all trace files having synchronized metrics variable that are being processed. This poses a problem when reading the trace records from multiple files. Because only a global value of the last accumulated metric variable, PLastCum (M), is maintained, the postprocessor must either sequentially process the trace files or simultaneously process all trace files by reading trace records in order of the value of the accumulate metric variable, PCum (M). In the simultaneous processing case, only the trace record containing avalue of the accumulated metric variable, PCum (M), is used. That value of the accumulated metric variable, PCum (M), is closest value in any file to the global value of the metric variable, PLastCum (M) and will yield a valid value of Delta (M) for all active threads. Therefore, both the value of the accumulated metric variable, PCum (M) and the change in the metric variable, Delta (M), are treated as a global variables.

[0210] Returning to step 2704, a dispatch trace record from a single trace buffer will contain PID/TID information. The postprocessor determines the processor ID from the postprocessing table using the PID/TID containing a method entry/exit trace record from a single trace buffer or alternatively, if the trace record is from a trace file written from an individual processor's trace buffer, the processor ID will be contained in the trace record file header (step 2706).

[0211] A determination is then made as to whether the event is a dispatch event or a method entry/exit event (step 2708). If the event is a dispatch event, the process flows to FIG. 27B where a buffer is checked for the global value of the last accumulated metric variable, PLastCum (M)(step 2712). Only one global value of the last metric variable, PLastCum (M) is maintained for each active thread rather than one value of the last accumulated metric variable for each processor, PLastCum (M,p), as discussed above. If an entry value for PLastCum (M) does not exist, then the process must be starting and no records have thus far been read. The postprocessor enters PID/TID from the event type information of the trace record in the postprocessing table for processor (p) (step 2714). Then, the postprocessor sets the global value of the last accumulated metric variable, PLastCum (M), held in the buffer, to the value of the accumulated metric variable, PCum (M), read from the first trace record (each trace record must include a non-discrete metric variable value) (step 2716). The global value of the last accumulated metric variable, PLastCum (M), is set by:

[0212] PLastCum (M)=PCum (M)

[0213] Initial postprocessing a dispatch trace record is now complete.

[0214] Returning to step 2712, if the global value of the last accumulated metric variable, PLastCum (M), exists, then the global value of the change in the accumulated metric variable, Delta (M), may be calculated and applied to each active method running on each processor. Initially the postprocessor gets the global value of the last accumulated metric variable, PLastCum (M), from its buffer (step 2720). The postprocessor then calculates the global value of the change in the metric variable, Delta (M), by finding the difference between the global value of the accumulated metric variable, PCum (M), from the trace record, and the global value of the last accumulated metric variable, PLastCum (M), read from the buffer (step 2722). The global value of the change in the metric variable, Delta (M) is calculated for each active processor by:

[0215] Delta (M)=PCum (M)−PLastCum (M)

[0216] Next, the postprocessor gets the node pointer to the current method node from the PID/TID thread node of each active thread running on a processor from the postprocessing table (step 2724). The PID/TID entries in the postprocessing table identify the current thread nodes in the tree structure for the threads running on each active processor. The thread nodes contain node pointers to the current method nodes running on the individual processors, but may instead, point to the thread nodes themselves. The postprocessor then updates the value of the base metric variables, Base (M) for each active thread, with the global value of the change of the metric variable, Delta (M) (step 2726). The metric variable Base (M) is updated by:

[0217] Base (M)+=Delta (M)

[0218] Next, the postprocessor enters the value of PID/TID from the current trace record in the postprocessing table for only processor (p), and deletes any other occurrence of the identical value of PID/TID from the trace record in the postprocessing table (step 2714). The postprocessor then sets the global value of the last accumulated metric variable, PLastCum (M), to the global value of accumulated metric variable from the trace record, PCum (M) (step 2716). The value of the last accumulated metric variable, PLastCum (M), is set by:

[0219] PLastCum (M)=PCum (M)

[0220] Postprocessing a dispatch trace record is now complete.

[0221] Turning again to step 2708, if the trace record describes a method entry/exit event, the process flows to FIG. 27C, where the existence of an entry for the global value of the last accumulated metric variable, PLastCum (M) is checked (step 2730). If a PLastCum (M) does not exist, then the postprocessing table has not been used to calculate the value of the change in the metric variable, Delta (M). In that case, the postprocessor gets the global value of the accumulated metric variable for processor (p), PCum (M), from the first trace record (step 2742). In the case of simultaneously processing separate trace records, the trace record containing lowest value for the accumulated metric variable, Pcum (M) is used. The postprocessor then sets the global value of the last accumulated metric variable, PLastCum (M), in the buffer, to the value of the accumulated metric variable, PCum (M), read from the first trace record (step 2744). The metric variable PLastCum (M) is updated by:

[0222] PLastCum (M)=PCum (M)

[0223] The postprocessor gets the new method ID and/or PID/TID from the event type information in the trace record and enters the PID/TID in the postprocessing table for processor (p) (2746). Then the postprocessor determines whether a node currently exists in the tree structure for the new method and/or new PID/TID thread node (step 2748). If a node does not exist in the tree structure for either the new method or the new PID/TID thread node, the postprocessor creates the appropriate node in the tree structure (step 2750). Once a node exists for the current thread, the node pointer to the current method node held in the PID/TID thread node is changed to the current method node for thread PID/TID processed on processor (p) (step 2752). The node pointer to the current method node held in the PID/TID thread node may point to itself. Returning to step 2748, if a node currently exists in the tree structure for the new method and/or the new PID/TID thread node, the process flows directly to step 2752 without creating a new node in the tree structure. The process for updating the postprocessing table (and possibly the tree structure) for processor (p) is now complete.

[0224] Returning to step 2730, if a global value for the last accumulative metric variable, PLastCum (M), exists, then the global value of the base metric variable, Base (M), may be updated for every method currently running on any processor. Initially, the postprocessor gets the global value of the accumulated metric variable, PCum (M), from the trace record (step 2732). The global value of the last accumulated metric variable, PLastCum (M) is also retrieved (step 2734). The postprocessor then calculates the global value of the change in the metric variable, Delta (M) from the difference of the global value of the accumulated metric variable, PCum (M), and the global value of the last accumulated metric variable, PLastCum (M) (step 2736). The metric variable Delta (M) is calculated by:

[0225] Delta (M)=PCum (M)−PLastCum (M)

[0226] The postprocessor then gets the node pointers to the current thread nodes from the PID/TID thread node for each active thread from the postprocessing table (step 2738). The node pointer may point to the PID/TID thread node itself. Using the node pointers to the current method nodes, the values of the base metric variable, Base (M), held in the tree structure nodes for each active thread, are updated with the value of the change in the metric variable, Delta (M) (step 2740). The metric variable Base (M) is updated by:

[0227] Base (M)+=Delta (M)

[0228] The postprocessor then sets the global value the last accumulated metric variable, PLastCum (M), to the global value of the accumulated metric variable, PCum (M) (step 2744). The global metric variable PLastCum (M) is updated by:

[0229] PLastCum (M)=PCum (M)

[0230] Next, the postprocessor gets the new method ID and/or PID/TID from the event type information in the trace record and enters the PID/TID in the postprocessing table for processor (p) (2746). The postprocessor then determines whether a node currently exists in the tree structure for the new method and/or new PID/TID thread node (step 2748). If a node does not exist in the tree structure for either the new method or the new PID/TID thread node, the postprocessor creates the appropriate node in the tree structure (step 2750). Once a node exists for the current thread, the node pointer to the current method node held in the PID/TID thread node is changed to the current method node for thread PID/TID processed on processor (p) (step 2752). Again, the node pointer to the current method node held in the PID/TID thread node may point to itself. Returning to step 2748, if a node currently exists in the tree structure for the new method and/or the new PID/TID thread node, the process flows directly to step 2752 without creating a new node in the tree structure. The process for updating the base metric variable using synchronized metric variables for all active methods and the postprocessing table (and possibly the tree structure) is now complete.

[0231] As discussed above, trace records may be processed in realtime rather than postprocessing the trace information using the above described processes.

[0232] It is important to note that while the present invention has been described in the context of a fully functioning data processing system, those of ordinary skill in the art will appreciate that the processes of the present invention are capable of being distributed in a form of a computer readable medium of instructions and a variety of forms and that the present invention applies equally regardless of the particular type of signal bearing media actually used to carry out the distribution. Examples of computer readable media include recordable-type media such as a floppy disc, a hard disk drive, a RAM, and CD-ROMs and transmission-type media, such as digital and analog communications links.

[0233] It is important to note that while the present invention has been described in the context of a single active,Jvm within an operating system, there are no constraints to its application to multiple Jvms. This generalization is well within the means of those with ordinary skill in the art.

[0234] The description of the present invention has been presented for purposes of illustration and description, but is not limited to be exhaustive or limited to the invention in the form disclosed. Many modifications and variations will be apparent to those of ordinary skill in the art. For example, the present invention may be applied to other interpreted programming systems and environments other than Java. The embodiment was chosen and described in order to best explain the principles of the invention the practical application and to enable others of ordinary skill in the art to understand the invention for various embodiments with various modifications as are suited to the particular use contemplated.

[0235] Java is a registered trademark of Sun Microsystems, Inc. for a programming language and associated software. JVM (or Jvm) is a registered trademark of Sun Microsystems, Inc. for a computer program. JavaOS is a registered trademark of Sun Microsystems, Inc. for a computer program.