SV#8, when sleeping in main and interrupt happens when in idle Topic is solved

[faisal]

I'm getting the Halt with SV#8 . I know this is typically caused by IRQs with priorities <=2 . I've reviewed the interrupt priorities, and they are all > 2 for the ones I am using (Vector15C is 10 for example). As a side note, I wonder why don't we set all interrupt priorities in ChibiOS/HAL to 15 on initialization. Because at reset, they are all 0 (highest priority).

So, here's what is going on. From main(), I issue a wspiCommand. The main() thread duly goes to sleep, as it calls osalThreadSuspendS - waiting for the interrupt to occur and wake it up. Great. So, main thread goes to sleep and switches to the IDLE thread. A context switch occurs, and soon after the interrupt happens and I get a Halt with SV#8 (ch.dbg.lock_cnt != 0).

1. ch.dbg.lock_cnt is 1 when the main() thread goes to sleep by calling osalThreadSuspendS(). I created a trace event here - see USER wspicmd below.
2. A context switch occurs to the IDLE thread
3. Vector15C (STM32_QUADSPI1_HANDLER) interrupt occurs
4. Halt SV#8

I captured a trace of what's going on:

Code: Select all

0,t=21,dt=0,rt=3705723  HALT {reason = 0x801c33c "SV#8"}
1,t=21,dt=0,rt=3705616  ISR_ENTER {name = 0x801b958 <__func__.10306.lto_priv.678> "Vector15C"}
2,t=21,dt=0,rt=3705269  SWITCH in = idle, out_state = 3, wtobjp = (void *) 0x20005f38 <WSPID1+8>
3,t=21,dt=0,rt=3705051  USER wspicmd,1

I knew it would reach the halt condition soon after the osalThreadSuspendS() in wspiCommand, so I placed a breakpoint there. I also added a watchpoint on ch.dbg.lock_cnt, and a breakpoint in the idle thread.

Code: Select all

(gdb) info breakpoints
Num     Type           Disp Enb Address    What
1       breakpoint     keep y   0x080099aa in wspiCommand at ../../ChibiOS_20.x.x/os/hal/osal/rt-nil/osal.h:735
2       hw watchpoint  keep y              ch.dbg.lock_cnt
3       breakpoint     keep y   0x080018c0 in _idle_thread.lto_priv.362 at ../../ChibiOS_20.x.x/os/rt/src/chsys.c:73

As you can see below, it went straight from the osalThreadSuspendS() in wspiCommand() to the Halt without hitting the watchpoint or landing in the idle thread.

Code: Select all

(gdb) where
#0  wspiCommand (wspip=0x20005f30 <WSPID1>, cmdp=cmdp@entry=0x801c460 <cmd_reset_enable_4>) at ../../ChibiOS_20.x.x/os/hal/src/hal_wspi.c:235

(gdb) c   
Continuing.

Thread 1 received signal SIGINT, Interrupt.
[Switching to Thread 536900256]
0x080039a0 in chSysHalt (reason=reason@entry=0x801c33c "SV#8") at ../../ChibiOS_20.x.x/os/rt/src/chsys.c:199

All this is happening upon bootup, while I'm initializing a bunch of stuff. I'm probably missing something, but I fail to see where ch.dbg.lock_cnt is decremented back to 0? Other interrupts occur in my system (8 or so UART interrupts while printing out string), but they didn't trigger this problem - but that's probably because it was always in the main thread and never got to switch to the IDLE thread for those interrupts. That's a difference.

Help!

[Giovanni]

Hi,

Probably this is the effect of something else. Could you check for stack overflows?

This could also be the effect of erroneous use of the scheduler API, do you use any of those directly?

Giovanni

[faisal]

Hi,

Probably this is the effect of something else. Could you check for stack overflows?

I've been looking, haven't found any evidence of that yet. Will report back after I'm more confident it's not a stack overflow.

Can you explain what is supposed to be happening to ch.dbg.lock_cnt in this situation - because it is that which is causing the assertion. In main it calls chsyslock and then suspends itself. This results in ch.dbg.lock_cnt being set to 1. Apparently there is a context switch initiated to the idle thread (without actually completing fully? Because the breakpoint in the idle thread is never hit...), And then and interrupt occurs where it checks for ch.dbg.lock_cnt in the prologue. I'm assuming somewhere in this process it should be set to 0 - but where?

This could also be the effect of erroneous use of the scheduler API, do you use any of those directly?
Giovanni

Will check and report back.

Thanks!

[Giovanni]

