regarding profiling web application using JIP

Help
2009-04-13
2013-04-17
  • Hozaifa Naseem
    Hozaifa Naseem
    2009-04-13

    dear all...

    recently, i have started working with Java Interactive Profiler.
    i have successfully profiled a stand alone java class;
    but, i am not getting the right information while profiling the web application using JIP.

    i am not getting the details regarding methods, i.e. call count, how much time it is taking to execute, etc.

    also, let me know how can i transform the xml output file to html format.

    any suggestion will be helpful.

    thanks in advance,
    hozaifa.

     
    • Andrew Wilcox
      Andrew Wilcox
      2009-04-14

      Hi Hozaifa,

      In order to better help you with your profiling problem, please post your profile.properties file, a sample of the output you're getting and some additional information about what you were expecting to see.

      Unfortunately, I don't have anything that will transform the xml into html. You might considering using xslt.

      Andrew.

       
    • Hozaifa Naseem
      Hozaifa Naseem
      2009-04-15

      Hi Andrew,

      Thank you for writing.

      i have set the env. variable JAVA_OPTS as below:
      -javaagent:E:\Jip-src-1.1.1\profile\profile.jar -Dprofile.properties=E:\Jip-src-1.1.1\profile\profile.properties

      the profile.properties file is shown below:
      -------------------------------------------------
      # Is the profiler on or off when the app starts?
      # (on | off)
      # default = on
      #
      profiler=on
      #
      # Can the profiler be controlled remotely ?
      # (on | off)
      # default = off
      #
      remote=on
      #
      # TCP listen port for remote control
      # default =15599
      #
      port=15599
      #
      #
      ClassLoaderFilter.2=com.mentorgen.tools.profile.instrument.clfilter.WebAppClassLoaderFilter
      #
      # What is the maximum depth for thread dumps
      # (-1 means no limit)
      # default = -1
      # (you may also use 'compact')
      #
      thread-depth=-1
      #
      # When compacting thread dumps, what in the minimum total time you want
      # to show
      # default = 10 (ms)
      #
      thread.compact.threshold.ms=1
      #
      # What is the maximum number of methods to show in the method dump
      # (-1 means no limit)
      # default = -1
      # (you may also use 'compact')
      #
      max-method-count=-1
      #
      # defaults to 10 (ms)
      #
      method.compact.threshold.ms=1
      #
      # What is the default file name for the profile information
      # default=./profile.txt
      #
      file=E:/JIP Output/15 Apr
      #
      # What packages are excluded from the display
      # (comma separated)
      # Note: com.mentorgen.tools.profile is always excluded
      #
      #exlude=
      debug=off
      #
      # Track Object Allocation (very expensive)
      # values: on, off
      # default = off
      #
      track.object.alloc=on
      #
      output=both
      #output-method-signatures=yes
      #profiler-class=net.sourceforge.jiprof.timeline.TimeLineProfiler
      #clock-resolution=ms
      ----------------------------------------------------------------

      here goes the output file:

      +----------------------------------------------------------------------
      |  File: E:\JIP Output\15 Apr\20090415-113329.txt
      |  Date: 2009.04.15 11:33:29 AM
      +----------------------------------------------------------------------

      +------------------------------
      | Thread depth limit: Unlimited
      +------------------------------
      +------------------------------
      | Thread: 1
      +------------------------------
                    Time            Percent   
             ----------------- ---------------
      Count    Total      Net   Total     Net  Location
      =====    =====      ===   =====     ===  =========
           1      3.3      3.3   100.0   100.0  +--LogFactory:<init>    (org.apache.juli.logging)
      +------------------------------
      | Thread: 1 (interaction #2)
      +------------------------------
                    Time            Percent   
             ----------------- ---------------
      Count    Total      Net   Total     Net  Location
      =====    =====      ===   =====     ===  =========
           1     13.8      0.1   100.0     0.5  +--LogFactory:getLog    (org.apache.juli.logging)
           1      0.1      0.1     0.5     0.5  | +--LogFactory:getFactory    (org.apache.juli.logging)
           1     13.7      0.1    99.0     0.5  | +--LogFactory:getInstance    (org.apache.juli.logging)
           1     13.6     10.0    98.5    72.1  | | +--LogFactory:getInstance    (org.apache.juli.logging)
           1      3.6      0.1    26.4     0.6  | | | +--DirectJDKLog:getInstance    (org.apache.juli.logging)
           1      3.6      3.6    25.8    25.8  | | | | +--DirectJDKLog:<init>    (org.apache.juli.logging)
      +------------------------------
      | Thread: 1 (interaction #3)
      +------------------------------
                    Time            Percent   
             ----------------- ---------------
      Count    Total      Net   Total     Net  Location
      =====    =====      ===   =====     ===  =========
           1    315.3      0.1   100.0          +--Bootstrap:main    (org.apache.catalina.startup)
           1      0.1      0.1     0.0          | +--Bootstrap:<init>    (org.apache.catalina.startup)
           1    200.3     99.0    63.5    31.4  | +--Bootstrap:init    (org.apache.catalina.startup)
           1      0.1      0.1     0.0          | | +--Bootstrap:setCatalinaHome    (org.apache.catalina.startup)
           1      0.0      0.0     0.0          | | +--Bootstrap:setCatalinaBase    (org.apache.catalina.startup)
           1     99.7      0.1    31.6          | | +--Bootstrap:initClassLoaders    (org.apache.catalina.startup)
           3     99.6     90.5    31.6    28.7  | | | +--Bootstrap:createClassLoader    (org.apache.catalina.startup)
           2      0.6      0.1     0.2          | | | | +--LogFactory:getLog    (org.apache.juli.logging)
           2      0.0      0.0     0.0          | | | | | +--LogFactory:getFactory    (org.apache.juli.logging)
           2      0.4      0.1     0.1          | | | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           2      0.4      0.1     0.1          | | | | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           2      0.3      0.1     0.1          | | | | | | | +--DirectJDKLog:getInstance    (org.apache.juli.logging)
           2      0.2      0.2     0.1          | | | | | | | | +--DirectJDKLog:<init>    (org.apache.juli.logging)
           1      0.8      0.6     0.3     0.2  | | | | +--CatalinaProperties:loadProperties    (org.apache.catalina.startup)
           1      0.1      0.1     0.0          | | | | | +--CatalinaProperties:getConfigUrl    (org.apache.catalina.startup)
           1      0.1      0.1     0.0          | | | | | +--CatalinaProperties:getCatalinaBase    (org.apache.catalina.startup)
           1      0.1      0.1     0.0          | | | | | | +--CatalinaProperties:getCatalinaHome    (org.apache.catalina.startup)
           3      0.1      0.1     0.0          | | | | +--CatalinaProperties:getProperty    (org.apache.catalina.startup)
           2      0.1      0.1     0.0          | | | | +--Bootstrap:getCatalinaHome    (org.apache.catalina.startup)
           2      0.1      0.1     0.0          | | | | +--DirectJDKLog:isDebugEnabled    (org.apache.juli.logging)
           1      7.5      7.3     2.4     2.3  | | | | +--ClassLoaderFactory:createClassLoader    (org.apache.catalina.startup)
          20      0.1      0.1     0.0          | | | | | +--DirectJDKLog:isDebugEnabled    (org.apache.juli.logging)
           1      0.1      0.1     0.0          | | | | | +--StandardClassLoader:<init>    (org.apache.catalina.loader)
           1      0.1      0.1     0.0          | | +--SecurityClassLoad:securityClassLoad    (org.apache.catalina.security)
           2      0.0      0.0     0.0          | | +--DirectJDKLog:isDebugEnabled    (org.apache.juli.logging)
           5      1.3      0.4     0.4     0.1  | | +--LogFactory:getLog    (org.apache.juli.logging)
           5      0.0      0.0     0.0          | | | +--LogFactory:getFactory    (org.apache.juli.logging)
           5      0.9      0.1     0.3          | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           5      0.7      0.1     0.2          | | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           5      0.6      0.1     0.2          | | | | | +--DirectJDKLog:getInstance    (org.apache.juli.logging)
           5      0.5      0.5     0.1     0.1  | | | | | | +--DirectJDKLog:<init>    (org.apache.juli.logging)
           2      0.0      0.0     0.0          | | +--CatalinaProperties:getProperty    (org.apache.catalina.startup)
           1    114.8    111.1    36.4    35.2  | +--Bootstrap:stopServer    (org.apache.catalina.startup)
           7      1.1      0.3     0.4          | | +--LogFactory:getLog    (org.apache.juli.logging)
           7      0.0      0.0     0.0          | | | +--LogFactory:getFactory    (org.apache.juli.logging)
           7      0.8      0.1     0.3          | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           4      0.3      0.1     0.1          | | | | +--DirectJDKLog:getInstance    (org.apache.juli.logging)
           4      0.2      0.2     0.1          | | | | | +--DirectJDKLog:<init>    (org.apache.juli.logging)
           3      0.4      0.1     0.1          | | | | +--LogFactory:getInstance    (org.apache.juli.logging)
           3      0.3      0.1     0.1          | | | | | +--DirectJDKLog:getInstance    (org.apache.juli.logging)
           3      0.3      0.3     0.1          | | | | | | +--DirectJDKLog:<init>    (org.apache.juli.logging)
          96      2.5      2.5     0.8     0.8  | | +--DirectJDKLog:isDebugEnabled    (org.apache.juli.logging)

      +--------------------------------------
      | Most expensive methods (by net time)
      | Frame Count Limit: Unlimited
      +--------------------------------------

                     Net
                ------------
      Count     Time    Pct  Location
      =====     ====    ===  ========
           1    111.1   33.4  org.apache.catalina.startup.Bootstrap:stopServer
           1     99.0   29.8  org.apache.catalina.startup.Bootstrap:init
           3     90.5   27.2  org.apache.catalina.startup.Bootstrap:createClassLoader
           1     10.0    3.0  org.apache.juli.logging.LogFactory:getInstance
           1      7.3    2.2  org.apache.catalina.startup.ClassLoaderFactory:createClassLoader
           1      3.6    1.1  org.apache.juli.logging.DirectJDKLog:<init>
           1      3.3    1.0  org.apache.juli.logging.LogFactory:<init>
          96      2.5    0.8  org.apache.juli.logging.DirectJDKLog:isDebugEnabled
           1      0.6    0.2  org.apache.catalina.startup.CatalinaProperties:loadProperties
           5      0.5    0.1  org.apache.juli.logging.DirectJDKLog:<init>
           5      0.4    0.1  org.apache.juli.logging.LogFactory:getLog
           3      0.3    0.1  org.apache.juli.logging.DirectJDKLog:<init>
           7      0.3    0.1  org.apache.juli.logging.LogFactory:getLog
           2      0.2    0.1  org.apache.juli.logging.DirectJDKLog:<init>
           4      0.2    0.1  org.apache.juli.logging.DirectJDKLog:<init>
           7      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           5      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           5      0.1    0.0  org.apache.juli.logging.DirectJDKLog:getInstance
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:initClassLoaders
           1      0.1    0.0  org.apache.catalina.loader.StandardClassLoader:<init>
           5      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           4      0.1    0.0  org.apache.juli.logging.DirectJDKLog:getInstance
          20      0.1    0.0  org.apache.juli.logging.DirectJDKLog:isDebugEnabled
           2      0.1    0.0  org.apache.juli.logging.LogFactory:getLog
           2      0.1    0.0  org.apache.juli.logging.DirectJDKLog:isDebugEnabled
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:main
           1      0.1    0.0  org.apache.catalina.security.SecurityClassLoad:securityClassLoad
           1      0.1    0.0  org.apache.juli.logging.DirectJDKLog:getInstance
           2      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           1      0.1    0.0  org.apache.juli.logging.LogFactory:getFactory
           3      0.1    0.0  org.apache.juli.logging.DirectJDKLog:getInstance
           2      0.1    0.0  org.apache.juli.logging.DirectJDKLog:getInstance
           1      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           3      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:setCatalinaHome
           1      0.1    0.0  org.apache.juli.logging.LogFactory:getLog
           2      0.1    0.0  org.apache.catalina.startup.Bootstrap:getCatalinaHome
           2      0.1    0.0  org.apache.juli.logging.LogFactory:getInstance
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getConfigUrl
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getCatalinaHome
           3      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getProperty
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:<init>
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getCatalinaBase
           1      0.0    0.0  org.apache.catalina.startup.Bootstrap:setCatalinaBase
           7      0.0    0.0  org.apache.juli.logging.LogFactory:getFactory
           2      0.0    0.0  org.apache.juli.logging.DirectJDKLog:isDebugEnabled
           5      0.0    0.0  org.apache.juli.logging.LogFactory:getFactory
           2      0.0    0.0  org.apache.catalina.startup.CatalinaProperties:getProperty
           2      0.0    0.0  org.apache.juli.logging.LogFactory:getFactory

      +--------------------------------------+
      | Most expensive methods summarized    |
      +--------------------------------------+

                     Net
                ------------
      Count     Time    Pct  Location
      =====     ====    ===  ========
           1    111.1   33.4  org.apache.catalina.startup.Bootstrap:stopServer
           1     99.0   29.8  org.apache.catalina.startup.Bootstrap:init
           3     90.5   27.2  org.apache.catalina.startup.Bootstrap:createClassLoader
          26     10.6    3.2  org.apache.juli.logging.LogFactory:getInstance
           1      7.3    2.2  org.apache.catalina.startup.ClassLoaderFactory:createClassLoader
          15      4.7    1.4  org.apache.juli.logging.DirectJDKLog:<init>
           1      3.3    1.0  org.apache.juli.logging.LogFactory:<init>
         120      2.8    0.8  org.apache.juli.logging.DirectJDKLog:isDebugEnabled
          15      0.9    0.3  org.apache.juli.logging.LogFactory:getLog
           1      0.6    0.2  org.apache.catalina.startup.CatalinaProperties:loadProperties
          15      0.5    0.1  org.apache.juli.logging.DirectJDKLog:getInstance
          15      0.2    0.1  org.apache.juli.logging.LogFactory:getFactory
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:initClassLoaders
           1      0.1    0.0  org.apache.catalina.loader.StandardClassLoader:<init>
           5      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getProperty
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:main
           1      0.1    0.0  org.apache.catalina.security.SecurityClassLoad:securityClassLoad
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:setCatalinaHome
           2      0.1    0.0  org.apache.catalina.startup.Bootstrap:getCatalinaHome
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getConfigUrl
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getCatalinaHome
           1      0.1    0.0  org.apache.catalina.startup.Bootstrap:<init>
           1      0.1    0.0  org.apache.catalina.startup.CatalinaProperties:getCatalinaBase
           1      0.0    0.0  org.apache.catalina.startup.Bootstrap:setCatalinaBase

      +---------------------------------+
      | Object Allocation               |
      +---------------------------------+

           Count Class Name
           ===== ==========
              15  org.apache.juli.logging.DirectJDKLog
               1  org.apache.catalina.loader.StandardClassLoader
               1  org.apache.juli.logging.LogFactory
               1  org.apache.catalina.startup.Bootstrap

      ----------------------------------------------------------------

      I want to see the details regarding my web app method e.g. validateUser() like how many times it is called, how much time it is taking to execute, etc.

      Hozaifa

       
    • Andrew Wilcox
      Andrew Wilcox
      2009-04-17

      Hi Hozaifa,

      Thanks for the detailed information -- it really helps!

      In your profile.properties file, you need to change this:

      ClassLoaderFilter.2=...

      to this:

      ClassLoaderFilter.1=...

      JIP looks for ClassLoaderFilters starting with ClassLoaderFilter.1 and stops when it can't find ClassLoaderFilter.x.
      Since there is no ClassLoaderFilter.1 in your profile.properties file, JIP doesn't look for ClassLoaderFilter.2 and uses the default ClassLoaderFilter.

      Andrew.

       
    • Hozaifa Naseem
      Hozaifa Naseem
      2009-04-21

      hi all...

      Kindly let me know how to profile a web application using JIP.

      I have tried following the steps mentioned in "Whitepaper.pdf", without success.

      Sometimes, I am getting output file containing no description of my application methods;
      Sometimes, I am not getting the output file at all.

      I am using Eclipse3.3.2, jdk1.5.0_09, apache-tomcat-6.0.10

      Kindly tell me how to configure "profile.properties" & other files.

      Any advice would be of great help...

      Thanks,
      Hozaifa

       
    • Andrew Wilcox
      Andrew Wilcox
      2009-04-21

      It's easiest to start with the webapp.profile.properties file located in the profile directory of the JIP distribution and change the profile.properties VM argument to match. For example:

      ... -Dprofile.properties=E:\Jip-src-1.1.1\profile\webapp.profile.properties

      If you're still not getting the output you're expecting add

      debug=on

      to the webapp.profile.properties file.

      As classes get classloaded at runtime, you'll see a message telling you whether or not JIP is instrumenting the class for profiling. If the class is being instrumented, the line will start with [INST]. If not, the line will start with [SKIP]. In general, this tells you if the wrong classes are being instrumented or if anything is getting instrumented at all.

      Andrew.