Programatic manipulation of profiler?

  • MyronSchabe

    MyronSchabe - 2009-01-13

    I am trying to programatically manipulate the profiler as stated in the readme:

    Profile.clear(); // initialises the profiler
    Profile.start(); // starts the profiler
    Profile.stop();  // stops the profiler
    Profile.setFileName(String fileName); // changes the output file name
    Profile.shutdown(); // shuts the profiler down.

    but am not yet successful.  I have tried with both remote on and off and the profiler off as per instructions.

    I am calling in this sequence:

    Profile.clear(); // initialises the profiler
    Profile.setFileName(String fileName);

    //other code


    But am not seeing my file being created/updated nor any of the output to the console I see when running with the bat files.  (I am successful when using start.bat and finish.bat with remote on, so it is configured correctly from that point of view).

    I am running locally using Eclipse and Tomcat.  Are there any other properties that need to be set one way or the other (port?) or other ideas why it is not working?

    Thanks again!

    • Andrew Wilcox

      Andrew Wilcox - 2009-01-14

      I'm not sure why this is not working. Try this:

      In the profile properties file, make sure that:
      and that 'file' is set to the file you want.

      change your code to NOT call Profile.setFileName(...) and  Profile.shutdown().

      My concern is that Profile.shutdown() doesn't output your profile, it just cleans up any loose ends. This will get called again when the VM is shutdown and I'm concerned that might be messing up your profile.

      If you're running a test case and what to see the profile after you're done but without shutting down Tomcat, make sure remote=on in the profile properties file. To see the output, run this from the command line:

      java -jar client.jar dump localhost 15599

      Note that if you set file=<name> to a directory, each dump will generate a unique file in that directory.

      Please post again to say whether or not this worked.

      BTW, thanks for all the info you posted about what you're doing, what you've tried and what environment you're running in it really does help!



    • MyronSchabe

      MyronSchabe - 2009-01-14


      I made a silly error when specifying my file in code by not including File.separator when setting the file name.  When that was fixed and I tried to run with the original above mentioned sequence it did generate an output file as expected.


      I am seeing something curious when I compare the output files generated from start and stopping from the .bat files as with one generated programatically (even though I following the same 'click sequence' in my web app in both cases).  One big difference is that the call tree tab in jipviewer has say some 50 thread/interactions when the file was generated programtically as compared to two when generated from the .bat files.  As well, in the 50 interactions there are methods like 'spread out all over the place' wherein the other - the threads are very, very similar in sequencing.  Any ideas here?  The most expensive method hierarchy is basically similar but far from exact though, certainly, it will never be exact. 

      Where I am going with getting it working programatically is that I want to expose turning it on and off etc. thru JMX mbean (in JBoss) making it more easy/convenient when running in production.

      • Andrew Wilcox

        Andrew Wilcox - 2009-01-15

        First of all, I love the JMX mbean idea. Please let me know how that turns out. That would make a nice addition to the next version of JIP if you wanted to contribute the code.

        The reason for needing "interactions" at all is that, in a tradition profiler, a thread is profiled from start to finish. When you're profiling interactively, there's a chance that the profile is starting in the middle of a thread's lifetime rather than the beginning.

        JIP's runtime profiler works by keeping its own call stack for each thread. When a thread calls a method, the method being called is pushed on to that thread's call stack. When the method returns, JIP pops the method of the top of the call stack. If JIP starts in the middle of a thread's lifetime, there's a chance that the method in which the profile started will end. At that point, the profiler has no way of further tracking the performance of the thread since JIP's call stack for that thread is now empty.

        This is where interactions come in. When the last method on a thread's call stack ends, JIP labels that "thread #x, interaction #1", the next activity that happens on that thread starts a new call stack, and hence a new interaction.

        When you're running inside a container, there are a lot of threads that are already running. Imagine the situation where JIP starts profiling and a certain thread is in the middle of executing method E:

        > B
        >> C 
        >>> D
        >>>> E  <-- jip starts profiling here

        When E ends, you get an interaction, and JIP starts a new interaction based on method D. When D returns, that interaction ends and you get another interaction starting for method C, etc. In this scenario, you could end up with up to 5 very small interactions for this thread.

        Getting 50 interactions is messy. Yes, you get the result you wanted to look at, but you also get a lot of noise. I think that at one point, I considered limiting profiles that were initiated programmatically to the thread in which the initiation occurred. The downside to that approach is that you might be missing out on valuable activity happening in pooled resources. I suppose I could add a flag to the programmatic profiling API that you could use to limit the profile to the current thread. What do you think?


    • MyronSchabe

      MyronSchabe - 2009-01-15

      Thanks again --  that thorough description is helpful in understanding what is going on, but I am still curious as to why the output generated from starting and stopping with the .bat files differs from the one from the inline calls as both are 'profiling interactively, with a chance that the profile is starting in the middle of a thread's lifetime rather than the beginning'?  (Or perhaps the .bat files initialize etc. in some other way).

      I am still working on setting things up in JMX and I can report back what the results look like in terms of the call tree.  I was simply planning to call Profile.start(), Profile.stop() etc. from the implementation class of the mBean.  And, yes, sure if it works out, and I can get clearance thru all the hoops here a contribution would be cool.

      Another question while I'm at it -- is there a way to point to a different properties file, or in some way change properties, without restarting the JVM?  One use case we can envision here is to be able to change the class filtering mechanism (ClassLoaderFilter.1), when trying to debug in a production environment.  Certainly, I would expect to have to stop and restart the profiler for changes like that, but again, can you do so without a jvm restart?

      • Andrew Wilcox

        Andrew Wilcox - 2009-01-16

        I like the idea of swapping out properties files at runtime. However, changing the class filtering mechanism without a jvm restart is not possible. This is because JIP instruments each class that it profiles via bytecode rewriting that happens at classloaded time. So, instead of profiling everything and then filtering the output, JIP essentially applies the filter up front. Profiling everything has a massively negative impact on performance, which is why JIP is so much faster than many other profilers. Unfortunately, once a class has been loaded by the classloader, bytecode rewriting is no longer possible.


    • MyronSchabe

      MyronSchabe - 2009-01-29

      Ok – I am now running on a unix server with Tomcat 5.5 and Java 6.  And have two questions (though we have plans to move to Tomcat 6 in the next couple of days):

      1.)    The first involves the JMX console – I have one implemented and things seem to be working – the one problem is that when I call shutdown, it does not dump the profiler info at that time, it does dump it, though, when the jvm is shutdown.  (All my jmx bean does is call the static Profile methods start stop etc.)  I’ve looked at the code for shutdown and I don’t see any explicit ‘dumping’ in there.  Do you have any suggestions how I can get this working?  Should I modify the code and do something more specific in the shutdown method?

      2.)    Now that I am running on the unix box I am seeing this situation of having many, many (like 100) interactions in the call tree tab of jipviewer regardless of how I initiated the profiling – either from the jmx console or from the, scripts – nor does not seem to make a difference whether I set the file thru the or just rely on the one in  I am running against a different application but still the call tree tab is really not giving any sense of a proper call tree – each interaction has say between 1 and say 5 levels of recursion – the majority are just one though.  Is this surprising? – As before I was only seeing this situation when the log file was generated via inline calls to Profile.  Granted I am testing against a different application but I don’t think that should make a difference. My prop file does have profiler=off and remote=on.  I do recall your previous description of why this happens but it seemed that may have been relegated to the inline profiling.  Any suggestions on what can be done to get a more linear call tree?

      Thanks again for your help.

    • Andrew Wilcox

      Andrew Wilcox - 2009-02-02

      Profile.shutdown()  doesn't dump the profile, but you're right, it should. You can fix this by calling ProfileDump.dump() at the end of the shutdown method.

      I don't think that it's at all surprising that you're seeing so many interactions. But just to be sure, if you could post one of your output files, I'll take a look to make sure something's not amiss.



Log in to post a comment.