英文:
Byte-buddy transform running multiple times for a single execution
问题
我写了一个如下的 javaagent 用于捕获 Apache org.apache.http.client.HttpClient 的 execute 方法的执行时间。它能够捕获时间，但运行了三次。
import java.lang.instrument.Instrumentation;
import net.bytebuddy.agent.builder.AgentBuilder;
import net.bytebuddy.implementation.MethodDelegation;
import static net.bytebuddy.matcher.ElementMatchers.isMethod;
import static net.bytebuddy.matcher.ElementMatchers.isAbstract;
import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
import static net.bytebuddy.matcher.ElementMatchers.takesArgument;
import static net.bytebuddy.matcher.ElementMatchers.named;
import static net.bytebuddy.matcher.ElementMatchers.not;
public class TimerAgent {
public static void premain(
String arguments,
Instrumentation instrumentation
) {
new AgentBuilder.Default()
.type(
implementsInterface(named("org.apache.http.client.HttpClient"))
)
.transform((builder, type, classLoader, module) ->
builder.method(isMethod()
.and(named("execute"))
.and(not(isAbstract()))
.and(takesArguments(3))
.and(takesArgument(0, named("org.apache.http.client.methods.HttpUriRequest")))
.and(takesArgument(1, named("org.apache.http.client.ResponseHandler")))
.and(takesArgument(2, named("org.apache.http.protocol.HttpContext"))))
.intercept(MethodDelegation
.to(TimingInterceptor.class))
).installOn(instrumentation);
}
}
import java.lang.reflect.Method;
import java.util.concurrent.Callable;
import net.bytebuddy.implementation.bind.annotation.Origin;
import net.bytebuddy.implementation.bind.annotation.RuntimeType;
import net.bytebuddy.implementation.bind.annotation.SuperCall;
public class TimingInterceptor {
@RuntimeType()
public static Object intercept(
@Origin Method method,
@SuperCall Callable<?> callable
) {
long start = System.currentTimeMillis();
try {
try {
return callable.call();
} catch (Exception e) {
e.printStackTrace();
}
} finally {
System.out.println(
"Took " + (System.currentTimeMillis() - start));
}
return 0;
}
}
我正在使用 DefaultHttpClient 发起 HTTP 请求。
客户端代码：
import java.io.IOException;
import org.apache.http.HttpEntity;
import org.apache.http.HttpResponse;
import org.apache.http.client.ClientProtocolException;
import org.apache.http.client.HttpClient;
import org.apache.http.client.ResponseHandler;
import org.apache.http.client.methods.HttpGet;
import org.apache.http.client.methods.HttpUriRequest;
import org.apache.http.impl.client.DefaultHttpClient;
public class Main {
public static void main(String[] args) throws IOException {
HttpClient client = new DefaultHttpClient();
HttpUriRequest httpUriRequest = new HttpGet("http://www.google.com");
HttpResponse response = client
.execute(httpUriRequest, new ResponseHandler<HttpResponse>() {
public HttpResponse handleResponse(final HttpResponse response)
throws ClientProtocolException, IOException {
return response;
}
});
}
}
控制台输出：
Took 512
Took 512
Took 512
Maven 依赖：
<dependency>
<groupId>net.bytebuddy</groupId>
<artifactId>byte-buddy</artifactId>
<version>1.10.10</version>
</dependency>
<dependency>
<groupId>org.apache.httpcomponents</groupId>
<artifactId>httpasyncclient</artifactId>
<version>4.1.4</version>
<scope>provided</scope>
</dependency>
这是我执行应用程序的方式：
java -javaagent:"javaagent.jar" -jar application.jar
我不确定是什么原因导致它打印了 3 次。
更新：
感谢 @kriegaex 提供了最小可复现示例（MCVE），你可以在此 GitHub 存储库中找到它。
英文:
I wrote a javaagent as below to capture the execution time of the execute method of the apache org.apache.http.client.HttpClient. It is capturing the time, but it's running three times.
import java.lang.instrument.Instrumentation;
import net.bytebuddy.agent.builder.AgentBuilder;
import net.bytebuddy.implementation.MethodDelegation;
import static net.bytebuddy.matcher.ElementMatchers.isMethod;
import static net.bytebuddy.matcher.ElementMatchers.isAbstract;
import static net.bytebuddy.matcher.ElementMatchers.takesArguments;
import static net.bytebuddy.matcher.ElementMatchers.takesArgument;
import static net.bytebuddy.matcher.ElementMatchers.named;
import static net.bytebuddy.matcher.ElementMatchers.not;
public class TimerAgent {
public static void premain(
String arguments,
Instrumentation instrumentation
) {
new AgentBuilder.Default()
.type(
implementsInterface(named("org.apache.http.client.HttpClient"))
)
.transform((builder, type, classLoader, module) ->
builder.method(isMethod()
.and(named("execute"))
.and(not(isAbstract()))
.and(takesArguments(3))
.and(takesArgument(0, named("org.apache.http.client.methods.HttpUriRequest")))
.and(takesArgument(1, named("org.apache.http.client.ResponseHandler")))
.and(takesArgument(2, named("org.apache.http.protocol.HttpContext"))))
.intercept(MethodDelegation
.to(TimingInterceptor.class))
).installOn(instrumentation);
}
}
import java.lang.reflect.Method;
import java.util.concurrent.Callable;
import net.bytebuddy.implementation.bind.annotation.Origin;
import net.bytebuddy.implementation.bind.annotation.RuntimeType;
import net.bytebuddy.implementation.bind.annotation.SuperCall;
public class TimingInterceptor {
@RuntimeType()
public static Object intercept(
@Origin Method method,
@SuperCall Callable<?> callable
) {
long start = System.currentTimeMillis();
try {
try {
return callable.call();
} catch (Exception e) {
e.printStackTrace();
}
} finally {
System.out.println(
"Took " + (System.currentTimeMillis() - start));
}
return 0;
}
}
I am using DefaultHttpClient to make a HTTP request.
Client code:
import java.io.IOException;
import org.apache.http.HttpEntity;
import org.apache.http.HttpResponse;
import org.apache.http.client.ClientProtocolException;
import org.apache.http.client.HttpClient;
import org.apache.http.client.ResponseHandler;
import org.apache.http.client.methods.HttpGet;
import org.apache.http.client.methods.HttpUriRequest;
import org.apache.http.impl.client.DefaultHttpClient;
public class Main {
public static void main(String[] args) throws IOException {
HttpClient client = new DefaultHttpClient();
HttpUriRequest httpUriRequest = new HttpGet("http://www.google.com");
HttpResponse response = client
.execute(httpUriRequest, new ResponseHandler<HttpResponse>() {
public HttpResponse handleResponse(final HttpResponse response)
throws ClientProtocolException, IOException {
return response;
}
});
}
}
Console output:
Took 512
Took 512
Took 512
Maven dependency:
<dependency>
<groupId>net.bytebuddy</groupId>
<artifactId>byte-buddy</artifactId>
<version>1.10.10</version>
</dependency>
<dependency>
<groupId>org.apache.httpcomponents</groupId>
<artifactId>httpasyncclient</artifactId>
<version>4.1.4</version>
<scope>provided</scope>
</dependency>
This is the implementation for implementsInterface
This is how I am executing the application:
java -javaagent:"javaagent.jar" -jar application.jar
I am not sure what is causing it to print 3 times.
Update:
Thanks to @kriegaex for the MCVE, it can be found in this GitHub repository.
答案1
得分: 1
First of all, where do you get the implementsInterface element matcher from? It is not part of ByteBuddy, at least not in the current version. I replaced it by isSubTypeOf in order to make the code compile. Anyway, if you activate logging like this
new AgentBuilder.Default()
.with(AgentBuilder.Listener.StreamWriting.toSystemError().withTransformationsOnly())
.with(AgentBuilder.InstallationListener.StreamWriting.toSystemError())
.type(isSubTypeOf(HttpClient.class))
// ...
you will see something like this on the console:
[Byte Buddy] BEFORE_INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@1eb5174b on sun.instrument.InstrumentationImpl@67080771
[Byte Buddy] INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@1eb5174b on sun.instrument.InstrumentationImpl@67080771
[Byte Buddy] TRANSFORM org.apache.http.impl.client.DefaultHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
[Byte Buddy] TRANSFORM org.apache.http.impl.client.AbstractHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
[Byte Buddy] TRANSFORM org.apache.http.impl.client.CloseableHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
Handling response: HTTP/1.1 200 OK [Date: Mon, 26 Oct 2020 04:46:18 GMT, Expires: -1, Cache-Control: private, max-age=0, Content-Type: text/html; charset=ISO-8859-1, P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.", Server: gws, X-XSS-Protection: 0, X-Frame-Options: SAMEORIGIN, Set-Cookie: 1P_JAR=2020-10-26-04; expires=Wed, 25-Nov-2020 04:46:18 GMT; path=/; domain=.google.com; Secure, Set-Cookie: NID=204=qecfPmmSAIwXyTGneon07twIXIIw4EyPiArm67OK5nHyUowAq3_8QJZ7gw9k8Nz5ZuGuHoyadCK-nsAKGkZ8TGaD5mdPlAXeVenWwzQrmFkNNDiEpxCj-naf4V6SKDhDUgA18I-2z36ornlEUN7xinrHwWfR0pc4lvlAUx3ssJk; expires=Tue, 27-Apr-2021 04:46:18 GMT; path=/; domain=.google.com; HttpOnly, Accept-Ranges: none, Vary: Accept-Encoding, Transfer-Encoding: chunked] org.apache.http.conn.BasicManagedEntity@6928f576
Took 1870
Took 1871
Took 1871
See? You have installed your interceptor in the whole class hierarchy, three classes all in all:
Hence, you either need to limit your element matcher or have to live with multiple log lines.
Disclaimer: I am not a ByteBuddy expert and maybe Rafael Winterhalter will write a much better answer later, maybe my solution is not canonical.
It looks as if the interceptor matches all classes, even though technically the method is only defined in CloseableHttpClient and not overridden in AbstractHttpClient or DefaultHttpClient. One way to limit type matching is to check if the target class actually contains the method you wish to instrument:
ElementMatcher.Junction<MethodDescription> executeMethodDecription = isMethod()
.and(named("execute"))
.and(not(isAbstract()))
.and(takesArguments(3))
.and(takesArgument(0, named("org.apache.http.client.methods.HttpUriRequest")))
.and(takesArgument(1, named("org.apache.http.client.ResponseHandler")))
.and(takesArgument(2, named("org.apache.http.protocol.HttpContext")));
new AgentBuilder.Default()
.with(AgentBuilder.Listener.StreamWriting.toSystemError().withTransformationsOnly())
.with(AgentBuilder.InstallationListener.StreamWriting.toSystemError())
.type(
isSubTypeOf(HttpClient.class)
.and(declaresMethod(executeMethodDecription))
)
.transform((builder, type, classLoader, module) -> builder
.method(executeMethodDecription)
.intercept(MethodDelegation.to(TimingInterceptor.class))
)
.installOn(instrumentation);
Now the console log should turn into:
[Byte Buddy] BEFORE_INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@67080771 on sun.instrument.InstrumentationImpl@72cde7cc
[Byte Buddy] INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@67080771 on sun.instrument.InstrumentationImpl@72cde7cc
[Byte Buddy] TRANSFORM org.apache.http.impl.client.CloseableHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @6ea2bc93, loaded=false]
Handling response: HTTP/1.1 200 OK [Date: Mon, 26 Oct 2020 05:21:25 GMT, Expires: -1, Cache-Control: private, max-age=0, Content-Type: text/html; charset=ISO-8859-1, P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.", Server: gws, X-XSS-Protection: 0, X-Frame-Options: SAMEORIGIN, Set-Cookie: 1P_JAR=2020-10-26-05; expires=Wed, 25-Nov-2020 05:21:25 GMT; path=/; domain=.google.com; Secure, Set-Cookie: NID=204=N7U6SBBW5jjM1hynbowChQ2TyMSbiLHHwioKYusPVHzJPkiRaSvpmeIlHipo34BAq5QqlJnD7GDD1iv6GhIZlEEl7k3MclOxNY9WGn9c6elHikj6MPUhXsAapYz9pOVFl_DjAInWv5pI00FfUZ6i5mK14kq3JIXu-AV84WKDxdc; expires=Tue, 27-Apr-2021 05:21:25 GMT; path=/; domain=.google.com;
<details>
<summary>英文:</summary>
First of all, where do you get the `implementsInterface` element matcher from? It is not part of ByteBuddy, at least not in the current version. I replaced it by `isSubTypeOf` in order to make the code compile. Anyway, if you activate logging like this
```java
new AgentBuilder.Default()
.with(AgentBuilder.Listener.StreamWriting.toSystemError().withTransformationsOnly())
.with(AgentBuilder.InstallationListener.StreamWriting.toSystemError())
.type(isSubTypeOf(HttpClient.class))
// ...
you will see something like this on the console:
[Byte Buddy] BEFORE_INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@1eb5174b on sun.instrument.InstrumentationImpl@67080771
[Byte Buddy] INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@1eb5174b on sun.instrument.InstrumentationImpl@67080771
[Byte Buddy] TRANSFORM org.apache.http.impl.client.DefaultHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
[Byte Buddy] TRANSFORM org.apache.http.impl.client.AbstractHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
[Byte Buddy] TRANSFORM org.apache.http.impl.client.CloseableHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @4d518b32, loaded=false]
Handling response: HTTP/1.1 200 OK [Date: Mon, 26 Oct 2020 04:46:18 GMT, Expires: -1, Cache-Control: private, max-age=0, Content-Type: text/html; charset=ISO-8859-1, P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.", Server: gws, X-XSS-Protection: 0, X-Frame-Options: SAMEORIGIN, Set-Cookie: 1P_JAR=2020-10-26-04; expires=Wed, 25-Nov-2020 04:46:18 GMT; path=/; domain=.google.com; Secure, Set-Cookie: NID=204=qecfPmmSAIwXyTGneon07twIXIIw4EyPiArm67OK5nHyUowAq3_8QJZ7gw9k8Nz5ZuGuHoyadCK-nsAKGkZ8TGaD5mdPlAXeVenWwzQrmFkNNDiEpxCj-naf4V6SKDhDUgA18I-2z36ornlEUN7xinrHwWfR0pc4lvlAUx3ssJk; expires=Tue, 27-Apr-2021 04:46:18 GMT; path=/; domain=.google.com; HttpOnly, Accept-Ranges: none, Vary: Accept-Encoding, Transfer-Encoding: chunked] org.apache.http.conn.BasicManagedEntity@6928f576
Took 1870
Took 1871
Took 1871
See? You have installed your interceptor in the whole class hierarchy, three classes all in all:
Hence, you either need to limit your element matcher or have to live with multiple log lines.
Disclaimer: I am not a ByteBuddy expert and maybe Rafael Winterhalter will write a much better answer later, maybe my solution is not canonical.
It looks as if the interceptor matches all classes, even though technically the method is only defined in CloseableHttpClient and not overridden in AbstractHttpClient or DefaultHttpClient. One way to limit type matching is to check if the target class actually contains the method you wish to instrument:
ElementMatcher.Junction<MethodDescription> executeMethodDecription = isMethod()
.and(named("execute"))
.and(not(isAbstract()))
.and(takesArguments(3))
.and(takesArgument(0, named("org.apache.http.client.methods.HttpUriRequest")))
.and(takesArgument(1, named("org.apache.http.client.ResponseHandler")))
.and(takesArgument(2, named("org.apache.http.protocol.HttpContext")));
new AgentBuilder.Default()
.with(AgentBuilder.Listener.StreamWriting.toSystemError().withTransformationsOnly())
.with(AgentBuilder.InstallationListener.StreamWriting.toSystemError())
.type(
isSubTypeOf(HttpClient.class)
.and(declaresMethod(executeMethodDecription))
)
.transform((builder, type, classLoader, module) -> builder
.method(executeMethodDecription)
.intercept(MethodDelegation.to(TimingInterceptor.class))
)
.installOn(instrumentation);
Now the console log should turn into:
[Byte Buddy] BEFORE_INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@67080771 on sun.instrument.InstrumentationImpl@72cde7cc
[Byte Buddy] INSTALL net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport@67080771 on sun.instrument.InstrumentationImpl@72cde7cc
[Byte Buddy] TRANSFORM org.apache.http.impl.client.CloseableHttpClient [jdk.internal.loader.ClassLoaders$AppClassLoader@2626b418, unnamed module @6ea2bc93, loaded=false]
Handling response: HTTP/1.1 200 OK [Date: Mon, 26 Oct 2020 05:21:25 GMT, Expires: -1, Cache-Control: private, max-age=0, Content-Type: text/html; charset=ISO-8859-1, P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info.", Server: gws, X-XSS-Protection: 0, X-Frame-Options: SAMEORIGIN, Set-Cookie: 1P_JAR=2020-10-26-05; expires=Wed, 25-Nov-2020 05:21:25 GMT; path=/; domain=.google.com; Secure, Set-Cookie: NID=204=N7U6SBBW5jjM1hynbowChQ2TyMSbiLHHwioKYusPVHzJPkiRaSvpmeIlHipo34BAq5QqlJnD7GDD1iv6GhIZlEEl7k3MclOxNY9WGn9c6elHikj6MPUhXsAapYz9pOVFl_DjAInWv5pI00FfUZ6i5mK14kq3JIXu-AV84WKDxdc; expires=Tue, 27-Apr-2021 05:21:25 GMT; path=/; domain=.google.com; HttpOnly, Accept-Ranges: none, Vary: Accept-Encoding, Transfer-Encoding: chunked] org.apache.http.conn.BasicManagedEntity@5471388b
Took 1274
Update: Actually the behaviour of intercept() is described in its javadoc:
> Implements the previously defined or matched method by the supplied implementation. A method interception is typically implemented in one of the following ways:
> 1. If a method is declared by the instrumented type and the type builder creates a subclass or redefinition, any preexisting method is replaced by the given implementation. Any previously defined implementation is lost.
> 2. If a method is declared by the instrumented type and the type builder creates a rebased version of the instrumented type, the original method is preserved within a private, synthetic method within the instrumented type. The original method therefore remains invokeable and is treated as the direct super method of the new method. When rebasing a type, it therefore becomes possible to invoke a non-virtual method's super method when a preexisting method body is replaced.
> 3. If a virtual method is inherited from a super type, it is overridden. The overridden method is available for super method invocation.
Update 2: My full MCVE is available for everyone's convenience in this GitHub repository.
通过集体智慧和协作来改善编程学习和解决问题的方式。致力于成为全球开发者共同参与的知识库，让每个人都能够通过互相帮助和分享经验来进步。
评论