Getting started with the Performance tools Java profiling tool BTrace

Small knowledge, big challenge! This article is participating in the creation activity of “Essential Tips for Programmers”.

This article has participated in the “Digitalstar Project” and won a creative gift package to challenge the creative incentive money.

One, the introduction

When we do performance analysis of Java applications, we often use logs to locate and analyze problems. But what if our logs lack relevant information? Remote debugging will affect the normal operation of the application, modify the code to redeploy the application, real-time and flexibility is difficult to ensure, is there a flexible and non-invasive method without affecting the normal operation of the application?

The answer is yes, it is a Java artifact -BTrace

What is BTrace?

BTrace uses Java Attach technology, which allows us to seamlessly Attach our BTrace script to the JVM. You can retrieve any data you want from the script, which is very secure and invasive, especially for locating online problems.

3. BTrace Principle

BTrace is based on dynamic bytecode modification technology (Hotswap) to inject trace code into the bytecode of the target program.

Four, installation and configuration

For the installation, configuration and use of BTrace, I will not repeat the wheel here, there are too many tutorials online.

Official website: github.com/btraceio/bt…

Five, matters needing attention

Production environment can be used, but the bytecode modification will not be restored, using Btrace, need to make sure tracking action is read-only (i.e., the tracking can not change the state of an object program) and limited behavior (i.e., the tracking needs for a limited time to terminate), a tracking behavior need to meet the following limits:

• You can’t create new objects you can’t create new arrays
• Cannot throw an exception
• Unable to catch exceptions
• No instance or static method calls – only methods declared from public static methods in BTraceUtils or in the current script can be called by BTrace
• There can be no external, internal, nested, or native classes
• There cannot be synchronized blocks or synchronized methods
• No loops (for, while, do.. While)
• Cannot inherit abstract classes (parent must be java.lang.object)
• Unable to implement interface
• There can be no assertion statements
• There can be no class reserved word

These restrictions can be bypassed by using the Unsafe mode. Both tracing scripts and engines must be set to unsafe mode. Unsafe =true. Modify the BTrace script in the bin directory of the BTrace installation directory to change -dcom.sun.btrace. Unsafe =false to -dcom.sun.btrace.

Note: With unsafe, if your application has been traced by BTrace, the unsafe setting will remain relevant for the entire life of the process. If you change the Unsafe setting, you will need to restart the target process to get the desired result. If your application cannot be restarted at will, decide which mode to use to start the engine before using the bTrace final process for the first time.

Six, use examples

1. Intercept a normal method

The control method

@GetMapping(value = "/arg1")
	public String arg1(@RequestParam("name") String name) throws InterruptedException {
		Thread.sleep(2000);
		return "7DGroup," + name;
	}
Copy the code

BTrace scripts

/** * intercepting example */
@BTrace
public class PrintArgSimple {

	@ OnMethod (/ / the name of the class clazz = "com. Techstar. Monitordemo. Controller. UserController", / / the method name method = "arg1, / / intercept moments: Location = @location (kind.entry))

	/** * Interceptor class name and method name */ public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {
		BTraceUtils.printArray(args);
		BTraceUtils.println(pcn + ","+ pmn); BTraceUtils.println(); }}Copy the code

Interception result:

192: Btrace apple $JPS - 369, 5889 l/Users/apple/Downloads/performance/apache - jmeter - 4.0 / bin/ApacheJMeter. Jar, 25922 sun.tools.jps.Jps 23011 org.jetbrains.idea.maven.server.RemoteMavenServer 25914 org.jetbrains.jps.cmdline.Launcher 25915  com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 25915 PrintArgSimple.java [zuozewei, ] com.techstar.monitordemo.controller.UserController,arg1 [zee, ] com.techstar.monitordemo.controller.UserController,arg1Copy the code

2. Intercepting constructors

The constructor

@Data
public class User {

