JView Profiler Sample

This sample is located in \Samples\Profiler\Jviewprf.

Note   To use this sample, it is recommended that you have Microsoft® Visual C++® version 5.0 or higher installed.

Description
Using the Sample
Key Project Files
Technologies Demonstrated

Description

This sample demonstrates how the profiling option (/prof) for jview and wjview was implemented. The sample builds a .dll which enables profiling for special versions of jview and wjview built with PROFILER_HOOK defined. These special versions, called pjview and pwjview, can be built with the makefile in \Samples\Native\JView using the commands nmake cfg="PJView" and nmake cfg="PWJView".

Using the Sample

To compile the sample

Use Nmake.exe to compile the makefile in the \Samples\Profiler\Jviewprf directory. The resulting profiler program file (jviewprf.dll) can be found in the debug directory.

Use the following command to build a release version of the same file:

nmake cfg=release

This puts the profiler program into the release subdirectory.

To install the sample

Add Jviewprf.dll to your path, or set the JVIEW_PROFILER environment variable to the full name of Jviewprf.dll. Pjview and pwjview will be profiling-enabled, which makes the profiling command-line option (/prof) available in addition to the normal jview and wjview options.

To uninstall the sample

Delete jviewprf.dll from your path.

Pjview and Pwjview Command-Line Parameters

Pjview and pwjview support all the jview and wjview options plus the new /prof option. The syntax of the /prof option is as follows:

/prof[:<parameter>, <parameter>, …]

The following parameters can be used.

Parameter Description
call[time]s[=<methods>] Shows time execution in the specified methods.
calltrace[=<methods>] Prints entry and exit messages.
callparams[=<methods>] Prints parameters and return values.
permethodalloc Counts per-method allocations.
perclassalloc Counts per-class allocations.
gc Prints per-garbage-collection heap information.
heapdump Dumps a list of live objects at each garbage collection.
file=<filename> Appends profiling output to the specified file.
sample[=<frequency>] Samples method locations with the given frequency.
verbose Prints class loads and thread creations.
table Prints tabular output in simple space-delimited form.

You can specify several parameters on the command line, separating them with commas. To display this list of parameters on the command line, type:

pjview /prof:?

Example

pjview /prof:calls=MyClass.*+Pkg/mySample.bar()V,gc,file=prof.out.

This command does the following:

Profiler Examples

The following examples show how to use the /prof option with its parameters.

/prof:calls

Use this parameter to stop the application precisely at single method calls.

Code example:

public class Hello
{
             public static void main (String[] args)
                {
                    try { throw new Error(); } catch (Throwable e) {}
                    System.out.println("Hello");
                }
}

Profiler command and results:

