Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>regarding this particular latency, could you try the attached patch
>ontop of -Q5? It turns the ->poll() loop into separate, individually
>preemptable iterations instead of one batch of processing. In theory
>this should result in latency being lower regardless of the
>netdev_max_backlog value.

First time - stopped during init script - when trying to start a network
service (automount).
Second time - stopped during init script - did not get the "OK" for
bringing up interface eth0.
Alt-SysRq-P still does not show any data [not sure why].
Alt-SysRq-T captured data - for example, shows dhclient in sys_select ->
__pollwait -> do_select -> process_timeout -> add_wait_queue ->
schedule_timeout -> __mod_timer. Very odd, almost every other task (except
initlog) is stuck in one of:
 - generic_handle_IRQ_event
 - sub_preempt_count
 - do_irqd
 - do_hardirq
and all the tasks I can see have "S" status.
Third time - ditto - back to stopping at automount start up.
Alt-SysRq-T captured data, again everything I could look at in "S" mode.
In all three cases, another system attempting to "ping" the system under
test failed to get any responses.

In all cases, Ctrl-Alt-Del was good enough to get a clean reboot.

This looks like a bad patch; will go back to the last good kernel for
further testing.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Mark_H_Johnson@Raytheon.com <Mark_H_Johnson@Raytheon.com> wrote:

> >regarding this particular latency, could you try the attached patch
> >ontop of -Q5? It turns the ->poll() loop into separate, individually
> >preemptable iterations instead of one batch of processing. In theory
> >this should result in latency being lower regardless of the
> >netdev_max_backlog value.
> 
> First time - stopped during init script - when trying to start a network
> service (automount).

in theory the patch is more or less equivalent to setting
netdev_max_backlog to a value of 1 - could you try that setting too?
(with the patch unapplied.)

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 1124 bytes --]


* Mark_H_Johnson@Raytheon.com <Mark_H_Johnson@Raytheon.com> wrote:

> >regarding this particular latency, could you try the attached patch
> >ontop of -Q5? It turns the ->poll() loop into separate, individually
> >preemptable iterations instead of one batch of processing. In theory
> >this should result in latency being lower regardless of the
> >netdev_max_backlog value.

> In all cases, Ctrl-Alt-Del was good enough to get a clean reboot.
> 
> This looks like a bad patch; will go back to the last good kernel for
> further testing.

ok, i think i found why it broke for you - forgot to update 'budget' in
the else branch. Could you try the attached patch ontop of -Q5? You'll
get a new sysctl as /proc/sys/net/core/netdev_backlog_granularity, with
a default value of 1. This should result in a working system with a
healthy backlog but with the preemption properties of netdev_max_backlog
== 1. Increasing the granularity will do give more chunkyness of
processing. Do you still get long RX latencies with the finest
granularity of 1, without any of the bad side-effects like booting
problems or lost packets?

	Ingo

