= 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:
{{{#!highlight c
static long demo_admit_task(struct task_struct *tsk)
{
	TRACE_TASK(tsk, "rejected by demo plugin.\n");

	/* Reject every task. */
	return -EINVAL;
}
}}}

== 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 [[Tracing|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 [[../Step4|next step]].