From mboxrd@z Thu Jan  1 00:00:00 1970
From: Daniel.Thibault@drdc-rddc.gc.ca (Thibault, Daniel)
Date: Thu, 6 Feb 2014 20:04:06 +0000
Subject: [lttng-dev] sched_switch event
Message-ID: <48CF5AC71E61DB46B70D0F388054EFFD267DFAF9@VAL-E-02.valcartier.drdc-rddc.gc.ca>

   In linux-source-3.2.0/include/trace/events/sched.h, or
   linux-headers-3.2.0-53/include/trace/events/sched.h, or
   lttng-modules/instrumentation/events/mainline/sched.h,
   we have in part:

TRACE_EVENT(sched_switch,

	TP_PROTO(struct task_struct *prev,
		 struct task_struct *next),

	TP_ARGS(prev, next),

	TP_STRUCT__entry(
		__array(	char,	prev_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	prev_pid			)
		__field(	int,	prev_prio			)
		__field(	long,	prev_state			)
		__array(	char,	next_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	next_pid			)
		__field(	int,	next_prio			)
	),

	TP_fast_assign(
		memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
		__entry->prev_pid	= prev->pid;
		__entry->prev_prio	= prev->prio;
		__entry->prev_state	= __trace_sched_switch_state(prev);
		memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
		__entry->next_pid	= next->pid;
		__entry->next_prio	= next->prio;
	),

	TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d",
		__entry->prev_comm, __entry->prev_pid, __entry->prev_prio,
		__entry->prev_state & (TASK_STATE_MAX-1) ?
		  __print_flags(__entry->prev_state & (TASK_STATE_MAX-1), "|",
				{ 1, "S"} , { 2, "D" }, { 4, "T" }, { 8, "t" },
				{ 16, "Z" }, { 32, "X" }, { 64, "x" },
				{ 128, "W" }) : "R",
		__entry->prev_state & TASK_STATE_MAX ? "+" : "",
		__entry->next_comm, __entry->next_pid, __entry->next_prio)
);

   Note how the TP_fast_assign lines are switching __entry->next_comm and __entry->prev_comm, unlike the TP_printk lines.

   In lttng-modules/instrumentation/events/lttng-module/sched.h, we find:

	TP_STRUCT__entry(
		__array_text(	char,	prev_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	prev_tid			)
		__field(	int,	prev_prio			)
		__field(	long,	prev_state			)
		__array_text(	char,	next_comm,	TASK_COMM_LEN	)
		__field(	pid_t,	next_tid			)
		__field(	int,	next_prio			)
	),

   Which is probably why nobody noticed this before, since LTTng traces correctly identify the previous and next processes in the sched_switch event.

   This is an upstream Linux kernel bug or what?

   Another question is: if the kernel tracepoint event definitions appearing in the source are ignored, why are they included at all?

Daniel U. Thibault
Protection des syst?mes et contremesures (PSC) | Systems Protection & Countermeasures (SPC)
Cyber s?curit? pour les missions essentielles (CME) | Mission Critical Cyber Security (MCCS)
R & D pour la d?fense Canada - Valcartier (RDDC Valcartier) | Defence R&D Canada - Valcartier (DRDC Valcartier)
2459 route de la Bravoure
Qu?bec QC? G3J 1X5
CANADA
Vox?: (418) 844-4000 x4245
Fax?: (418) 844-4538
NAC?: 918V QSDJ <http://www.travelgis.com/map.asp?addr=918V%20QSDJ>
Gouvernement du Canada?| Government of Canada
<http://www.valcartier.drdc-rddc.gc.ca/>