<div dir="ltr">Hi<div><br></div><div>I got more information.</div><div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">The result I showed in the first email is tested with hyper thread disabled. In the result the interval of thread cpu timer goes greater than that of wall clock so we get a difference of a negative value.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">However, if I enable the hyperthreading in BIOS, the wall clock will always greater so we get a difference of positive value. Yet the value will still double if I double the loop time.</div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Do you have any idea why this happens?</div></div><div style="font-size:12.8px"><br></div><div style="font-size:12.8px">Best wishes</div><div style="font-size:12.8px">Shuai</div><div><br></div></div><div class="gmail_extra"><br><div class="gmail_quote">On 16 March 2016 at 23:22, Shuai Zhao <span dir="ltr"><<a href="mailto:zs673@york.ac.uk" target="_blank">zs673@york.ac.uk</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">Hi All<div><br></div><div>Thank you for helping.</div><div><br></div><div>1. It happens both on Generic Linux kernel and Litmus. I suppose that it is an issue with generic Linux or my machine. But I think you may now the answer as you also deal with clocks in Litmus.</div><div><br></div><div>2. It seems that NTP is not responsible as I tried with clock CLOCK_MONOTONIC_RAW as well, but get same results. </div><div><br></div><div>3. Yes, I bind the thread to core 1 during its life time but still same results. </div><div><br></div><div>More info, I tried out the same test program on a laptop and the results are opposite. The difference between thread cpu timer and wall clock still doubles but the interval of wall clock is always greater. Yet on my desktop the interval of thread cpu time is greater. Really Really weird. The cpu clock speed on the laptop is 2000 MHz but it runs at 1996 MHz.</div><div><br></div><div>I attached the program here so you can also try out at your side. Compile with <span style="font-size:12.8px">gcc -g -Wall -O2 clock.c -lrt -lpthread. The program takes a param to set how many times the thread will loop. </span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">Thank you for helping again.</span></div><div><span style="font-size:12.8px"><br></span></div><div><span style="font-size:12.8px">Best wishes</span></div><span class="HOEnZb"><font color="#888888"><div><span style="font-size:12.8px">Shuai</span></div></font></span></div><div class="HOEnZb"><div class="h5"><div class="gmail_extra"><br><div class="gmail_quote">On 16 March 2016 at 19:14, <span dir="ltr"><<a href="mailto:litmus-dev-request@lists.litmus-rt.org" target="_blank">litmus-dev-request@lists.litmus-rt.org</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Send litmus-dev mailing list submissions to<br>
<a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
<br>
To subscribe or unsubscribe via the World Wide Web, visit<br>
<a href="https://lists.litmus-rt.org/listinfo/litmus-dev" rel="noreferrer" target="_blank">https://lists.litmus-rt.org/listinfo/litmus-dev</a><br>
or, via email, send a message with subject or body 'help' to<br>
<a href="mailto:litmus-dev-request@lists.litmus-rt.org" target="_blank">litmus-dev-request@lists.litmus-rt.org</a><br>
<br>
You can reach the person managing the list at<br>
<a href="mailto:litmus-dev-owner@lists.litmus-rt.org" target="_blank">litmus-dev-owner@lists.litmus-rt.org</a><br>
<br>
When replying, please edit your Subject line so it is more specific<br>
than "Re: Contents of litmus-dev digest..."<br>
<br>
<br>
Today's Topics:<br>
<br>
1. Re: Interesting thread cpu time VS wall clock (Bj?rn Brandenburg)<br>
2. Re: Interesting thread cpu time VS wall clock (Glenn Elliott)<br>
3. Re: Interesting thread cpu time VS wall clock (Manohar Vanga)<br>
<br>
<br>
----------------------------------------------------------------------<br>
<br>
Message: 1<br>
Date: Wed, 16 Mar 2016 19:21:14 +0100<br>
From: Bj?rn Brandenburg <<a href="mailto:bbb@mpi-sws.org" target="_blank">bbb@mpi-sws.org</a>><br>
To: <a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
Subject: Re: [LITMUS^RT] Interesting thread cpu time VS wall clock<br>
Message-ID: <<a href="mailto:2802045C-31A7-436E-9356-A5F09F34EB6D@mpi-sws.org" target="_blank">2802045C-31A7-436E-9356-A5F09F34EB6D@mpi-sws.org</a>><br>
Content-Type: text/plain; charset=utf-8<br>
<br>
<br>
> On 16 Mar 2016, at 18:40, Shuai Zhao <<a href="mailto:zs673@york.ac.uk" target="_blank">zs673@york.ac.uk</a>> wrote:<br>
><br>
> Hi<br>
><br>
> I found an interesting thing while I trying to get response time of tasks: The CPU time of a task (CLOCK_THREAD_CPUTIME_ID) accounts faster than wall clock (CLOCK_REALTIME) !<br>
><br>
> I noticed that you use the same thing in the rtspin.c so I guess that you may know the answer.<br>
><br>
> I know that this is a question related to generic Linux or may be the cpu clock speed instead of litmus, but would you please have a look and help me?<br>
><br>
> The CPU I use is i7 6700k 4.0MHz. But the clock speed is actually 4006 MHz when I cat /proc/cpuinfo.<br>
><br>
> Here is the code:<br>
><br>
> /************* CPU cycle cosuming for 3 threads *************/<br>
> #define NUMS 500<br>
> static int num[NUMS];<br>
> static int loop_once(void) {<br>
> int i, j = 0;<br>
> for (i = 0; i < NUMS; i++)<br>
> j += num[i]++;<br>
> return j;<br>
> }<br>
> /************* CPU cycle cosuming END *************/<br>
><br>
> void* run(void *tcontext) {<br>
> struct timespec start, end, start1, end1, sleep = {0,10};<br>
> int i;<br>
><br>
> exit_program = 0;<br>
><br>
> do {<br>
> nanosleep(&sleep, NULL);<br>
><br>
> clock_gettime(CLOCK_REALTIME, &start);<br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &start1);<br>
><br>
><br>
> for(i = 0; i < loop_times; i++)<br>
> loop_once();<br>
><br>
><br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &end1);<br>
> clock_gettime(CLOCK_REALTIME, &end);<br>
><br>
><br>
> response_time[0][count_first] = (end.tv_sec * 1000000000 + end.tv_nsec) - (start.tv_sec * 1000000000 + start.tv_nsec);<br>
><br>
> response_time[1][count_first] = (end1.tv_sec * 1000000000 + end1.tv_nsec) - (start1.tv_sec * 1000000000 + start1.tv_nsec);<br>
><br>
><br>
> /*finish the program */<br>
> count_first++;<br>
> if (count_first >= 10000)<br>
> exit_program = 1;<br>
> } while (exit_program != 1);<br>
><br>
> return NULL;<br>
> }<br>
><br>
> I basically copies the code from rtspin.c here. In the program I get time stamps of the wall-clock and thread-cpu clock and then let the thread loops for a given times. Then I get time stamps again to check the differences between these two clocks (wallclock - threadcpuclock).<br>
><br>
> The difference I expect should be the interval of wall-clock always be bigger than thread cpu clock as there will be timer or reschedule interrupts.<br>
><br>
> But on my machine I got amazing results: with the increment of the loop_times, the thread-cpu clock will goes faster than wall clock and I got results like this: (clock 0 is wall clock and clock 1 is thread cpu clock)<br>
><br>
> <IMG_0257.JPG>?<br>
><br>
> So we can see that the thread cpu clock goes faster than wall clock by 33191 nanosecond when we loop 100000 times and I am shock by this result.<br>
><br>
> If the wall clock is greater then it makes sense, but here we have a negative difference.<br>
><br>
> One possibility is that the wall clock and the cpu time are accounted by different timers in kernel. But they should all updated based on the HZ, which is 1000 in my case. So I cannot explain the reason why the cpu time in my computer counts faster than the wall clock.<br>
><br>
> Thank you in advance for helping and looking forward your reply.<br>
><br>
> Best wishes<br>
> Shuai<br>
><br>
<br>
Dear Shuai,<br>
<br>
I?ve not seen this before. Does it happen only with LITMUS^RT, or also with a vanilla Linux kernel?<br>
<br>
- Bj?rn<br>
<br>
<br>
<br>
<br>
<br>
------------------------------<br>
<br>
Message: 2<br>
Date: Wed, 16 Mar 2016 11:53:08 -0700<br>
From: Glenn Elliott <<a href="mailto:gelliott@cs.unc.edu" target="_blank">gelliott@cs.unc.edu</a>><br>
To: <a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
Subject: Re: [LITMUS^RT] Interesting thread cpu time VS wall clock<br>
Message-ID: <<a href="mailto:67257061-AB20-4094-AA1B-0D65329390B4@cs.unc.edu" target="_blank">67257061-AB20-4094-AA1B-0D65329390B4@cs.unc.edu</a>><br>
Content-Type: text/plain; charset=utf-8<br>
<br>
<br>
<br>
> On Mar 16, 2016, at 10:40 AM, Shuai Zhao <<a href="mailto:zs673@york.ac.uk" target="_blank">zs673@york.ac.uk</a>> wrote:<br>
><br>
> Hi<br>
><br>
> I found an interesting thing while I trying to get response time of tasks: The CPU time of a task (CLOCK_THREAD_CPUTIME_ID) accounts faster than wall clock (CLOCK_REALTIME) !<br>
><br>
> I noticed that you use the same thing in the rtspin.c so I guess that you may know the answer.<br>
><br>
> I know that this is a question related to generic Linux or may be the cpu clock speed instead of litmus, but would you please have a look and help me?<br>
><br>
> The CPU I use is i7 6700k 4.0MHz. But the clock speed is actually 4006 MHz when I cat /proc/cpuinfo.<br>
><br>
> Here is the code:<br>
><br>
> /************* CPU cycle cosuming for 3 threads *************/<br>
> #define NUMS 500<br>
> static int num[NUMS];<br>
> static int loop_once(void) {<br>
> int i, j = 0;<br>
> for (i = 0; i < NUMS; i++)<br>
> j += num[i]++;<br>
> return j;<br>
> }<br>
> /************* CPU cycle cosuming END *************/<br>
><br>
> void* run(void *tcontext) {<br>
> struct timespec start, end, start1, end1, sleep = {0,10};<br>
> int i;<br>
><br>
> exit_program = 0;<br>
><br>
> do {<br>
> nanosleep(&sleep, NULL);<br>
><br>
> clock_gettime(CLOCK_REALTIME, &start);<br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &start1);<br>
><br>
><br>
> for(i = 0; i < loop_times; i++)<br>
> loop_once();<br>
><br>
><br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &end1);<br>
> clock_gettime(CLOCK_REALTIME, &end);<br>
><br>
><br>
> response_time[0][count_first] = (end.tv_sec * 1000000000 + end.tv_nsec) - (start.tv_sec * 1000000000 + start.tv_nsec);<br>
><br>
> response_time[1][count_first] = (end1.tv_sec * 1000000000 + end1.tv_nsec) - (start1.tv_sec * 1000000000 + start1.tv_nsec);<br>
><br>
><br>
> /*finish the program */<br>
> count_first++;<br>
> if (count_first >= 10000)<br>
> exit_program = 1;<br>
> } while (exit_program != 1);<br>
><br>
> return NULL;<br>
> }<br>
><br>
> I basically copies the code from rtspin.c here. In the program I get time stamps of the wall-clock and thread-cpu clock and then let the thread loops for a given times. Then I get time stamps again to check the differences between these two clocks (wallclock - threadcpuclock).<br>
><br>
> The difference I expect should be the interval of wall-clock always be bigger than thread cpu clock as there will be timer or reschedule interrupts.<br>
><br>
> But on my machine I got amazing results: with the increment of the loop_times, the thread-cpu clock will goes faster than wall clock and I got results like this: (clock 0 is wall clock and clock 1 is thread cpu clock)<br>
><br>
> <IMG_0257.JPG>?<br>
><br>
> So we can see that the thread cpu clock goes faster than wall clock by 33191 nanosecond when we loop 100000 times and I am shock by this result.<br>
><br>
> If the wall clock is greater then it makes sense, but here we have a negative difference.<br>
><br>
> One possibility is that the wall clock and the cpu time are accounted by different timers in kernel. But they should all updated based on the HZ, which is 1000 in my case. So I cannot explain the reason why the cpu time in my computer counts faster than the wall clock.<br>
><br>
> Thank you in advance for helping and looking forward your reply.<br>
><br>
> Best wishes<br>
> Shuai<br>
<br>
Hi Shuai,<br>
<br>
Could NTP or PTP be responsible? Seems unlikely, but can you rule it out?<br>
<br>
-Glenn<br>
<br>
<br>
------------------------------<br>
<br>
Message: 3<br>
Date: Wed, 16 Mar 2016 20:14:25 +0100<br>
From: Manohar Vanga <<a href="mailto:mvanga@mpi-sws.org" target="_blank">mvanga@mpi-sws.org</a>><br>
To: <a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
Subject: Re: [LITMUS^RT] Interesting thread cpu time VS wall clock<br>
Message-ID:<br>
<<a href="mailto:CAEktxaEHLP_8FjSxPRo8rbg3SqOp0_x5ijucMZ_OYGF09Fy8kQ@mail.gmail.com" target="_blank">CAEktxaEHLP_8FjSxPRo8rbg3SqOp0_x5ijucMZ_OYGF09Fy8kQ@mail.gmail.com</a>><br>
Content-Type: text/plain; charset="utf-8"<br>
<br>
Hey Shuai,<br>
<br>
Are you pinning the thread to a single core? If not, can you check this<br>
(eg. using the taskset command)? I ask because we've seen timestamp counter<br>
variations across CPUs in that range in the past (tens of microseconds) on<br>
larger server machines. Although it is unlikely to be so prominent on a<br>
smaller desktop like the one you're using, it might be worth ruling out.<br>
<br>
Thanks!<br>
<br>
On Wed, Mar 16, 2016 at 6:40 PM, Shuai Zhao <<a href="mailto:zs673@york.ac.uk" target="_blank">zs673@york.ac.uk</a>> wrote:<br>
<br>
> Hi<br>
><br>
> I found an interesting thing while I trying to get response time of tasks:<br>
> The CPU time of a task (CLOCK_THREAD_CPUTIME_ID) accounts faster than wall<br>
> clock (CLOCK_REALTIME) !<br>
><br>
> I noticed that you use the same thing in the rtspin.c so I guess that you<br>
> may know the answer.<br>
><br>
> I know that this is a question related to generic Linux or may be the cpu<br>
> clock speed instead of litmus, but would you please have a look and help me?<br>
><br>
> The CPU I use is i7 6700k 4.0MHz. But the clock speed is actually 4006 MHz<br>
> when I cat /proc/cpuinfo.<br>
><br>
> Here is the code:<br>
><br>
> /************* CPU cycle cosuming for 3 threads *************/<br>
> #define NUMS 500<br>
> static int num[NUMS];<br>
> static int loop_once(void) {<br>
> int i, j = 0;<br>
> for (i = 0; i < NUMS; i++)<br>
> j += num[i]++;<br>
> return j;<br>
> }<br>
> /************* CPU cycle cosuming END *************/<br>
><br>
> void* run(void *tcontext) {<br>
> struct timespec start, end, start1, end1, sleep = {0,10};<br>
> int i;<br>
><br>
> exit_program = 0;<br>
><br>
> do {<br>
> nanosleep(&sleep, NULL);<br>
><br>
> clock_gettime(CLOCK_REALTIME, &start);<br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &start1);<br>
><br>
><br>
> for(i = 0; i < loop_times; i++)<br>
> loop_once();<br>
><br>
><br>
> clock_gettime(CLOCK_THREAD_CPUTIME_ID, &end1);<br>
> clock_gettime(CLOCK_REALTIME, &end);<br>
><br>
> response_time[0][count_first] = (end.tv_sec * 1000000000 + end.tv_nsec) -<br>
> (start.tv_sec * 1000000000 + start.tv_nsec);<br>
><br>
> response_time[1][count_first] = (end1.tv_sec * 1000000000 + end1.tv_nsec)<br>
> - (start1.tv_sec * 1000000000 + start1.tv_nsec);<br>
><br>
><br>
> /*finish the program */<br>
> count_first++;<br>
> if (count_first >= 10000)<br>
> exit_program = 1;<br>
> } while (exit_program != 1);<br>
><br>
> return NULL;<br>
> }<br>
><br>
> I basically copies the code from rtspin.c here. In the program I get time<br>
> stamps of the wall-clock and thread-cpu clock and then let the thread loops<br>
> for a given times. Then I get time stamps again to check the differences<br>
> between these two clocks (wallclock - threadcpuclock).<br>
><br>
> The difference I expect should be the interval of wall-clock always be<br>
> bigger than thread cpu clock as there will be timer or reschedule<br>
> interrupts.<br>
><br>
> But on my machine I got amazing results: with the increment of the<br>
> loop_times, the thread-cpu clock will goes faster than wall clock and I got<br>
> results like this: (clock 0 is wall clock and clock 1 is thread cpu clock)<br>
><br>
> [image: Inline images 1]?<br>
><br>
> So we can see that the thread cpu clock goes faster than wall clock by<br>
> 33191 nanosecond when we loop 100000 times and I am shock by this result.<br>
><br>
> If the wall clock is greater then it makes sense, but here we have a<br>
> negative difference.<br>
><br>
> One possibility is that the wall clock and the cpu time are accounted by<br>
> different timers in kernel. But they should all updated based on the HZ,<br>
> which is 1000 in my case. So I cannot explain the reason why the cpu time<br>
> in my computer counts faster than the wall clock.<br>
><br>
> Thank you in advance for helping and looking forward your reply.<br>
><br>
> Best wishes<br>
> Shuai<br>
><br>
><br>
><br>
><br>
><br>
> _______________________________________________<br>
> litmus-dev mailing list<br>
> <a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
> <a href="https://lists.litmus-rt.org/listinfo/litmus-dev" rel="noreferrer" target="_blank">https://lists.litmus-rt.org/listinfo/litmus-dev</a><br>
><br>
><br>
-------------- next part --------------<br>
An HTML attachment was scrubbed...<br>
URL: <<a href="http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20160316/ed57c089/attachment.html" rel="noreferrer" target="_blank">http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20160316/ed57c089/attachment.html</a>><br>
-------------- next part --------------<br>
A non-text attachment was scrubbed...<br>
Name: IMG_0257.JPG<br>
Type: image/jpeg<br>
Size: 2858542 bytes<br>
Desc: not available<br>
URL: <<a href="http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20160316/ed57c089/attachment.jpe" rel="noreferrer" target="_blank">http://lists.litmus-rt.org/pipermail/litmus-dev/attachments/20160316/ed57c089/attachment.jpe</a>><br>
<br>
------------------------------<br>
<br>
_______________________________________________<br>
litmus-dev mailing list<br>
<a href="mailto:litmus-dev@lists.litmus-rt.org" target="_blank">litmus-dev@lists.litmus-rt.org</a><br>
<a href="https://lists.litmus-rt.org/listinfo/litmus-dev" rel="noreferrer" target="_blank">https://lists.litmus-rt.org/listinfo/litmus-dev</a><br>
<br>
<br>
End of litmus-dev Digest, Vol 49, Issue 4<br>
*****************************************<br>
</blockquote></div><br></div>
</div></div></blockquote></div><br></div>