Cannot print info to console

[TheodoreSKong]

Btrace cannot print info msg on console when using btrace pid scripts.java.
but when using btrace -v pid scripts.java, the msg can be printed along with debug info.

the trace scripts:

import org.openjdk.btrace.core.annotations.BTrace;
import org.openjdk.btrace.core.annotations.Injected;
import org.openjdk.btrace.core.annotations.OnMethod;
import org.openjdk.btrace.core.annotations.ProbeClassName;
import org.openjdk.btrace.core.annotations.ProbeMethodName;
import org.openjdk.btrace.core.annotations.Self;
import org.openjdk.btrace.core.annotations.ServiceType;
import org.openjdk.btrace.services.impl.Printer;

import static org.openjdk.btrace.core.BTraceUtils.*;

@BTrace
public class AllMethods {
    @Injected(ServiceType.RUNTIME)
    private static Printer printer;
    @OnMethod(
        clazz="/voldemort\\.server\\..*/", 
        method="/.*/"//"${m}"
    )
    public static void m(@Self Object o, @ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        printer.print("q");
        printer.print("entered " + probeClass);
        printer.println("." + probeMethod+"   TIME:"+ Time.millis());
    }
}

[jbachorik]

Can you provide more details?
OS, Java version?

How often are those method called? The output is buffered not to impact the traced application with constant flushes so if the method is not frequently invoked it may not flush to console. Try Ctrl-C , 4 to flush the output to see whether this helps.

[TheodoreSKong]

the test was run on Windows 10 (1909 18363.752), Java version is

java version "1.8.0_241"
Java(TM) SE Runtime Environment (build 1.8.0_241-b07)
Java HotSpot(TM) 64-Bit Server VM (build 25.241-b07, mixed mode)

Those methods are called frequently because I use btrace -v pid xxx.java can find that.
Since btrace -v perform normally, I thought there may be not the problem about the fluse.

[jbachorik]

Can you try flushing? The data is sent to stdout stream regardless of whether -v option is used or not. The only difference is that in verbose mode there is much more data to be output.

[TheodoreSKong]

I have tried to flush the console output but their still no out puts.

[jbachorik]

Argh. I will have to install windows 10 in virtualbox to debug this.
It is not really obvious why the data is not printed to console - it should go directly to stdout :/
Can you try running btrace ... -o <path_to_output>.txt to redirect the output to file and see whether the expected data is there?

[TheodoreSKong]

I have try the -o command but the log file is not created.
I also find the problem that when I use -v command to get the trace of a package with a lot methods, only two methods are recorded and I'm not sure if this is correct.

 @OnMethod(
            clazz = "/voldemort\\.server\\.niosocket\\..*/", 
            method = "/.*/"
    )
    public static void m(@Self Object o, @ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        println("entered:" + "[" + name(currentThread()) + "]" + "-" + probeClass + "." + probeMethod + "-atTime:" + timeNanos());
    }

[TheodoreSKong]

is there any different between the

method = "/.*/"

and

method = "${m}"

[TheodoreSKong]

I have try the -o command but the log file is not created.
I also find the problem that when I use -v command to get the trace of a package with a lot methods, only two methods are recorded and I'm not sure if this is correct.

 @OnMethod(
            clazz = "/voldemort\\.server\\.niosocket\\..*/", 
            method = "/.*/"
    )
    public static void m(@Self Object o, @ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        println("entered:" + "[" + name(currentThread()) + "]" + "-" + probeClass + "." + probeMethod + "-atTime:" + timeNanos());
    }

I have changed the class to clazz = "/.*/", but the outputs are only have two methods (also under -v command). a sample output likes following:

DEBUG: assuming default port 2020
DEBUG: assuming default classpath '.'
DEBUG: compiling .\cwj\AllMethods.java
DEBUG: compiled .\cwj\AllMethods.java
DEBUG: attaching to 13044
DEBUG: checking port availability: 2020
DEBUG: attached to 13044
DEBUG: loading C:\Users\buaak\Documents\btrace-bin\libs\btrace-agent.jar
DEBUG: agent args: port=2020,statsd=,debug=true,bootClassPath=.,systemClassPath=C:\Program Files\Java\jre1.8.0_241/lib/tools.jar,probeDescPath=.
DEBUG: loaded C:\Users\buaak\Documents\btrace-bin\libs\btrace-agent.jar
DEBUG: registering shutdown hook
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 org.openjdk.btrace.core.comm.RenameCommand@70b0b186
DEBUG: received org.openjdk.btrace.core.comm.OkayCommand@ba8d91c
DEBUG: received org.openjdk.btrace.core.comm.RetransformationStartNotification@7364985f
DEBUG: received org.openjdk.btrace.core.comm.MessageCommand@3d36e4cd
entered:[voldemort-nio-socket-server-t4]-voldemort.server.niosocket.NioSelectorManager.processEvents-atTime:439903813314300
DEBUG: received org.openjdk.btrace.core.comm.MessageCommand@6a472554
entered:[voldemort-admin-server-t1]-voldemort.server.niosocket.NioSelectorManager.processEvents-atTime:439903813315900
DEBUG: received org.openjdk.btrace.core.comm.MessageCommand@7ff2a664
entered:[voldemort-nio-socket-server-t5]-voldemort.server.niosocket.NioSelectorManager.processEvents-atTime:439903813316900
DEBUG: received org.openjdk.btrace.core.comm.MessageCommand@525b461a
entered:[voldemort-admin-server-t6]-voldemort.server.niosocket.NioSelectorManager.processEvents-atTime:439903813339000