[-- Attachment #2: rx-granularity.patch --]
[-- Type: text/plain, Size: 1949 bytes --]

--- linux/net/core/dev.c.orig
+++ linux/net/core/dev.c
@@ -1403,6 +1403,7 @@ out:
   =======================================================================*/
 
 int netdev_max_backlog = 8;
+int netdev_backlog_granularity = 1;
 int weight_p = 64;            /* old backlog weight */
 /* These numbers are selected based on intuition and some
  * experimentatiom, if you have more scientific way of doing this
@@ -1903,7 +1904,8 @@ static void net_rx_action(struct softirq
 {
 	struct softnet_data *queue = &__get_cpu_var(softnet_data);
 	unsigned long start_time = jiffies;
-	int budget = netdev_max_backlog;
+	int budget = netdev_max_backlog, left,
+		gran = netdev_backlog_granularity;
 
 	
 	local_irq_disable();
@@ -1926,7 +1928,8 @@ static void net_rx_action(struct softirq
 		dev = list_entry(queue->poll_list.next,
 				 struct net_device, poll_list);
 
-		if (dev->quota <= 0 || dev->poll(dev, &budget)) {
+		left = gran;
+		if (dev->quota <= 0 || dev->poll(dev, &left)) {
 			local_irq_disable();
 			list_del(&dev->poll_list);
 			list_add_tail(&dev->poll_list, &queue->poll_list);
@@ -1938,6 +1941,7 @@ static void net_rx_action(struct softirq
 			dev_put(dev);
 			local_irq_disable();
 		}
+		budget -= gran - left;
 	}
 out:
 	local_irq_enable();
--- linux/net/core/sysctl_net_core.c.orig
+++ linux/net/core/sysctl_net_core.c
@@ -12,7 +12,7 @@
 
 #ifdef CONFIG_SYSCTL
 
-extern int netdev_max_backlog;
+extern int netdev_max_backlog, netdev_backlog_granularity;
 extern int weight_p;
 extern int no_cong_thresh;
 extern int no_cong;
@@ -99,6 +99,14 @@ ctl_table core_table[] = {
 		.proc_handler	= &proc_dointvec
 	},
 	{
+		.ctl_name	= NET_CORE_MAX_BACKLOG,
+		.procname	= "netdev_backlog_granularity",
+		.data		= &netdev_backlog_granularity,
+		.maxlen		= sizeof(int),
+		.mode		= 0644,
+		.proc_handler	= &proc_dointvec
+	},
+	{
 		.ctl_name	= NET_CORE_NO_CONG_THRESH,
 		.procname	= "no_cong_thresh",
 		.data		= &no_cong_thresh,

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> TSC mcount
> ==========
> 
> >From your patch, added several mcount() calls to mark_offset_tsc.
> To summarize the trace results, here is a table that reports the
> delta times for each location. Each row represents one of the dozen
> trace outputs per latency trace. Row columns are the file names
> (lt.xx) in the tar file. Times are in usec.
> 
>      01  03  04  13  16  26  27  31  32  35  37  39
> 01  000 000 000 069 000 000 000 000 000 081 136 000
> 02  032 000 000 000 000 000 000 000 000 000 000 000
> 03  000 000 000 000 000 000 000 000 000 000 000 000
> 04  001 000 000 070 231 139 138 093 252 062 000 067
> 05  000 000 000 000 000 000 000 000 000 000 000 000
> 06  042 003 003 004 003 004 004 053 145 076 003 004
> 07  004 004 004 004 008 004 005 006 010 011 004 005
> 08  001 001 002 002 008 002 002 002 001 002 001 002
> 09  000 000 000 000 000 000 000 000 000 000 000 000
> 10  000 000 000 000 000 000 000 000 000 000 000 000
> 11  000 000 000 000 000 000 000 000 000 000 000 000
> 12  000 000 000 061 000 130 129 129 000 000 000 060

so ... not all codepaths contribute to the high latency.

it seems the following ones generate the highest overhead: #03-#04,
#05-#06. What code is there between mcount() #03 and #04?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Thu, 2004-09-02 at 12:59, Jaroslav Kysela wrote:
> On Tue, 31 Aug 2004, Ingo Molnar wrote:
> 
> > > > Ugh.  Please remove alsa-devel from any followups, as they seem to have
> > > > inadvertently enabled moderation.
> > > 
> > > IIRC, recently the moderation was disabled, so this should be no
> > > longer problem.
> > 
> > FYI, i still got 'your mail awaits moderation' messages just 2 minutes
> > ago.
> 
> Sorry, still one button was checked wrongly. Now it's definitely 
> corrected.
> 

Can you please approve all the messages that are awaiting moderator
approval now?  I have not received a message from alsa-devel since
Tuesday afternoon.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Jaroslav Kysela]

On Tue, 31 Aug 2004, Ingo Molnar wrote:

> > > Ugh.  Please remove alsa-devel from any followups, as they seem to have
> > > inadvertently enabled moderation.
> > 
> > IIRC, recently the moderation was disabled, so this should be no
> > longer problem.
> 
> FYI, i still got 'your mail awaits moderation' messages just 2 minutes
> ago.

Sorry, still one button was checked wrongly. Now it's definitely 
corrected.

						Jaroslav

-----
Jaroslav Kysela <perex@suse.cz>
Linux Kernel Sound Maintainer
ALSA Project, SUSE Labs

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> In 2.4, it appears that the duration of the write system call is
> basically fixed and dependent on the duration of the audio fragment.
> In 2.6, this behavior is now different. If I look at the chart in
> detail, it appears the system is queueing up several write operations
> during the first few seconds of testing. You can see this by
> consistently low elapsed times for the write system call. Then the
> elapsed time for the write bounces up / down in a sawtooth pattern
> over a 1 msec range. Could someone explain the cause of this new
> behavior and if there is a setting to restore the old behavior? I am
> concerned that this queueing adds latency to audio operations (when
> trying to synchronize audio with other real time behavior).

i think i found the reason for the sawtooth: it's a bug in hardirq
redirection. In certain situations we can end up not waking up softirqd,
resulting in a random 0-1msec latency between hardirq arrival and
softirq execution. We dont see higher latencies because timer IRQs
always wake up softirqd which hides the bug to a certain degree.

I'll fix this in -Q8.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Wed, 2004-09-01 at 11:52, Martin Josefsson wrote:
> On Wed, 2004-09-01 at 01:03, Lee Revell wrote:
> 
> Hi Lee
> 
> > This solves the problem with the random driver.  The worst latencies I
> > am seeing are in netif_receive_skb().  With netdev_max_backlog set to 8,
> > the worst is about 160 usecs:
> 
> I'm a bit curious... have you tried these tests with ip_conntrack
> enabled?

OK, loaded the ip_conntrack module.  'cat /proc/net/ip_conntrack'
produced a 2906 usec latency!

preemption latency trace v1.0.2
-------------------------------
 latency: 2906 us, entries: 4000 (7910)
    -----------------
    | task: cat/2091, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0xd/0x40
 => ended at:   local_bh_enable+0x12/0xa0
=======>
00000101 0.000ms (+0.000ms): touch_preempt_timing (cond_resched)
00000101 0.001ms (+0.001ms): ct_seq_show (seq_read)
00000101 0.002ms (+0.001ms): ct_seq_next (seq_read)
00000101 0.002ms (+0.000ms): ct_seq_show (seq_read)
00000101 0.002ms (+0.000ms): ct_seq_next (seq_read)
00000101 0.003ms (+0.000ms): ct_seq_show (seq_read)
00000101 0.003ms (+0.000ms): ct_seq_next (seq_read)
00000101 0.004ms (+0.000ms): ct_seq_show (seq_read)
00000101 0.004ms (+0.000ms): ct_seq_next (seq_read)
00000101 0.004ms (+0.000ms): ct_seq_show (seq_read)

[ this repeats hundreds of times ]

Full trace:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q6#/var/www/2.6.9-rc1-Q6/trace1.txt

netif_receive_skb still produces ~150 usec latencies with ip_conntrack,
but the code path is different: 

preemption latency trace v1.0.2
-------------------------------
 latency: 145 us, entries: 145 (145)
    -----------------
    | task: ksoftirqd/0/2, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: netif_receive_skb+0x6a/0x1d0
 => ended at:   netif_receive_skb+0x153/0x1d0
=======>
00000001 0.000ms (+0.000ms): netif_receive_skb (process_backlog)
00000001 0.001ms (+0.001ms): packet_rcv_spkt (netif_receive_skb)
00000001 0.002ms (+0.000ms): skb_clone (packet_rcv_spkt)
00000001 0.003ms (+0.000ms): kmem_cache_alloc (skb_clone)
00000001 0.004ms (+0.001ms): memcpy (skb_clone)
00000001 0.006ms (+0.002ms): strlcpy (packet_rcv_spkt)
00000002 0.008ms (+0.001ms): sk_run_filter (packet_rcv_spkt)
00000001 0.011ms (+0.002ms): __kfree_skb (packet_rcv_spkt)
00000001 0.012ms (+0.000ms): kfree_skbmem (__kfree_skb)
00000001 0.012ms (+0.000ms): skb_release_data (kfree_skbmem)
00000001 0.012ms (+0.000ms): kmem_cache_free (kfree_skbmem)
00000001 0.013ms (+0.000ms): ip_rcv (netif_receive_skb)
00000001 0.015ms (+0.001ms): nf_hook_slow (ip_rcv)
00000002 0.016ms (+0.000ms): nf_iterate (nf_hook_slow)
00000002 0.017ms (+0.001ms): ip_conntrack_defrag (nf_iterate)
00000002 0.018ms (+0.000ms): ip_conntrack_in (nf_iterate)
00000002 0.018ms (+0.000ms): ip_ct_find_proto (ip_conntrack_in)
00000103 0.019ms (+0.000ms): __ip_ct_find_proto (ip_ct_find_proto)
00000102 0.019ms (+0.000ms): local_bh_enable (ip_ct_find_proto)
00000002 0.021ms (+0.001ms): tcp_error (ip_conntrack_in)
00000002 0.022ms (+0.001ms): skb_checksum (tcp_error)
00000002 0.031ms (+0.008ms): ip_ct_get_tuple (ip_conntrack_in)
00000002 0.031ms (+0.000ms): tcp_pkt_to_tuple (ip_ct_get_tuple)
00000002 0.032ms (+0.000ms): ip_conntrack_find_get (ip_conntrack_in)
00000103 0.033ms (+0.000ms): __ip_conntrack_find (ip_conntrack_find_get)
00000103 0.033ms (+0.000ms): hash_conntrack (__ip_conntrack_find)
00000102 0.035ms (+0.002ms): local_bh_enable (ip_conntrack_find_get)
00000002 0.036ms (+0.000ms): tcp_packet (ip_conntrack_in)
00000103 0.037ms (+0.000ms): get_conntrack_index (tcp_packet)
00000103 0.038ms (+0.001ms): tcp_in_window (tcp_packet)
00000103 0.039ms (+0.000ms): tcp_sack (tcp_in_window)
00000102 0.041ms (+0.002ms): local_bh_enable (tcp_packet)
00000002 0.042ms (+0.000ms): ip_ct_refresh_acct (tcp_packet)
00000103 0.043ms (+0.000ms): del_timer (ip_ct_refresh_acct)
00000103 0.044ms (+0.000ms): __mod_timer (ip_ct_refresh_acct)
00000105 0.045ms (+0.001ms): internal_add_timer (__mod_timer)
00000102 0.046ms (+0.001ms): local_bh_enable (tcp_packet)
00000002 0.047ms (+0.001ms): ip_rcv_finish (nf_hook_slow)
00000002 0.048ms (+0.000ms): ip_route_input (ip_rcv_finish)
00000002 0.048ms (+0.000ms): rt_hash_code (ip_route_input)
00000002 0.051ms (+0.003ms): ip_local_deliver (ip_rcv_finish)
00000002 0.052ms (+0.000ms): nf_hook_slow (ip_local_deliver)
00000003 0.052ms (+0.000ms): nf_iterate (nf_hook_slow)
00000003 0.053ms (+0.000ms): ip_confirm (nf_iterate)
00000003 0.054ms (+0.000ms): ip_local_deliver_finish (nf_hook_slow)
00000004 0.055ms (+0.001ms): tcp_v4_rcv (ip_local_deliver_finish)
00000004 0.056ms (+0.000ms): tcp_v4_checksum_init (tcp_v4_rcv)
00000005 0.060ms (+0.004ms): tcp_v4_do_rcv (tcp_v4_rcv)
00000005 0.061ms (+0.000ms): tcp_rcv_established (tcp_v4_do_rcv)
00000005 0.062ms (+0.001ms): __tcp_checksum_complete_user (tcp_rcv_established)
00000005 0.063ms (+0.000ms): skb_checksum (__tcp_checksum_complete_user)
00000005 0.065ms (+0.001ms): tcp_rcv_rtt_update (tcp_rcv_established)
00000005 0.066ms (+0.001ms): tcp_event_data_recv (tcp_rcv_established)
00000005 0.069ms (+0.002ms): __tcp_ack_snd_check (tcp_rcv_established)
00000005 0.070ms (+0.000ms): __tcp_select_window (__tcp_ack_snd_check)
00000005 0.070ms (+0.000ms): tcp_send_ack (tcp_rcv_established)
00000005 0.071ms (+0.000ms): alloc_skb (tcp_send_ack)
00000005 0.071ms (+0.000ms): kmem_cache_alloc (alloc_skb)
00000005 0.072ms (+0.000ms): __kmalloc (alloc_skb)
00000005 0.074ms (+0.002ms): tcp_transmit_skb (tcp_send_ack)
00000005 0.076ms (+0.001ms): __tcp_select_window (tcp_transmit_skb)
00000005 0.078ms (+0.001ms): tcp_v4_send_check (tcp_transmit_skb)
00000005 0.079ms (+0.001ms): ip_queue_xmit (tcp_transmit_skb)
00000005 0.082ms (+0.003ms): nf_hook_slow (ip_queue_xmit)
00000006 0.083ms (+0.000ms): nf_iterate (nf_hook_slow)
00000006 0.084ms (+0.000ms): ip_conntrack_defrag (nf_iterate)
00000006 0.084ms (+0.000ms): ip_conntrack_local (nf_iterate)
00000006 0.085ms (+0.000ms): ip_conntrack_in (nf_iterate)
00000006 0.085ms (+0.000ms): ip_ct_find_proto (ip_conntrack_in)
00000107 0.086ms (+0.000ms): __ip_ct_find_proto (ip_ct_find_proto)
00000106 0.086ms (+0.000ms): local_bh_enable (ip_ct_find_proto)
00000006 0.087ms (+0.000ms): tcp_error (ip_conntrack_in)
00000006 0.088ms (+0.000ms): ip_ct_get_tuple (ip_conntrack_in)
00000006 0.088ms (+0.000ms): tcp_pkt_to_tuple (ip_ct_get_tuple)
00000006 0.089ms (+0.000ms): ip_conntrack_find_get (ip_conntrack_in)
00000107 0.089ms (+0.000ms): __ip_conntrack_find (ip_conntrack_find_get)
00000107 0.089ms (+0.000ms): hash_conntrack (__ip_conntrack_find)
00000106 0.090ms (+0.000ms): local_bh_enable (ip_conntrack_find_get)
00000006 0.091ms (+0.000ms): tcp_packet (ip_conntrack_in)
00000107 0.091ms (+0.000ms): get_conntrack_index (tcp_packet)
00000107 0.092ms (+0.000ms): tcp_in_window (tcp_packet)
00000107 0.093ms (+0.000ms): tcp_sack (tcp_in_window)
00000106 0.094ms (+0.001ms): local_bh_enable (tcp_packet)
00000006 0.094ms (+0.000ms): ip_ct_refresh_acct (tcp_packet)
00000107 0.095ms (+0.000ms): del_timer (ip_ct_refresh_acct)
00000107 0.095ms (+0.000ms): __mod_timer (ip_ct_refresh_acct)
00000109 0.096ms (+0.000ms): internal_add_timer (__mod_timer)
00000106 0.097ms (+0.000ms): local_bh_enable (tcp_packet)
00000006 0.098ms (+0.000ms): dst_output (nf_hook_slow)
00000006 0.098ms (+0.000ms): ip_output (dst_output)
00000006 0.099ms (+0.000ms): ip_finish_output (dst_output)
00000006 0.099ms (+0.000ms): nf_hook_slow (ip_finish_output)
00000007 0.100ms (+0.000ms): nf_iterate (nf_hook_slow)
00000007 0.100ms (+0.000ms): ip_refrag (nf_iterate)
00000007 0.101ms (+0.000ms): ip_confirm (ip_refrag)
00000007 0.101ms (+0.000ms): ip_finish_output2 (nf_hook_slow)
00000107 0.102ms (+0.001ms): local_bh_enable (ip_finish_output2)
00000007 0.103ms (+0.000ms): neigh_resolve_output (ip_finish_output2)
00000108 0.104ms (+0.001ms): eth_header (neigh_resolve_output)
00000107 0.106ms (+0.001ms): local_bh_enable (neigh_resolve_output)
00000007 0.107ms (+0.001ms): dev_queue_xmit (neigh_resolve_output)
00000109 0.108ms (+0.001ms): pfifo_fast_enqueue (dev_queue_xmit)
00000109 0.109ms (+0.000ms): qdisc_restart (dev_queue_xmit)
00000109 0.110ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
00000109 0.111ms (+0.001ms): dev_queue_xmit_nit (qdisc_restart)
0000010a 0.112ms (+0.000ms): skb_clone (dev_queue_xmit_nit)
0000010a 0.112ms (+0.000ms): kmem_cache_alloc (skb_clone)
0000010a 0.113ms (+0.000ms): memcpy (skb_clone)
0000010a 0.114ms (+0.001ms): packet_rcv_spkt (dev_queue_xmit_nit)
0000010a 0.114ms (+0.000ms): strlcpy (packet_rcv_spkt)
0000010b 0.115ms (+0.000ms): sk_run_filter (packet_rcv_spkt)
0000010a 0.116ms (+0.000ms): __kfree_skb (packet_rcv_spkt)
0000010a 0.116ms (+0.000ms): kfree_skbmem (__kfree_skb)
0000010a 0.117ms (+0.000ms): skb_release_data (kfree_skbmem)
0000010a 0.117ms (+0.000ms): kmem_cache_free (kfree_skbmem)
00000109 0.118ms (+0.000ms): rhine_start_tx (qdisc_restart)
00000109 0.122ms (+0.004ms): qdisc_restart (dev_queue_xmit)
00000109 0.122ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
00000108 0.123ms (+0.000ms): local_bh_enable (dev_queue_xmit)
00000005 0.124ms (+0.001ms): sock_def_readable (tcp_rcv_established)
00000006 0.125ms (+0.000ms): __wake_up (sock_def_readable)
00000007 0.126ms (+0.000ms): __wake_up_common (__wake_up)
00000007 0.127ms (+0.000ms): default_wake_function (__wake_up_common)
00000007 0.127ms (+0.000ms): try_to_wake_up (__wake_up_common)
00000007 0.128ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000008 0.129ms (+0.000ms): activate_task (try_to_wake_up)
00000008 0.129ms (+0.000ms): sched_clock (activate_task)
00000008 0.130ms (+0.000ms): recalc_task_prio (activate_task)
00000008 0.131ms (+0.000ms): effective_prio (recalc_task_prio)
00000008 0.131ms (+0.000ms): enqueue_task (activate_task)
00010007 0.133ms (+0.001ms): do_IRQ (__wake_up)
00010008 0.134ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010008 0.138ms (+0.004ms): generic_redirect_hardirq (do_IRQ)
00010008 0.138ms (+0.000ms): wake_up_process (generic_redirect_hardirq)
00010008 0.139ms (+0.000ms): try_to_wake_up (wake_up_process)
00010008 0.139ms (+0.000ms): task_rq_lock (try_to_wake_up)
00010009 0.140ms (+0.000ms): activate_task (try_to_wake_up)
00010009 0.140ms (+0.000ms): sched_clock (activate_task)
00010009 0.140ms (+0.000ms): recalc_task_prio (activate_task)
00010009 0.141ms (+0.000ms): effective_prio (recalc_task_prio)
00010009 0.141ms (+0.000ms): enqueue_task (activate_task)
00000001 0.145ms (+0.003ms): sub_preempt_count (netif_receive_skb)
00000001 0.146ms (+0.000ms): update_max_trace (check_preempt_timing)
00000001 0.146ms (+0.000ms): _mmx_memcpy (update_max_trace)
00000001 0.147ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Wed, 2004-09-01 at 11:52, Martin Josefsson wrote:
> On Wed, 2004-09-01 at 01:03, Lee Revell wrote:
> 
> Hi Lee
> 
> > This solves the problem with the random driver.  The worst latencies I
> > am seeing are in netif_receive_skb().  With netdev_max_backlog set to 8,
> > the worst is about 160 usecs:
> 
> I'm a bit curious... have you tried these tests with ip_conntrack
> enabled?

No, this is disabled in my config.  I will try enabling it.

What would the expected result be?

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Takashi Iwai]

At Wed, 1 Sep 2004 09:37:39 -0500,
Mark_H_Johnson@raytheon.com wrote:
> 
> >Ok, the second try.
> 
> This patch appears to work well. No snd_es1371 traces in over 25 minutes
> of testing (I had a couple hundred yesterday in similar tests). The sound
> was OK as well.

Thanks for confirmation.
I merged it to ALSA tree, hopefully promoted to bk tree soon later.


Takashi

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >since the latency tracer does not trigger, we need a modified tracer to
> >find out what's happening during such long delays. I've attached the
> >'user-latency-tracer' patch ontop of -Q5, which is a modification of the
> >latency tracer.
> 
> The attached file has a set of user latency traces taken about 1 second
> apart at the start of running "latencytest" (a tracing version of it).
> 
> The first few show the "fast path" result of calling write. The remaining
> ones vary with three different symptoms:
>  - the fast path
>  - a "long" delay (about 1000 traces)

lt.03 shows this long delay. Here are the relevant sections, the delay
seems to be triggered by the ALSA driver, by scheduling away
intentionally, in snd_pcn_lib_write1():

 00000002 0.023ms (+0.001ms): snd_pcm_update_hw_ptr (snd_pcm_lib_write1)
 00000002 0.023ms (+0.000ms): snd_ensoniq_playback1_pointer (snd_pcm_update_hw_ptr)
 00000002 0.025ms (+0.002ms): snd_pcm_playback_silence (snd_pcm_update_hw_ptr)
 00000002 0.026ms (+0.000ms): add_wait_queue (snd_pcm_lib_write1)
 00000000 0.027ms (+0.000ms): schedule_timeout (snd_pcm_lib_write1)
 00000000 0.027ms (+0.000ms): __mod_timer (schedule_timeout)

then it sleeps 700 usecs and is woken up by the soundcard's IRQ via
snd_pcm_period_elapsed():

 00010000 0.771ms (+0.000ms): snd_audiopci_interrupt (generic_handle_IRQ_event)
 00010000 0.774ms (+0.002ms): snd_pcm_period_elapsed (snd_audiopci_interrupt)
 00010002 0.775ms (+0.001ms): snd_ensoniq_playback1_pointer (snd_pcm_period_elapsed)
 00010002 0.779ms (+0.003ms): snd_pcm_playback_silence (snd_pcm_period_elapsed)
 00010002 0.780ms (+0.001ms): __wake_up (snd_pcm_period_elapsed)
 00010003 0.780ms (+0.000ms): __wake_up_common (__wake_up)
 00010003 0.780ms (+0.000ms): default_wake_function (__wake_up_common)
 00010003 0.781ms (+0.000ms): try_to_wake_up (__wake_up_common)
 00010003 0.782ms (+0.000ms): task_rq_lock (try_to_wake_up)
 00010004 0.783ms (+0.001ms): activate_task (try_to_wake_up)

and returns to userspace shortly afterwards. So the question is, why
does snd_pcm_lib_write1() cause the latencytest task to sleep (while
latencytest clearly doesnt expect this to happen and reports this as a
latency) - is this by design?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Martin Josefsson]

[-- Attachment #1: Type: text/plain, Size: 338 bytes --]

On Wed, 2004-09-01 at 01:03, Lee Revell wrote:

Hi Lee

> This solves the problem with the random driver.  The worst latencies I
> am seeing are in netif_receive_skb().  With netdev_max_backlog set to 8,
> the worst is about 160 usecs:

I'm a bit curious... have you tried these tests with ip_conntrack
enabled?

-- 
/Martin

[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>... Need to increase that data area so
>#define PERCPU_ENOUGH_ROOM 196608
>or something similar (should leave about 50K free for modules).
>
>I will rebuild with this change plus the latest of the others.

This booted fine today.

I reported the results of the audio patch separately. That seems to have
removed the audio latencies I saw previously.

A Whopper!
==========

A latency trace > 20 msec was seen (once). It starts pretty bad and then
gets stuck in a 1 msec loop.

preemption latency trace v1.0.2
-------------------------------
 latency: 23120 us, entries: 406 (406)
    -----------------
    | task: latencytest/4999, uid:0 nice:0 policy:1 rt_prio:99
    -----------------
 => started at: del_timer+0x4c/0x150
 => ended at:   del_timer+0xf2/0x150
=======>
00000001 0.000ms (+0.000ms): del_timer (del_singleshot_timer_sync)
00000001 0.700ms (+0.700ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 0.700ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.701ms (+0.000ms): profile_hook (profile_tick)
00010002 0.701ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.702ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.702ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 0.702ms (+0.000ms): update_one_process (update_process_times)
00010001 0.703ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.703ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.703ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.703ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.704ms (+0.001ms): rebalance_tick (scheduler_tick)
00000002 0.704ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 0.705ms (+0.000ms): __do_softirq (do_softirq)
00000002 0.705ms (+0.000ms): wake_up_process (do_softirq)
00000002 0.705ms (+0.000ms): try_to_wake_up (wake_up_process)
00000002 0.705ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000003 0.706ms (+0.000ms): activate_task (try_to_wake_up)
00000003 0.706ms (+0.000ms): sched_clock (activate_task)
00000003 0.706ms (+0.000ms): recalc_task_prio (activate_task)
00000003 0.706ms (+0.000ms): effective_prio (recalc_task_prio)
00000003 0.706ms (+0.000ms): enqueue_task (activate_task)
00010001 1.301ms (+0.594ms): do_IRQ (.text.lock.timer)
00010002 1.302ms (+0.000ms): mask_and_ack_level_ioapic_irq (do_IRQ)
00010002 1.302ms (+0.000ms): mask_IO_APIC_irq
(mask_and_ack_level_ioapic_irq)
00010003 1.302ms (+0.000ms): __mask_IO_APIC_irq (mask_IO_APIC_irq)
00010003 1.302ms (+0.000ms): __modify_IO_APIC_irq (__mask_IO_APIC_irq)
00010002 1.315ms (+0.013ms): generic_redirect_hardirq (do_IRQ)
00010001 1.315ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010001 1.316ms (+0.000ms): usb_hcd_irq (generic_handle_IRQ_event)
00010001 1.316ms (+0.000ms): uhci_irq (usb_hcd_irq)
00010001 1.316ms (+0.000ms): usb_hcd_irq (generic_handle_IRQ_event)
00010001 1.317ms (+0.000ms): uhci_irq (usb_hcd_irq)
00010001 1.317ms (+0.000ms): snd_audiopci_interrupt
(generic_handle_IRQ_event)
00010001 1.319ms (+0.001ms): snd_pcm_period_elapsed
(snd_audiopci_interrupt)
00010003 1.319ms (+0.000ms): snd_ensoniq_playback1_pointer
(snd_pcm_period_elapsed)
00010003 1.321ms (+0.001ms): snd_pcm_playback_silence
(snd_pcm_period_elapsed)
00010003 1.321ms (+0.000ms): __wake_up (snd_pcm_period_elapsed)
00010004 1.321ms (+0.000ms): __wake_up_common (__wake_up)
00010004 1.322ms (+0.000ms): default_wake_function (__wake_up_common)
00010004 1.322ms (+0.000ms): try_to_wake_up (__wake_up_common)
00010004 1.322ms (+0.000ms): task_rq_lock (try_to_wake_up)
00010001 1.323ms (+0.000ms): kill_fasync (snd_pcm_period_elapsed)
00010002 1.323ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010002 1.323ms (+0.000ms): end_level_ioapic_irq (do_IRQ)
00010002 1.323ms (+0.000ms): unmask_IO_APIC_irq (do_IRQ)
00010003 1.324ms (+0.000ms): __unmask_IO_APIC_irq (unmask_IO_APIC_irq)
00010003 1.324ms (+0.000ms): __modify_IO_APIC_irq (__unmask_IO_APIC_irq)
00000002 1.338ms (+0.013ms): do_softirq (do_IRQ)
00000002 1.338ms (+0.000ms): __do_softirq (do_softirq)
00000001 1.699ms (+0.361ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 1.700ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 1.700ms (+0.000ms): profile_hook (profile_tick)
00010002 1.700ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 1.700ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 1.700ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 1.701ms (+0.000ms): update_one_process (update_process_times)
00010001 1.701ms (+0.000ms): run_local_timers (update_process_times)
00010001 1.701ms (+0.000ms): raise_softirq (update_process_times)
00010001 1.701ms (+0.000ms): scheduler_tick (update_process_times)
00010001 1.701ms (+0.000ms): sched_clock (scheduler_tick)
00010001 1.702ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 1.702ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 1.702ms (+0.000ms): __do_softirq (do_softirq)
00000001 2.699ms (+0.996ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 2.699ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 2.699ms (+0.000ms): profile_hook (profile_tick)
00010002 2.699ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 2.699ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 2.700ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 2.700ms (+0.000ms): update_one_process (update_process_times)
00010001 2.700ms (+0.000ms): run_local_timers (update_process_times)
00010001 2.700ms (+0.000ms): raise_softirq (update_process_times)
00010001 2.700ms (+0.000ms): scheduler_tick (update_process_times)
00010001 2.701ms (+0.000ms): sched_clock (scheduler_tick)
00010001 2.701ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 2.701ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 2.701ms (+0.000ms): __do_softirq (do_softirq)
00010001 2.759ms (+0.057ms): do_IRQ (.text.lock.timer)
00010002 2.759ms (+0.000ms): mask_and_ack_level_ioapic_irq (do_IRQ)
00010002 2.759ms (+0.000ms): mask_IO_APIC_irq
(mask_and_ack_level_ioapic_irq)
00010003 2.760ms (+0.000ms): __mask_IO_APIC_irq (mask_IO_APIC_irq)
00010003 2.760ms (+0.000ms): __modify_IO_APIC_irq (__mask_IO_APIC_irq)
00010002 2.773ms (+0.013ms): generic_redirect_hardirq (do_IRQ)
00010001 2.773ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010001 2.773ms (+0.000ms): usb_hcd_irq (generic_handle_IRQ_event)
00010001 2.774ms (+0.000ms): uhci_irq (usb_hcd_irq)
00010001 2.774ms (+0.000ms): usb_hcd_irq (generic_handle_IRQ_event)
00010001 2.774ms (+0.000ms): uhci_irq (usb_hcd_irq)
00010001 2.775ms (+0.000ms): snd_audiopci_interrupt
(generic_handle_IRQ_event)
00010001 2.776ms (+0.001ms): snd_pcm_period_elapsed
(snd_audiopci_interrupt)
00010003 2.777ms (+0.000ms): snd_ensoniq_playback1_pointer
(snd_pcm_period_elapsed)
00010003 2.778ms (+0.001ms): snd_pcm_playback_silence
(snd_pcm_period_elapsed)
00010003 2.779ms (+0.001ms): snd_pcm_format_set_silence
(snd_pcm_playback_silence)
00010003 2.780ms (+0.000ms): snd_pcm_format_set_silence
(snd_pcm_playback_silence)
00010003 2.781ms (+0.000ms): xrun (snd_pcm_period_elapsed)
00010003 2.781ms (+0.000ms): snd_pcm_stop (xrun)
00010003 2.782ms (+0.000ms): snd_pcm_action (snd_pcm_stop)
00010003 2.783ms (+0.000ms): snd_pcm_action_single (snd_pcm_action)
00010003 2.783ms (+0.000ms): snd_pcm_pre_stop (snd_pcm_action_single)
00010003 2.783ms (+0.000ms): snd_pcm_do_stop (snd_pcm_action_single)
00010003 2.784ms (+0.000ms): snd_ensoniq_trigger (snd_pcm_do_stop)
00010003 2.786ms (+0.001ms): snd_pcm_post_stop (snd_pcm_action_single)
00010003 2.786ms (+0.000ms): snd_pcm_trigger_tstamp (snd_pcm_post_stop)
00010003 2.787ms (+0.000ms): do_gettimeofday (snd_pcm_trigger_tstamp)
00010003 2.787ms (+0.000ms): get_offset_tsc (do_gettimeofday)
00010003 2.788ms (+0.000ms): snd_timer_notify (snd_pcm_post_stop)
00010003 2.789ms (+0.001ms): snd_pcm_tick_set (snd_pcm_post_stop)
00010003 2.790ms (+0.000ms): snd_pcm_system_tick_set (snd_pcm_post_stop)
00010003 2.790ms (+0.000ms): del_timer (snd_pcm_post_stop)
00010003 2.791ms (+0.000ms): __wake_up (snd_pcm_action_single)
00010004 2.791ms (+0.000ms): __wake_up_common (__wake_up)
00010004 2.791ms (+0.000ms): default_wake_function (__wake_up_common)
00010004 2.791ms (+0.000ms): try_to_wake_up (__wake_up_common)
00010004 2.791ms (+0.000ms): task_rq_lock (try_to_wake_up)
00010001 2.792ms (+0.000ms): kill_fasync (snd_pcm_period_elapsed)
00010002 2.793ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010002 2.793ms (+0.000ms): end_level_ioapic_irq (do_IRQ)
00010002 2.793ms (+0.000ms): unmask_IO_APIC_irq (do_IRQ)
00010003 2.793ms (+0.000ms): __unmask_IO_APIC_irq (unmask_IO_APIC_irq)
00010003 2.793ms (+0.000ms): __modify_IO_APIC_irq (__unmask_IO_APIC_irq)
00000002 2.807ms (+0.013ms): do_softirq (do_IRQ)
00000002 2.807ms (+0.000ms): __do_softirq (do_softirq)
00000001 3.698ms (+0.890ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 3.698ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 3.698ms (+0.000ms): profile_hook (profile_tick)
00010002 3.699ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 3.699ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 3.699ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 3.699ms (+0.000ms): update_one_process (update_process_times)
00010001 3.700ms (+0.000ms): run_local_timers (update_process_times)
00010001 3.700ms (+0.000ms): raise_softirq (update_process_times)
00010001 3.700ms (+0.000ms): scheduler_tick (update_process_times)
00010001 3.700ms (+0.000ms): sched_clock (scheduler_tick)
00010001 3.701ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 3.701ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 3.701ms (+0.000ms): __do_softirq (do_softirq)
00000001 4.697ms (+0.996ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 4.698ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 4.698ms (+0.000ms): profile_hook (profile_tick)
00010002 4.698ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 4.698ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 4.698ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 4.699ms (+0.000ms): update_one_process (update_process_times)
00010001 4.699ms (+0.000ms): run_local_timers (update_process_times)
00010001 4.699ms (+0.000ms): raise_softirq (update_process_times)
00010001 4.699ms (+0.000ms): scheduler_tick (update_process_times)
00010001 4.699ms (+0.000ms): sched_clock (scheduler_tick)
00010001 4.700ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 4.700ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 4.700ms (+0.000ms): __do_softirq (do_softirq)
00000001 5.697ms (+0.996ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 5.697ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 5.697ms (+0.000ms): profile_hook (profile_tick)
00010002 5.697ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 5.698ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 5.698ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 5.698ms (+0.000ms): update_one_process (update_process_times)
00010001 5.698ms (+0.000ms): run_local_timers (update_process_times)
00010001 5.698ms (+0.000ms): raise_softirq (update_process_times)
00010001 5.698ms (+0.000ms): scheduler_tick (update_process_times)
(this cycle repeats several times, exited as follows)
00000001 21.686ms (+0.996ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 21.686ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 21.686ms (+0.000ms): profile_hook (profile_tick)
00010002 21.686ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 21.687ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 21.687ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 21.687ms (+0.000ms): update_one_process (update_process_times)
00010001 21.687ms (+0.000ms): run_local_timers (update_process_times)
00010001 21.687ms (+0.000ms): raise_softirq (update_process_times)
00010001 21.687ms (+0.000ms): scheduler_tick (update_process_times)
00010001 21.688ms (+0.000ms): sched_clock (scheduler_tick)
00010001 21.688ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 21.688ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 21.688ms (+0.000ms): __do_softirq (do_softirq)
00000001 22.685ms (+0.996ms): smp_apic_timer_interrupt (.text.lock.timer)
00010001 22.685ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 22.685ms (+0.000ms): profile_hook (profile_tick)
00010002 22.686ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 22.686ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 22.686ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 22.686ms (+0.000ms): update_one_process (update_process_times)
00010001 22.686ms (+0.000ms): run_local_timers (update_process_times)
00010001 22.686ms (+0.000ms): raise_softirq (update_process_times)
00010001 22.687ms (+0.000ms): scheduler_tick (update_process_times)
00010001 22.687ms (+0.000ms): sched_clock (scheduler_tick)
00010001 22.687ms (+0.000ms): rebalance_tick (scheduler_tick)
00000002 22.687ms (+0.000ms): do_softirq (smp_apic_timer_interrupt)
00000002 22.688ms (+0.000ms): __do_softirq (do_softirq)
00000001 23.120ms (+0.432ms): sub_preempt_count (del_timer)
00000001 23.121ms (+0.000ms): update_max_trace (check_preempt_timing)

TSC mcount
==========

>From your patch, added several mcount() calls to mark_offset_tsc.
To summarize the trace results, here is a table that reports the
delta times for each location. Each row represents one of the dozen
trace outputs per latency trace. Row columns are the file names
(lt.xx) in the tar file. Times are in usec.

     01  03  04  13  16  26  27  31  32  35  37  39
01  000 000 000 069 000 000 000 000 000 081 136 000
02  032 000 000 000 000 000 000 000 000 000 000 000
03  000 000 000 000 000 000 000 000 000 000 000 000
04  001 000 000 070 231 139 138 093 252 062 000 067
05  000 000 000 000 000 000 000 000 000 000 000 000
06  042 003 003 004 003 004 004 053 145 076 003 004
07  004 004 004 004 008 004 005 006 010 011 004 005
08  001 001 002 002 008 002 002 002 001 002 001 002
09  000 000 000 000 000 000 000 000 000 000 000 000
10  000 000 000 000 000 000 000 000 000 000 000 000
11  000 000 000 000 000 000 000 000 000 000 000 000
12  000 000 000 061 000 130 129 129 000 000 000 060

NOTE: This is not all the results w/ mark_offset_tsc listed. After the
first few items, I only listed those with significant (>100 usec) delays.

Network Poll
============

I still have a few traces w/ long durations during network poll. Since
you merged that other change into Q6 (and I assume Q7) I will try that
later today.

I will also try to make a modified version of latencytest that does
the extended trace of the write system call (occasionally) to see what
is going on there as well.

For reference, I will send the tar file with all the traces in another
message (not to linux-kernel).

 --Mark

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>Ok, the second try.

This patch appears to work well. No snd_es1371 traces in over 25 minutes
of testing (I had a couple hundred yesterday in similar tests). The sound
was OK as well.

I am seeing some additional CPU overhead during the disk I/O tests with
today's kernel but I don't think this is due to this patch.

Thanks.
  --Mark

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Mon, 2004-08-30 at 05:06, Ingo Molnar wrote:

>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5

Also, the rt_garbage_collect latency is still present:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace11.txt

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Andi Kleen <ak@muc.de> wrote:

> > the third wbinvd() in post_set() seems unnecessary too - what kind of
> > cache do we expect to flush, we've disabled caching in the CPU ... But
> > the Intel pseudocode does it too - this is a thinko i think.
> 
> The multiple steps are needed, otherwise there can be problems with
> hyperthreading (the first x86-64 didn't do it in all cases, and it
> causes occassional problens with Intel CPUs)

i'm quite sure the first one is unnecessary - any interrupt could
already come inbetween and generate dirty cachelines, so it has zero
guaranteed effect.

the third one _seems_ unnecessary - what dirty cachelines can there be
after we've disabled the cache?

the hyperthreading question is valid but no way does the flush solve the
HT problems this code already has! The only proper way i can see to
_guarantee_ zero cache effects is to do a 'catch CPUs', 'disable IRQs,
all caches and flush them', and 'set MTRR's on all CPUs', 'enable all
caches', 'continue CPUs' sequence, SMP-synchronized at every point.
Otherwise you can always get some dirty cache state due to HT races and
whatever data corruption there might occur. I believe the MTRR code is
quite incorrectly coded as-is.

> Also repeated calls of this are relatively cheap because at the second
> time there is not much to flush anymore.

the trace shows that the first one is 300 usecs, the second and third 
one is 150 usecs each, so it's not exactly cheap.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Mon, 2004-08-30 at 05:06, Ingo Molnar wrote:
> i've uploaded -Q5 to:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5

Hmm, 385 usec latency triggered by 'lsof /smb' (this is a samba export):

preemption latency trace v1.0.2
-------------------------------
 latency: 385 us, entries: 626 (626)
    -----------------
    | task: lsof/17876, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: unix_seq_start+0x10/0x50
 => ended at:   unix_seq_stop+0xf/0x30
=======>
00000001 0.000ms (+0.000ms): unix_seq_start (seq_read)
00000001 0.000ms (+0.000ms): unix_seq_idx (unix_seq_start)
00000001 0.027ms (+0.027ms): unix_seq_show (seq_read)
00000002 0.028ms (+0.000ms): sock_i_ino (unix_seq_show)
00000002 0.029ms (+0.001ms): seq_printf (unix_seq_show)
00000002 0.030ms (+0.000ms): vsnprintf (seq_printf)
00000002 0.032ms (+0.002ms): number (vsnprintf)
00000002 0.036ms (+0.004ms): skip_atoi (vsnprintf)
00000002 0.037ms (+0.000ms): number (vsnprintf)
00000002 0.038ms (+0.001ms): skip_atoi (vsnprintf)
00000002 0.039ms (+0.000ms): number (vsnprintf)
00000002 0.039ms (+0.000ms): skip_atoi (vsnprintf)
00000002 0.040ms (+0.000ms): number (vsnprintf)
00000002 0.041ms (+0.000ms): skip_atoi (vsnprintf)
00000002 0.041ms (+0.000ms): number (vsnprintf)
00000002 0.042ms (+0.000ms): skip_atoi (vsnprintf)
00000002 0.043ms (+0.000ms): number (vsnprintf)
00000002 0.043ms (+0.000ms): skip_atoi (vsnprintf)
00000002 0.044ms (+0.000ms): number (vsnprintf)
00000002 0.046ms (+0.001ms): seq_putc (unix_seq_show)
00000002 0.047ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.047ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.047ms (+0.000ms): seq_putc (unix_seq_show)

...

00000002 0.374ms (+0.000ms): number (vsnprintf)
00000002 0.375ms (+0.000ms): skip_atoi (vsnprintf)
00000002 0.376ms (+0.000ms): number (vsnprintf)
00000002 0.377ms (+0.001ms): seq_putc (unix_seq_show)
00000002 0.377ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.378ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.378ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.378ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.379ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.379ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.380ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.380ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.380ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.381ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.381ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.381ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.382ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.382ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.382ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.383ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.383ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.383ms (+0.000ms): seq_putc (unix_seq_show)
00000002 0.384ms (+0.000ms): seq_putc (unix_seq_show)
00000001 0.384ms (+0.000ms): preempt_schedule (unix_seq_show)
00000001 0.384ms (+0.000ms): seq_putc (unix_seq_show)
00000001 0.385ms (+0.000ms): unix_seq_stop (seq_read)
00000001 0.386ms (+0.000ms): sub_preempt_count (unix_seq_stop)
00000001 0.386ms (+0.000ms): _mmx_memcpy (check_preempt_timing)
00000001 0.387ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

Full trace:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace9.txt

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Mon, 2004-08-30 at 05:06, Ingo Molnar wrote:
> i've uploaded -Q5 to:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5

This is with netdev_max_backlog = 1:

preemption latency trace v1.0.2
-------------------------------
 latency: 386 us, entries: 328 (328)
    -----------------
    | task: ksoftirqd/0/2, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: tcp_delack_timer+0x1c/0x1d0
 => ended at:   tcp_delack_timer+0x127/0x1d0
=======>
00000001 0.000ms (+0.000ms): tcp_delack_timer (run_timer_softirq)
00000001 0.000ms (+0.000ms): __sk_stream_mem_reclaim (tcp_delack_timer)
00000001 0.004ms (+0.003ms): tcp_v4_do_rcv (tcp_delack_timer)
00000001 0.005ms (+0.001ms): tcp_rcv_established (tcp_v4_do_rcv)
00000001 0.007ms (+0.001ms): __tcp_checksum_complete_user (tcp_rcv_established)
00000001 0.008ms (+0.000ms): skb_checksum (__tcp_checksum_complete_user)
00000001 0.018ms (+0.010ms): tcp_ack (tcp_rcv_established)
00000001 0.019ms (+0.001ms): tcp_ack_update_window (tcp_ack)
00000001 0.021ms (+0.001ms): tcp_urg (tcp_rcv_established)
00000001 0.021ms (+0.000ms): tcp_data_queue (tcp_rcv_established)
00000001 0.023ms (+0.001ms): sk_stream_mem_schedule (tcp_data_queue)

...

00000103 0.377ms (+0.000ms): skb_release_data (kfree_skbmem)
00000103 0.378ms (+0.000ms): kfree (kfree_skbmem)
00000103 0.379ms (+0.000ms): kmem_cache_free (kfree_skbmem)
00000103 0.383ms (+0.004ms): qdisc_restart (dev_queue_xmit)
00000103 0.384ms (+0.000ms): pfifo_fast_dequeue (qdisc_restart)
00000102 0.384ms (+0.000ms): local_bh_enable (dev_queue_xmit)
00000001 0.386ms (+0.001ms): sub_preempt_count (tcp_delack_timer)
00000001 0.387ms (+0.000ms): _mmx_memcpy (check_preempt_timing)
00000001 0.387ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

Also, I do not get the packet loss/timeout problems that another poster
reported when setting this to 1.  The network works normally, it just
does not affect the latency at all.

Full trace:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace5.txt

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Andi Kleen]

Ingo Molnar <mingo@elte.hu> writes:

> * Ingo Molnar <mingo@elte.hu> wrote:
>
>> 
>> * Lee Revell <rlrevell@joe-job.com> wrote:
>> 
>> > File under boot-time stuff, I guess.  This could be bad if X crashes,
>> > but I can't remember the last time this happened to me, and I use xorg
>> > CVS.
>> 
>> but the first wbinvd() within prepare_set() seems completely unnecessary
>> - we can flush the cache after disabling the cache just fine.
>
> the third wbinvd() in post_set() seems unnecessary too - what kind of
> cache do we expect to flush, we've disabled caching in the CPU ... But
> the Intel pseudocode does it too - this is a thinko i think.

The multiple steps are needed, otherwise there can be problems
with hyperthreading (the first x86-64 didn't do it in all cases,
and it causes occassional problens with Intel CPUs) 

Also repeated calls of this are relatively cheap because at the
second time there is not much to flush anymore.

I would suggest to not do this change, it could cause very
subtle problems.

-Andi

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Andi Kleen]

Ingo Molnar <mingo@elte.hu> writes:

> The question is, does any of the Intel (or AMD) docs
> say that the CPU cache has to be write-back flushed when setting MTRRs,
> or were those calls only done out of paranoia?

Both the Intel and AMD docs require the cache flush for MTRR
caching attribute changes. 

At least in pageattr (which is related) i know of cases where
not doing them caused data corruption in real loads.

-Andi

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 02:53, Ingo Molnar wrote:
> > > 
> > >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5
>
> ok. It seems the random driver is _mostly_ in shape latency-wise, except
> the IP rekeying visible in the above trace. To solve this problem, could
> you try the patch below, ontop of -Q5? It moves the random seed
> generation outside of the spinlock - AFAICS the spinlock is only needed
> to protect the IP sequence counter itself.

This solves the problem with the random driver.  The worst latencies I
am seeing are in netif_receive_skb().  With netdev_max_backlog set to 8,
the worst is about 160 usecs:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace2.txt
http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace3.txt

Setting netdev_max_backlog to 1 has no effect:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-Q5#/var/www/2.6.9-rc1-Q5/trace4.txt

I would expect this one to scale with CPU speed, so this is pretty good
considering my relatively underpowered system.  I would imagine on a
fast UP system you would not see any latencies worse than 100 usecs.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 16:39, Ingo Molnar wrote:

> hm, this doesnt seem to be an mtrr latency - this is a text-console 
> blanking operation apparently running with the BKL enabled.
> 

Yes, this seemed strange to me too, but I reproduced this several times,
even across reboots.  This one must have been happening right before the
MTRR initialization, and was getting masked by it.

Lee 

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> On Tue, 2004-08-31 at 16:20, Ingo Molnar wrote:
> > so ... could you try the patch below - does it work and how does the
> > latency look like now? (ontop of an unmodified generic.c)
> > 
> 
> Now it looks like this:
> 
> preemption latency trace v1.0.2
> -------------------------------
>  latency: 574 us, entries: 19 (19)
>     -----------------
>     | task: X/1391, uid:0 nice:0 policy:0 rt_prio:0
>     -----------------
>  => started at: cond_resched+0xd/0x40
>  => ended at:   sys_ioctl+0xdf/0x290
> =======>
> 00000001 0.000ms (+0.000ms): touch_preempt_timing (cond_resched)
> 00000001 0.000ms (+0.000ms): do_blank_screen (vt_ioctl)
> 00000001 0.000ms (+0.000ms): is_console_locked (do_blank_screen)
> 00000001 0.001ms (+0.000ms): hide_cursor (do_blank_screen)
> 00000001 0.002ms (+0.000ms): vgacon_cursor (hide_cursor)
> 00000001 0.004ms (+0.001ms): hide_softcursor (do_blank_screen)
> 00000001 0.004ms (+0.000ms): is_console_locked (do_blank_screen)
> 00000001 0.004ms (+0.000ms): vgacon_save_screen (do_blank_screen)
> 00000001 0.005ms (+0.000ms): _mmx_memcpy (vgacon_save_screen)
> 00000001 0.006ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)
> 00000001 0.481ms (+0.475ms): vgacon_blank (do_blank_screen)
> 00000001 0.481ms (+0.000ms): vgacon_set_origin (vgacon_blank)
> 00000001 0.573ms (+0.091ms): set_origin (vt_ioctl)
> 00000001 0.573ms (+0.000ms): is_console_locked (set_origin)
> 00000001 0.573ms (+0.000ms): vgacon_set_origin (set_origin)
> 00000001 0.574ms (+0.000ms): release_console_sem (vt_ioctl)
> 00000001 0.575ms (+0.000ms): sub_preempt_count (sys_ioctl)
> 00000001 0.575ms (+0.000ms): _mmx_memcpy (check_preempt_timing)
> 00000001 0.575ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

hm, this doesnt seem to be an mtrr latency - this is a text-console 
blanking operation apparently running with the BKL enabled.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> >since the latency tracer does not trigger, we need a modified tracer to
> >find out what's happening during such long delays. I've attached the
> >'user-latency-tracer' patch ontop of -Q5, which is a modification of the
> >latency tracer.
> Grr. I should have checked before I built with this patch. With this in
> I now get the
>   kernel: Could not allocate 4 bytes percpu data
> messages again. Need to increase that data area so
>   #define PERCPU_ENOUGH_ROOM 196608
> or something similar (should leave about 50K free for modules).

ok, i've upped that value in my tree too.

> I will rebuild with this change plus the latest of the others.

since your traces do show those 'mystic' latency incidents causing
200-500 usec overhead in few-instructions code paths, perhaps the 1 msec
jitter you are seeing could a consequence of this too. So perhaps it
would make sense to first try disabling IDE DMA, to see whether this has
any effect on the magic latencies.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 16:20, Ingo Molnar wrote:
> so ... could you try the patch below - does it work and how does the
> latency look like now? (ontop of an unmodified generic.c)
> 

Now it looks like this:

preemption latency trace v1.0.2
-------------------------------
 latency: 574 us, entries: 19 (19)
    -----------------
    | task: X/1391, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0xd/0x40
 => ended at:   sys_ioctl+0xdf/0x290
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (cond_resched)
00000001 0.000ms (+0.000ms): do_blank_screen (vt_ioctl)
00000001 0.000ms (+0.000ms): is_console_locked (do_blank_screen)
00000001 0.001ms (+0.000ms): hide_cursor (do_blank_screen)
00000001 0.002ms (+0.000ms): vgacon_cursor (hide_cursor)
00000001 0.004ms (+0.001ms): hide_softcursor (do_blank_screen)
00000001 0.004ms (+0.000ms): is_console_locked (do_blank_screen)
00000001 0.004ms (+0.000ms): vgacon_save_screen (do_blank_screen)
00000001 0.005ms (+0.000ms): _mmx_memcpy (vgacon_save_screen)
00000001 0.006ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)
00000001 0.481ms (+0.475ms): vgacon_blank (do_blank_screen)
00000001 0.481ms (+0.000ms): vgacon_set_origin (vgacon_blank)
00000001 0.573ms (+0.091ms): set_origin (vt_ioctl)
00000001 0.573ms (+0.000ms): is_console_locked (set_origin)
00000001 0.573ms (+0.000ms): vgacon_set_origin (set_origin)
00000001 0.574ms (+0.000ms): release_console_sem (vt_ioctl)
00000001 0.575ms (+0.000ms): sub_preempt_count (sys_ioctl)
00000001 0.575ms (+0.000ms): _mmx_memcpy (check_preempt_timing)
00000001 0.575ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> 
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > File under boot-time stuff, I guess.  This could be bad if X crashes,
> > but I can't remember the last time this happened to me, and I use xorg
> > CVS.
> 
> but the first wbinvd() within prepare_set() seems completely unnecessary
> - we can flush the cache after disabling the cache just fine.

the third wbinvd() in post_set() seems unnecessary too - what kind of
cache do we expect to flush, we've disabled caching in the CPU ... But
the Intel pseudocode does it too - this is a thinko i think.

another thing is that interrupts are not disabled (although the Intel
docs suggest so). It is best to disable interrupts because any handler
executing in this window will perform extremely slowly (because caches
are disabled), and might even interfere with MTRR setting. Best disable
IRQs.

so ... could you try the patch below - does it work and how does the
latency look like now? (ontop of an unmodified generic.c)

	Ingo

--- linux/arch/i386/kernel/cpu/mtrr/generic.c.orig	
+++ linux/arch/i386/kernel/cpu/mtrr/generic.c	
@@ -240,11 +240,14 @@ static void prepare_set(void)
 	/*  Note that this is not ideal, since the cache is only flushed/disabled
 	   for this CPU while the MTRRs are changed, but changing this requires
 	   more invasive changes to the way the kernel boots  */
-	spin_lock(&set_atomicity_lock);
+	/*
+	 * Since we are disabling the cache dont allow any interrupts - they
+	 * would run extremely slow and would only increase the pain:
+	 */
+	spin_lock_irq(&set_atomicity_lock);
 
 	/*  Enter the no-fill (CD=1, NW=0) cache mode and flush caches. */
 	cr0 = read_cr0() | 0x40000000;	/* set CD flag */
-	wbinvd();
 	write_cr0(cr0);
 	wbinvd();
 
@@ -266,8 +269,7 @@ static void prepare_set(void)
 
 static void post_set(void)
 {
-	/*  Flush caches and TLBs  */
-	wbinvd();
+	/*  Flush TLBs (no need to flush caches - they are disabled)  */
 	__flush_tlb();
 
 	/* Intel (P6) standard MTRRs */
@@ -279,7 +281,7 @@ static void post_set(void)
 	/*  Restore value of CR4  */
 	if ( cpu_has_pge )
 		write_cr4(cr4);
-	spin_unlock(&set_atomicity_lock);
+	spin_unlock_irq(&set_atomicity_lock);
 }
 
 static void generic_set_all(void)

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> File under boot-time stuff, I guess.  This could be bad if X crashes,
> but I can't remember the last time this happened to me, and I use xorg
> CVS.

but the first wbinvd() within prepare_set() seems completely unnecessary
- we can flush the cache after disabling the cache just fine.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>since the latency tracer does not trigger, we need a modified tracer to
>find out what's happening during such long delays. I've attached the
>'user-latency-tracer' patch ontop of -Q5, which is a modification of the
>latency tracer.
Grr. I should have checked before I built with this patch. With this in
I now get the
  kernel: Could not allocate 4 bytes percpu data
messages again. Need to increase that data area so
  #define PERCPU_ENOUGH_ROOM 196608
or something similar (should leave about 50K free for modules).

I will rebuild with this change plus the latest of the others.

--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 16:09, Ingo Molnar wrote:
> * Ingo Molnar <mingo@elte.hu> wrote:
> 
> > it's more complex than that - MTRR's are caching attributes that the
> > CPU listens to. Mis-setting them can cause anything from memory
> > corruption to hard lockups. The question is, does any of the Intel (or
> > AMD) docs say that the CPU cache has to be write-back flushed when
> > setting MTRRs, or were those calls only done out of paranoia?
> 
> the Intel docs suggest a cache-flush when changing MTRR's, so i guess
> we've got to live with this. _Perhaps_ we could move the cache-disabling
> and the wbinvd() out of the spinlocked section, but this would make it
> preemptable, possibly causing other tasks to run with the CPU cache
> disabled! I'd say that is worse than a single 0.5 msec latency during
> MTRR setting.
> 

File under boot-time stuff, I guess.  This could be bad if X crashes,
but I can't remember the last time this happened to me, and I use xorg
CVS.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> it's more complex than that - MTRR's are caching attributes that the
> CPU listens to. Mis-setting them can cause anything from memory
> corruption to hard lockups. The question is, does any of the Intel (or
> AMD) docs say that the CPU cache has to be write-back flushed when
> setting MTRRs, or were those calls only done out of paranoia?

the Intel docs suggest a cache-flush when changing MTRR's, so i guess
we've got to live with this. _Perhaps_ we could move the cache-disabling
and the wbinvd() out of the spinlocked section, but this would make it
preemptable, possibly causing other tasks to run with the CPU cache
disabled! I'd say that is worse than a single 0.5 msec latency during
MTRR setting.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Commented out all calls to wbinvd(), seems to work fine.  I even tried
> repeatedly killing the X server before it could finish starting, no
> problems at all.
> 
> I guess the worst that could happen here would be display corruption,
> which would get fixed on the next refresh?

it's more complex than that - MTRR's are caching attributes that the CPU
listens to. Mis-setting them can cause anything from memory corruption
to hard lockups. The question is, does any of the Intel (or AMD) docs
say that the CPU cache has to be write-back flushed when setting MTRRs,
or were those calls only done out of paranoia?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 15:37, Ingo Molnar wrote:
> i believe that the invalidations are excessive. It is quite likely that
> no invalidation has to be done at all. Does your box still start up X
> fine if you uncomment all those wbinvd() calls?
> 

Commented out all calls to wbinvd(), seems to work fine.  I even tried
repeatedly killing the X server before it could finish starting, no
problems at all.

I guess the worst that could happen here would be display corruption,
which would get fixed on the next refresh?

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Thomas Charbonnel]

