2.5.13 IDE and preemptible kernel problems

2.5.13 IDE and preemptible kernel problems

[Andi Kleen]

Hi,

When booting an preemptible kernel 2.5.13 kernel on x86-64 I get 
very quickly an scheduling in interrupt BUG. It looks like the 
preempt_count becomes 0 inside the ATA interrupt handler. This 
could happen when save_flags/restore_flags and friends are unmatched
and you have too many flags restores in IDE. 

-Andi


No ksyms, skipping lsmod
Kernel BUG at sched.c:759
invalid operand: 0000
CPU 0 
Pid: 0, comm: swapper Not tainted
RIP: 0010:[<ffffffff80118643>]
Using defaults from ksymoops -t elf64-x86-64 -a i386:x86-64
RSP: ffffffff803688d8  EFLAGS: 00010002
RAX: 0000000000000001 RBX: ffffffff8036dfd8 RCX: 0000000000000000
RDX: 0000000000000000 RSI: ffffffff80368a78 RDI: 0000000000000000
RBP: ffffffff80368908 R08: 000001000197fe98 R09: 000000000000000e
R10: 00000000ffffffff R11: 000000000000000a R12: ffffffff8022c6b0
R13: ffffffff80357590 R14: ffffffff8036df08 R15: 0000000000000000
FS:  0000000000000000(0000) GS:ffffffff803649c0(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 0000000000101000 CR4: 00000000000006a0
Process swapper (pid: 0, stackpage=ffffffff802ece80)
Stack: ffffffff803688d8 0000000000000000 000001000197fd48 000001000197fd90 
       000001000197fd48 ffffffff80368918 ffffffff8036dfd8 ffffffff8022c6b0 
       ffffffff80357590 ffffffff80368928 
Call Trace: [<ffffffff8022c6b0>] [<ffffffff80118a9e>] [<ffffffff8022dc58>] 
       [<ffffffff8022c709>] [<ffffffff8022f0d4>] [<ffffffff80110fef>] 
       [<ffffffff80111255>] [<ffffffff8010ce60>] [<ffffffff8010ce60>] 
       [<ffffffff8010f44e>]  <EOI> [<ffffffff8010ce60>] [<ffffffff8010ce60>] 
       [<ffffffff8010f580>] [<ffffffff8010ce85>] [<ffffffff8010cf1f>] 
Code: 0f 0b 80 56 2a 80 ff ff ff ff f7 02 90 65 48 8b 04 25 08 00 


>>RIP; ffffffff80118643 <schedule+23/450>   <=====

>>RBX; ffffffff8036dfd8 <init_thread_union+1fd8/4000>
>>RSI; ffffffff80368a78 <runqueues+38/1240>
>>RBP; ffffffff80368908 <boot_cpu_stack+3ec8/4000>
>>R08; 000001000197fe98 Before first symbol
>>R10; 00000000ffffffff Before first symbol
>>R12; ffffffff8022c6b0 <task_no_data_intr+0/60>
>>R13; ffffffff80357590 <ide_hwifs+150/5690>
>>R14; ffffffff8036df08 <init_thread_union+1f08/4000>

Trace; ffffffff8022c6b0 <task_no_data_intr+0/60>
Trace; ffffffff80118a9e <preempt_schedule+2e/40>
Trace; ffffffff8022dc58 <ide_end_drive_cmd+1d8/1f0>
Trace; ffffffff8022c709 <task_no_data_intr+59/60>
Trace; ffffffff8022f0d4 <ata_irq_request+f4/190>
Trace; ffffffff80110fef <handle_IRQ_event+3f/80>
Trace; ffffffff80111255 <do_IRQ+c5/160>
Trace; ffffffff8010ce60 <default_idle+0/30>
Trace; ffffffff8010ce60 <default_idle+0/30>
Trace; ffffffff8010f44e <ret_from_intr+0/f>
Trace; ffffffff8010f580 <retint_kernel+38/50>
Trace; ffffffff8010ce85 <default_idle+25/30>
Trace; ffffffff8010cf1f <cpu_idle+1f/40>

Code;  ffffffff80118643 <schedule+23/450>
0000000000000000 <_RIP>:
Code;  ffffffff80118643 <schedule+23/450>   <=====
   0:   0f 0b                     ud2a      <=====
Code;  ffffffff80118645 <schedule+25/450>
   2:   80 56 2a 80               adcb   $0x80,0x2a(%rsi)
Code;  ffffffff80118649 <schedule+29/450>
   6:   ff                        (bad)  
Code;  ffffffff8011864a <schedule+2a/450>
   7:   ff                        (bad)  
Code;  ffffffff8011864b <schedule+2b/450>
   8:   ff                        (bad)  
Code;  ffffffff8011864c <schedule+2c/450>
   9:   ff f7                     pushq  %edi
Code;  ffffffff8011864e <schedule+2e/450>
   b:   02 90 65 48 8b 04         add    0x48b4865(%rax),%dl
Code;  ffffffff80118654 <schedule+34/450>
  11:   25 08 00 00 00            and    $0x8,%eax

 <0>Kernel panic: Aiee, killing interrupt handler!

Re: 2.5.13 IDE and preemptible kernel problems

[Martin Dalecki]

Uz.ytkownik Andi Kleen napisa?:
> Hi,
> 
> When booting an preemptible kernel 2.5.13 kernel on x86-64 I get 
> very quickly an scheduling in interrupt BUG. It looks like the 
> preempt_count becomes 0 inside the ATA interrupt handler. This 
> could happen when save_flags/restore_flags and friends are unmatched
> and you have too many flags restores in IDE. 

Thank you for pointing out. I will re check it.

Re: 2.5.13 IDE and preemptible kernel problems

[Linus Torvalds]

On Fri, 3 May 2002, Martin Dalecki wrote:

> Uz.ytkownik Andi Kleen napisa?:
> > Hi,
> >
> > When booting an preemptible kernel 2.5.13 kernel on x86-64 I get
> > very quickly an scheduling in interrupt BUG. It looks like the
> > preempt_count becomes 0 inside the ATA interrupt handler. This
> > could happen when save_flags/restore_flags and friends are unmatched
> > and you have too many flags restores in IDE.
>
> Thank you for pointing out. I will re check it.

Martin, may I suggest that the next line of cleanups should be to remove
all vestiges of the old global interrupt locking from the IDE driver?
Including, for example, the crap "PCI method 1" access stuff in CMD640x..

Also, if you turn on spinlock debugging, that tends to help find the
really silly things faster (leaving the harder races to be solved by
brainforce ;)

		Linus

Re: 2.5.13 IDE and preemptible kernel problems

[Martin Dalecki]

Uz.ytkownik Linus Torvalds napisa?:
> 
> On Fri, 3 May 2002, Martin Dalecki wrote:
> 
> 
>>Uz.ytkownik Andi Kleen napisa?:
>>
>>>Hi,
>>>
>>>When booting an preemptible kernel 2.5.13 kernel on x86-64 I get
>>>very quickly an scheduling in interrupt BUG. It looks like the
>>>preempt_count becomes 0 inside the ATA interrupt handler. This
>>>could happen when save_flags/restore_flags and friends are unmatched
>>>and you have too many flags restores in IDE.
>>
>>Thank you for pointing out. I will re check it.
> 
> 
> Martin, may I suggest that the next line of cleanups should be to remove
> all vestiges of the old global interrupt locking from the IDE driver?

Right agreed. I forgot that this is just presumably a "workaround
for borken hardware", which in fact is a long standing workarodund
for driver reentrancy problems.

> Including, for example, the crap "PCI method 1" access stuff in CMD640x..

Naj... I could try.

> Also, if you turn on spinlock debugging, that tends to help find the
> really silly things faster (leaving the harder races to be solved by
> brainforce ;)

Indeed... thank you for this hint.

Re: 2.5.13 IDE and preemptible kernel problems

[Martin Dalecki]

Użytkownik Linus Torvalds napisał:
> 
> On Fri, 3 May 2002, Martin Dalecki wrote:
> 
> 
>>Uz.ytkownik Andi Kleen napisa?:
>>
>>>Hi,
>>>
>>>When booting an preemptible kernel 2.5.13 kernel on x86-64 I get
>>>very quickly an scheduling in interrupt BUG. It looks like the
>>>preempt_count becomes 0 inside the ATA interrupt handler. This
>>>could happen when save_flags/restore_flags and friends are unmatched
>>>and you have too many flags restores in IDE.
>>
>>Thank you for pointing out. I will re check it.
> 
> 
> Martin, may I suggest that the next line of cleanups should be to remove
> all vestiges of the old global interrupt locking from the IDE driver?
> Including, for example, the crap "PCI method 1" access stuff in CMD640x..
> 
> Also, if you turn on spinlock debugging, that tends to help find the
> really silly things faster (leaving the harder races to be solved by
> brainforce ;)


OK, lest's make a deal you do the following and - realize
immediately that there is a need for single argument
time_past() or whatever and I turn spinlock debugging on :-).

