2010/11/24 Jean-Michel Hautbois <jhautbois@xxxxxxxxx>: > 2010/11/23 Â<jhautbois@xxxxxxxxx>: >> Some precisions : >> >> I am working on a MPC5200 board. >> Packets are transfered thanks to a transparent bridge. >> This is an L2 proprietary protocol. >> >> Le , Jean-Michel Hautbois <jhautbois@xxxxxxxxx> a ÃcritÂ: >>> Hi, >>> >>> >>> >>> I have a latency issue using the linux-2.6.33.7-rt29 kernel. >>> >>> Here is my setup : >>> >>> >>> >>>         Â| Board 1| | Board 2| >>> >>> PC -->  --> eth->wifi->wifi->eth -->  --> PC >>> >>>     |_ tap Â----------DAG------- tap_| >>> >>> >>> >>> The measure is done thanks to external TAP devices. >>> >>> >>> >>> The DAG card is on another PC and does the measure. >>> >>> But it is an "out of the box" measure and this is done only after I >>> >>> stop the capture by merging pcap files and using timestamps. >>> >>> >>> >>> The issue, now... >>> >>> >>> >>> As you can see on the following two pictures, at least two events >>> >>> occur during my test. >>> >>> http://rostedt.homelinux.com/rt-jitter/latencies_1500us_rt_cable_noip7.png >>> >>> http://rostedt.homelinux.com/rt-jitter/latencies_1500us_rt_cable_noip8.png >>> >>> >>> >>> Each graph is representing the latency in Âs vs. the packet number. >>> >>> Each packet is separated from the previous one by 1500Âs. >>> >>> I don't have any IP address configured (I removed the loopback and all >>> >>> other interfaces are configured using ifconfig 0.0.0.0). >>> >>> >>> >>> The problem occurs in PREEMPT_RT and PREEMPT_DESKTOP. >>> >>> The period is bigger when I change HZ (I am currently using HZ=1000). >>> >>> Hrtimers are configured, but even when not using it, the problem is the >>> same. >>> >>> >>> >>> I have done many many tests, removing timers, changing frequencies, etc. >>> >>> I also tried to change priority of my processes associated with >>> >>> sirq-rx, sirq-tx, and the interrupts. >>> >>> >>> >>> I can't find the cause. >>> >>> If you have *any* idea, thanks in advance ! >>> >>> >>> >>> Here are the timers after the test associated to the picture named >>> >>> "latencies_1500us_rt_cable_noip8.png" : >>> >>> >>> >>> Board 1 (eth -> wifi) : >>> >>> ----------------------- >>> >>> Sample period: 1654.752 s >>> >>> Â1654753,   4 sirq-timer/0   hrtimer_start_range_ns (tick_sched_timer) >>> >>> Â1655,   4 sirq-timer/0   __enqueue_rt_entity (sched_rt_period_timer) >>> >>> Â1649,  Â15 events/0     phy_state_machine (delayed_work_timer_fn) >>> >>> Â1650,  Â15 events/0     msleep (process_timeout) >>> >>> Â824,  Â15 events/0     msleep (process_timeout) >>> >>> Â275,   4 sirq-timer/0   arm_supers_timer (sync_supers_timer_fn) >>> >>> Â330,  Â80 bdi-default   Âbdi_forker_task (process_timeout) >>> >>> Â109D,  Â15 events/0     neigh_periodic_work (delayed_work_timer_fn) >>> >>> Â27D,  Â15 events/0     rt_worker_func (delayed_work_timer_fn) >>> >>>  26,   4 sirq-timer/0   dev_watchdog (dev_watchdog) >>> >>>  26,   4 sirq-timer/0   dev_watchdog (dev_watchdog) >>> >>>  13,   4 sirq-timer/0   peer_check_expire (peer_check_expire) >>> >>>  Â5,  Â15 events/0     rekey_seq_generator (delayed_work_timer_fn) >>> >>>  Â2,   4 sirq-timer/0   inet_frag_secret_rebuild >>> >>> (inet_frag_secret_rebuild) >>> >>>  1D,   4 sirq-timer/0   rt_secret_rebuild (rt_secret_rebuild) >>> >>> 1661345 total events, 1003.107 events/sec >>> >>> >>> >>> Board 2 (wifi -> eth) : >>> >>> ----------------------- >>> >>> Sample period: 1649.636 s >>> >>> Â1649636,   4 sirq-timer/0   hrtimer_start_range_ns (tick_sched_timer) >>> >>> Â1650,   4 sirq-timer/0   __enqueue_rt_entity (sched_rt_period_timer) >>> >>> Â1644,  Â15 events/0     phy_state_machine (delayed_work_timer_fn) >>> >>> Â1644,  Â15 events/0     msleep (process_timeout) >>> >>> Â822,  Â15 events/0     msleep (process_timeout) >>> >>> Â329,  Â80 bdi-default   Âbdi_forker_task (process_timeout) >>> >>> Â274,   4 sirq-timer/0   arm_supers_timer (sync_supers_timer_fn) >>> >>> Â108D,  Â15 events/0     neigh_periodic_work (delayed_work_timer_fn) >>> >>>  27,   4 sirq-timer/0   dev_watchdog (dev_watchdog) >>> >>>  27,   4 sirq-timer/0   dev_watchdog (dev_watchdog) >>> >>> Â26D,  Â15 events/0     rt_worker_func (delayed_work_timer_fn) >>> >>>  13,   4 sirq-timer/0   peer_check_expire (peer_check_expire) >>> >>>  Â4,  Â15 events/0     rekey_seq_generator (delayed_work_timer_fn) >>> >>>  Â1,   4 sirq-timer/0   inet_frag_secret_rebuild >>> >>> (inet_frag_secret_rebuild) >>> >>>  1D,   4 sirq-timer/0   rt_secret_rebuild (rt_secret_rebuild) >>> >>> 1656207 total events, 1003.603 events/sec >>> >>> >>> >>> And here is my ifconfig on each board : >>> >>> >>> >>> Board 1 (eth -> wifi) : >>> >>> ----------------------- >>> >>> ath0   ÂLink encap:Ethernet ÂHWaddr 00:0B:6B:2F:9F:8A >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:0 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:3866892 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:0 >>> >>>     ÂRX bytes:0 (0.0 B) ÂTX bytes:777245292 (741.2 MiB) >>> >>> >>> >>> br0    Link encap:Ethernet ÂHWaddr 00:0B:6B:2F:9F:8A >>> >>>     ÂUP BROADCAST RUNNING NOARP ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:0 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:0 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:0 >>> >>>     ÂRX bytes:0 (0.0 B) ÂTX bytes:0 (0.0 B) >>> >>> >>> >>> eth0   ÂLink encap:Ethernet ÂHWaddr 00:10:02:0F:B8:06 >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:3866892 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:0 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:1000 >>> >>>     ÂRX bytes:792712860 (755.9 MiB) ÂTX bytes:0 (0.0 B) >>> >>>     ÂInterrupt:133 Base address:0x3000 >>> >>> >>> >>> wifi0   Link encap:UNSPEC ÂHWaddr >>> >>> 00-0B-6B-2F-9F-8A-00-00-00-00-00-00-00-00-00-00 >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:0 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:3866892 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:199 >>> >>>     ÂRX bytes:0 (0.0 B) ÂTX bytes:912586512 (870.3 MiB) >>> >>>     ÂInterrupt:66 >>> >>> >>> >>> >>> >>> Board 2 (wifi -> eth) : >>> >>> ----------------------- >>> >>> ath0   ÂLink encap:Ethernet ÂHWaddr 00:0B:6B:2F:A0:14 >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:3818800 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:0 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:0 >>> >>>     ÂRX bytes:767578800 (732.0 MiB) ÂTX bytes:0 (0.0 B) >>> >>> >>> >>> br0    Link encap:Ethernet ÂHWaddr 00:0B:6B:2F:A0:14 >>> >>>     ÂUP BROADCAST RUNNING NOARP ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:0 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:0 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:0 >>> >>>     ÂRX bytes:0 (0.0 B) ÂTX bytes:0 (0.0 B) >>> >>> >>> >>> eth0   ÂLink encap:Ethernet ÂHWaddr 00:10:02:0F:B8:05 >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:0 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:3818800 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:1000 >>> >>>     ÂRX bytes:0 (0.0 B) ÂTX bytes:782854000 (746.5 MiB) >>> >>>     ÂInterrupt:133 Base address:0x3000 >>> >>> >>> >>> wifi0   Link encap:UNSPEC ÂHWaddr >>> >>> 00-0B-6B-2F-A0-14-00-00-00-00-00-00-00-00-00-00 >>> >>>     ÂUP BROADCAST RUNNING MULTICAST ÂMTU:1500 ÂMetric:1 >>> >>>     ÂRX packets:3818800 errors:0 dropped:0 overruns:0 frame:0 >>> >>>     ÂTX packets:0 errors:0 dropped:0 overruns:0 carrier:0 >>> >>>     Âcollisions:0 txqueuelen:199 >>> >>>     ÂRX bytes:901236800 (859.4 MiB) ÂTX bytes:0 (0.0 B) >>> >>>     ÂInterrupt:66 >>> >>> >>> >>> JM >>> > > I have done some tests using two different HZ values with > CONFIG_PREEMPT_DESKTOP. > Here are the results : > With HZ=1000 > http://picasaweb.google.com/lh/photo/ltb6hZvfssCFN0uF1iscP5MU3g7ObZTPqzWaaCIpUqI?feat=directlink > With HZ=250 > http://picasaweb.google.com/lh/photo/H9mKcM-Tarfumezbu8IJUZMU3g7ObZTPqzWaaCIpUqI?feat=directlink > > It seems to be related to a timer, maybe the scheduler itself... > Here is my ps result (on busybox) after the HZ=250 test : > PID  USER   TIME  COMMAND >  Â1 root    0:02 init >  Â2 root    0:00 [kthreadd] >  Â3 root    0:00 [sirq-high/0] >  Â4 root    0:21 [sirq-timer/0] >  Â5 root    0:00 [sirq-net-tx/0] >  Â6 root    3:08 [sirq-net-rx/0] >  Â7 root    0:00 [sirq-block/0] >  Â8 root    0:00 [sirq-block-iopo] >  Â9 root    1:56 [sirq-tasklet/0] >  10 root    0:00 [sirq-sched/0] >  11 root    0:00 [sirq-hrtimer/0] >  12 root    0:22 [sirq-rcu/0] >  13 root    0:00 [posixcputmr/0] >  14 root    0:00 [desched/0] >  15 root    0:00 [events/0] >  16 root    0:00 [khelper] >  19 root    0:00 [async/mgr] >  78 root    0:00 [sync_supers] >  80 root    0:00 [bdi-default] >  81 root    0:00 [kblockd/0] > Â105 root    0:00 [kswapd0] > Â106 root    0:00 [aio/0] > Â107 root    0:00 [crypto/0] > Â128 root    0:00 [mtdblockd] > Â188 root    0:00 [irq/144-i2c-mpc] > Â192 root    0:00 [kstriped] > Â194 root    0:00 [ksnapd] > Â198 root    0:00 [irq/139-mpc52xx] > Â216 root    0:00 [jffs2_gcd_mtd14] > Â221 root    0:00 /usr/bin/update 1 > Â240 root    1:00 [irq/66-wifi%d] > Â257 root    0:00 [irq/133-mpc52xx] > Â258 root    1:10 [irq/192-mpc52xx] > Â259 root    0:00 [irq/193-mpc52xx] > Â280 root    0:00 dropbear > Â281 root    0:00 -/bin/sh > Â308 root    0:00 ps > For those who may be interested, CONFIG_TINY_RCU changes the behaviour (it was CONFIG_TREE_PREEMPT_RCU) : http://picasaweb.google.com/lh/photo/DmKJyIv04fvnN_y0wR0_9ZMU3g7ObZTPqzWaaCIpUqI?feat=directlink -- To unsubscribe from this list: send the line "unsubscribe linux-rt-users" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