Ingo Molnar wrote :
> * Thomas Charbonnel <thomas@undata.org> wrote:
> 
> > As you can see ~1ms was probably an accident, and the latency does not
> > always come from do_timer. The constant is do_IRQ interrupting the
> > idle thread.
> 
> (do you have any sort of powersaving mode (ACPI/APM) enabled? If yes,
> could you try to tune it down as much as possible - disable any
> powersaving option in the BIOS and in the .config - kill apmd, etc.)
> 
> but i dont think it's powersaving - why would such an overhead show up
> in those functions. The only common thing seems to be that both
> mark_offset_tsc() and mask_and_ack_8259A() does port IO, which is slow -
> but still it shouldnt take ~0.5 msecs!
> 
> 	Ingo

Indeed, I just checked and my xrun every ~8 seconds problem is back. I
have acpi compiled in but acpi=off, but it doesn't seem to be honoured
(it was with 2.6.8.1, IIRC).

Thomas

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> 00000001 0.009ms (+0.000ms): generic_set_mtrr (set_mtrr)
> 00000001 0.009ms (+0.000ms): prepare_set (generic_set_mtrr)

this is the call to prepare_set() [implicit mcount()].

> 00000002 0.010ms (+0.000ms): prepare_set (generic_set_mtrr)

explicit mcount() #1,