[root@kozaczek linux]# find ./ -name "*.[ch]" -exec grep time_after /dev/null {} 
\; | wc
     265    1638   21285
[root@kozaczek linux]# find ./ -name "*.[ch]" -exec grep time_after /dev/null {} 
\; | grep jiffies | wc
     239    1497   19080
[root@kozaczek linux]#

Re: 2.5.13 IDE and preemptible kernel problems

[Linus Torvalds]

On Sun, 5 May 2002, Martin Dalecki wrote:
>
> OK, lest's make a deal you do the following and - realize
> immediately that there is a need for single argument
> time_past() or whatever and I turn spinlock debugging on :-).

Hmm.. Something like

	#define timeout_expired(x)	time_after(jiffies, (x))

migth indeed make sense.

But I'm a lazy bastard. Is there some victim^H^H^H^H^H^Hhero who would
want to do the 'sed s/time_after(jiffies,/timeout_expired(/g' and verify
that it does the right thing and send it to me as a patch?

The thing is, I wonder if it should be "time_after(jiffies,x)" or
"time_after_eq(jiffies,x)". There's a single-tick difference there..

		Linus

Re: 2.5.13 IDE and preemptible kernel problems

[Tim Schmielau]

On Sat, 4 May 2002, Linus Torvalds wrote:

