0

I have written a test kernel module named hello.ko which spawns a kernel thread with the following function :

static int thread_fn(void *data)
{
    while(1)
    {
        printk(KERN_INFO "thread is running....\n");
        ssleep(5);

        printk(KERN_INFO "checking if I need to stop\n");
        if(kthread_should_stop())
            break;
    }
    printk(KERN_INFO "thread exiting\n");
    return 0;
}

static int __init hello_init(void)
{
    printk(KERN_INFO "This is from init \n");
    mythread = kthread_create(thread_fn, NULL, "mythread");
    if(!mythread)
    {
        printk(KERN_ERR "Thread creation failed\n");
        return 1;
    }
    else
    {
        printk(KERN_INFO "Thread created successfully.\n");
        //thread is not running yet. Its in sleep state.
    }
    //bind to CPU 1
    kthread_bind(mythread,2);
    //start the thread
    wake_up_process(mythread);
    return 0;
}

static void __exit hello_exit(void)
{
    int rc;
    printk(KERN_INFO "This is from exit \n");
    rc = kthread_stop(mythread);
    if(rc)
        printk(KERN_ERR "kthread stop failed\n");
}

module_init(hello_init);
module_exit(hello_exit);

Now I want to trace this function via ftrace. So I can see that the symbol is available once the module is loaded.

/sys/kernel/debug/tracing # cat available_filter_functions  | grep thread_fn
smpboot_thread_fn
irq_thread_fn
irq_forced_thread_fn
thread_fn [hello]  <<<< my module's function that is to be traced

I set this function to be filtered and turn on the tracing, but I see nothing on the trace, even though I am getting dmesg logs from my thread_fn which indicate that the function is getting called.

/sys/kernel/debug/tracing # cat set_ftrace_filter
thread_fn [hello]
/sys/kernel/debug/tracing # cat set_graph_function
thread_fn [hello]
/sys/kernel/debug/tracing # cat tracing_on
1
/sys/kernel/debug/tracing # cat current_tracer
function_graph
/sys/kernel/debug/tracing # cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
/sys/kernel/debug/tracing #

I get nothing on trace, but below are dmesg logs that I am getting repeatedly from the same function that I am trying to trace:

[  856.633370] thread is running....
[  861.752050] checking if I need to stop
[  861.752476] thread is running....
[  866.872571] checking if I need to stop
[  866.872978] thread is running....
[  871.992339] checking if I need to stop
[  871.992821] thread is running....
[  877.113347] checking if I need to stop
[  877.113712] thread is running....
[  882.232438] checking if I need to stop

My kernel version is 5.8.0 and I am running this on qemu-aarch64 version 2.11.1(Debian 1:2.11+dfsg-1ubuntu7.37~cloud0)

Am I doing anything stupid here? Or am I hitting some known issue?

EDIT I am using Buildroot as my rootfs. I used trace-cmd this time instead of directly interacting with the ftrace. I loaded my module and can see dmesg logs as shown above from thread_fn.

trace-cmd record -p function_graph -l thread_fn

But I again did not get anything.

EDIT After realizing the mistake from @IanAbbott comments, I modified my code slightly, so that the function that is being traced at least gets called while trace is active (instead of previous case where the entry/exit was not having but only few lines were executing in loop while the trace is active).

void hello_log(void)
{
    printk(KERN_INFO "should I stop\n");
}
EXPORT_SYMBOL(hello_log);

static int thread_fn(void *data)
{
    while(1)
    {
        printk(KERN_INFO "thread is running....\n");
        ssleep(5);

        hello_log();
        if(kthread_should_stop())
            break;
    }
    printk(KERN_INFO "thread exiting\n");
    return 0;
}

Now I was expecting to get traces from hello_log function but again I do not getting anything in the trace. What's wrong now?

Naveen
  • 7,944
  • 12
  • 78
  • 165
  • As I understand it, ftrace is for tracing function *calls*. You have shown evidence of `thread_fn` running in a `while` loop, but haven't shown evidence that `thread_fn` has been called after you set up the trace. – Ian Abbott Sep 14 '21 at 13:21
  • @IanAbbott Sorry that I could not explain well. As I mentioned above, I kept getting the dmesg logs from my `thread_fn` after setting the trace but did not get anything from the trace. – Naveen Sep 14 '21 at 15:04
  • Is the kernel thread with entry routine `thread_fn` created before or after you start the trace? Can you trace a function called from within `thread_fn`'s `while` loop? – Ian Abbott Sep 14 '21 at 15:15
  • @IanAbbott : I updated the question with the complete code. The thread is created as soon as I load the module (using `modprobe`). Once I start getting the dmesg logs , then I start the trace. – Naveen Sep 14 '21 at 15:26
  • So it is not hitting the call trace because the function is not being called while the trace is active. – Ian Abbott Sep 14 '21 at 17:44
  • @IanAbbott : Sorry I did not get the reason as why its not getting traced. Once the kernel thread is started, I start the trace and keep it recording for 10-15 seconds. By that time, the `thread_fn` should have hit twice or thrice. Can you please explain why do you feel the function is not being called while the trace is active? As per my understanding, one the trace record is started, it continuously records (unless we open pipe for reading trace which is when it stops reading intermittently). – Naveen Sep 15 '21 at 06:07
  • The function is **called only once** when the thread is created, which you have already said occurs before the trace is started. – Ian Abbott Sep 15 '21 at 09:18
  • Oh man!!! I was being so stupid this whole time. You are right. The ftrace works by inserting special hooks at the entry and exit of the functions. Hence any statements if repeated within that function, will not be catched by ftrace, unless a re-entry or exit happens. – Naveen Sep 15 '21 at 11:59
  • @IanAbbott Can you please check the EDIT above. I still have the same problem. – Naveen Sep 16 '21 at 04:14

0 Answers0