> 00000002 0.010ms (+0.000ms): prepare_set (generic_set_mtrr)

#2,

> 00000002 0.375ms (+0.364ms): prepare_set (generic_set_mtrr)

#3. So the latency is this codepath:

+       mcount();
        wbinvd();
+       mcount();

bingo ...

to continue:

> 00000002 0.375ms (+0.000ms): prepare_set (generic_set_mtrr)

mcount #4

> 00000002 0.526ms (+0.150ms): prepare_set (generic_set_mtrr)

#5. This means the following code had the latency:

        write_cr0(cr0);
+       mcount();
        wbinvd();
+       mcount();

the other wbinvd(). Since we didnt execute all that much it didnt take
as much time as the first wbinvd() [the cache was just write-flushed, so
less flushing had to be done second time around].

plus:

 00000002 0.548ms (+0.006ms): generic_set_mtrr (set_mtrr)
 00000002 0.552ms (+0.004ms): post_set (generic_set_mtrr)
 00000001 0.708ms (+0.155ms): set_mtrr (mtrr_add_page)
 00000001 0.713ms (+0.005ms): sub_preempt_count (sys_ioctl)

proves that it's post_set() that took 155 usecs here, which too does a 
wbinvd().

so it's the invalidation of the cache that takes so long.

i believe that the invalidations are excessive. It is quite likely that
no invalidation has to be done at all. Does your box still start up X
fine if you uncomment all those wbinvd() calls?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Thomas Charbonnel <thomas@undata.org> wrote:

> As you can see ~1ms was probably an accident, and the latency does not
> always come from do_timer. The constant is do_IRQ interrupting the
> idle thread.

(do you have any sort of powersaving mode (ACPI/APM) enabled? If yes,
could you try to tune it down as much as possible - disable any
powersaving option in the BIOS and in the .config - kill apmd, etc.)

but i dont think it's powersaving - why would such an overhead show up
in those functions. The only common thing seems to be that both
mark_offset_tsc() and mask_and_ack_8259A() does port IO, which is slow -
but still it shouldnt take ~0.5 msecs!

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Thomas Charbonnel]

Ingo Molnar wrote :

(...)
> > and a weird one with do_timer (called from do_IRQ) taking more than 1ms
> > to complete :
> > http://www.undata.org/~thomas/do_irq.trace
> 
> hm, indeed this is a weird one. 1 msec is too close to the timer 
> frequency to be accidental. According to the trace:
> 
>  00010000 0.002ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
>  00010001 0.002ms (+0.000ms): mark_offset_tsc (timer_interrupt)
>  00010001 1.028ms (+1.025ms): do_timer (timer_interrupt)
>  00010001 1.028ms (+0.000ms): update_process_times (do_timer)
> 
> the latency happened between the beginning of mark_offset_tsc() and the
> calling of do_timer() - i.e. the delay happened somewhere within
> mark_offset_tsc() itself. Is this an SMP system?
> 
> 	Ingo

It isn't an SMP system, but here are some other traces that can prove
useful :
preemption latency trace v1.0.2
-------------------------------
 latency: 567 us, entries: 35 (35)
    -----------------
    | task: swapper/0, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: do_IRQ+0x19/0x190
 => ended at:   do_IRQ+0x13d/0x190
=======>
00010000 0.000ms (+0.000ms): do_IRQ (common_interrupt)
00010000 0.000ms (+0.000ms): do_IRQ (default_idle)
00010001 0.000ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010001 0.002ms (+0.002ms): generic_redirect_hardirq (do_IRQ)
00010000 0.002ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010000 0.002ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010001 0.003ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010001 0.562ms (+0.559ms): do_timer (timer_interrupt)
00010001 0.562ms (+0.000ms): update_process_times (do_timer)
00010001 0.562ms (+0.000ms): update_one_process (update_process_times)
00010001 0.562ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.562ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.562ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.562ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.563ms (+0.000ms): update_wall_time (do_timer)
00010001 0.563ms (+0.000ms): update_wall_time_one_tick
(update_wall_time)
00010001 0.563ms (+0.000ms): profile_tick (timer_interrupt)
00010001 0.563ms (+0.000ms): profile_hook (profile_tick)
00010002 0.563ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.564ms (+0.000ms): profile_hit (timer_interrupt)
00010001 0.564ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010001 0.564ms (+0.000ms): end_8259A_irq (do_IRQ)
00010001 0.564ms (+0.000ms): enable_8259A_irq (do_IRQ)
00000001 0.565ms (+0.000ms): do_softirq (do_IRQ)
00000001 0.565ms (+0.000ms): __do_softirq (do_softirq)
00000001 0.565ms (+0.000ms): wake_up_process (do_softirq)
00000001 0.565ms (+0.000ms): try_to_wake_up (wake_up_process)
00000001 0.566ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000002 0.566ms (+0.000ms): activate_task (try_to_wake_up)
00000002 0.566ms (+0.000ms): sched_clock (activate_task)
00000002 0.566ms (+0.000ms): recalc_task_prio (activate_task)
00000002 0.566ms (+0.000ms): effective_prio (recalc_task_prio)
00000002 0.567ms (+0.000ms): enqueue_task (activate_task)
00000001 0.567ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000001 0.567ms (+0.000ms): sub_preempt_count (do_IRQ)

preemption latency trace v1.0.2
-------------------------------
 latency: 624 us, entries: 35 (35)
    -----------------
    | task: swapper/0, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: do_IRQ+0x19/0x190
 => ended at:   do_IRQ+0x13d/0x190
