Short version:
Doing this in user space:
while(1){
usleep(1);
}causes kernel time to drift _a lot_. Clock rate seems to become ~1000(!) ppms off. Long version: We have seen some time drift problems for a long time, but they got a lot worse when implementing a new DMA function that increases the number of context switches. It finally boiled down to the 'while(1) usleep(1);' test which seems to be some kind of worst case scenario. Increasing the sleep reduces the time drift. Increasing the timer min_delta_ns also reduces the time drift. But, both also reduce the number of context switches, so it seems that drift is related to the number of CS somehow. I found one potential issue with the oneshot timer: When canceling a oneshot event timer (by replacing it with a new one), the old timer could have just expired and thus the timer irq is already pending. (In mach-davinci/time.c - timer32_config() ) This makes the new event timer trigger prematurely. Hacking in an irq clear after the old timer has been disabled to make sure we don't get an old irq doesn't affect the time drift problem though. I have spent quite a few hours trying to pin down the source of the problem, but not there yet. Ideas and suggestions are appreciated to help me track this down. Like, does it affect all Davinci platforms or DM644x only? Tested with 2.6.36, 3.4 and master, all behave the same. Note that tests are done with dynamic ticks and hrtimers enabled. Attached logs from DVEVM 6446 board with master HEAD. Regards, /Thomas ---- Origin: git://gitorious.org/linux-davinci/linux-davinci.git $ git show commit c22cf7755db6500df037cecdd6b290394d82392e Merge: 1ff04b7 3202e13 Author: Sekhar Nori <[email protected]> Date: Tue Oct 30 14:10:56 2012 +0530 rebuild linux-davinci from branches -----
while ntpdate -qp1 172.16.1.4; do sleep 1;echo; done server 172.16.1.4, stratum 3, offset -0.000402, delay 0.02628 6 Dec 10:41:46 ntpdate[866]: adjust time server 172.16.1.4 offset -0.000402 sec server 172.16.1.4, stratum 3, offset -0.000431, delay 0.02615 6 Dec 10:41:48 ntpdate[870]: adjust time server 172.16.1.4 offset -0.000431 sec server 172.16.1.4, stratum 3, offset -0.000588, delay 0.02638 6 Dec 10:41:49 ntpdate[874]: adjust time server 172.16.1.4 offset -0.000588 sec server 172.16.1.4, stratum 3, offset -0.000591, delay 0.02626 6 Dec 10:41:50 ntpdate[878]: adjust time server 172.16.1.4 offset -0.000591 sec server 172.16.1.4, stratum 3, offset -0.000650, delay 0.02628 6 Dec 10:41:51 ntpdate[882]: adjust time server 172.16.1.4 offset -0.000650 sec server 172.16.1.4, stratum 3, offset -0.000686, delay 0.02623 6 Dec 10:41:52 ntpdate[886]: adjust time server 172.16.1.4 offset -0.000686 sec server 172.16.1.4, stratum 3, offset -0.000749, delay 0.02623 6 Dec 10:41:53 ntpdate[890]: adjust time server 172.16.1.4 offset -0.000749 sec server 172.16.1.4, stratum 3, offset -0.000837, delay 0.02621 6 Dec 10:41:55 ntpdate[894]: adjust time server 172.16.1.4 offset -0.000837 sec ************ usleep-loop started **************** server 172.16.1.4, stratum 3, offset -0.000620, delay 0.02634 6 Dec 10:41:56 ntpdate[899]: adjust time server 172.16.1.4 offset -0.000620 sec server 172.16.1.4, stratum 3, offset 0.000378, delay 0.02623 6 Dec 10:41:57 ntpdate[903]: adjust time server 172.16.1.4 offset 0.000378 sec server 172.16.1.4, stratum 3, offset 0.001333, delay 0.02623 6 Dec 10:41:58 ntpdate[907]: adjust time server 172.16.1.4 offset 0.001333 sec server 172.16.1.4, stratum 3, offset 0.002279, delay 0.02623 6 Dec 10:42:00 ntpdate[911]: adjust time server 172.16.1.4 offset 0.002279 sec server 172.16.1.4, stratum 3, offset 0.003205, delay 0.02623 6 Dec 10:42:01 ntpdate[915]: adjust time server 172.16.1.4 offset 0.003205 sec server 172.16.1.4, stratum 3, offset 0.004135, delay 0.02634 6 Dec 10:42:02 ntpdate[919]: adjust time server 172.16.1.4 offset 0.004135 sec server 172.16.1.4, stratum 3, offset 0.005126, delay 0.02615 6 Dec 10:42:04 ntpdate[923]: adjust time server 172.16.1.4 offset 0.005126 sec server 172.16.1.4, stratum 3, offset 0.006027, delay 0.02634 6 Dec 10:42:05 ntpdate[927]: adjust time server 172.16.1.4 offset 0.006027 sec server 172.16.1.4, stratum 3, offset 0.007035, delay 0.02621 6 Dec 10:42:06 ntpdate[931]: adjust time server 172.16.1.4 offset 0.007035 sec server 172.16.1.4, stratum 3, offset 0.007918, delay 0.02628 6 Dec 10:42:07 ntpdate[935]: adjust time server 172.16.1.4 offset 0.007918 sec server 172.16.1.4, stratum 3, offset 0.008922, delay 0.02621 6 Dec 10:42:09 ntpdate[939]: adjust time server 172.16.1.4 offset 0.008922 sec server 172.16.1.4, stratum 3, offset 0.009877, delay 0.02623 6 Dec 10:42:10 ntpdate[943]: adjust time server 172.16.1.4 offset 0.009877 sec server 172.16.1.4, stratum 3, offset 0.010810, delay 0.02623 6 Dec 10:42:11 ntpdate[947]: adjust time server 172.16.1.4 offset 0.010810 sec server 172.16.1.4, stratum 3, offset 0.011761, delay 0.02615 6 Dec 10:42:13 ntpdate[951]: adjust time server 172.16.1.4 offset 0.011761 sec server 172.16.1.4, stratum 3, offset 0.012661, delay 0.02632 6 Dec 10:42:14 ntpdate[955]: adjust time server 172.16.1.4 offset 0.012661 sec server 172.16.1.4, stratum 3, offset 0.013673, delay 0.02623 6 Dec 10:42:15 ntpdate[959]: adjust time server 172.16.1.4 offset 0.013673 sec server 172.16.1.4, stratum 3, offset 0.014635, delay 0.02615 6 Dec 10:42:16 ntpdate[963]: adjust time server 172.16.1.4 offset 0.014635 sec server 172.16.1.4, stratum 3, offset 0.015561, delay 0.02623 6 Dec 10:42:18 ntpdate[967]: adjust time server 172.16.1.4 offset 0.015561 sec server 172.16.1.4, stratum 3, offset 0.016456, delay 0.02632 6 Dec 10:42:19 ntpdate[971]: adjust time server 172.16.1.4 offset 0.016456 sec ************ usleep-loop stopped **************** server 172.16.1.4, stratum 3, offset 0.016546, delay 0.02620 6 Dec 10:42:20 ntpdate[975]: adjust time server 172.16.1.4 offset 0.016546 sec server 172.16.1.4, stratum 3, offset 0.016575, delay 0.02628 6 Dec 10:42:21 ntpdate[979]: adjust time server 172.16.1.4 offset 0.016575 sec server 172.16.1.4, stratum 3, offset 0.016418, delay 0.02628 6 Dec 10:42:23 ntpdate[983]: adjust time server 172.16.1.4 offset 0.016418 sec server 172.16.1.4, stratum 3, offset 0.016390, delay 0.02615 6 Dec 10:42:24 ntpdate[987]: adjust time server 172.16.1.4 offset 0.016390 sec server 172.16.1.4, stratum 3, offset 0.016321, delay 0.02623 6 Dec 10:42:25 ntpdate[991]: adjust time server 172.16.1.4 offset 0.016321 sec server 172.16.1.4, stratum 3, offset 0.016188, delay 0.02637 6 Dec 10:42:26 ntpdate[995]: adjust time server 172.16.1.4 offset 0.016188 sec server 172.16.1.4, stratum 3, offset 0.016199, delay 0.02615 6 Dec 10:42:27 ntpdate[999]: adjust time server 172.16.1.4 offset 0.016199 sec
procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 0 110600 0 2424 0 0 0 0 78 82 1 8 91 0 1 0 0 110600 0 2424 0 0 0 0 110 78 42 5 53 0 1 0 0 110396 0 2432 0 0 0 0 4605 9008 37 33 28 2 2 0 0 110396 0 2432 0 0 0 0 6180 12244 5 38 57 0 1 0 0 110396 0 2432 0 0 0 0 6593 13125 4 7 89 0 1 0 0 110396 0 2432 0 0 0 0 6072 11999 5 44 51 0 1 0 0 110396 0 2432 0 0 0 0 6039 11956 3 44 54 0 1 0 0 110396 0 2432 0 0 0 0 6071 12012 20 30 50 0 1 0 0 110396 0 2432 0 0 0 0 6230 12338 9 29 63 0 1 0 0 110396 0 2432 0 0 0 0 6570 13068 0 14 86 0 1 0 0 110396 0 2432 0 0 0 0 6086 12018 10 38 51 0 1 0 0 110396 0 2432 0 0 0 0 6078 12034 16 29 55 0 1 0 0 110396 0 2432 0 0 0 0 6038 11930 5 46 49 0 2 0 0 110396 0 2432 0 0 0 0 6586 13096 0 14 86 0 1 0 0 110396 0 2432 0 0 0 0 6198 12284 11 26 63 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 2 0 0 110396 0 2432 0 0 0 0 6035 11929 8 39 53 0 1 0 0 110396 0 2432 0 0 0 0 6070 12006 13 32 55 0 1 0 0 110396 0 2432 0 0 0 0 6263 12391 3 36 61 0 1 0 0 110396 0 2432 0 0 0 0 6556 13037 3 14 83 0 1 0 0 110396 0 2432 0 0 0 0 6067 12004 8 39 53 0 1 0 0 110396 0 2432 0 0 0 0 6056 11976 5 44 51 0 1 0 0 110396 0 2432 0 0 0 0 6045 11955 3 48 50 0 2 0 0 110364 0 2432 0 0 0 0 6434 12774 6 27 67 0 1 0 0 110396 0 2432 0 0 0 0 6349 12605 6 24 70 0 1 0 0 110396 0 2432 0 0 0 0 6064 11985 0 49 51 0 0 0 0 110420 0 2432 0 0 0 0 5326 10507 2 38 60 0 0 0 0 110480 0 2432 0 0 0 0 73 79 2 7 91 0 1 0 0 110480 0 2432 0 0 0 0 50 52 1 6 93 0
# cat /proc/timer_list Timer List Version: v0.7 HRTIMER_MAX_CLOCK_BASES: 3 now at 160415794708 nsecs cpu: 0 clock 0: .base: c0386d90 .index: 0 .resolution: 1 nsecs .get_time: ktime_get .offset: 0 nsecs active timers: #0: <c0387950>, tick_sched_timer, S:01, hrtimer_start_range_ns, swapper/0 # expires at 160420000000-160420000000 nsecs [in 4205292 to 4205292 nsecs] #1: <c7221a80>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, dropbear/855 # expires at 371168357429-371268357429 nsecs [in 210752562721 to 210852562721 nsecs] #2: <c72b5a80>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, dropbear/858 # expires at 379481706502-379581706502 nsecs [in 219065911794 to 219165911794 nsecs] #3: <c724ba80>, hrtimer_wakeup, S:01, hrtimer_start_range_ns, dropbear/852 # expires at 460370275893-460470275893 nsecs [in 299954481185 to 300054481185 nsecs] clock 1: .base: c0386dc8 .index: 1 .resolution: 1 nsecs .get_time: ktime_get_real .offset: 1354790468536551118 nsecs active timers: clock 2: .base: c0386e00 .index: 2 .resolution: 1 nsecs .get_time: ktime_get_boottime .offset: 0 nsecs active timers: .expires_next : 160420000000 nsecs .hres_active : 1 .nr_events : 147883 .nr_retries : 70 .nr_hangs : 0 .max_hang_time : 0 nsecs .nohz_mode : 2 .last_tick : 160410000000 nsecs .tick_stopped : 0 .idle_jiffies : 4294953336 .idle_calls : 137032 .idle_sleeps : 122134 .idle_entrytime : 160409126930 nsecs .idle_waketime : 160406388190 nsecs .idle_exittime : 160406643041 nsecs .idle_sleeptime : 133004755578 nsecs .iowait_sleeptime: 97820593 nsecs .last_jiffies : 4294953336 .next_jiffies : 4294953337 .idle_expires : 160480000000 nsecs jiffies: 4294953337 Tick Device: mode: 1 Per CPU device: 0 Clock Event Device: timer0_0 max_delta_ns: 159072864101 min_delta_ns: 50000 mult: 115964116 shift: 32 mode: 3 next_event: 160420000000 nsecs set_next_event: davinci_set_next_event set_mode: davinci_set_mode event_handler: hrtimer_interrupt retries: 0
console.gz
Description: Unix tar archive
config.gz
Description: Unix tar archive
// Running this test causes massive time drift with Davinci kernel // By [email protected] 121206 #include <stdio.h> #include <unistd.h> #include <stdlib.h> int main(int argc, char *argv[]){ while(1){ usleep(1); } }
_______________________________________________ Davinci-linux-open-source mailing list [email protected] http://linux.davincidsp.com/mailman/listinfo/davinci-linux-open-source
