recording traces with address filtering of thread start_routine functions

[man9ourah]

Hello..
I dont know if this is the right place to report this since it is not an issue with the decoding really.. if you may, please refer me to the right place to post this issue if this isn't.

I dont know if this is specific to thread start_routine, or is it for all callback functions that a binary provide to a library, but I will present my case:

Assume this test code (from https://www.geeksforgeeks.org/multithreading-c-2/):

#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>

// Let us create a global variable to change it in threads 
int g = 0;

// The function to be executed by all threads 
void *myThreadFun(void *vargp)
{
    // Store the value argument passed to this thread 
    int *myid = (int *)vargp;

    // Let us create a static variable to observe its changes 
    static int s = 0;

    // Change static and global variables 
    // Print the argument, static and global variables 
    printf("Thread ID: %d, Static: %d, Global: %d\n", *myid, ++s, ++g);

    if(g > 2)
        printf("Test\n");
}

int main()
{
    int i;
    pthread_t tid;

    // Let us create three threads 
    for (i = 0; i < 3; i++)
        pthread_create(&tid, NULL, myThreadFun, (void *)&i);

    pthread_exit(NULL);
    return 0;
}

I want to trace the function myThreadFun, so I do this:
perf record -m 512,10000 -e intel_pt//u -T --switch-events --filter 'filter myThreadFun @ ./test' -- ./test

Then I decode with perf script .. but the trace is empty?!

Now when I trace, without the filters:
perf record -m 512,10000 -e intel_pt//u -T --switch-events -- ./test

I can see myThreadFun in perf script..

Is this a bug? or am I doing something wrong?

Thanks!

[markus-metzger]

I have not tried your example but I tried other examples and I did get the trace I expected to get. I checked again with perf 4.18.7 and it worked with my example.

If the trace is empty where you think it should not be empty, I'd start by reporting this to the perf maintainers. Adrian Hunter may be a good start.

You can also use the -v option to perf record to have it print the filter it is using. Double-check that you get what you expected.

[man9ourah]

Thank you Markus, for your response..
Now that I have looked into this further, I know the issue is not with library callback functions but rather it's with tracing child threads while using filters. For some reason, child threads are not traced whenever any address filter is applied.. using the above example:

$perf record -m 512,10000 -e intel_pt//u -T -- ./test
rounding mmap pages size to 64M (16384 pages)
Thread ID: 2, Static: 2, Global: 2
Test
adaad
adee
Thread ID: 1, Static: 1, Global: 1
Test
adaad
adee
Thread ID: 3, Static: 3, Global: 3
Test
adaad
adee
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.032 MB perf.data ]

$perf script | grep 'myThreadFun'
            test  9706 [002]   558.666171:          1     branches:u:      7f76aca636b2 start_thread (/lib/x86_64-linux-gnu/libpthread-2.23.so) =>           4006d6 myThreadFun (/home/mansourah/tests/test1/test)
            test  9706 [002]   558.666171:          1     branches:u:            400726 myThreadFun (/home/mansourah/tests/test1/test) =>           4005a0 printf@plt (/home/mansourah/tests/test1/test)
.....
other traces of myThreadFun

Now when tracing with address filters:

$ perf record -m 512,10000 -e intel_pt//u -T --filter 'filter * @ ./test' -- ./test  
rounding mmap pages size to 64M (16384 pages)
Thread ID: 2, Static: 1, Global: 1
Test
adaad
adee
Thread ID: 2, Static: 2, Global: 2
Test
adaad
adee
Thread ID: 3, Static: 3, Global: 3
Test
adaad
adee
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.015 MB perf.data ]

$ perf script | grep 'myThreadFun' 

no trace of myThreadFun() or any instructions that was executed by child thread.. Main thread trace does exist..

I am using perf version 4.15.18... with kernel 4.15.0-36-generic

[man9ourah]

I just tried this with perf version 4.18.12 and kernel 4.18.12-041812-generic.. the same issue exist ..

[man9ourah]

It turned out to be a bug, it is fixed now, please refer to: https://lkml.org/lkml/2018/10/8/649