=======>
00010000 0.000ms (+0.000ms): do_IRQ (common_interrupt)
00010000 0.000ms (+0.000ms): do_IRQ (default_idle)
00010001 0.000ms (+0.000ms): mask_and_ack_8259A (do_IRQ)
00010001 0.613ms (+0.612ms): generic_redirect_hardirq (do_IRQ)
00010000 0.613ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010000 0.613ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010001 0.613ms (+0.000ms): mark_offset_tsc (timer_interrupt)
00010001 0.619ms (+0.005ms): do_timer (timer_interrupt)
00010001 0.619ms (+0.000ms): update_process_times (do_timer)
00010001 0.619ms (+0.000ms): update_one_process (update_process_times)
00010001 0.619ms (+0.000ms): run_local_timers (update_process_times)
00010001 0.619ms (+0.000ms): raise_softirq (update_process_times)
00010001 0.619ms (+0.000ms): scheduler_tick (update_process_times)
00010001 0.619ms (+0.000ms): sched_clock (scheduler_tick)
00010001 0.620ms (+0.000ms): update_wall_time (do_timer)
00010001 0.620ms (+0.000ms): update_wall_time_one_tick
(update_wall_time)
00010001 0.620ms (+0.000ms): profile_tick (timer_interrupt)
00010001 0.620ms (+0.000ms): profile_hook (profile_tick)
00010002 0.620ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.621ms (+0.000ms): profile_hit (timer_interrupt)
00010001 0.621ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010001 0.621ms (+0.000ms): end_8259A_irq (do_IRQ)
00010001 0.621ms (+0.000ms): enable_8259A_irq (do_IRQ)
00000001 0.622ms (+0.000ms): do_softirq (do_IRQ)
00000001 0.622ms (+0.000ms): __do_softirq (do_softirq)
00000001 0.622ms (+0.000ms): wake_up_process (do_softirq)
00000001 0.622ms (+0.000ms): try_to_wake_up (wake_up_process)
00000001 0.623ms (+0.000ms): task_rq_lock (try_to_wake_up)
00000002 0.623ms (+0.000ms): activate_task (try_to_wake_up)
00000002 0.623ms (+0.000ms): sched_clock (activate_task)
00000002 0.623ms (+0.000ms): recalc_task_prio (activate_task)
00000002 0.623ms (+0.000ms): effective_prio (recalc_task_prio)
00000002 0.623ms (+0.000ms): enqueue_task (activate_task)
00000001 0.624ms (+0.000ms): preempt_schedule (try_to_wake_up)
00000001 0.624ms (+0.000ms): sub_preempt_count (do_IRQ)

As you can see ~1ms was probably an accident, and the latency does not
always come from do_timer. The constant is do_IRQ interrupting the idle
thread.

Thomas

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 03:06, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > Otherwise, this looks pretty good.  Here is a new one, I got this
> > starting X:
> > 
> > http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-bk4-Q5#/var/www/2.6.9-rc1-bk4-Q5/trace2.txt
> 
> ok, MTRR setting overhead. It is not quite clear to me which precise
> code took so much time, could you stick a couple of 'mcount();' lines
> into arch/i386/kernel/cpu/mtrr/generic.c's prepare_set() and
> generic_set_mtrr() functions? In particular the wbinvd() [cache
> invalidation] instructions within prepare_set() look like a possible
> source of latency.
> 
> (explicit calls to mcount() can be used to break up latency paths
> manually - they wont affect the latency itself, they make the resulting
> trace more finegrained.)

OK, here is the trace after adding a bunch of mcount()s:

preemption latency trace v1.0.2
-------------------------------
 latency: 713 us, entries: 31 (31)
    -----------------
    | task: X/1398, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched+0xd/0x40
 => ended at:   sys_ioctl+0xdf/0x290
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (cond_resched)
00000001 0.000ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.001ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.002ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.002ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.003ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.004ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.004ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.005ms (+0.000ms): generic_get_mtrr (mtrr_add_page)
00000001 0.005ms (+0.000ms): generic_get_free_region (mtrr_add_page)
00000001 0.006ms (+0.000ms): generic_get_mtrr (generic_get_free_region)
00000001 0.006ms (+0.000ms): generic_get_mtrr (generic_get_free_region)
00000001 0.007ms (+0.000ms): generic_get_mtrr (generic_get_free_region)
00000001 0.008ms (+0.000ms): generic_get_mtrr (generic_get_free_region)
00000001 0.008ms (+0.000ms): set_mtrr (mtrr_add_page)
00000001 0.009ms (+0.000ms): generic_set_mtrr (set_mtrr)
00000001 0.009ms (+0.000ms): generic_set_mtrr (set_mtrr)
00000001 0.009ms (+0.000ms): prepare_set (generic_set_mtrr)
00000002 0.010ms (+0.000ms): prepare_set (generic_set_mtrr)
00000002 0.010ms (+0.000ms): prepare_set (generic_set_mtrr)
00000002 0.375ms (+0.364ms): prepare_set (generic_set_mtrr)
00000002 0.375ms (+0.000ms): prepare_set (generic_set_mtrr)
00000002 0.526ms (+0.150ms): prepare_set (generic_set_mtrr)
00000002 0.534ms (+0.008ms): generic_set_mtrr (set_mtrr)
00000002 0.541ms (+0.007ms): generic_set_mtrr (set_mtrr)
00000002 0.548ms (+0.006ms): generic_set_mtrr (set_mtrr)
00000002 0.552ms (+0.004ms): post_set (generic_set_mtrr)
00000001 0.708ms (+0.155ms): set_mtrr (mtrr_add_page)
00000001 0.713ms (+0.005ms): sub_preempt_count (sys_ioctl)
00000001 0.714ms (+0.000ms): _mmx_memcpy (check_preempt_timing)
00000001 0.715ms (+0.000ms): kernel_fpu_begin (_mmx_memcpy)

And here is a patch showing where I added the mcount()s, with some extra
context for clarity:

--- linux-2.6.8.1-Q3-preemptible-hardirqs/arch/i386/kernel/cpu/mtrr/generic.c	2004-08-14 06:55:33.000000000 -0400
+++ linux-2.6.9-rc1-bk4-Q5/arch/i386/kernel/cpu/mtrr/generic.c	2004-08-31 15:05:36.000000000 -0400
@@ -234,28 +234,33 @@
 static spinlock_t set_atomicity_lock = SPIN_LOCK_UNLOCKED;
 
 static void prepare_set(void)
 {
 	unsigned long cr0;
 
 	/*  Note that this is not ideal, since the cache is only flushed/disabled
 	   for this CPU while the MTRRs are changed, but changing this requires
 	   more invasive changes to the way the kernel boots  */
 	spin_lock(&set_atomicity_lock);
 
 	/*  Enter the no-fill (CD=1, NW=0) cache mode and flush caches. */
+	mcount();
 	cr0 = read_cr0() | 0x40000000;	/* set CD flag */
+	mcount();
 	wbinvd();
+	mcount();
 	write_cr0(cr0);
+	mcount();
 	wbinvd();
+	mcount(); 
 
 	/*  Save value of CR4 and clear Page Global Enable (bit 7)  */
 	if ( cpu_has_pge ) {
 		cr4 = read_cr4();
 		write_cr4(cr4 & (unsigned char) ~(1 << 7));
 	}
 
 	/* Flush all TLBs via a mov %cr3, %reg; mov %reg, %cr3 */
 	__flush_tlb();
 
 	/*  Save MTRR state */
 	rdmsr(MTRRdefType_MSR, deftype_lo, deftype_hi);
@@ -305,38 +310,41 @@
 static void generic_set_mtrr(unsigned int reg, unsigned long base,
 			     unsigned long size, mtrr_type type)
 /*  [SUMMARY] Set variable MTRR register on the local CPU.
     <reg> The register to set.
     <base> The base address of the region.
     <size> The size of the region. If this is 0 the region is disabled.
     <type> The type of the region.
     <do_safe> If TRUE, do the change safely. If FALSE, safety measures should
     be done externally.
     [RETURNS] Nothing.
 */
 {
+	mcount();
 	prepare_set();
-
+	mcount();
 	if (size == 0) {
 		/* The invalid bit is kept in the mask, so we simply clear the
 		   relevant mask register to disable a range. */
 		wrmsr(MTRRphysMask_MSR(reg), 0, 0);
 	} else {
 		wrmsr(MTRRphysBase_MSR(reg), base << PAGE_SHIFT | type,
 		      (base & size_and_mask) >> (32 - PAGE_SHIFT));
+		mcount();
 		wrmsr(MTRRphysMask_MSR(reg), -size << PAGE_SHIFT | 0x800,
 		      (-size & size_and_mask) >> (32 - PAGE_SHIFT));
 	}
-
+	mcount();
 	post_set();
+	mcount();
 }
 
 int generic_validate_add_page(unsigned long base, unsigned long size, unsigned int type)
 {
 	unsigned long lbase, last;
 
 	/*  For Intel PPro stepping <= 7, must be 4 MiB aligned 
 	    and not touch 0x70000000->0x7003FFFF */
 	if (is_cpu(INTEL) && boot_cpu_data.x86 == 6 &&
 	    boot_cpu_data.x86_model == 1 &&
 	    boot_cpu_data.x86_mask <= 7) {
 		if (base & ((1 << (22 - PAGE_SHIFT)) - 1)) {


Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Takashi Iwai]

At Tue, 31 Aug 2004 20:48:46 +0200,
Ingo Molnar wrote:
> 
> 
> * Takashi Iwai <tiwai@suse.de> wrote:
> 
> > Does the attached patch fix this problem?
> > 
> > 
> > Takashi
> > 
> > --- linux/sound/pci/ens1370.c	25 Aug 2004 09:57:03 -0000	1.64
> > +++ linux/sound/pci/ens1370.c	31 Aug 2004 18:17:45 -0000
> > @@ -513,6 +513,7 @@
> >  		r = inl(ES_REG(ensoniq, 1371_SMPRATE));
> >  		if ((r & ES_1371_SRC_RAM_BUSY) == 0)
> >  			return r;
> > +		cond_resched();
> 
> but ... snd_es1371_wait_src_ready() is being called with
> ensoniq->reg_lock held and you must not reschedule with a spinlock held. 

Oh yes, you're right.  I overlooked that.

> cond_resched_lock(&ensoniq->req_lock) might not crash immediately, but 
> is it really safe to release the driver lock at this point?

The lock can be released, but then *_rate() functions may become racy
with each other.

Ok, the second try.


Takashi

--- linux/sound/pci/ens1370.c	25 Aug 2004 09:57:03 -0000	1.64
+++ linux/sound/pci/ens1370.c	31 Aug 2004 19:00:33 -0000
@@ -372,6 +372,7 @@
 
 struct _snd_ensoniq {
 	spinlock_t reg_lock;
+	struct semaphore src_mutex;
 
 	int irq;
 
@@ -513,6 +514,7 @@
 		r = inl(ES_REG(ensoniq, 1371_SMPRATE));
 		if ((r & ES_1371_SRC_RAM_BUSY) == 0)
 			return r;
+		cond_resched();
 	}
 	snd_printk("wait source ready timeout 0x%lx [0x%x]\n", ES_REG(ensoniq, 1371_SMPRATE), r);
 	return 0;
@@ -696,6 +698,7 @@
 {
 	unsigned int n, truncm, freq, result;
 
+	down(&ensoniq->src_mutex);
 	n = rate / 3000;
 	if ((1 << n) & ((1 << 15) | (1 << 13) | (1 << 11) | (1 << 9)))
 		n--;
@@ -719,12 +722,14 @@
 	snd_es1371_src_write(ensoniq, ES_SMPREG_ADC + ES_SMPREG_VFREQ_FRAC, freq & 0x7fff);
 	snd_es1371_src_write(ensoniq, ES_SMPREG_VOL_ADC, n << 8);
 	snd_es1371_src_write(ensoniq, ES_SMPREG_VOL_ADC + 1, n << 8);
+	up(&ensoniq->src_mutex);
 }
 
 static void snd_es1371_dac1_rate(ensoniq_t * ensoniq, unsigned int rate)
 {
 	unsigned int freq, r;
 
+	down(&ensoniq->src_mutex);
 	freq = ((rate << 15) + 1500) / 3000;
 	r = (snd_es1371_wait_src_ready(ensoniq) & (ES_1371_SRC_DISABLE | ES_1371_DIS_P2 | ES_1371_DIS_R1)) | ES_1371_DIS_P1;
 	outl(r, ES_REG(ensoniq, 1371_SMPRATE));
@@ -734,12 +739,14 @@
 	snd_es1371_src_write(ensoniq, ES_SMPREG_DAC1 + ES_SMPREG_VFREQ_FRAC, freq & 0x7fff);
 	r = (snd_es1371_wait_src_ready(ensoniq) & (ES_1371_SRC_DISABLE | ES_1371_DIS_P2 | ES_1371_DIS_R1));
 	outl(r, ES_REG(ensoniq, 1371_SMPRATE));
+	up(&ensoniq->src_mutex);
 }
 
 static void snd_es1371_dac2_rate(ensoniq_t * ensoniq, unsigned int rate)
 {
 	unsigned int freq, r;
 
+	down(&ensoniq->src_mutex);
 	freq = ((rate << 15) + 1500) / 3000;
 	r = (snd_es1371_wait_src_ready(ensoniq) & (ES_1371_SRC_DISABLE | ES_1371_DIS_P1 | ES_1371_DIS_R1)) | ES_1371_DIS_P2;
 	outl(r, ES_REG(ensoniq, 1371_SMPRATE));
@@ -749,6 +756,7 @@
 	snd_es1371_src_write(ensoniq, ES_SMPREG_DAC2 + ES_SMPREG_VFREQ_FRAC, freq & 0x7fff);
 	r = (snd_es1371_wait_src_ready(ensoniq) & (ES_1371_SRC_DISABLE | ES_1371_DIS_P1 | ES_1371_DIS_R1));
 	outl(r, ES_REG(ensoniq, 1371_SMPRATE));
+	up(&ensoniq->src_mutex);
 }
 
 #endif /* CHIP1371 */
@@ -870,11 +878,12 @@
 	case 44100: ensoniq->ctrl |= ES_1370_WTSRSEL(3); break;
 	default: snd_BUG();
 	}
-#else
-	snd_es1371_dac1_rate(ensoniq, runtime->rate);
 #endif
 	outl(ensoniq->ctrl, ES_REG(ensoniq, CONTROL));
 	spin_unlock_irq(&ensoniq->reg_lock);
+#ifndef CHIP1370
+	snd_es1371_dac1_rate(ensoniq, runtime->rate);
+#endif
 	return 0;
 }
 
@@ -908,11 +917,12 @@
 		ensoniq->ctrl |= ES_1370_PCLKDIVO(ES_1370_SRTODIV(runtime->rate));
 		ensoniq->u.es1370.pclkdiv_lock |= ES_MODE_PLAY2;
 	}
-#else
-	snd_es1371_dac2_rate(ensoniq, runtime->rate);
 #endif
 	outl(ensoniq->ctrl, ES_REG(ensoniq, CONTROL));
 	spin_unlock_irq(&ensoniq->reg_lock);
+#ifndef CHIP1370
+	snd_es1371_dac2_rate(ensoniq, runtime->rate);
+#endif
 	return 0;
 }
 
@@ -944,11 +954,12 @@
 		ensoniq->ctrl |= ES_1370_PCLKDIVO(ES_1370_SRTODIV(runtime->rate));
 		ensoniq->u.es1370.pclkdiv_lock |= ES_MODE_CAPTURE;
 	}
-#else
-	snd_es1371_adc_rate(ensoniq, runtime->rate);
 #endif
 	outl(ensoniq->ctrl, ES_REG(ensoniq, CONTROL));
 	spin_unlock_irq(&ensoniq->reg_lock);
+#ifndef CHIP1370
+	snd_es1371_adc_rate(ensoniq, runtime->rate);
+#endif
 	return 0;
 }
 
@@ -1886,6 +1897,7 @@
 	if (ensoniq == NULL)
 		return -ENOMEM;
 	spin_lock_init(&ensoniq->reg_lock);
+	init_MUTEX(&ensoniq->src_mutex);
 	ensoniq->card = card;
 	ensoniq->pci = pci;
 	ensoniq->irq = -1;

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Takashi Iwai <tiwai@suse.de> wrote:

> At Tue, 31 Aug 2004 14:09:33 -0400,
> Lee Revell wrote:
> > 
> > On Tue, 2004-08-31 at 13:20, Lee Revell wrote:
> > > Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The ALSA
> > > team would probably be able to help.  Takashi, any ideas?
> > 
> > Ugh.  Please remove alsa-devel from any followups, as they seem to have
> > inadvertently enabled moderation.
> 
> IIRC, recently the moderation was disabled, so this should be no
> longer problem.

FYI, i still got 'your mail awaits moderation' messages just 2 minutes
ago.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Takashi Iwai]

At Tue, 31 Aug 2004 14:09:33 -0400,
Lee Revell wrote:
> 
> On Tue, 2004-08-31 at 13:20, Lee Revell wrote:
> > Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The ALSA
> > team would probably be able to help.  Takashi, any ideas?
> 
> Ugh.  Please remove alsa-devel from any followups, as they seem to have
> inadvertently enabled moderation.

IIRC, recently the moderation was disabled, so this should be no
longer problem.


Takashi

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The
> ALSA team would probably be able to help.  Takashi, any ideas?

i'd suggest to postpone this issue for the time being, the SMP hardware
in question produces 'mysterious' latencies in other, very unexpected
places as well. I suspect there's some issue that hits whatever code
happens to run - and the es1371 driver is used for the latency testing. 
So i believe it's just an innocent bystander. I'd suggest to look at
these again if they pop up after the 'mysterious' latency source is
found.

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Takashi Iwai <tiwai@suse.de> wrote:

> Does the attached patch fix this problem?
> 
> 
> Takashi
> 
> --- linux/sound/pci/ens1370.c	25 Aug 2004 09:57:03 -0000	1.64
> +++ linux/sound/pci/ens1370.c	31 Aug 2004 18:17:45 -0000
> @@ -513,6 +513,7 @@
>  		r = inl(ES_REG(ensoniq, 1371_SMPRATE));
>  		if ((r & ES_1371_SRC_RAM_BUSY) == 0)
>  			return r;
> +		cond_resched();

