Re: Understand userspace events in babeltrace output

Re: Understand userspace events in babeltrace output

[Jonathan Rajotte-Julien]

Hi Zvi,

On Fri, Jul 19, 2019 at 05:28:48PM +0300, Zvi Vered wrote:
> Hello,
> 
> Using babeltrace I created a text trace.
> How can I understand it ?

Here lies the heavy work!

> 
> For example:
> I logged userspace events. One of my threads is called: RSPOn3

As far as I can tell sched_* are not userspace events they are "kernelspace"
events.

> I can see the following lines:
> 
> sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
> prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
> next_prio = 20 }
> 
> sched_wakeup: { cpu_id = 0 }, { comm = "RSPOn3", tid = 27307, prio = -58,
> success = 1, target_cpu = 0 }
> 
> sched_switch: { cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0,
> prev_prio = 20, prev_state = 0, next_comm = "RSPOn3", next_tid = 27307,
> next_prio = -58 }
> 
> sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
> prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
> next_prio = 20 }
> 
> How can I know the meaning of each field in each line ?

You will need to understand the kernel state transition of the scheduler. There
is multiple ways to go about it.

You could use TraceCompass[1][2] or lttng-analyses[3] to ease/complement your
learning experience a bit.

You could dive in the kernel source code and understand the control flow
surrounding each events and understand the significance of the events payload.

Another interesting place to look is the kernel trace documentation [4]. Some
subsystems have clear explanation regarding each tracepoint [5].

> 1. sched_switch, sched_wakeup
> 2. prev_comm
> 3. prev_state
> 4. next_comm
> 
> If a task is blocked (e.g waiting for TCP) and then runs for some time and
> then waits again, how this will be logged ?

Babeltrace is a trace converter, it does not perform any analysis. TraceCompass
and lttng-analyses might have analysis fitting your needs.

Cheers

[1] https://www.eclipse.org/tracecompass/
[2] https://archive.eclipse.org/tracecompass/doc/stable/org.eclipse.tracecompass.doc.user/LTTng-Kernel-Analysis.html#LTTng_Kernel_Analysis
[3] https://github.com/lttng/lttng-analyses
[4] https://www.kernel.org/doc/Documentation/trace/
[5] https://www.kernel.org/doc/Documentation/trace/events-kmem.txt

-- 
Jonathan Rajotte-Julien
EfficiOS

Re: Understand userspace events in babeltrace output

[Zvi Vered]

[-- Attachment #1.1: Type: text/plain, Size: 2615 bytes --]

Hi Jonathan,

Thank you very much !

Best regards,
Zvika

On Fri, Jul 19, 2019 at 11:48 PM Jonathan Rajotte-Julien <
jonathan.rajotte-julien@efficios.com> wrote:

> Hi Zvi,
>
> On Fri, Jul 19, 2019 at 05:28:48PM +0300, Zvi Vered wrote:
> > Hello,
> >
> > Using babeltrace I created a text trace.
> > How can I understand it ?
>
> Here lies the heavy work!
>
> >
> > For example:
> > I logged userspace events. One of my threads is called: RSPOn3
>
> As far as I can tell sched_* are not userspace events they are
> "kernelspace"
> events.
>
> > I can see the following lines:
> >
> > sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
> > prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
> > next_prio = 20 }
> >
> > sched_wakeup: { cpu_id = 0 }, { comm = "RSPOn3", tid = 27307, prio = -58,
> > success = 1, target_cpu = 0 }
> >
> > sched_switch: { cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0,
> > prev_prio = 20, prev_state = 0, next_comm = "RSPOn3", next_tid = 27307,
> > next_prio = -58 }
> >
> > sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
> > prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
> > next_prio = 20 }
> >
> > How can I know the meaning of each field in each line ?
>
> You will need to understand the kernel state transition of the scheduler.
> There
> is multiple ways to go about it.
>
> You could use TraceCompass[1][2] or lttng-analyses[3] to ease/complement
> your
> learning experience a bit.
>
> You could dive in the kernel source code and understand the control flow
> surrounding each events and understand the significance of the events
> payload.
>
> Another interesting place to look is the kernel trace documentation [4].
> Some
> subsystems have clear explanation regarding each tracepoint [5].
>
> > 1. sched_switch, sched_wakeup
> > 2. prev_comm
> > 3. prev_state
> > 4. next_comm
> >
> > If a task is blocked (e.g waiting for TCP) and then runs for some time
> and
> > then waits again, how this will be logged ?
>
> Babeltrace is a trace converter, it does not perform any analysis.
> TraceCompass
> and lttng-analyses might have analysis fitting your needs.
>
> Cheers
>
> [1] https://www.eclipse.org/tracecompass/
> [2]
> https://archive.eclipse.org/tracecompass/doc/stable/org.eclipse.tracecompass.doc.user/LTTng-Kernel-Analysis.html#LTTng_Kernel_Analysis
> [3] https://github.com/lttng/lttng-analyses
> [4] https://www.kernel.org/doc/Documentation/trace/
> [5] https://www.kernel.org/doc/Documentation/trace/events-kmem.txt
>
> --
> Jonathan Rajotte-Julien
> EfficiOS
>

[-- Attachment #1.2: Type: text/html, Size: 3920 bytes --]

[-- Attachment #2: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Understand userspace events in babeltrace output

[Zvi Vered]

[-- Attachment #1.1: Type: text/plain, Size: 1087 bytes --]

Hello,

Using babeltrace I created a text trace.
How can I understand it ?

For example:
I logged userspace events. One of my threads is called: RSPOn3
I can see the following lines:

sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
next_prio = 20 }

sched_wakeup: { cpu_id = 0 }, { comm = "RSPOn3", tid = 27307, prio = -58,
success = 1, target_cpu = 0 }

sched_switch: { cpu_id = 0 }, { prev_comm = "swapper/0", prev_tid = 0,
prev_prio = 20, prev_state = 0, next_comm = "RSPOn3", next_tid = 27307,
next_prio = -58 }

sched_switch: { cpu_id = 0 }, { prev_comm = "RSPOn3", prev_tid = 27307,
prev_prio = -58, prev_state = 1, next_comm = "swapper/0", next_tid = 0,
next_prio = 20 }

How can I know the meaning of each field in each line ?
1. sched_switch, sched_wakeup
2. prev_comm
3. prev_state
4. next_comm

If a task is blocked (e.g waiting for TCP) and then runs for some time and
then waits again, how this will be logged ?

Curently I need help only on userspace events.

Thank you,
Zvika

[-- Attachment #1.2: Type: text/html, Size: 1558 bytes --]

[-- Attachment #2: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev