No console output if not in verbose mode

[wy96f]

Hi, i am a newbie of btrace.

I have written a script(Calls.java) to profile our app as follow:

import com.sun.btrace.AnyType;
import com.sun.btrace.annotations.;
import static com.sun.btrace.BTraceUtils.;
import com.sun.btrace.Profiler;

/**

• • This script demonstrates the possibility to intercept
• • method calls that are about to be executed from the body of
• • a certain method. This is achieved by using the {@linkplain Kind#CALL}

• * location value.
  

•  */
  

@btrace public class Calls {
@Property
private static Profiler swingProfiler = Profiling.newProfiler();

@OnMethod(clazz="/com\\.handwin\\.game\\.controller\\..*/", method="/.*/")
public static void entry(@ProbeMethodName(fqn=true) String probeMethod) { // all calls to the methods with signature "()"
    //print(str(self) + " in " + probeMethod + ": ");
    println("entry " + probeMethod);
    Profiling.recordEntry(swingProfiler, probeMethod);
}

@OnMethod(clazz="/com\\.handwin\\.game\\.controller\\..*/", method="/.*/", location=@Location(value=Kind.RETURN))
public static void exit(@ProbeMethodName(fqn=true) String probeMethod, @Duration long duration) { // all calls to the methods with signature "()"
    println("exit " + probeMethod);
    Profiling.recordExit(swingProfiler, probeMethod, duration);
}

@onerror
public static void onError(Throwable t) {
print("btrace throw: ");
println(t);
}

@OnTimer(10000)
public static void timer() {
    Profiling.printSnapshot("Swing performance profile", swingProfiler);
}

}

The script works well in verbose mode( export JAVA_HOME=/opt/jdk8 && ./bin/btrace -v 22967 Calls.java):
[faceshow@ip-10-1-40-222 btrace]$ export JAVA_HOME=/opt/jdk8 && ./bin/btrace -v 22967 Calls.java
DEBUG: assuming default port 2020
DEBUG: assuming default classpath '.'
DEBUG: compiling Calls.java
DEBUG: compiled Calls.java
DEBUG: attaching to 22967
DEBUG: checking port availability: 2020
DEBUG: attached to 22967
DEBUG: loading /opt/faceshow/btrace/build/btrace-agent.jar
DEBUG: agent args: port=2020,statsd=,debug=true,bootClassPath=.,systemClassPath=/opt/jdk8/jre/../lib/tools.jar,probeDescPath=.
DEBUG: loaded /opt/faceshow/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: setting up client settings
DEBUG: sending instrument command
DEBUG: entering into command loop
DEBUG: received com.sun.btrace.comm.RenameCommand@43bd930a
DEBUG: received com.sun.btrace.comm.OkayCommand@33723e30
DEBUG: received com.sun.btrace.comm.RetransformationStartNotification@64f6106c
DEBUG: received com.sun.btrace.comm.OkayCommand@553a3d88
DEBUG: received com.sun.btrace.comm.MessageCommand@543c6f6d
entry public final java.util.Map com.handwin.game.controller.GameController$$EnhancerBySpringCGLIB$$c0ce67f0#getGames(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@13eb8acf
entry public java.lang.Object com.handwin.game.controller.GameController$$FastClassBySpringCGLIB$$e44b30f2#invoke(int, java.lang.Object, java.lang.Object[])
DEBUG: received com.sun.btrace.comm.MessageCommand@51c8530f
entry public java.util.Map com.handwin.game.controller.GameController#getGames(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@7403c468
entry private boolean com.handwin.game.controller.GameController#shouldBuy(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@43738a82
entry private int com.handwin.game.controller.GameController#compareVersion(java.lang.String, java.lang.String)
DEBUG: received com.sun.btrace.comm.MessageCommand@c81cdd1
exit private int com.handwin.game.controller.GameController#compareVersion(java.lang.String, java.lang.String)
DEBUG: received com.sun.btrace.comm.MessageCommand@1fc2b765
exit private boolean com.handwin.game.controller.GameController#shouldBuy(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@75881071
entry private boolean com.handwin.game.controller.GameController#shouldGetPlayerNum(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@2a70a3d8
exit private boolean com.handwin.game.controller.GameController#shouldGetPlayerNum(javax.servlet.http.HttpServletRequest)
DEBUG: received com.sun.btrace.comm.MessageCommand@289d1c02
entry private void com.handwin.game.controller.GameController#lambda$getGames$0(com.handwin.game.entity.User, int, com.handwin.game.entity.vo.game.GameVo)
DEBUG: received com.sun.btrace.comm.MessageCommand@22eeefeb
exit private void com.handwin.game.controller.GameController#lambda$getGames$0(com.handwin.game.entity.User, int, com.handwin.game.entity.vo.game.GameVo)
DEBUG: received com.sun.btrace.comm.MessageCommand@17d0685f
entry private void com.handwin.game.controller.GameController#lambda$getGames$0(com.handwin.game.entity.User, int, com.handwin.game.entity.vo.game.GameVo)
DEBUG: received com.sun.btrace.comm.MessageCommand@3891771e