	private int id;
	private String name;

}
Copy the code

The control method

@GetMapping(value = "/arg2")
	public User arg2(User user) {
		return user;
	}
Copy the code

BTrace scripts

/** * intercepts the constructor */
@BTrace
public class PrintConstructor {

	@OnMethod(clazz = "com.techstar.monitordemo.domain.User", method = "<init>")
	public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, AnyType[] args) {
		BTraceUtils.println(pcn + ","+ pmn); BTraceUtils.printArray(args); BTraceUtils.println(); }}Copy the code

Intercept the results

192:Btrace apple$ btrace 34119 PrintConstructor.java 
com.techstar.monitordemo.domain.User,<init>
[1, zuozewei, ]
Copy the code

3. Intercept functions with the same name to distinguish between arguments

The control method

@GetMapping(value = "/same1")
	public String same(@RequestParam("name") String name) {
		return "7DGroup," + name;
	}

	@GetMapping(value = "/same2")
	public String same(@RequestParam("id") int id, @RequestParam("name") String name) {
		return "7DGroup," + name + "," + id;
	}
Copy the code

BTrace scripts

/** * intercepts the function with the same name

@BTrace
public class PrintSame {

	@OnMethod(clazz = "com.techstar.monitordemo.controller.UserController", method = "same")
	public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, String name) {
		BTraceUtils.println(pcn + "," + pmn + ","+ name); BTraceUtils.println(); }}Copy the code

Intercept the results

192: Btrace apple $JPS - 369, 5889 l/Users/apple/Downloads/performance/apache - jmeter - 4.0 / bin/ApacheJMeter. Jar, 34281 sun.tools.jps.Jps 34220 org.jetbrains.jps.cmdline.Launcher 34221 com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 34221 PrintSame.java com.techstar.monitordemo.controller.UserController,same,zuozewei com.techstar.monitordemo.controller.UserController,same,zuozewei com.techstar.monitordemo.controller.UserController,same,zuozeweiCopy the code

4. Intercept the method return value

BTrace scripts

/** * intercepts the return value */
@BTrace
public class PrintReturn {

	@ OnMethod (clazz = "com. Techstar. Monitordemo. Controller. UserController", method = "arg1, / / intercept moments: RETURN value location = @ location (kind.return)
	public static void anyRead(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Return AnyType result) {
		BTraceUtils.println(pcn + "," + pmn + ","+ result); BTraceUtils.println(); }}Copy the code

Intercept the results

192:Btrace apple$ jps -l 34528 org.jetbrains.jps.cmdline.Launcher 34529 com.techstar.monitordemo.MonitordemoApplication 369 5889 / Users/apple/Downloads/performance/apache - jmeter - 4.0 / bin/ApacheJMeter. 34533 sun jar. View the JPS. 192: the JPS Btrace Apple's $34529 PrintReturn btrace. Java com. Techstar. Monitordemo. Controller. UserController, arg1, 7 dgroup zuozeweiCopy the code

5. Anomaly analysis

Sometimes, some important exceptions are eaten by the developer because of unreasonable exception processing. In addition, there is no log or the log is not detailed, which makes it difficult for performance analysis to locate the problem. We can use BTrace to solve the problem

The control method

@GetMapping(value = "/exception")
	public String exception(a) {
		try {
			System.out.println("start...");
			System.out.println(1 / 0); // Simulate an exception
			System.out.println("end...");
		} catch (Exception e) {}
		return "successful...";
	}
Copy the code

BTrace scripts

/** * Sometimes exceptions are eaten and the log is not printed. This example demonstrates printing stack trace * of an exception and thread local variables. This * trace script prints exception stack trace whenever * java.lang.Throwable's constructor returns. This way * you can trace  all exceptions that may be caught and * "eaten" silently by the traced program. Note that the * assumption is that the exceptions are thrown soon after * creation [like in "throw new FooException();"]  rather * that be stored and thrown later. */
@BTrace
public class PrintOnThrow {
	// store current exception in a thread local
	// variable (@TLS annotation). Note that we can't
	// store it in a global variable!
	@TLS
	static Throwable currentException;