Hi,

My idea is that it fails a context switch because an overflow and it switches-in somewhere non handling dbg as expected, this is why you see SV#8 but the reason is another (a ready list corruption could cause a similar effect).

If you are compiling using -O0 then try -O2, it uses much less stack, see if the result is the same or if it works (or perhaps a different kind of error).

Giovanni

[faisal]

I'm using O2 with LTO. Will try some other combinations .. as well as play around with stack sizes. At this point where the problem is occurring only main() is running. Other threads are created in a suspended state and haven't been run yet.

Can you explain what is supposed to be happening to ch.dbg.lock_cnt in this situation - between going into S-lock state in main thread, suspending, and then switching to idle thread.

[faisal]

Another clue. I disabled the WSPI interrupt (by commenting out where it enables it in wspi_lld_init(), and it reaches the breakpoint in the idle thread. ch.dbg.lock_cnt is still 1 there. If the context switch happened correctly, it should be 0 - correct?

Code: Select all

(gdb) bt
#0  _idle_thread.lto_priv.364 (p=0x0) at ../../ChibiOS_20.x.x/os/rt/src/chsys.c:73
#1  0x0800030e in _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:202
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) print ch.dbg.lock_cnt
$4 = 1
(gdb) source ../../utils/debugger_scripts/chtrace
0,t=18,dt=0,rt=11614898  SWITCH in = idle, out_state = 3, wtobjp = (void *) 0x20005f38 <WSPID1+8>
1,t=18,dt=0,rt=11614667  USER wspicmd,1
2,t=10,dt=8,rt=11553556  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
3,t=10,dt=0,rt=11553019  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
4,t=10,dt=0,rt=11550329  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
5,t=10,dt=0,rt=11549796  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
6,t=9,dt=1,rt=11547107  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
7,t=9,dt=0,rt=11546600  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
8,t=9,dt=0,rt=11543945  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
9,t=9,dt=0,rt=11543418  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
10,t=9,dt=0,rt=11540869  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
11,t=9,dt=0,rt=11540345  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
12,t=8,dt=1,rt=11537560  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
13,t=8,dt=0,rt=11537019  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
14,t=8,dt=0,rt=11534489  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
15,t=8,dt=0,rt=11533962  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
16,t=8,dt=0,rt=11532747  ISR_LEAVE {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
17,t=8,dt=0,rt=11532220  ISR_ENTER {name = 0x801ba18 <__func__.10367.lto_priv.664> "VectorD4"}
(gdb) info threads
  Id   Target Id         Frame
  1    Thread 536899736 (Name: main, State: SUSPENDED) chSchGoSleepTimeoutS (newstate=newstate@entry=3 '\003', timeout=4294967295) at ../../ChibiOS_20.x.x/os/rt/src/chschd.c:393
* 2    Thread 536900256 (Name: idle, State: CURRENT) _idle_thread.lto_priv.364 (p=0x0) at ../../ChibiOS_20.x.x/os/rt/src/chsys.c:73
  3    Thread 537197824 (Name: sensored1, State: WTSTART) _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:193
  4    Thread 537196432 (Name: sensored2, State: WTSTART) _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:193
  5    Thread 537195552 (Name: sensored3, State: WTSTART) _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:193
  6    Thread 537193912 (Name: sensored4, State: WTSTART) _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:193
  7    Thread 537192520 (Name: sensored5, State: WTSTART) _port_thread_start () at ../../ChibiOS_20.x.x/os/common/ports/ARMCMx/compilers/GCC/chcoreasm_v7m.S:193


[Giovanni]

Hi,

Yes, it should be zero when outside a critical section and the idle thread is definitely not in a critical section.

The question is: how does it get there without going through a chSysUnlock() ?

Giovanni

[Giovanni]

Do you have critical sections with I-class or S-class functions called inside?

Giovanni

[faisal]

Since the IDLE thread never got a chance to start, it jumped to _port_thread_start (for the IDLE thread) after the context switch from the main thread. There, it should call _dbg_check_unlock. However ...

In my makefile I use the following to override the #define in chconf.h:
UDEFS += -DCH_DBG_SYSTEM_STATE_CHECK=TRUE

But I didn't add the same symbol to UADEFS !!! Calls are made to dbg_check_unlock and the such in the chcoreasm_v7m.S - and naturally it checks if that symbol is defined.

Calamity averted. PBKAC (Problem Between Keyboard And Chair) .

[Giovanni]

It had to be something like this, definitions are required for both .c and .S files.

Giovanni