Re: [Bug #12650] Strange load average and ksoftirqd behavior with 2.6.29-rc2-git1

Paul E. McKenney
2009-02-16T16:06:25Z

On Mon, Feb 16, 2009 at 02:21:51PM +0100, Ingo Molnar wrote:
>
> * Damien Wyart <damien.wyart@free.fr> wrote:
>
> > * Ingo Molnar <mingo@elte.hu> [090216 13:26]:
> > > We do get 0x100 which is 1 << RCU_SOFTIRQ, i.e. the RCU softirq. Paul,
> > > this indeed seems to be a CONFIG_TREE_RCU=y bug.
> >
> > > What is weird is that RCU_SOFTIRQ gets set again and again - but there's
> > > no raise_softirq() calls. Could you please do a two-CPU trace too via:
> >
> > > echo 3 > /debug/tracing/tracing_cpumask
> >
> > > So that we can see what's happening on the other CPU?
> >
> > > Also, could you please apply the debug patch below (or update to the
> > > very latest -tip tree), so that we get trace entries of softirq triggers
> > > too?
> >
> > Ok, the new trace with these additional modifications is here:
> > http://damien.wyart.free.fr/ksoftirqd_pb/trace_tip_2009.02.16_1300_ksoftirqd_pb_abstime_proc_mask3.txt.gz
>
> thanks.
>
> This confirms that SOFTIRQ_RCU gets raised here in the timer IRQ:
>
> 136.255963 | 0) sleep-2345 | | update_process_times() {
> 136.255964 | 0) sleep-2345 | | account_process_tick() {
> 136.255965 | 0) sleep-2345 | 0.779 us | account_system_time();
> 136.255966 | 0) sleep-2345 | 2.262 us | }
> 136.255967 | 0) sleep-2345 | | run_local_timers() {
> 136.255968 | 0) sleep-2345 | 0.802 us | hrtimer_run_queues();
> 136.255969 | 0) sleep-2345 | | raise_softirq() {
> 136.255970 | 0) sleep-2345 | | raise_softirq_irqoff() {
> 136.255971 | 0) sleep-2345 | | __raise_softirq_irqoff() {
> 136.255972 | 0) sleep-2345 | | /* nr: 1 */
> 136.255973 | 0) sleep-2345 | 2.194 us | }
> 136.255974 | 0) sleep-2345 | 3.832 us | }
> 136.255975 | 0) sleep-2345 | 5.491 us | }
> 136.255976 | 0) sleep-2345 | 8.667 us | }
> 136.255976 | 0) sleep-2345 | 0.792 us | rcu_pending();
> 136.255978 | 0) sleep-2345 | | rcu_check_callbacks() {
> 136.255979 | 0) sleep-2345 | 0.781 us | idle_cpu();
> 136.255981 | 0) sleep-2345 | | raise_softirq() {
> 136.255981 | 0) sleep-2345 | | raise_softirq_irqoff() {
> 136.255982 | 0) sleep-2345 | | __raise_softirq_irqoff() {
> 136.255983 | 0) sleep-2345 | | /* nr: 8 */
> 136.255984 | 0) sleep-2345 | 1.555 us | }
> 136.255984 | 0) sleep-2345 | 3.059 us | }
> 136.255985 | 0) sleep-2345 | 4.594 us | }
> 136.255986 | 0) sleep-2345 | 7.800 us | }
> 136.255987 | 0) sleep-2345 | 0.737 us | printk_tick();
>
> again and again.

Interesting...

I will take a look!

Thanx, Paul