[TheodoreSKong]

I also find a warning info, does that matter?

btrace INFO: "org.openjdk.btrace.core.cmdQueueLimit" not provided. Using the default cmd queue limit of 100

[TheodoreSKong]

BTrace is such a useful tool that I used it to complete my empirical study on software runtime analysis.
Recently I find some information that may help to deal the problem,
the issue (no output to console) happen when I try to trace an application named Voldemort.
Voldemort has a lot of working thread (more than 10 ) and I tried to trace a module in it named NIO (used to process non-block I/O).
When I use BTrace in this situation, the output cannot be dumped out in non verbose mode, in verbose mode, only two methods are record, but there should be a lot of methods being executed.
some debug information are printed to the console which Voldemort work (only debug info, no outputs from probe methods are printed here)and the others are printed on the BTrace console (the outputs are not completed in verbose mode, no outputs when in non verbose mode).
I use a small app like hello world, the btrace work normally (on Windows).

So the problems may be caused by the multi-thread problems or to much information that need output cause packet dropout? (I guess)

following debug information may help

DEBUG: sending instrument command: []
DEBUG: entering into command loop

[jbachorik]

is there any different between the

method = "/.*/"

and

method = "${m}"

The first form is a statically defined regex matching all methods. The second form will take the user arg value to define the method filter - then you can do eg. btrace your.app your_script.java m=/interesting.*method/ to define the methods to instrument 'dynamically'.

[jbachorik]

BTrace is such a useful tool that I used it to complete my empirical study on software runtime analysis.
Recently I find some information that may help to deal the problem,
the issue (no output to console) happen when I try to trace an application named Voldemort.
Voldemort has a lot of working thread (more than 10 ) and I tried to trace a module in it named NIO (used to process non-block I/O).
When I use BTrace in this situation, the output cannot be dumped out in non verbose mode, in verbose mode, only two methods are record, but there should be a lot of methods being executed.
some debug information are printed to the console which Voldemort work (only debug info, no outputs from probe methods are printed here)and the others are printed on the BTrace console (the outputs are not completed in verbose mode, no outputs when in non verbose mode).
I use a small app like hello world, the btrace work normally (on Windows).

So the problems may be caused by the multi-thread problems or to much information that need output cause packet dropout? (I guess)

following debug information may help

DEBUG: sending instrument command: []
DEBUG: entering into command loop

Can you capture also the debug output from the traced application? It would really interesting to see which methods are instrumented and whether there are any warnings printed out.

[buzuotaxuan]

Btrace cannot print info msg on console when using btrace pid scripts.java.
but when using btrace -v pid scripts.java, the msg can be printed along with debug info.

the trace scripts:

import org.openjdk.btrace.core.annotations.BTrace;
import org.openjdk.btrace.core.annotations.Injected;
import org.openjdk.btrace.core.annotations.OnMethod;
import org.openjdk.btrace.core.annotations.ProbeClassName;
import org.openjdk.btrace.core.annotations.ProbeMethodName;
import org.openjdk.btrace.core.annotations.Self;
import org.openjdk.btrace.core.annotations.ServiceType;
import org.openjdk.btrace.services.impl.Printer;

import static org.openjdk.btrace.core.BTraceUtils.*;

@BTrace
public class AllMethods {
    @Injected(ServiceType.RUNTIME)
    private static Printer printer;
    @OnMethod(
        clazz="/voldemort\\.server\\..*/", 
        method="/.*/"//"${m}"
    )
    public static void m(@Self Object o, @ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        printer.print("q");
        printer.print("entered " + probeClass);
        printer.println("." + probeMethod+"   TIME:"+ Time.millis());
    }
}

Can you provide more details?
OS, Java version?

How often are those method called? The output is buffered not to impact the traced application with constant flushes so if the method is not frequently invoked it may not flush to console. Try Ctrl-C , 4 to flush the output to see whether this helps.

I wander if it's relate to the way you start the application ,i run the application with the jar package that include all third package

[jbachorik]

The underlying problem was that one of the instrumented classes does not verify properly. Unfortunately, I am not able to figure out what is actually causing the verification problem as the JVM verifier does not provide any explanatory message and the ASM CheckClassAdapter successfully verifies the instrumented class so it seems to be some JVM verifier quirk which is not known even to ASM authors :/

The reason you could see the output in verbose mode is that in that mode the classes are retransformed one by one - it takes more time but allows to report on progress and failures.
I have added a fallback mode when the batch retransform fails with a verification error to retry the classes one by one - and have the instrumentation applied where possible while failed attempts are logged with the class name so it is easier to figure out why something might not be working.

If I get to the root of the verification error I will fix it - until then such classes will just be skipped.