But if i remove -v, there is no output.
Could you guys shed light on me?

[jbachorik]

Most probably it is due 'System.out' buffering. The stream is not force-flushed and we rely on the output to appear on console eventually. The verbose mode is generating more data and the output is flushed more frequently.

Anyway, I would expect the output to be displayed upon the BTrace client exit.

As an enhancement, I could provide a new client action to be displayed in the menu invoked by Ctrl-C that would allow force-flushing the console output.

[jbachorik]

I have added the extra command - you will need to pull the changes and rebuild BTrace to test it out.

[wy96f]

Hi, jbachorik
Thanks for the reply. It's not the 'System.out' buffering problem bcs there is profiler output every 10s like this:
Swing performance profile
Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max
Swing performance profile
Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max
Swing performance profile
Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max

Anyway I have built latest btrace and tried it without -v parameter. Even I called the flush command, the script still failed to record the call. The output is as follows:
[faceshow@ip-10-0-20-139 btrace-1.4]$ export JAVA_HOME=/opt/jdk8 && ./bin/btrace 20454 Calls.java
^CPlease enter your option:
1. exit
2. send an event
3. send a named event
4. flush console output
4

Swing performance profile
Block Invocations SelfTime.Total SelfTime.Avg SelfTime.Min SelfTime.Max WallTime.Total WallTime.Avg WallTime.Min WallTime.Max
^CPlease enter your option:
1. exit
2. send an event
3. send a named event
4. flush console output
1

[jbachorik]

Ok, this info was missing from the original report :) So, the output is properly flushed.

If you remove the recordEntry and recordExit calls will you get the println generated traces? I will try to reproduce as well but I haven't seen such strange behavior yet.

[jbachorik]

I have tested the script from samples/Profiling.java against a simple Swing application (AnagramGame from the sample applications in NetBeans) and everything seems to be operating normally.

[wy96f]

Hi, jbachorik
Still no println generated traces after removing the recordEntry and recordExit. By the way, we deploy a war(our spring mvc application) to tomcat.

[jbachorik]

Ok, if you run btrace -d <path> ... you will get the compiled BTrace script class as well as the instrumented classes stored in the <path>. You could then zip it and attach to this issue so I could check the instrumentation.

