[LITMUS^RT] Questions about the time measurement in ft_trace

[Luo, Zheng]

________________________________
From: litmus-dev-bounces at lists.litmus-rt.org <litmus-dev-bounces at lists.litmus-rt.org> on behalf of Bj?rn Brandenburg <bbb at mpi-sws.org>
Sent: Wednesday, January 29, 2014 12:27 AM
To: litmus-dev at lists.litmus-rt.org
Subject: Re: [LITMUS^RT] Questions about the time measurement in ft_trace

On 28 Jan 2014, at 22:33, Luo, Zheng <luozheng at wustl.edu<mailto:luozheng at wustl.edu>> wrote:

I have a question about the time measure measurement in ft_trace in Litmus.

I was wondering how does the ft_trace get the timestamp information, then I found that it used this function:

#include <asm/feather_trace.h>
#include <asm/timex.h> /* for get_cycles() */
static inline unsigned long long ft_timestamp(void)
{
    return get_cycles();
}

This function will return the cycle of the CPU, I checked all the program in the ft_tool and the sched-trace-tool-master, I thought when you get_cycles of the CPU, should not you divide the current frequency of the CPU to get the time. I did not find the division, or the current get cycle did give you the time information?

When I run a small program, I get the output here, and I also send a picture as an attachment.

luozheng at luozheng-Ubuntu:~/Documents/Litmus/sched-trace-tools-master$ ./st_show st--6.bin
[         0] NAME            4420/0     on CPU  6 base_task
[         0] PARAM           4420/0     on CPU  6 T=(cost:100.00ms, period:500.00ms, phase:  0.00ms), part=0
[   2914923] SWITCH_FROM     4420/1     on CPU  6
[   2914923] SWITCH_TO       4420/1     on CPU  6
[   2914923] SWITCH_FROM     4420/1     on CPU  6
[   2914923] COMPLETION      4420/1     on CPU  6
[   2915423] RELEASE         4420/2     on CPU  6 2915923.27ms
[   2915423] SWITCH_TO       4420/2     on CPU  6
[   2915774] SWITCH_FROM     4420/2     on CPU  6
[   2915774] COMPLETION      4420/2     on CPU  6
[   2915923] RELEASE         4420/3     on CPU  6 2916423.27ms
[   2915923] SWITCH_TO       4420/3     on CPU  6
[   2916274] SWITCH_FROM     4420/3     on CPU  6
[   2916274] COMPLETION      4420/3     on CPU  6
[   2916423] RELEASE         4420/4     on CPU  6 2916923.27ms
[   2916423] SWITCH_TO       4420/4     on CPU  6
[   2916774] COMPLETION      4420/4     on CPU  6

I get a little confused here. Is number in the [] should be the cycles of the CPU? The number like 2915923.27ms is the actual time? Or how do we interpret this? I think I need some help here. Thank you very much.

Hi Zheng,

the overhead tracing uses raw processor cycles. You are looking at sched-trace-tools, which uses the same tracing infrastructure but a different time source.

https://github.com/LITMUS-RT/litmus-rt/blob/master/litmus/sched_task_trace.c#L20

The time units in sched_trace traces are nanoseconds. The tool st_show does some rounding to display millisecond values (which for a human are easier to read).

Best regards,
Bj?rn



Hi Bj?rn,

Thank you very much for the reply. I still some questions.

For the line like this:
[ 2915923] RELEASE 4420/3 on CPU 6 2916423.27ms
Why the 2915923 and the 2916423.27ms is different, and what is the meaning of them?


All the time stamps are using:
static inline lt_t litmus_clock(void)
{
    return ktime_to_ns(ktime_get());
}
I have two questions:
1. Should we use the ktime_get() to get the time? Because it is a kernel function call, it takes longer time than just read the RDTSC value. Why use a kernel space function call instead of a user space function all? I am not sure about that, so I have this question.
2. Also, is there any reference to show that how you measure the overhead of the scheduling?

Thank you very much. Look forward to your reply.

Zheng Luo

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20140129/f79a7b93/attachment.html>