Log Debug Messages with TRACE()

Next we are going to export some debugging message with the TRACE() macro. Specifically, we use TRACE_TASK() to record tasks as they are being rejected by the plugin.

To do so, include litmus/debug_trace.h into litmus/sched_demo.c and change demo_admit_task() to look like this:

   1 static long demo_admit_task(struct task_struct *tsk)
   2 {
   3         TRACE_TASK(tsk, "rejected by demo plugin.\n");
   4 
   5         /* Reject every task. */
   6         return -EINVAL;
   7 }

What about printk()?

Why not use the standard Linux-provided printk()? The reason is an implementation limitation of printk(). To avoid polling, printk() is designed to wake up the system message logging daemon when new messages become available. However, waking up a process requires acquiring scheduler locks. This can lead to deadlock if the calling code is already holding some scheduler locks. Therefore, it is not safe to call printk() from within schedule() and some of the other callbacks. To facilitate debugging, LITMUS^RT provides the alternative TRACE() macro, which avoids the need to wake up processes by forcing clients to poll for changes (this is transparent to users).

From the point of view of the developer, TRACE() is exactly like printk(), except for that it can be used from within the scheduler.

Observing TRACE() messages

With the above changes in place, it is now possible to see the message when a task is rejected in /dev/litmus/log (again, test this from within a VM running the modified kernel):

[root@litmus-rt ~]# setsched DEMO
[root@litmus-rt ~]# cat /dev/litmus/log > debug.txt &
[1] 1462
[root@litmus-rt ~]# liblitmus/rtspin 10 100 10
could not become RT task: Invalid argument
[root@litmus-rt ~]# cat debug.txt 
1 P3 [vprintk@kernel/printk.c:883]: Setting up rt task parameters for process 1464.
2 P1 [alloc_ctrl_page@litmus/ctrldev.c:25]: (rtspin/1464:0) alloc_ctrl_page ctrl_page = ffff88007881d000
3 P1 [map_ctrl_page@litmus/ctrldev.c:39]: (rtspin/1464:0) litmus/ctrl: mapping ffff88007881d000 (pfn:7881d) to 0x7fc686ed5000 (prot:8000000000000027)
4 P1 [litmus_ctrl_mmap@litmus/ctrldev.c:114]: (rtspin/1464:0) litmus_ctrl_mmap flags=0x2166073 prot=0x8000000000000027
5 P1 [demo_admit_task@litmus/sched_demo.c:21]: (rtspin/1464:0) rejected by demo plugin.
6 P1 [litmus_ctrl_vm_close@litmus/ctrldev.c:53]: (rtspin/1464:0) litmus_ctrl_vm_close flags=0x2164073 prot=0x27
7 P1 [litmus_ctrl_vm_close@litmus/ctrldev.c:58]: (rtspin/1464:0) litmus/ctrl: 00007fc686ed5000:00007fc686ed6000 vma:ffff8800793e01e0 vma->vm_private_data:          (null) closed.
8 P1 [exit_litmus@litmus/litmus.c:497]: (rtspin/1464:0) freeing ctrl_page ffff88007881d000

Note that message 5 was generated by demo_admit_task().

Tracing is explained in more detail in the tracing tutorial.

If you are seeing a lot of "noise" in the log similar to SCHED_STATE [P0] 0x1 (TASK_SCHEDULED) -> 0x4 (WILL_SCHEDULE), this is the result of the configuration option CONFIG_PREEMPT_STATE_TRACE, which can be disabled in the kernel configuration (menu LITMUS^RT->Tracing->"Trace preemption state machine transitions").

On to the next step.