but ... snd_es1371_wait_src_ready() is being called with
ensoniq->reg_lock held and you must not reschedule with a spinlock held. 
cond_resched_lock(&ensoniq->req_lock) might not crash immediately, but 
is it really safe to release the driver lock at this point?

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Takashi Iwai]

At Tue, 31 Aug 2004 13:20:19 -0400,
Lee Revell wrote:
> 
> On Tue, 2004-08-31 at 11:17, Mark_H_Johnson@raytheon.com wrote:
> > >I will be running some additional tests
> > >- reducing preempt_max_latency
> > >- running with sortirq and hardirq_preemption=0
> > >to see if these uncover any further problems.
> > 
> > #1 - audio driver
> >  latency: 621 us, entries: 28 (28)
> >     -----------------
> >     | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
> >     -----------------
> >  => started at: snd_ensoniq_playback1_prepare+0x74/0x180
> >  => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
> > =======>
> > 00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
> > (snd_pcm_do_prepare)
> > 00000001 0.014ms (+0.014ms): snd_es1371_dac1_rate
> > (snd_ensoniq_playback1_prepare)
> > 00000001 0.014ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_dac1_rate)
> > 00000001 0.562ms (+0.548ms): snd_es1371_src_read (snd_es1371_dac1_rate)
> > 00000001 0.562ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_read)
> > 00000001 0.578ms (+0.015ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_read)
> > 00000001 0.585ms (+0.006ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> > 00000001 0.585ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_write)
> > 00000001 0.601ms (+0.015ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> > 00000001 0.601ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_write)
> > 00000001 0.602ms (+0.001ms): snd_es1371_wait_src_ready
> > (snd_es1371_dac1_rate)
> > 00000001 0.616ms (+0.013ms): smp_apic_timer_interrupt
> > (snd_ensoniq_playback1_prepare)
> > 
> > or
> > 
> >  latency: 663 us, entries: 41 (41)
> >     -----------------
> >     | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
> >     -----------------
> >  => started at: snd_ensoniq_playback1_prepare+0x74/0x180
> >  => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
> > =======>
> > 00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
> > (snd_pcm_do_prepare)
> > 00000001 0.004ms (+0.004ms): snd_es1371_dac1_rate
> > (snd_ensoniq_playback1_prepare)
> > 00000001 0.005ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_dac1_rate)
> > 00000001 0.006ms (+0.001ms): snd_es1371_src_read (snd_es1371_dac1_rate)
> > 00000001 0.006ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_read)
> > 00000001 0.019ms (+0.012ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_read)
> > 00000001 0.607ms (+0.588ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> > 00000001 0.608ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_write)
> > 00000001 0.624ms (+0.016ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> > 00000001 0.624ms (+0.000ms): snd_es1371_wait_src_ready
> > (snd_es1371_src_write)
> > 00000001 0.626ms (+0.001ms): snd_es1371_wait_src_ready
> > (snd_es1371_dac1_rate)
> > 00000001 0.639ms (+0.013ms): smp_apic_timer_interrupt
> > (snd_ensoniq_playback1_prepare)
> 
> Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The ALSA
> team would probably be able to help.  Takashi, any ideas?

Does the attached patch fix this problem?


Takashi

--- linux/sound/pci/ens1370.c	25 Aug 2004 09:57:03 -0000	1.64
+++ linux/sound/pci/ens1370.c	31 Aug 2004 18:17:45 -0000
@@ -513,6 +513,7 @@
 		r = inl(ES_REG(ensoniq, 1371_SMPRATE));
 		if ((r & ES_1371_SRC_RAM_BUSY) == 0)
 			return r;
+		cond_resched();
 	}
 	snd_printk("wait source ready timeout 0x%lx [0x%x]\n", ES_REG(ensoniq, 1371_SMPRATE), r);
 	return 0;

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 13:20, Lee Revell wrote:
> Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The ALSA
> team would probably be able to help.  Takashi, any ideas?

Ugh.  Please remove alsa-devel from any followups, as they seem to have
inadvertently enabled moderation.

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Peter Zijlstra]

On Mon, 2004-08-30 at 11:06 +0200, Ingo Molnar wrote:
> i've uploaded -Q5 to:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5
> 
> ontop of:
> 
>   http://redhat.com/~mingo/voluntary-preempt/diff-bk-040828-2.6.8.1.bz2
> 
> -Q5 should fix the PS2 problems and the early boot problems, and it
> might even fix the USB, ACPI and APIC problems some people were
> reporting.
> 
> There were a number of bugs that led to the PS2 problems:
> 
>  - a change to __cond_resched() in the -Q series caused the starvation
>    of the IRQ1 and IRQ12 threads during init - causing a silent timeout
>    and misdetection in the ps2 driver(s).
> 
>  - even with the starvation bug fixed, we must set system_state to
>    SCHEDULER_OK only once the init thread has started - otherwise the
>    idle thread might hang during bootup.
> 
>  - the redirected IRQ handling now matches that of non-redirected IRQs
>    better, the outer loop in generic_handle_IRQ has been flattened.
> 
> i also re-added the synchronize_irq() fix, it was not causing the PS2
> problems.
> 
> 	Ingo

Hi Ingo,

this one is great, it's been rock solid for over 24h now. No more SMP
problems for me. Thanks for all the hard work.

Kind regards.

-- 
Peter Zijlstra <a.p.zijlstra@chello.nl>

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Tue, 2004-08-31 at 11:17, Mark_H_Johnson@raytheon.com wrote:
> >I will be running some additional tests
> >- reducing preempt_max_latency
> >- running with sortirq and hardirq_preemption=0
> >to see if these uncover any further problems.
> 
> #1 - audio driver
>  latency: 621 us, entries: 28 (28)
>     -----------------
>     | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
>     -----------------
>  => started at: snd_ensoniq_playback1_prepare+0x74/0x180
>  => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
> =======>
> 00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
> (snd_pcm_do_prepare)
> 00000001 0.014ms (+0.014ms): snd_es1371_dac1_rate
> (snd_ensoniq_playback1_prepare)
> 00000001 0.014ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_dac1_rate)
> 00000001 0.562ms (+0.548ms): snd_es1371_src_read (snd_es1371_dac1_rate)
> 00000001 0.562ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_read)
> 00000001 0.578ms (+0.015ms): snd_es1371_wait_src_ready
> (snd_es1371_src_read)
> 00000001 0.585ms (+0.006ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> 00000001 0.585ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_write)
> 00000001 0.601ms (+0.015ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> 00000001 0.601ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_write)
> 00000001 0.602ms (+0.001ms): snd_es1371_wait_src_ready
> (snd_es1371_dac1_rate)
> 00000001 0.616ms (+0.013ms): smp_apic_timer_interrupt
> (snd_ensoniq_playback1_prepare)
> 
> or
> 
>  latency: 663 us, entries: 41 (41)
>     -----------------
>     | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
>     -----------------
>  => started at: snd_ensoniq_playback1_prepare+0x74/0x180
>  => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
> =======>
> 00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
> (snd_pcm_do_prepare)
> 00000001 0.004ms (+0.004ms): snd_es1371_dac1_rate
> (snd_ensoniq_playback1_prepare)
> 00000001 0.005ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_dac1_rate)
> 00000001 0.006ms (+0.001ms): snd_es1371_src_read (snd_es1371_dac1_rate)
> 00000001 0.006ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_read)
> 00000001 0.019ms (+0.012ms): snd_es1371_wait_src_ready
> (snd_es1371_src_read)
> 00000001 0.607ms (+0.588ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> 00000001 0.608ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_write)
> 00000001 0.624ms (+0.016ms): snd_es1371_src_write (snd_es1371_dac1_rate)
> 00000001 0.624ms (+0.000ms): snd_es1371_wait_src_ready
> (snd_es1371_src_write)
> 00000001 0.626ms (+0.001ms): snd_es1371_wait_src_ready
> (snd_es1371_dac1_rate)
> 00000001 0.639ms (+0.013ms): smp_apic_timer_interrupt
> (snd_ensoniq_playback1_prepare)

Hmm, looks like the es1371 takes ~0.5 ms to set the DAC rate.  The ALSA
team would probably be able to help.  Takashi, any ideas?

Lee

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>I will be running some additional tests
>- reducing preempt_max_latency
>- running with sortirq and hardirq_preemption=0
>to see if these uncover any further problems.

Same system / kernel combination as described previously.

With preempt_max_latency=500, I went from a handful of traces to 63 in
a 25 minute test run. Most traces during the last half of the test while
the disk was active (write, copy, read). I will send a copy of the full
traces separately (not to linux-kernel), but here is a summary of the
information gathered. If someone else wants the full traces, please send
an email separately.

Note - I did not repeat the network poll / number of read cycles
problem since we are already working that one.

Cascade
=======
Occurred five times, with latencies of
 latency: 964 us, entries: 285 (285)
 latency: 964 us, entries: 285 (285)
 latency: 1827 us, entries: 454 (454)
 latency: 1111 us, entries: 318 (318)
 latency: 969 us, entries: 279 (279)

Starts / ends at
 => started at: run_timer_softirq+0x12f/0x2a0
 => ended at:   run_timer_softirq+0x10a/0x2a0

For example:
00000001 0.000ms (+0.000ms): run_timer_softirq (___do_softirq)
00000001 0.000ms (+0.000ms): cascade (run_timer_softirq)
00000001 0.005ms (+0.004ms): cascade (run_timer_softirq)
00000001 0.009ms (+0.004ms): cascade (run_timer_softirq)
00000001 0.013ms (+0.004ms): cascade (run_timer_softirq)
00000001 0.018ms (+0.004ms): cascade (run_timer_softirq)
...
00000001 0.891ms (+0.004ms): cascade (run_timer_softirq)
00000001 0.895ms (+0.004ms): cascade (run_timer_softirq)
00000001 0.896ms (+0.000ms): internal_add_timer (cascade)
00010001 0.899ms (+0.003ms): do_IRQ (run_timer_softirq)
00010002 0.899ms (+0.000ms): mask_and_ack_level_ioapic_irq (do_IRQ)
00010002 0.899ms (+0.000ms): mask_IO_APIC_irq
(mask_and_ack_level_ioapic_irq)
00010003 0.900ms (+0.000ms): __mask_IO_APIC_irq (mask_IO_APIC_irq)
00010003 0.900ms (+0.000ms): __modify_IO_APIC_irq (__mask_IO_APIC_irq)
00010002 0.914ms (+0.013ms): generic_redirect_hardirq (do_IRQ)
...


Long Duration Trace Entries
===========================

Each of these traces had a delay of about 1/2 msec at one step.

#1 - audio driver
 latency: 621 us, entries: 28 (28)
    -----------------
    | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
    -----------------
 => started at: snd_ensoniq_playback1_prepare+0x74/0x180
 => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
=======>
00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
(snd_pcm_do_prepare)
00000001 0.014ms (+0.014ms): snd_es1371_dac1_rate
(snd_ensoniq_playback1_prepare)
00000001 0.014ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_dac1_rate)
00000001 0.562ms (+0.548ms): snd_es1371_src_read (snd_es1371_dac1_rate)
00000001 0.562ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_read)
00000001 0.578ms (+0.015ms): snd_es1371_wait_src_ready
(snd_es1371_src_read)
00000001 0.585ms (+0.006ms): snd_es1371_src_write (snd_es1371_dac1_rate)
00000001 0.585ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_write)
00000001 0.601ms (+0.015ms): snd_es1371_src_write (snd_es1371_dac1_rate)
00000001 0.601ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_write)
00000001 0.602ms (+0.001ms): snd_es1371_wait_src_ready
(snd_es1371_dac1_rate)
00000001 0.616ms (+0.013ms): smp_apic_timer_interrupt
(snd_ensoniq_playback1_prepare)

or

 latency: 663 us, entries: 41 (41)
    -----------------
    | task: latencytest/11492, uid:0 nice:0 policy:1 rt_prio:99
    -----------------
 => started at: snd_ensoniq_playback1_prepare+0x74/0x180
 => ended at:   snd_ensoniq_playback1_prepare+0x11d/0x180
=======>
00000001 0.000ms (+0.000ms): snd_ensoniq_playback1_prepare
(snd_pcm_do_prepare)
00000001 0.004ms (+0.004ms): snd_es1371_dac1_rate
(snd_ensoniq_playback1_prepare)
00000001 0.005ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_dac1_rate)
00000001 0.006ms (+0.001ms): snd_es1371_src_read (snd_es1371_dac1_rate)
00000001 0.006ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_read)
00000001 0.019ms (+0.012ms): snd_es1371_wait_src_ready
(snd_es1371_src_read)
00000001 0.607ms (+0.588ms): snd_es1371_src_write (snd_es1371_dac1_rate)
00000001 0.608ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_write)
00000001 0.624ms (+0.016ms): snd_es1371_src_write (snd_es1371_dac1_rate)
00000001 0.624ms (+0.000ms): snd_es1371_wait_src_ready
(snd_es1371_src_write)
00000001 0.626ms (+0.001ms): snd_es1371_wait_src_ready
(snd_es1371_dac1_rate)
00000001 0.639ms (+0.013ms): smp_apic_timer_interrupt
(snd_ensoniq_playback1_prepare)

#2 - Scheduler

preemption latency trace v1.0.2
-------------------------------
 latency: 567 us, entries: 48 (48)
    -----------------
    | task: cpu_burn/9444, uid:0 nice:10 policy:0 rt_prio:0
    -----------------
 => started at: schedule+0x51/0x7b0
 => ended at:   schedule+0x35b/0x7b0
=======>
00000001 0.000ms (+0.000ms): schedule (io_schedule)
00000001 0.001ms (+0.001ms): sched_clock (schedule)
00000002 0.001ms (+0.000ms): deactivate_task (schedule)
00000002 0.002ms (+0.000ms): dequeue_task (deactivate_task)
00000002 0.549ms (+0.546ms): __switch_to (schedule)
00000002 0.550ms (+0.001ms): finish_task_switch (schedule)
00000002 0.550ms (+0.000ms): smp_apic_timer_interrupt (finish_task_switch)
00010002 0.551ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010002 0.551ms (+0.000ms): profile_hook (profile_tick)

[I have a LOT more traces where __switch_to has the big time delay]
but also note...

preemption latency trace v1.0.2
-------------------------------
 latency: 591 us, entries: 62 (62)
    -----------------
    | task: fam/4524, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: schedule+0x51/0x7b0
 => ended at:   schedule+0x35b/0x7b0
=======>
00000001 0.000ms (+0.000ms): schedule (io_schedule)
00000001 0.000ms (+0.000ms): sched_clock (schedule)
00000002 0.066ms (+0.066ms): deactivate_task (schedule)
00000002 0.066ms (+0.000ms): dequeue_task (deactivate_task)
00000002 0.475ms (+0.408ms): dequeue_task (schedule)
00000002 0.475ms (+0.000ms): recalc_task_prio (schedule)
00000002 0.475ms (+0.000ms): effective_prio (recalc_task_prio)
00000002 0.475ms (+0.000ms): enqueue_task (schedule)
00000002 0.557ms (+0.081ms): __switch_to (schedule)
00000002 0.558ms (+0.000ms): finish_task_switch (schedule)
00000002 0.558ms (+0.000ms): smp_apic_timer_interrupt (finish_task_switch)
00010002 0.559ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
where dequeue_task can take a while as well or this one

preemption latency trace v1.0.2
-------------------------------
 latency: 591 us, entries: 77 (77)
    -----------------
    | task: ksoftirqd/0/3, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: schedule+0x51/0x7b0
 => ended at:   schedule+0x35b/0x7b0
=======>
00000001 0.000ms (+0.000ms): schedule (io_schedule)
00000001 0.000ms (+0.000ms): sched_clock (schedule)
00000002 0.000ms (+0.000ms): deactivate_task (schedule)
00000002 0.000ms (+0.000ms): dequeue_task (deactivate_task)
00000002 0.480ms (+0.479ms): load_balance_newidle (schedule)
00000002 0.514ms (+0.034ms): find_busiest_group (load_balance_newidle)
00000002 0.554ms (+0.039ms): find_next_bit (find_busiest_group)
00000002 0.555ms (+0.001ms): find_next_bit (find_busiest_group)
00000002 0.555ms (+0.000ms): find_busiest_queue (load_balance_newidle)
00000002 0.556ms (+0.000ms): find_next_bit (find_busiest_queue)
00000002 0.557ms (+0.000ms): double_lock_balance (load_balance_newidle)
00000003 0.557ms (+0.000ms): move_tasks (load_balance_newidle)
00000003 0.559ms (+0.002ms): find_next_bit (move_tasks)
00000003 0.560ms (+0.000ms): find_next_bit (move_tasks)
00000003 0.561ms (+0.000ms): find_next_bit (move_tasks)
04000002 0.563ms (+0.002ms): __switch_to (schedule)
04000002 0.564ms (+0.000ms): finish_task_switch (schedule)

where it appears load balancing takes a long time.

#3 - kmap / kunmap

preemption latency trace v1.0.2
-------------------------------
 latency: 602 us, entries: 53 (53)
    -----------------
    | task: cp/11501, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: kmap_atomic+0x23/0xe0
 => ended at:   kunmap_atomic+0x7b/0xa0