This is very odd behavior - I have never seen that happening :(

[jbachorik]

Any news regarding this. Were you able to capture the instrumented classes?

[zeocio]

By the way I just encountered this as well. I was using 1.3.9 release against a hadoop container process. I tried both oracle jdk1.8.0_112 and java-1.8.0-openjdk-1.8.0.121-0.b13 and they behaved the same, with verbose option producing output (and killing the container quickly due to rapidly growing mem footprint) and non-verbose option producing absolutely no output.

The trace script I wrote generates a large quantity of output so buffering/flushing shouldn't be an issue? Is there anything I can try to further diagnose this?

[jbachorik]

Was anybody, by chance, able to run btrace -d <path> ... in order to capture the instrumented classes and preprocesed probe bytecode? That would really help diagnosing this problem. I still can not reproduce it on my side.

[grapeqin]

@jbachorik
My btrace version is 1.3.11.
-----------------start btrace script-----------------
package com.y.shpt.ao;

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

import com.sun.btrace.AnyType;
import com.sun.btrace.annotations.*;

@btrace
public class trace{

@OnMethod(clazz = "/y\\..*\\..*\\.service\\.impl\\..*ServiceImpl/", method = "/.*/", location = @Location(Kind.RETURN))
public static void traceShop(@ProbeClassName String clazzName, @ProbeMethodName String method, AnyType[] args,@Return AnyType result, @Duration long time) {
    if (time / 1000000 > 5) {
        print("clazzName:" + clazzName + ",method:" + method + " cost " + time / 1000000 + " ms");
        println("--------------------------------------------------------------------");
    }
}

}

-----------------end btrace script-----------------

-----------------start btrace output-----------------

[test@sz-dev-a-5 bin]$ ./btrace -p 2021 12817 trace.java
^CPlease enter your option:
1. exit
2. send an event
3. send a named event
4. flush console output
1
[test@sz-dev-a-5 bin]$ ./btrace -p 2021 12817 trace.java -v
DEBUG: accepting port 2021
DEBUG: assuming default classpath '.'
DEBUG: compiling trace.java
DEBUG: compiled trace.java
DEBUG: attaching to 12817
DEBUG: checking port availability: 2021
DEBUG: attached to 12817
DEBUG: loading /home/test/local/btrace-1.3.11/build/btrace-agent.jar
DEBUG: agent args: port=2021,statsd=,debug=true,bootClassPath=.,systemClassPath=/data/svr/jdk1.8.0_144-weixin/jre/../lib/tools.jar,probeDescPath=.
DEBUG: loaded /home/test/local/btrace-1.3.11/build/btrace-agent.jar
DEBUG: registering shutdown hook
DEBUG: registering signal handler for SIGINT
DEBUG: submitting the BTrace program
DEBUG: opening socket to 2021
DEBUG: setting up client settings
DEBUG: sending instrument command: [-v]
DEBUG: entering into command loop
DEBUG: received com.sun.btrace.comm.RenameCommand@481a15ff
DEBUG: received com.sun.btrace.comm.OkayCommand@78186a70
DEBUG: received com.sun.btrace.comm.RetransformationStartNotification@306279ee
DEBUG: received com.sun.btrace.comm.MessageCommand@4c762604
clazzname:y.s.shop.service.impl.shoppackagerecordserviceimpl,method:list cost 279 ms
DEBUG: received com.sun.btrace.comm.MessageCommand@2641e737--------------------------------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@727803de
clazzName:y.s.shop.service.impl.ShopPackageServiceImpl,method:get cost 231 ms
DEBUG: received com.sun.btrace.comm.MessageCommand@704921a5--------------------------------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@df27fae
clazzName:y.s.shop.service.impl.ShopPackageRecordServiceImpl,method:checkPackageIsExpire cost 232 ms
DEBUG: received com.sun.btrace.comm.MessageCommand@24a35978--------------------------------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@16f7c8c1
clazzName:y.s.shop.service.impl.ShopPackageServiceImpl,method:get cost 10 ms
DEBUG: received com.sun.btrace.comm.MessageCommand@2f0a87b3--------------------------------------------------------------------
DEBUG: received com.sun.btrace.comm.MessageCommand@319b92f3
clazzName:y.s.shop.service.impl.ShopPackageRecordServiceImpl,method:getUsefulPackage cost 522 ms
^CPlease enter your option:
1. exit
2. send an event
3. send a named event
4. flush console output
1
DEBUG: sending exit command
[test@sz-dev-a-5 bin]$ ./btrace -p 2021 12817 trace.java
^CPlease enter your option:
1. exit
2. send an event
3. send a named event
4. flush console output
1
-----------------end btrace output----------------

-----------------start btrace -d----------------

12817.zip

from the output we see when i add -v then has print，remove then disappear.
Look forward to your reply.

[github-actions]

Stale issue message