C:\>pjview /prof:calls Hello
VM state: Interpreter loop, Fast interpreter loop, JIT compiler
Start time: 02/15/1999 15:28:45
Hello
End time: 02/15/1999 15:28:46
Method                                            Type Calls Throws Time
java/lang/System.<clinit>()V                      f    1     0      81250.81
java/io/OutputStreamWriter.write([CII)V           j    1     0      34115.50
sun/io/CharToByteConverter.getDefault()Lsun/io/CharToByteConverter;
                                                  j    2     0      26027.04
java/io/PrintStream.write(Ljava/lang/String;)V    j    1     0      17455.01
java/io/PrintStream.print(Ljava/lang/String;)V    j    1     0      13404.49
java/io/BufferedWriter.flushBuffer()V             j    1     0      12155.73
java/io/BufferedWriter.write(Ljava/lang/String;II)V
                                                  j    1     0      11854.02
java/io/PrintStream.newLine()V                    j    1     0      11729.14
java/io/Writer.write(Ljava/lang/String;)V         j    1     0      11005.86
java/io/DataOutputStream.writeChars(Ljava/lang/String;)V
                                                  j    1     0      10472.00
java/io/OutputStreamWriter.<init>(Ljava/io/OutputStream;)V
                                                  j    2     0      10381.48
(...)
--- End of profiler output. ---

For each method, the results show the following:

/prof:calltrace and /prof:callparams

Use these parameters to see how a particular component in the code is used or which APIs are called. The callparams parameter is similar to calltrace, but also prints the parameters and the return value. To restrict the set of methods and reduce profiling overhead (which makes the application run faster), use wildcards with the parameter.

Profiler command and results for system class calls is as follows:

C:\>pjview /prof:callparams=java/lang/System.* Hello
VM state: Interpreter loop, Fast interpreter loop, JIT compiler
Start time: 02/15/1999 15:31:46
      3c java/lang/System.<clinit>()V [fast interpreted]
      3c  java/lang/System.nullInputStream()Ljava/io/InputStream; [JIT-compiled]

      3c   java/lang/System.currentTimeMillis()J [native]
      3c    return value: 919121506357
      3c   return value: null
      3c  java/lang/System.nullPrintStream()Ljava/io/PrintStream; [JIT-compiled]

      3c   java/lang/System.currentTimeMillis()J [native]
      3c    return value: 919121506377
      3c   return value: null
      3c  java/lang/System.nullPrintStream()Ljava/io/PrintStream; [JIT-compiled]

      3c   java/lang/System.currentTimeMillis()J [native]
      3c    return value: 919121506387
      3c   return value: null
      3c 
(...)

java/lang/System.getProperty(Ljava/lang/String;Ljava/lang/String;)
Ljava/lang/String; [JIT-compiled]
      3c   parameters: "file.encoding", "8859_1"
      3c   return value: "Cp1252"
      3c  java/lang/System.getProperty(Ljava/lang/String;)Ljava/lang/String;
[JIT-compiled]
      3c   parameters: "line.separator"
      3c   return value: "
"
      3c  java/lang/System.getProperty(Ljava/lang/String;Ljava/lang/String;)
Ljava/lang/String; [JIT-compiled]
      3c   parameters: "file.encoding", "8859_1"
      3c   return value: "Cp1252"
      3c  java/lang/System.getProperty(Ljava/lang/String;)Ljava/lang/String;
[JIT-compiled]
      3c   parameters: "line.separator"
      3c   return value: "
"
      3c  

(...)

End time: 02/15/1999 15:31:46
--- End of profiler output. ---

/prof:sample

Use this parameter to periodically stop the application or to specify when you want it to stop (for example, every 10 milliseconds).

Example code:

public class Loop
{
             static double d1 = 1.23;
             static double d2 = 4.56;

             static double compute ()
          {
                 return Math.sin(d1) * Math.tan(d1) * Math.pow(d1, d2);
          }

             public static void main (String[] args)
             {
                 long start = System.currentTimeMillis();
                 long stop = start + 1000;
                 double sum = 0;
                 double prod = 1;
                 while (System.currentTimeMillis() < stop)
              {
                  double result = compute();
                  sum += result;
                  prod *= result;
              }
          }
}

Profiler command and results are as follows:

C:\>pjview /prof:sample Loop
VM state: Interpreter loop, Fast interpreter loop, JIT compiler
Start time: 02/15/1999 15:45:55
End time: 02/15/1999 15:45:56
Total sampling overhead: 63 ms
Sampling frequency: 10 ms
333 total samples
Average accuracy of all samples: 24.2%
Average accuracy of method samples: 100.0%
Method                                                    Type Samples Accuracy
Loop.compute()D                                           j    34      100.00
java/lang/System.currentTimeMillis()J                     n    22      100.00
Loop.main([Ljava/lang/String;)V                           j    8       100.00
sun/io/CharToByteConverter.getConverter(Ljava/lang/String;)Lsun/io/CharToByteConverter;

(...)
                                                          j    2       100.00
java/lang/System.makeProps()V                             j    1       100.00
java/util/Hashtable.rehash()V                             j    1       100.00
java/lang/StringBuffer.<init>()V                          j    1       100.00
sun/io/CharToByteConverter.<init>()V                      j    1       100.00
java/util/Hashtable.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;
                                                          j    1       100.00
java/lang/System.initProperties2(Ljava/util/Properties;)Ljava/util/Properties;
                                                          n    1       100.00
--- End of profiler output ---

The Accuracy column is usually 100. In rare cases, the profiler APIs cannot accurately associate the current processor state with a Java method. The API then "guesses" and indicates that the sample has low accuracy.

/prof:permethodalloc

Use this parameter to determine where the objects are allocated.

Profiler command and results are as follows:

C:\>pjview /prof:permethodalloc Hello
VM state: Interpreter loop, Fast interpreter loop, JIT compiler
Start time: 02/15/1999 15:30:12
Hello
End time: 02/15/1999 15:30:12
Allocations:
937 objects
82870 bytes
                                                  Total       Per GC    Overall
Method                        Type           Num   Bytes   Num  Bytes  #/Bytes
java/lang/System.<clinit>()V  java.io.FileOutputStream
                                             2     32      0    10      0%  0%
java/io/PrintStream.<init>(Ljava/io/OutputStream;Z)V
                              java.io.OutputStreamWriter
                                             2     64      0    21      0%  0%
java/lang/System.makeProps()V com.ms.lang.SystemProperties
                                             1     40      0    13      0%  0%
java/lang/Class.getPrimitiveClass(Ljava/lang/String;)Ljava/lang/Class;
                              java.lang.Class
                                             2     64      0    21      0%  0%
.
.
.
--- End of profiler output. ---

The previous code shows the types of objects and the methods where they were created. The Total and PerGC columns show the length of the average allocation activity between garbage collections.

/prof:perclassalloc

This parameter is similar to permethodalloc, but it omits the method granularity (that is, to get the output of perclassalloc, add all the per-method numbers).

/prof:gc

This parameter is similar to perclassalloc, but it provides per-garbage-collection information exclusively.

Profiler command and results are as follows:

C:\>pjview /prof:gc Hello
VM state: Interpreter loop, Fast interpreter loop, JIT compiler
Start time: 02/15/1999 15:52:51
Hello
GC 1 duration: 1 ms
Heap dump duration: 2 ms
Total objects: 911
Gen Type                                        Total New  Live Bytes  Avg.age
1   java.io.FileOutputStream                    2     2    2    40     1.00
1   java.io.OutputStreamWriter                  2     2    2    72     1.00
1   com.ms.lang.SystemProperties                1     1    1    44     1.00
1   java.lang.Class                             3     3    3    108    1.00
1   [I                                          5     5    2    112    1.00
1   java.io.PrintStream                         2     2    2    72     1.00
1   java.io.FileDescriptor                      3     3    3    48     1.00
1   java.lang.OutOfMemoryError                  1     1    1    20     1.00
1   [Ljava.lang.String;                         1     1    1    20     1.00
1   java.io.DataOutputStream                    2     2    2    48     1.00
1   java.lang.StackOverflowError                1     1    1    20     1.00
1   [B                                          10    10   8    20586  1.00
1   java.util.HashtableEntry                    380   380  380  10640  1.00

(...)

In this example:

/prof:heapdump

Use this parameter to dump the entire heap contents at each garbage collection. To minimize the output, use the JVIEWProfiler class to enable and disable heap dumping from within the application. Heap dumping is enabled by default, which is shown in the following example.

void myMethod ()
{
             JVIEWProfiler.EnableHeapDumping(false);

// Do lots of stuff that causes uninteresting garbage collections.

             ...

                   // Now I want to see what's in the heap.

             JVIEWProfiler.EnableHeapDumping(true);
             System.gc();
             JVIEWProfiler.EnableHeapDumping(false);

             ...
}

/prof:table

Use this parameter to omit spacing, line wrapping, and alignment in the output. The result will be easier to import into another format (such as Microsoft® Excel).

Key Project Files

Allocprf.cpp

Allocprf.hpp

These files implement the permethodalloc parameter.

Callprof.cpp

Callprof.hpp

These files implement the calls parameter.

Calltrac.cpp

Calltrac.hpp

These files implement the calltrace and callparam parameters.

Gcprof.cpp

Gcprof.hpp

These files implement the gc and heapdump parameters.

Sampler.cpp

Sampler.hpp

These files implement the sample parameter.

Guids.cpp

Defines GUIDS used by the sample.

Jviewprf.hpp

Main.cpp

Contains the EventMonitor class, which implements IJavaEventMonitor2 for event dispatching. These files also implement profiler registration and output formatting.

Timer.cpp

Timer.hpp

Contains three forms of timers: a clock tick timer, a performance counter timer, and a CPU cycle timer.

JVIEWProfiler.java

Defines Java methods that a profiled Java application uses to control the profiler.

Project.hpp

Header file (precompiled).

Jviewprf.def

Defines exports of the DLL.

Resource.h

Jviewprf.rc

Defines string resources presented to the user.

Technologies Demonstrated

Profiler

© 1999 Microsoft Corporation. All rights reserved. Terms of use.