=======>
00000001 0.000ms (+0.000ms): kmap_atomic (file_read_actor)
00000001 0.000ms (+0.000ms): page_address (file_read_actor)
00000001 0.000ms (+0.000ms): __copy_to_user_ll (file_read_actor)
00000001 0.502ms (+0.501ms): smp_apic_timer_interrupt (__copy_to_user_ll)
00010001 0.502ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.502ms (+0.000ms): profile_hook (profile_tick)
00010002 0.502ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.570ms (+0.068ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.571ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 0.571ms (+0.000ms): update_one_process (update_process_times)
00010001 0.571ms (+0.000ms): run_local_timers (update_process_times)

or

preemption latency trace v1.0.2
-------------------------------
 latency: 615 us, entries: 75 (75)
    -----------------
    | task: cat/11844, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: kmap_atomic+0x23/0xe0
 => ended at:   kunmap_atomic+0x7b/0xa0
=======>
00000001 0.000ms (+0.000ms): kmap_atomic (file_read_actor)
00000001 0.000ms (+0.000ms): page_address (file_read_actor)
00000001 0.000ms (+0.000ms): __copy_to_user_ll (file_read_actor)
00000001 0.563ms (+0.562ms): smp_apic_timer_interrupt (__copy_to_user_ll)
00010001 0.563ms (+0.000ms): profile_tick (smp_apic_timer_interrupt)
00010001 0.563ms (+0.000ms): profile_hook (profile_tick)
00010002 0.564ms (+0.000ms): notifier_call_chain (profile_hook)
00010001 0.564ms (+0.000ms): profile_hit (smp_apic_timer_interrupt)
00010001 0.564ms (+0.000ms): update_process_times
(smp_apic_timer_interrupt)
00010001 0.564ms (+0.000ms): update_one_process (update_process_times)

#4 - mmap

preemption latency trace v1.0.2
-------------------------------
 latency: 660 us, entries: 48 (48)
    -----------------
    | task: get_ltrace.sh/12120, uid:0 nice:-20 policy:0 rt_prio:0
    -----------------
 => started at: cond_resched_lock+0x7b/0x140
 => ended at:   exit_mmap+0x168/0x210
=======>
00000001 0.000ms (+0.000ms): touch_preempt_timing (cond_resched_lock)
00000001 0.000ms (+0.000ms): __bitmap_weight (unmap_vmas)
00000001 0.000ms (+0.000ms): vm_acct_memory (exit_mmap)
00000001 0.001ms (+0.000ms): clear_page_tables (exit_mmap)
00010001 0.520ms (+0.518ms): do_IRQ (clear_page_tables)
00010002 0.564ms (+0.044ms): ack_edge_ioapic_irq (do_IRQ)
00010002 0.564ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010001 0.564ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010001 0.564ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010002 0.565ms (+0.001ms): mark_offset_tsc (timer_interrupt)
00010002 0.618ms (+0.052ms): do_timer (timer_interrupt)
00010002 0.618ms (+0.000ms): update_wall_time (do_timer)
00010002 0.618ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010002 0.619ms (+0.000ms): generic_note_interrupt (do_IRQ)
00010002 0.619ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
00000002 0.619ms (+0.000ms): do_softirq (do_IRQ)

#5 - network poll

preemption latency trace v1.0.2
-------------------------------
 latency: 753 us, entries: 371 (371)
    -----------------
    | task: ksoftirqd/1/5, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: rtl8139_poll+0x3c/0x160
 => ended at:   rtl8139_poll+0x100/0x160
=======>
00000001 0.000ms (+0.000ms): rtl8139_poll (net_rx_action)
00000001 0.000ms (+0.000ms): rtl8139_rx (rtl8139_poll)
00000001 0.002ms (+0.001ms): alloc_skb (rtl8139_rx)
00000001 0.002ms (+0.000ms): kmem_cache_alloc (alloc_skb)
00000001 0.002ms (+0.000ms): __kmalloc (alloc_skb)
00000001 0.004ms (+0.002ms): eth_type_trans (rtl8139_rx)
00000001 0.005ms (+0.000ms): netif_receive_skb (rtl8139_rx)
00000002 0.008ms (+0.002ms): packet_rcv_spkt (netif_receive_skb)
00000002 0.008ms (+0.000ms): skb_clone (packet_rcv_spkt)
00000002 0.009ms (+0.000ms): kmem_cache_alloc (skb_clone)
00000002 0.078ms (+0.069ms): memcpy (skb_clone)
00010002 0.498ms (+0.419ms): do_IRQ (skb_clone)
00010003 0.498ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ)
00010003 0.498ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010002 0.499ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010002 0.499ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010003 0.568ms (+0.068ms): mark_offset_tsc (timer_interrupt)
00010003 0.582ms (+0.014ms): do_timer (timer_interrupt)
00010003 0.582ms (+0.000ms): update_wall_time (do_timer)

or

preemption latency trace v1.0.2
-------------------------------
 latency: 752 us, entries: 395 (395)
    -----------------
    | task: ksoftirqd/1/5, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: rtl8139_poll+0x3c/0x160
 => ended at:   rtl8139_poll+0x100/0x160
=======>
00000001 0.000ms (+0.000ms): rtl8139_poll (net_rx_action)
00000001 0.000ms (+0.000ms): rtl8139_rx (rtl8139_poll)
00000001 0.002ms (+0.001ms): alloc_skb (rtl8139_rx)
00000001 0.002ms (+0.000ms): kmem_cache_alloc (alloc_skb)
00000001 0.002ms (+0.000ms): __kmalloc (alloc_skb)
00000001 0.005ms (+0.002ms): eth_type_trans (rtl8139_rx)
00000001 0.146ms (+0.140ms): netif_receive_skb (rtl8139_rx)
00000002 0.566ms (+0.420ms): packet_rcv_spkt (netif_receive_skb)
00000002 0.567ms (+0.000ms): skb_clone (packet_rcv_spkt)
00000002 0.567ms (+0.000ms): kmem_cache_alloc (skb_clone)
00000002 0.568ms (+0.000ms): memcpy (skb_clone)
00000002 0.570ms (+0.001ms): strlcpy (packet_rcv_spkt)

Separately I ran a series of tests with:
  preempt_max_latency=500
  hardirq_preemption=0
  softirq_preemption=0
which should be similar to the configuration I used in 2.4 kernels.
There were > 100 latency traces (my script stops at 100) in the same
25 minute test. In addition to the traces listed above, I had the
following problems.

RT Run Flush
============

preemption latency trace v1.0.2
-------------------------------
 latency: 1592 us, entries: 4000 (6306)
    -----------------
    | task: latencytest/6440, uid:0 nice:0 policy:1 rt_prio:99
    -----------------
 => started at: smp_apic_timer_interrupt+0x43/0x130
 => ended at:   smp_apic_timer_interrupt+0xaa/0x130

...
00000101 0.041ms (+0.001ms): add_entropy_words (extract_entropy)
00000101 0.042ms (+0.000ms): SHATransform (extract_entropy)
00000101 0.042ms (+0.000ms): memcpy (SHATransform)
00000101 0.044ms (+0.001ms): add_entropy_words (extract_entropy)
00000101 0.045ms (+0.000ms): add_entropy_words (extract_entropy)
00000101 0.046ms (+0.001ms): credit_entropy_store (extract_entropy)
00000102 0.047ms (+0.001ms): __wake_up (extract_entropy)
00000103 0.047ms (+0.000ms): __wake_up_common (__wake_up)
00000101 0.048ms (+0.000ms): SHATransform (extract_entropy)
00000101 0.048ms (+0.000ms): memcpy (SHATransform)
00000101 0.050ms (+0.001ms): add_entropy_words (extract_entropy)
00000101 0.050ms (+0.000ms): SHATransform (extract_entropy)
00000101 0.050ms (+0.000ms): memcpy (SHATransform)
00000101 0.052ms (+0.001ms): add_entropy_words (extract_entropy)
00000201 0.053ms (+0.001ms): local_bh_enable (rt_run_flush)
00000101 0.053ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 0.053ms (+0.000ms): cond_resched_softirq (rt_run_flush)
00000201 0.054ms (+0.000ms): local_bh_enable (rt_run_flush)
00000101 0.054ms (+0.000ms): cond_resched_all (rt_run_flush)
00000101 0.054ms (+0.000ms): cond_resched_softirq (rt_run_flush)
... the last 3 lines repeat over 1000 times and fill
the trace buffer completely ...

The above sequence occurred twice during testing.

Short But Long
==============

preemption latency trace v1.0.2
-------------------------------
 latency: 549 us, entries: 4 (4)
    -----------------
    | task: kblockd/1/11, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: worker_thread+0x22d/0x3a0
 => ended at:   worker_thread+0x2a2/0x3a0
=======>
00000001 0.000ms (+0.000ms): worker_thread (kthread)
00000001 0.000ms (+0.000ms): __wake_up (worker_thread)
00000002 0.549ms (+0.549ms): __wake_up_common (__wake_up)
00000001 0.550ms (+0.000ms): sub_preempt_count (worker_thread)

or

preemption latency trace v1.0.2
-------------------------------
 latency: 551 us, entries: 4 (4)
    -----------------
    | task: kblockd/1/11, uid:0 nice:-10 policy:0 rt_prio:0
    -----------------
 => started at: worker_thread+0x22d/0x3a0
 => ended at:   worker_thread+0x2a2/0x3a0
=======>
00000001 0.000ms (+0.000ms): worker_thread (kthread)
00000001 0.000ms (+0.000ms): __wake_up (worker_thread)
00000002 0.000ms (+0.000ms): __wake_up_common (__wake_up)
00000001 0.552ms (+0.551ms): sub_preempt_count (worker_thread)

or this one apparently preempting the real time task [why??]
Now that I look, the first set of tests preempted the max priority
real time application six (6) times and the second set of tests
preempted the RT application thirty (30) times.

preemption latency trace v1.0.2
-------------------------------
 latency: 566 us, entries: 13 (13)
    -----------------
    | task: latencytest/7959, uid:0 nice:0 policy:1 rt_prio:99
    -----------------
 => started at: do_IRQ+0x19/0x290
 => ended at:   do_IRQ+0x1cf/0x290
=======>
00010000 0.000ms (+0.000ms): do_IRQ (common_interrupt)
00010000 0.000ms (+0.000ms): do_IRQ (<08049b20>)
00010001 0.000ms (+0.000ms): ack_edge_ioapic_irq (do_IRQ)
00010001 0.000ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010000 0.000ms (+0.000ms): generic_handle_IRQ_event (do_IRQ)
00010000 0.001ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
00010001 0.549ms (+0.548ms): mark_offset_tsc (timer_interrupt)
00010001 0.564ms (+0.014ms): do_timer (timer_interrupt)
00010001 0.564ms (+0.000ms): update_wall_time (do_timer)
00010001 0.564ms (+0.000ms): update_wall_time_one_tick (update_wall_time)
00010001 0.565ms (+0.001ms): generic_note_interrupt (do_IRQ)
00010001 0.566ms (+0.000ms): end_edge_ioapic_irq (do_IRQ)
00000001 0.566ms (+0.000ms): sub_preempt_count (do_IRQ)

Another Long Time
=================

#1 - kmap / kunmap

Similar stop / end locations to above, but a different cause.

preemption latency trace v1.0.2
-------------------------------
 latency: 696 us, entries: 131 (131)
    -----------------
    | task: sleep/8854, uid:0 nice:-20 policy:0 rt_prio:0
    -----------------
 => started at: kmap_atomic+0x23/0xe0
 => ended at:   kunmap_atomic+0x7b/0xa0
=======>
00000001 0.000ms (+0.000ms): kmap_atomic (do_anonymous_page)
00000001 0.000ms (+0.000ms): page_address (do_anonymous_page)
00010001 0.413ms (+0.413ms): do_IRQ (do_anonymous_page)
00010002 0.452ms (+0.038ms): ack_edge_ioapic_irq (do_IRQ)
00010002 0.452ms (+0.000ms): generic_redirect_hardirq (do_IRQ)
00010001 0.454ms (+0.001ms): generic_handle_IRQ_event (do_IRQ)
00010001 0.488ms (+0.034ms): timer_interrupt (generic_handle_IRQ_event)
00010002 0.557ms (+0.069ms): mark_offset_tsc (timer_interrupt)
00010002 0.573ms (+0.015ms): do_timer (timer_interrupt)
00010002 0.574ms (+0.000ms): update_wall_time (do_timer)
00010002 0.574ms (+0.000ms): update_wall_time_one_tick (update_wall_time)

Perhaps the most disturbing finding tat the max priority RT application
can get preempted for a long time, even though there is:
 - only one real time task
 - two CPU's to do work

  --Mark

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>in theory the patch is more or less equivalent to setting
>netdev_max_backlog to a value of 1 - could you try that setting too?
>(with the patch unapplied.)

Ugh. That setting is VERY BAD. Just a quick test without
doing anything complex...
  # echo 1 > /proc/sys/net/core/netdev_max_backlog
  # ping dws7
  PING dws7 (192.52.215.17) 56(84) bytes of data.
[so the DNS lookup worked]
  From dws77... (192.52.215.87) icmp_seq=0 Destination Host Unreachable
  From dws77... (192.52.215.87) icmp_seq=1 Destination Host Unreachable
  From dws77... (192.52.215.87) icmp_seq=2 Destination Host Unreachable
  ...
[NOTE - these are plugged into the same 10/100 Ethernet switch]
  # echo 8 > /proc/sys/net/core/netdev_max_backlog
  # ping dws7
  PING dws7 (192.52.215.17) 56(84) bytes of data.
[so the DNS lookup worked]
  From dws77... (192.52.215.87) icmp_seq=0 ttl=64 time=2210 ms
  From dws77... (192.52.215.87) icmp_seq=1 ttl=64 time=1210 ms
  From dws77... (192.52.215.87) icmp_seq=2 ttl=64 time=210 ms
  From dws77... (192.52.215.87) icmp_seq=2 ttl=64 time=0.355 ms
  From dws77... (192.52.215.87) icmp_seq=2 ttl=64 time=0.397 ms
  ...
I tried again with 2, 3, and 4. Two appears to be "way too small" with
a ping of 1000 ms and nominal values of 0.800 ms. Three does not appear
to be good either with nominal values of 0.500 ms. Four has similar
results to eight (8).


--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 2144 bytes --]


* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> VARYING SYSTEM CALL TIMES
> =========================
> 
> In 2.4, it appears that the duration of the write system call is
> basically fixed and dependent on the duration of the audio fragment.
> In 2.6, this behavior is now different. If I look at the chart in
> detail, it appears the system is queueing up several write operations
> during the first few seconds of testing. You can see this by
> consistently low elapsed times for the write system call. Then the
> elapsed time for the write bounces up / down in a sawtooth pattern
> over a 1 msec range. Could someone explain the cause of this new
> behavior and if there is a setting to restore the old behavior? I am
> concerned that this queueing adds latency to audio operations (when
> trying to synchronize audio with other real time behavior).

since the latency tracer does not trigger, we need a modified tracer to
find out what's happening during such long delays. I've attached the
'user-latency-tracer' patch ontop of -Q5, which is a modification of the
latency tracer. This patch enables free-running tracing which includes
all kernel functions not just critical sections. To activate this, two
things have to be done. Firstly:

	echo 2 > /proc/sys/kernel/trace_enabled

this turns off the normal latency tracer and turns on the 'user tracer'. 
Traces can be generated by userspace via a hack done to
sys_gettimeofday():

	gettimeofday(0,1); // enable the tracer
	gettimeofday(0,0); // save current trace and disable the tracer

this way the tracing can be limited to the suspected codepaths only.

could you try to insert gettimeofday(0,1) into your testsuite just
before the write() call is done, and right after the write() call, and
save a couple of representative traces? The patch also ups the # of
latency entries to 8000 - if that is still insufficient then please
increase it as needed.

NOTE: on SMP the tracing on/off is strictly per-CPU. So do the enabling
and disabling of the trace on the same CPU. (doing otherwise wont cause
problems, but the generated traces will be less useful.)

	Ingo

