5

Note: there are several similar questions, with the general answer being "If you want to trace a multithreaded process, or follow children, use -f". This doesn't help me, as i am using -f already.

I need to strace a java application, that starts a child process and exec's a script on a regular basis. I want to see the command line parameters given to the script, and for reasons too complicated to explain here, i can't put a wrapper around the script.

My problem is that, tracing the java process, i can see the clone() system calls, but i can't see what happens in the child process after the clone().

Here's a minimal test program:

package exectest;
import java.io.IOException;
public class Exectest {
    public static void main(String[] args) {
        for (;;) {
            createProcess();
            try {
                Thread.sleep(15000);
            } catch (InterruptedException ex) {
                ;
            }
        }
    }
    static void createProcess()  {
        String[] params;
        params=new String[100000];
        for (int i=0; i<100000; i++) {
            params[i]=Integer.toString(i);
        }
        params[0]="echo";
        params[1]="test";
        try {
            Runtime.getRuntime().exec(params);
        } catch (IOException ex) {
            ;
        }
    }
}

Running it, and starting the trace, yields:

# /path/to/java -version
java version "1.6.0_81"
Java(TM) SE Runtime Environment (build 1.6.0_81-b08)
Java HotSpot(TM) 64-Bit Server VM (build 20.81-b05, mixed mode)
# /path/to/java -jar /tmp/exectest.jar &
[1] 143280
# strace -tt -e '!futex' -f -p 143280
[pid 143281] 14:16:11.146692 mmap(NULL, 1052672, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb0a070d000
[pid 143281] 14:16:11.146767 clone(child_stack=0x7fb0a080cff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb0a080d9d0, tls=0x7fb0a080d700, child_tidptr=0x7fb0a080d9d0) = 143981
[pid 143281] 14:16:26.177072 mmap(NULL, 1052672, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb0a060c000
[pid 143281] 14:16:26.177150 clone(child_stack=0x7fb0a070bff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb0a070c9d0, tls=0x7fb0a070c700, child_tidptr=0x7fb0a070c9d0) = 144187

This just repeats until i stop the process. Nothing from the child processes is shown. As seen, it's a subthread 143281 that does the clone() calls, not the "main" thread. However, when i try tracing the subthread, strace does follow the new process, but it kills the parent with SIGTRAP after a while:

# strace -tt -e '!futex' -f -p 143281 
....
[pid 143281] 14:19:26.529955 mprotect(0x7fb0a8107000, 4096, PROT_READ|PROT_WRITE) = 0
[pid 143281] 14:19:26.530049 mprotect(0x7fb0a8108000, 4096, PROT_READ|PROT_WRITE) = 0
[pid 143281] 14:19:26.530084 mmap(NULL, 1052672, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7fb045b6a000
[pid 143281] 14:19:26.530147 clone(Process 146745 attached
child_stack=0x7fb045c69ff0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7fb045c6a9d0, tls=0x7fb045c6a700, child_tidptr=0x7fb045c6a9d0) = 146745
[pid 146745] 14:19:26.530275 set_robust_list(0x7fb045c6a9e0, 0x18) = 0
[pid 146745] 14:19:26.530322 gettid()   = 146745
....
[pid 143307] 14:19:26.589462 --- SIGTRAP (Trace/breakpoint trap) @ 0 (0) ---
Process 143307 detached
[pid 146746] 14:19:26.589595 write(1, " 8414 8415 8416 8417 8418 8419 8"..., 4096) = 4096
[pid 146746] 14:19:26.590052 write(1, "9233 9234 9235 9236 9237 9238 92"..., 4096 <unfinished ...>
[pid 146358] 14:19:26.590751 +++ killed by SIGTRAP +++
[pid 146746] 14:19:26.590765 <... write resumed> ) = 4096
[pid 146745] 14:19:26.590775 +++ killed by SIGTRAP +++
[pid 146541] 14:19:26.590781 +++ killed by SIGTRAP +++
[pid 146176] 14:19:26.590787 +++ killed by SIGTRAP +++
[pid 145811] 14:19:26.590792 +++ killed by SIGTRAP +++
[pid 145408] 14:19:26.590797 +++ killed by SIGTRAP +++

This happens on a RHEL6 system with RHEL-provided strace, as well as with an strace binary copied over from a Ubuntu 14.04 LTS system.

Is there anything i'm missing, any options to strace that i should set, or a bug in strace, or a general limitation i'm not aware of? Any ideas?

  • What are strace versions? Did you tried to run whole java from strace, e.g. strace -tt -e '!futex' -f /path/to/java -jar /tmp/exectest.jar? – user140866 Feb 3 '16 at 3:11
  • strace -V says 4.5.19 in both cases. Running java from strace seems to work, but is, unfortunately, not an option, as i need to debug a daemon process that runs well for a long time and starts showing issues after several days, and i can't run it under control of strace all the time for performance reasons. – Guntram Blohm Feb 3 '16 at 8:53
  • Strace is rather complicated program, and I face same issue sometimes, especially with multithreaded programs that use pthreads. I was forced to filter by syscalls including needed syscalls and omitting the rest noise. Not sure if there is a complete workaround, so +1. – user140866 Feb 3 '16 at 10:45

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.