	// introduce probe into every constructor of java.lang.Throwable
	// class and store "this" in the thread local variable.
	@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
	public static void onthrow(@Self Throwable self) {
		currentException = self;
	}

	@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
	public static void onthrow1(@Self Throwable self, String s) {
		currentException = self;
	}

	@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
	public static void onthrow1(@Self Throwable self, String s, Throwable cause) {
		currentException = self;
	}

	@OnMethod(clazz = "java.lang.Throwable", method = "<init>")
	public static void onthrow2(@Self Throwable self, Throwable cause) {
		currentException = self;
	}

	// when any constructor of java.lang.Throwable returns
	// print the currentException's stack trace.
	@OnMethod(clazz = "java.lang.Throwable", method = "<init>", location = @Location(Kind.RETURN))
	public static void onthrowreturn(a) {
		if(currentException ! =null) {
			Threads.jstack(currentException);
			BTraceUtils.println("= = = = = = = = = = = = = = = = = = = = =");
			currentException = null; }}}Copy the code

Intercept the results

192: Btrace apple $JPS - 369, 5889 l/Users/apple/Downloads/performance/apache - jmeter - 4.0 / bin/ApacheJMeter. Jar, 34727 sun.tools.jps.Jps 34666 org.jetbrains.jps.cmdline.Launcher 34667 com.techstar.monitordemo.MonitordemoApplication 192:Btrace apple$ btrace 34667 PrintOnThrow.java java.lang.ClassNotFoundException: org.apache.catalina.webresources.WarResourceSet java.net.URLClassLoader.findClass(URLClassLoader.java:381) java.lang.ClassLoader.loadClass(ClassLoader.java:424) java.lang.ClassLoader.loadClass(ClassLoader.java:411) sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:349)
	java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	org.apache.catalina.webresources.StandardRoot.isPackedWarFile(StandardRoot.java:656)
	org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:109)
	org.apache.catalina.webresources.Cache.getResource(Cache.java:69)
	org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)
	org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206)
	org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:1027)
	org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:842)
	org.apache.catalina.mapper.Mapper.map(Mapper.java:698)
	org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:679)
	org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)
	org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
	org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:800)
	org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1471)
	org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	java.lang.Thread.run(Thread.java:748)
=====================
...
Copy the code

Locate a function that exceeds a threshold

BTrace scripts

** * A program that detects whether the execution time of a method under a package path exceeds a certain threshold, and prints stack information for the current thread if the threshold is exceeded. * /import com.sun.btrace.BTraceUtils;
import com.sun.btrace.annotations.*;

import static com.sun.btrace.BTraceUtils.*;

@BTrace
public class PrintDurationTracer {
	@OnMethod(clazz = "/com\\.techstar\\.monitordemo\\.. */", method = "/.*/", location = @Location(Kind.RETURN))
	public static void trace(@ProbeClassName String pcn, @ProbeMethodName String pmn, @Duration long duration) {
		Duration is in nanoseconds
		if (duration > 1000 * 1000 * 2) {
			BTraceUtils.println(Strings.strcat(Strings.strcat(pcn, "."), pmn));
			BTraceUtils.print("Take.");
			BTraceUtils.print(duration);
			BTraceUtils.println("Nanosecond, stack information is as follows."); jstack(); }}}Copy the code

Intercept the results

192:Btrace apple$ btrace 39644 PrintDurationTracer.java com.techstar.monitordemo.controller.Adder.execute Time: 1715294657 nanoseconds, stack information below com. Techstar. Monitordemo. Controller. The Adder. Execute (Adder. Java: 13) com.techstar.monitordemo.controller.Main.main(Main.java:10) com.techstar.monitordemo.controller.Adder.execute Time: 893795666 nanoseconds, stack information below com. Techstar. Monitordemo. Controller. The Adder. Execute (Adder. Java: 13) com.techstar.monitordemo.controller.Main.main(Main.java:10) com.techstar.monitordemo.controller.Adder.execute Time: 1331363658 nanoseconds, stack information below com. Techstar. Monitordemo. Controller. The Adder. Execute (Adder. Java: 13)Copy the code