[-- Attachment #2: user-latency-2.6.9-rc1-bk4-Q5-A0 --]
[-- Type: text/plain, Size: 3598 bytes --]

--- linux/kernel/latency.c.orig
+++ linux/kernel/latency.c
@@ -27,7 +27,7 @@ static DECLARE_MUTEX(max_mutex);
 
 #ifdef CONFIG_LATENCY_TRACE
 
-#define MAX_TRACE 4000UL
+#define MAX_TRACE 8000UL
 
 struct trace_entry {
 	unsigned long preempt_count;
@@ -63,14 +63,13 @@ static unsigned long max_nice;
 static unsigned long max_policy;
 static unsigned long max_rt_priority;
 
-inline void notrace
+static inline void notrace
 ____trace(struct cpu_trace *tr, unsigned long eip, unsigned long parent_eip)
 {
 	struct trace_entry *entry;
 
-	BUG_ON(!irqs_disabled());
-
-	if (tr->trace_idx < MAX_TRACE) {
+	if ((tr->critical_start || (trace_enabled == 2)) &&
+			(tr->trace_idx < MAX_TRACE)) {
 		entry = tr->trace + tr->trace_idx;
 		entry->eip = eip;
 		entry->parent_eip = parent_eip;
@@ -80,7 +79,7 @@ ____trace(struct cpu_trace *tr, unsigned
 	tr->trace_idx++;
 }
 
-inline void notrace
+static inline void notrace
 ___trace(unsigned long eip, unsigned long parent_eip)
 {
 	unsigned long flags;
@@ -266,6 +265,18 @@ static int setup_preempt_thresh(char *s)
 }
 __setup("preempt_thresh=", setup_preempt_thresh);
 
+static void update_max_trace(struct cpu_trace *tr)
+{
+	memcpy(&max_trace, tr, sizeof (max_trace));
+
+	memcpy(max_comm, current->comm, 16);
+	max_pid = current->pid;
+	max_uid = current->uid;
+	max_nice = current->static_prio - 20 - MAX_RT_PRIO;
+	max_policy = current->policy;
+	max_rt_priority = current->rt_priority;
+}
+
 static void notrace check_preempt_timing(struct cpu_trace *tr)
 {
 #ifdef CONFIG_LATENCY_TRACE
@@ -274,6 +285,10 @@ static void notrace check_preempt_timing
 	unsigned long parent_eip = (unsigned long)__builtin_return_address(1);
 	unsigned long latency;
 
+#ifdef CONFIG_LATENCY_TRACE
+	if (trace_enabled == 2)
+		return;
+#endif
 	atomic_inc(&tr->disabled);
 	latency = cycles_to_usecs(get_cycles() - tr->preempt_timestamp);
 
@@ -293,14 +308,7 @@ static void notrace check_preempt_timing
 
 #ifdef CONFIG_LATENCY_TRACE
 	____trace(tr, eip, parent_eip);
-	memcpy(&max_trace, tr, sizeof (max_trace));
-
-	memcpy(max_comm, current->comm, 16);
-	max_pid = current->pid;
-	max_uid = current->uid;
-	max_nice = current->static_prio - 20 - MAX_RT_PRIO;
-	max_policy = current->policy;
-	max_rt_priority = current->rt_priority;
+	update_max_trace(tr);
 #endif
 
 	if (preempt_thresh)
@@ -354,6 +362,10 @@ void notrace add_preempt_count(int val)
 #endif
 
 	preempt_count() += val;
+#ifdef CONFIG_LATENCY_TRACE
+	if (trace_enabled == 2)
+		return;
+#endif
 	if (preempt_count() == val) {
 		struct cpu_trace *tr = &__get_cpu_var(trace);
 
@@ -383,3 +395,27 @@ void notrace sub_preempt_count(int val)
 	preempt_count() -= val;
 }
 EXPORT_SYMBOL(sub_preempt_count);
+
+void user_trace_start(void)
+{
+	struct cpu_trace *tr;
+
+	if (trace_enabled != 2)
+		return;
+	tr = &get_cpu_var(trace);
+	tr->trace_idx = 0;
+	mcount();
+	put_cpu_var(trace);
+}
+
+void user_trace_stop(void)
+{
+	struct cpu_trace *tr;
+
+	if (trace_enabled != 2)
+		return;
+	tr = &get_cpu_var(trace);
+	mcount();
+	update_max_trace(tr);
+	put_cpu_var(trace);
+}
--- linux/kernel/time.c.orig2	
+++ linux/kernel/time.c	
@@ -90,8 +90,17 @@ asmlinkage long sys_stime(time_t __user 
 
 #endif /* __ARCH_WANT_SYS_TIME */
 
+extern void user_trace_start(void);
+extern void user_trace_stop(void);
+
 asmlinkage long sys_gettimeofday(struct timeval __user *tv, struct timezone __user *tz)
 {
+#ifdef CONFIG_LATENCY_TRACE
+	if (!tv && ((int)tz == 1))
+		user_trace_start();
+	if (!tv && !tz)
+		user_trace_stop();
+#endif
 	if (likely(tv != NULL)) {
 		struct timeval ktv;
 		do_gettimeofday(&ktv);

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> Otherwise, this looks pretty good.  Here is a new one, I got this
> starting X:
> 
> http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-bk4-Q5#/var/www/2.6.9-rc1-bk4-Q5/trace2.txt

ok, MTRR setting overhead. It is not quite clear to me which precise
code took so much time, could you stick a couple of 'mcount();' lines
into arch/i386/kernel/cpu/mtrr/generic.c's prepare_set() and
generic_set_mtrr() functions? In particular the wbinvd() [cache
invalidation] instructions within prepare_set() look like a possible
source of latency.

(explicit calls to mcount() can be used to break up latency paths
manually - they wont affect the latency itself, they make the resulting
trace more finegrained.)

	Ingo

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> On Mon, 2004-08-30 at 05:06, Ingo Molnar wrote:
> > i've uploaded -Q5 to:
> > 
> >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5
> 
> This fixes the PS/2 issue.  Entropy rekeying is still a big problem:
> 
> http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-bk4-Q5#/var/www/2.6.9-rc1-bk4-Q5/trace3.txt

ok. It seems the random driver is _mostly_ in shape latency-wise, except
the IP rekeying visible in the above trace. To solve this problem, could
you try the patch below, ontop of -Q5? It moves the random seed
generation outside of the spinlock - AFAICS the spinlock is only needed
to protect the IP sequence counter itself.

	Ingo

--- linux/drivers/char/random.c.orig
+++ linux/drivers/char/random.c
@@ -2226,17 +2226,18 @@ static unsigned int ip_cnt;
 
 static void rekey_seq_generator(void *private_)
 {
-	struct keydata *keyptr;
+	struct keydata *keyptr, tmp;
 	struct timeval 	tv;
 
 	do_gettimeofday(&tv);
+	get_random_bytes(tmp.secret, sizeof(tmp.secret));
 
 	spin_lock_bh(&ip_lock);
 	keyptr = &ip_keydata[ip_cnt&1];
 
 	keyptr = &ip_keydata[1^(ip_cnt&1)];
 	keyptr->rekey_time = tv.tv_sec;
-	get_random_bytes(keyptr->secret, sizeof(keyptr->secret));
+	memcpy(keyptr->secret, tmp.secret, sizeof(keyptr->secret));
 	keyptr->count = (ip_cnt&COUNT_MASK)<<HASH_BITS;
 	mb();
 	ip_cnt++;

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Lee Revell]

On Mon, 2004-08-30 at 05:06, Ingo Molnar wrote:
> i've uploaded -Q5 to:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5

This fixes the PS/2 issue.  Entropy rekeying is still a big problem:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-bk4-Q5#/var/www/2.6.9-rc1-bk4-Q5/trace3.txt

Otherwise, this looks pretty good.  Here is a new one, I got this
starting X:

http://krustophenia.net/testresults.php?dataset=2.6.9-rc1-bk4-Q5#/var/www/2.6.9-rc1-bk4-Q5/trace2.txt

Lee    

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 728 bytes --]


* Mark_H_Johnson@raytheon.com <Mark_H_Johnson@raytheon.com> wrote:

> LONG NETWORK LATENCIES
> ======================
> 
> In about 25 minutes of heavy testing, I had two latency traces with
> /proc/sys/kernel/preempt_max_latency set to 700. They had the same start /
> end location with the long delay as follows:
>   730 us, entries: 361
>   ...
>   started at rtl8139_poll+0x3c/0x160
>   ended at   rtl8139_poll+0x100/0x160

regarding this particular latency, could you try the attached patch
ontop of -Q5? It turns the ->poll() loop into separate, individually
preemptable iterations instead of one batch of processing. In theory
this should result in latency being lower regardless of the
netdev_max_backlog value.

	Ingo

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

--- linux/net/core/dev.c.orig2	
+++ linux/net/core/dev.c	
@@ -1903,7 +1903,7 @@ static void net_rx_action(struct softirq
 {
 	struct softnet_data *queue = &__get_cpu_var(softnet_data);
 	unsigned long start_time = jiffies;
-	int budget = netdev_max_backlog;
+	int budget = netdev_max_backlog, loops;
 
 	
 	local_irq_disable();
@@ -1926,7 +1926,10 @@ static void net_rx_action(struct softirq
 		dev = list_entry(queue->poll_list.next,
 				 struct net_device, poll_list);
 
-		if (dev->quota <= 0 || dev->poll(dev, &budget)) {
+		loops = 1;
+		if (dev->quota <= 0 || dev->poll(dev, &loops)) {
+			if (loops < 1)
+				budget--;
 			local_irq_disable();
 			list_del(&dev->poll_list);
 			list_add_tail(&dev->poll_list, &queue->poll_list);

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Mark_H_Johnson]

>i've uploaded -Q5 to:
> [snip the rest...]

Thanks.

This appears to be the first 2.6.x kernel I've run that has results
comparable to 2.4.x kernels with low latency patches and kernel preemption.
The few remaining symptoms I see include:

 - a few long (> 1 msec) delays in the real time CPU loop (no system calls)
 - varying time to complete the write system call (for audio) - much
different than 2.4
 - a couple latency traces (> 700 usec) in the network driver

For reference, these tests were performed on the following SMP system:
  Dual 866 Mhz Pentium III
  512 Mbyte memory
  IDE system disk (DMA enabled)
The basic test is Benno's latency test
(http://www.gardena.net/benno/linux/audio) with some slight modifications
to the tests to keep the second CPU busy (non real time CPU burner) and to
add network I/O tests. The 2.4 tests were run with 2.4.20, the 2.6 tests
were run with 2.4.9-rc1-Q5. On 2.6, voluntary_preemption,
kernel_preemption, hardirq_preemption, and softirq_preemption are all 1. I
also set
  /sys/block/hda/queue/max_sectors_kb = 32
  /sys/block/hda/queue/read_ahead_kb = 32
  /proc/sys/net/core/netdev_max_backlog = 8
and the audio driver was set to be non-threaded.

BASIC RESULTS
=============
Comparison of results between 2.6.x and 2.4.x; values in milliseconds.
Nominal values for the write operation is 1.45 msec; the CPU loop is 1.16
msec.

          Max CPU Delta     Max Write Delta
Test     2.4.x     2.6.x    2.4.x     2.6.x
X11       0.10      0.16     0.05      0.65
/proc     0.07      0.17     0.05      0.65
net out   0.15      0.19     0.05      0.75
net in    0.17      0.23     0.05      0.95
dsk wrt   0.49      0.18     0.25      1.05
dsk copy  2.48      0.68     2.25      1.25
disk rd   3.03      1.61     2.75      1.35

LONG DELAYS
===========

Note I still see over 110% worst case overhead on a max priority real time
CPU task (no system calls) when doing heavy disk I/O on 2.6. It is much
better than 2.4, but still disturbing. What I would hope would happen on a
dual CPU system like mine, is that the real time task tends to be on one
CPU and the other system activity would tend to stay on the other CPU.
However, the results do not seem to indicate that behavior.

VARYING SYSTEM CALL TIMES
=========================

In 2.4, it appears that the duration of the write system call is basically
fixed and dependent on the duration of the audio fragment. In 2.6, this
behavior is now different. If I look at the chart in detail, it appears the
system is queueing up several write operations during the first few seconds
of testing. You can see this by consistently low elapsed times for the
write system call. Then the elapsed time for the write bounces up / down in
a sawtooth pattern over a 1 msec range. Could someone explain the cause of
this new behavior and if there is a setting to restore the old behavior? I
am concerned that this queueing adds latency to audio operations (when
trying to synchronize audio with other real time behavior).

LONG NETWORK LATENCIES
======================

In about 25 minutes of heavy testing, I had two latency traces with
/proc/sys/kernel/preempt_max_latency set to 700. They had the same start /
end location with the long delay as follows:
  730 us, entries: 361
  ...
  started at rtl8139_poll+0x3c/0x160
  ended at   rtl8139_poll+0x100/0x160
  00000001 0.000ms (+0.000ms): rtl8139_poll (net_rx_action)
  00000001 0.140ms (+0.140ms): rtl8139_rx (rtl8139_poll)
  00000001 0.556ms (+0.416ms): alloc_skb (rtl8139_rx)
  ... remaining items all > +0.005ms ...

  731 us, entries: 360
  ...
  started at rtl8139_poll+0x3c/0x160
  ended at   rtl8139_poll+0x100/0x160
  00000001 0.000ms (+0.000ms): rtl8139_poll (net_rx_action)
  00000001 0.000ms (+0.000ms): rtl8139_rx (rtl8139_poll)
  00000001 0.002ms (+0.001ms): alloc_skb (rtl8139_rx)
  00000001 0.141ms (+0.139ms): kmem_cache_alloc (alloc_skb)
  00000001 0.211ms (+0.070ms): __kmalloc (alloc_skb)
  00000001 0.496ms (+0.284ms): eth_type_trans (rtl8139_rx)
  00000001 0.565ms (+0.068ms): netif_receive_skb (rtl8139_rx)
  ... remaining items all > +0.005ms ...

Still much better than my previous results (before setting
netdev_max_backlog).

I will be running some additional tests
 - reducing preempt_max_latency
 - running with sortirq and hardirq_preemption=0
to see if these uncover any further problems.

Thanks again for the good work.
--Mark H Johnson
  <mailto:Mark_H_Johnson@raytheon.com>

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

[-- Attachment #1: Type: text/plain, Size: 1704 bytes --]


* Thomas Charbonnel <thomas@undata.org> wrote:

> Ingo Molnar wrote :
> > i've uploaded -Q5 to:
> > 
> >   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5
> > 
> 
> Here are the problematic spots for me with Q5:
> 
> rtl8139_poll (this one was also present with previous versions of the
> patch) :
> http://www.undata.org/~thomas/q5_rtl8139.trace

ok, rx processing latency again. You've set netdev_max_backlog to a low
value, right? I think we can break this particular loop independently of
netdev_max_backlog, could you try the attached patch ontop of -Q5, does
it help?

> =======>
> 00000001 0.000ms (+0.000ms): resolve_symbol (simplify_symbols)
> 00000001 0.000ms (+0.000ms): __find_symbol (resolve_symbol)
> 00000001 0.154ms (+0.154ms): use_module (resolve_symbol)
> 00000001 0.154ms (+0.000ms): sub_preempt_count (resolve_symbol)

seems resolve_symbol() is quite expensive ... no idea how to fix this
one right away, it seems to be pure algorithmic overhead.

> and a weird one with do_timer (called from do_IRQ) taking more than 1ms
> to complete :
> http://www.undata.org/~thomas/do_irq.trace

hm, indeed this is a weird one. 1 msec is too close to the timer 
frequency to be accidental. According to the trace:

 00010000 0.002ms (+0.000ms): timer_interrupt (generic_handle_IRQ_event)
 00010001 0.002ms (+0.000ms): mark_offset_tsc (timer_interrupt)
 00010001 1.028ms (+1.025ms): do_timer (timer_interrupt)
 00010001 1.028ms (+0.000ms): update_process_times (do_timer)

the latency happened between the beginning of mark_offset_tsc() and the
calling of do_timer() - i.e. the delay happened somewhere within
mark_offset_tsc() itself. Is this an SMP system?

	Ingo

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

--- linux/net/core/dev.c.orig2	
+++ linux/net/core/dev.c	
@@ -1903,7 +1903,7 @@ static void net_rx_action(struct softirq
 {
 	struct softnet_data *queue = &__get_cpu_var(softnet_data);
 	unsigned long start_time = jiffies;
-	int budget = netdev_max_backlog;
+	int budget = netdev_max_backlog, loops;
 
 	
 	local_irq_disable();
@@ -1926,7 +1926,10 @@ static void net_rx_action(struct softirq
 		dev = list_entry(queue->poll_list.next,
 				 struct net_device, poll_list);
 
-		if (dev->quota <= 0 || dev->poll(dev, &budget)) {
+		loops = 1;
+		if (dev->quota <= 0 || dev->poll(dev, &loops)) {
+			if (loops < 1)
+				budget--;
 			local_irq_disable();
 			list_del(&dev->poll_list);
 			list_add_tail(&dev->poll_list, &queue->poll_list);

Re: [patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Thomas Charbonnel]

Ingo Molnar wrote :
> i've uploaded -Q5 to:
> 
>   http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5
> 

Here are the problematic spots for me with Q5:

rtl8139_poll (this one was also present with previous versions of the
patch) :
http://www.undata.org/~thomas/q5_rtl8139.trace

use_module (modprobe) :
preemption latency trace v1.0.2
-------------------------------
 latency: 154 us, entries: 4 (4)
    -----------------
    | task: modprobe/8172, uid:0 nice:0 policy:0 rt_prio:0
    -----------------
 => started at: resolve_symbol+0x21/0xa0
 => ended at:   resolve_symbol+0x57/0xa0
=======>
00000001 0.000ms (+0.000ms): resolve_symbol (simplify_symbols)
00000001 0.000ms (+0.000ms): __find_symbol (resolve_symbol)
00000001 0.154ms (+0.154ms): use_module (resolve_symbol)
00000001 0.154ms (+0.000ms): sub_preempt_count (resolve_symbol)

and a weird one with do_timer (called from do_IRQ) taking more than 1ms
to complete :
http://www.undata.org/~thomas/do_irq.trace

Thomas

[patch] voluntary-preempt-2.6.9-rc1-bk4-Q5

[Ingo Molnar]

i've uploaded -Q5 to:

  http://redhat.com/~mingo/voluntary-preempt/voluntary-preempt-2.6.9-rc1-bk4-Q5

ontop of:

  http://redhat.com/~mingo/voluntary-preempt/diff-bk-040828-2.6.8.1.bz2

-Q5 should fix the PS2 problems and the early boot problems, and it
might even fix the USB, ACPI and APIC problems some people were
reporting.

There were a number of bugs that led to the PS2 problems:

 - a change to __cond_resched() in the -Q series caused the starvation
   of the IRQ1 and IRQ12 threads during init - causing a silent timeout
   and misdetection in the ps2 driver(s).

 - even with the starvation bug fixed, we must set system_state to
   SCHEDULER_OK only once the init thread has started - otherwise the
   idle thread might hang during bootup.

 - the redirected IRQ handling now matches that of non-redirected IRQs
   better, the outer loop in generic_handle_IRQ has been flattened.

i also re-added the synchronize_irq() fix, it was not causing the PS2
problems.

	Ingo