> Hmm.. Something like
> 
> 	#define timeout_expired(x)	time_after(jiffies, (x))
> 
> migth indeed make sense.
> 
> But I'm a lazy bastard. Is there some victim^H^H^H^H^H^Hhero who would
> want to do the 'sed s/time_after(jiffies,/timeout_expired(/g' and verify
> that it does the right thing and send it to me as a patch?
> 
> The thing is, I wonder if it should be "time_after(jiffies,x)" or
> "time_after_eq(jiffies,x)". There's a single-tick difference there..
> 

If you allow a lazy victim to throw in some statistics first:  ;-)

299 potential users preferring time_after_eq, and 160 voting for 
time_after (assuming use of !timeout_expired(x), too):

linux-2.5.13> find ./ -name "*.[ch]" -exec grep "time_before(*jiffies"
 /dev/null {} \; | wc -l
    248
linux-2.5.13> find ./ -name "*.[ch]" -exec grep "time_before_eq( *jiffies" 
 /dev/null {} \; | wc -l
     20
linux-2.5.13> find ./ -name "*.[ch]" -exec grep "time_after( *jiffies" 
 /dev/null {} \; | wc -l
    140
linux-2.5.13> find ./ -name "*.[ch]" -exec grep "time_after_eq( *jiffies" 
 /dev/null {} \; | wc -l
     51

That probably means we need both, as something like 
timeout_expired(x+1) seems to call for new "off by one" errors.


Tim

Re: 2.5.13 IDE and preemptible kernel problems

[Martin Dalecki]

Uz.ytkownik John Weber napisa?:
> Tim Schmielau wrote:
> 
>> On Sat, 4 May 2002, Linus Torvalds wrote:
>>
>>
>>> Hmm.. Something like
>>>
>>>     #define timeout_expired(x)    time_after(jiffies, (x))
>>>
>>> migth indeed make sense.
>>>
>>> But I'm a lazy bastard. Is there some victim^H^H^H^H^H^Hhero who would
>>> want to do the 'sed s/time_after(jiffies,/timeout_expired(/g' and verify
>>> that it does the right thing and send it to me as a patch?
>>>
>>> The thing is, I wonder if it should be "time_after(jiffies,x)" or
>>> "time_after_eq(jiffies,x)". There's a single-tick difference there..
>>>
>> That probably means we need both, as something like 
>> timeout_expired(x+1) seems to call for new "off by one" errors.
> 
> 
> Here's a patch with the s/time_after(jiffies,/timeout_expired(/g and 
> s/time_after_eq(jiffies,/timeout_expired(/g

Yeep. And now please take the next step and grep for "jiffies + 1"

to realize that a timeout primitive along the following

take_a_nap(temeout_function, timeout_data);

would help simpify the usage of timers and speed up the kernel
due to cache locality for stuff which is added to the global
timer list just for doing short micro-polls and beeing taken
out ther on the next scheduler round. In esp. nearly every
single eth driver out there shows precisely what I mean.

Becouse most of the timers get only added for one jiffie!

Re: 2.5.13 IDE and preemptible kernel problems

[Alan Cox]

> > immediately that there is a need for single argument
> > time_past() or whatever and I turn spinlock debugging on :-).
> 
> Hmm.. Something like
> 	#define timeout_expired(x)	time_after(jiffies, (x))
> 
> migth indeed make sense.

That would be good because in the longer term the elimination of random
references to jiffies is pretty essential to low power devices and for 
things like S/390 scaling.

Alan