Friday, October 31, 2014

Gem of Java: BTrace; Debugging production code on the fly


But the question is now how do u debug? Generally the loggers we kept are in-sufficient or in production they disabled debug, info levels of log4j; now how? or say we forgot logging a variable.. now how to debug the issue?

wouldnt it be nice if i have an agent sitting outside the main JVM and printing out the variable i wanted? is it possible? the answer is YES!!!


BTrace is the gem in Java-s Crown. So it works like this

  1. The original JVM runs on some PID
  2. The Btrace program runs outside and connects to this pid; printing ur variable as u wanted
You need to download the BTrace package; Create a java program; Typically it looks as follows



package my;


import services.reports.ReportContext;

import com.insideview.industryProfiles.IndustryProfile;
import com.insideview.industryProfiles.IndustrySic;
import com.sun.btrace.BTraceUtils;
import com.sun.btrace.annotations.BTrace;
import com.sun.btrace.annotations.Kind;
import com.sun.btrace.annotations.Location;
import com.sun.btrace.annotations.OnMethod;
import com.sun.btrace.annotations.Return;


@BTrace(unsafe=true)
public class Tracer {
        @OnMethod( clazz="services.reports.company.CompanyIndustryProfile",  method="appendSection", location=@Location(Kind.RETURN))
        public static void operate(@Return ReportContext rc  ){
         IndustryProfile industryProfile = (IndustryProfile) (rc.get("industryProfile"));
         BTraceUtils.printFields(industryProfile);
         BTraceUtils.println();
         IndustrySic sic = industryProfile.getSic();
  BTraceUtils.printFields(sic);
        }
}

If u see the highlighted area; they are the custom objects in the JVM running; now this program will print them when ever the method: CompanyIndustryProfile.appendSection() is hit injecting the return variable (i.e.. @Return)

In the dowloaded package, open the btrace file located in bin folder and in the end change to the below. The line is to the end of the file

 -Dcom.sun.btrace.debug=true



it will be initially set to false; Now run the command; below is the sample output.


[jboss@iv build]$ ../bin/btrace -cp "btrace-agent.jar:btrace-boot.jar:btrace-client.jar:velocity-1.7-dep.jar:company.jar" 26009  Tracer.java

DEBUG: btrace debug mode is set
DEBUG: btrace unsafe mode is set
DEBUG: accepting classpath btrace-agent.jar:btrace-boot.jar:btrace-client.jar:velocity-1.7-dep.jar:commpany.jar
DEBUG: assuming default port 2020
DEBUG: compiling Tracer.java
DEBUG: compiled Tracer.java
DEBUG: attaching to 8995
DEBUG: checking port availability: 2020
DEBUG: attached to 8995
DEBUG: loading /tmp/btrace/build/btrace-agent.jar
DEBUG: agent args: port=2020,debug=true,unsafe=true,systemClassPath=/usr/jdk1.6.0_29/lib/tools.jar,probeDescPath=.
DEBUG: loaded /tmp/btrace/build/btrace-agent.jar
DEBUG: registering shutdown hook
DEBUG: registering signal handler for SIGINT
DEBUG: submitting the BTrace program
DEBUG: opening socket to 2020
DEBUG: sending instrument command
DEBUG: entering into command loop
DEBUG: received com.sun.btrace.comm.OkayCommand@566711b0
DEBUG: received com.sun.btrace.comm.RetransformationStartNotification@8ba6621
DEBUG: received com.sun.btrace.comm.OkayCommand@5870501
DEBUG: received com.sun.btrace.comm.MessageCommand@2e2b5ba8
{industryDescription=null, industryId=564,abc=xyx,etc=etc], sizeStructureDescription=etc_etc}
DEBUG: received com.sun.btrace.comm.MessageCommand@26284112

DEBUG: received com.sun.btrace.comm.MessageCommand@1cc81850
$$$$$$$$$$$DEBUG: received com.sun.btrace.comm.MessageCommand@14b43af3
{id=7375, description=CBI Services, }


Issues to lookout
  1. If u havent changed btrace file, ran the above process and then modifed the unsafe to true on running the btrace u see VerificationError.
  2. As said here it happens because the 1st run made the target JVM to mark any unsafe to false
  3. for this u will have to restart the target m/c





2 comments:

  1. Hello man, hope you see this ! When i run my dbtrace it will hang on DEBUG: checking port availability: 2020 forever. Any idea what might cause this ? Thanks

    ReplyDelete
  2. this shouldnt happen. Make sure you are able to connect to the port via telnet --ensuring the port is open for the connection first

    ReplyDelete