7. Track method execution time

BTrace scripts

/** * Tracks the execution time of a method, just like AOP. * /
@BTrace
public class PrintExecuteTimeTracer {
	@TLS
	static long beginTime;

	@OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute")
	public static void traceExecuteBegin(a) {
		beginTime = timeMillis();
	}

	@OnMethod(clazz = "com.techstar.monitordemo.controller.Adder", method = "execute", location = @Location(Kind.RETURN))
	public static void traceExecute(int arg1, int arg2, @Return int result) {
		BTraceUtils.println(strcat(strcat("Adder. Execute time-consuming.", str(timeMillis() - beginTime)), "ms"));
		BTraceUtils.println(strcat("Return result :", str(result))); }}Copy the code

Intercept the results

192: Btrace apple $40863 PrintExecuteTimeTracer Btrace. Java Adder. Execute time: 803 ms to return the result as follows: 797 Adder. Execute time-consuming: 1266 ms Execute :784 adder. execute :1524ms 1521 adder. execute :1775ms is displayedCopy the code

8. Performance analysis

It is often found that a service is slow during pressure testing, but because the service has a lot of business logic and method composition, it is difficult to determine exactly where the slowness is. BTrace can solve this problem by roughly locating where the problem might exist, using packet path fuzzy matching to find the problem.

BTrace scripts

/** * * Description: * This script demonstrates new capabilities built into BTrace 1.2 * When omitting "public" identifier  in the class * definition one can safely omit all other modifiers when declaring methods * and variables * Extended syntax for@ProbeMethodName annotation - you can use
 * parameter to request a fully qualified method name instead of
 * the short one
 * Profiling support - you can use {@linkplain Profiler} instance to gather
 * performance data with the smallest overhead possible
 */
@BTrace
class Profiling {
	@Property
	Profiler profiler = BTraceUtils.Profiling.newProfiler();

	@OnMethod(clazz = "/com\\.techstar\\.. */", method = "/.*/")
	void entry(@ProbeMethodName(fqn = true) String probeMethod) {
		BTraceUtils.Profiling.recordEntry(profiler, probeMethod);
	}

	@OnMethod(clazz = "/com\\.techstar\\.. */", method = "/.*/", location = @Location(value = Kind.RETURN))
	void exit(@ProbeMethodName(fqn = true) String probeMethod, @Duration long duration) {
		BTraceUtils.Profiling.recordExit(profiler, probeMethod, duration);
	}

	@OnTimer(5000)
	void timer(a) {
		BTraceUtils.Profiling.printSnapshot("Performance profile", profiler);
	}
Copy the code

9, deadlock check

We doubt whether the program has a deadlock, can be traced through the following step scan, very simple and convenient.

/** * This BTrace program demonstrates deadlocks * built-in function. This example prints * deadlocks (if any) once every 4 seconds. */
@BTrace
public class PrintDeadlock {
	@OnTimer(4000)
	public static void print(a) { deadlocks(); }}Copy the code

Seven, summary

BTrace is an after-the-fact tool. The so-called after-the-fact tool is to use BTrace to dynamically trace the analysis after the service has been live or tested, but there is a problem.

1. For example, which methods execute too slowly, such as monitoring methods that take more than 1 second to execute;
2. See which methods call system.gc() and what the call stack looks like;
3. View the parameters and properties of the method
4. Which methods are abnormal

.

In a word, here are only some frequently used examples to draw inspiration from others, and there are many others that are not listed. You can refer to other official samples to play.

Source: github.com/zuozewei/bl…