Strace do Linux não segue processos filhos mesmo com -f (pai multithread)

5

Nota: existem várias perguntas semelhantes, com a resposta geral sendo "Se você deseja rastrear um processo multithread ou seguir filhos, use -f". Isso não me ajuda, já que estou usando -f.

Eu preciso strace um aplicativo java, que inicia um processo filho e exec um script em uma base regular. Eu quero ver os parâmetros de linha de comando dados ao script, e por razões muito complicadas para explicar aqui, eu não posso colocar um wrapper em torno do script.

Meu problema é que, rastreando o processo java, posso ver as chamadas do sistema clone() , mas não consigo ver o que acontece no processo filho depois do clone() .

Aqui está um programa de teste mínimo:

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) {
            ;
        }
    }
}

A execução e o início do rastreamento geram:

# /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

Isto apenas se repete até que eu pare o processo. Nada dos processos filhos é mostrado. Como visto, é um subthread 143281 que faz as chamadas clone() , não o segmento "principal". No entanto, quando eu tento rastrear a sub-rotina, strace segue o novo processo, mas mata o pai com SIGTRAP depois de um tempo:

# 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 +++

Isso acontece em um sistema RHEL6 com strace fornecido pelo RHEL, bem como com um binário strace copiado de um sistema Ubuntu 14.04 LTS.

Existe alguma coisa que eu estou faltando, alguma opção para strace que eu deveria definir, ou um bug na strace, ou uma limitação geral que eu não conheço? Alguma idéia?

    
por Guntram Blohm 02.02.2016 / 14:41

0 respostas

Tags