Very bad performance with PIC32

Question

I am encountering a problem with very bad performance in my PIC32 code. For example, I have this ISR which is servicing a few different interrupt sources:

volatile int rxEvents = 0;
volatile int txEvents   = 0;
volatile int int1Events = 0;
volatile int events     = 0;
volatile bool spi_read_flag  = 0;
volatile bool spi_write_flag = 0;
volatile bool spi_int_flag   = 0;
volatile bool adc_ready = 0;
void __attribute__((__interrupt__)) _DefaultInterrupt(){
    PIN(TIMER, LAT, LAT) = 1; // turn on an IO pin
    if(IFS0bits.T1IF){
        IFS0bits.T1IF = 0;
        AD1CON1bits.ASAM = 1; // begin sampling
    }
    if(IFS1bits.AD1IF){
        IFS1bits.AD1IF = 0;
        adc_ready = true;
    }

    ++events;
    if(IFS1bits.SPI2RXIF){
        ++rxEvents;
        IFS1bits.SPI2RXIF = 0;
        spi_read_flag = 1;
    }
    if(IFS1bits.SPI2TXIF){
        ++txEvents;
        IFS1bits.SPI2TXIF = 0;
        spi_write_flag = 1;
    }
    if(IFS0bits.INT1IF){
        ++int1Events;
        IFS0bits.INT1IF = 0;
        spi_int_flag = 1;
    }
    PIN(TIMER, LAT, LAT) = 0; // turn off the IO pin
}

As you can see, it is simply checking and clearing flag bits, and setting some boolean flags / performing some other simple actions.

When scoping the IO pin, I've found that in some cases this ISR can take up to 100us to complete, which at my clock rate of 8MHz would mean that it is requiring 800 instructions, which seems insane. A screenshot of the timing of the IO pin can be seen below.

My question is, what is causing this poor performance? Is there some clock setting I am missing? I have verified that the SPI clock is running at 500kHz, as expected with a prescale of 8, and a system clock of 8MHz. Below is the complete configuration I am using:

// DEVCFG3
// USERID = No Setting

// DEVCFG2
#pragma config FPLLIDIV = DIV_12        // PLL Input Divider (12x Divider)
#pragma config FPLLMUL = MUL_24         // PLL Multiplier (24x Multiplier)
#pragma config UPLLIDIV = DIV_12        // USB PLL Input Divider (12x Divider)
#pragma config UPLLEN = OFF             // USB PLL Enable (Disabled and Bypassed)
#pragma config FPLLODIV = DIV_256       // System PLL Output Clock Divider (PLL Divide by 256)

// DEVCFG1
#pragma config FNOSC = FRC              // Oscillator Selection Bits (Fast RC Osc (FRC))
#pragma config FSOSCEN = ON             // Secondary Oscillator Enable (Enabled)
#pragma config IESO = ON                // Internal/External Switch Over (Enabled)
#pragma config POSCMOD = OFF            // Primary Oscillator Configuration (Primary osc disabled)
#pragma config OSCIOFNC = ON            // CLKO Output Signal Active on the OSCO Pin (Enabled)
#pragma config FPBDIV = DIV_8           // Peripheral Clock Divisor (Pb_Clk is Sys_Clk/8)
#pragma config FCKSM = CSDCMD           // Clock Switching and Monitor Selection (Clock Switch Disable, FSCM Disabled)
#pragma config WDTPS = PS1048576        // Watchdog Timer Postscaler (1:1048576)
#pragma config FWDTEN = ON              // Watchdog Timer Enable (WDT Enabled)

// DEVCFG0
#pragma config DEBUG = OFF              // Background Debugger Enable (Debugger is disabled)
#pragma config ICESEL = ICS_PGx2        // ICE/ICD Comm Channel Select (ICE EMUC2/EMUD2 pins shared with PGC2/PGD2)
#pragma config PWP = OFF                // Program Flash Write Protect (Disable)
#pragma config BWP = OFF                // Boot Flash Write Protect bit (Protection Disabled)
#pragma config CP = OFF                 // Code Protect (Protection Disabled)

Here is the complete dissassembly, 121 instructions in all, I would think that that should mean a worst case execution time of about 15us, (unless I am missing some serious penalties related to memory access?):

17:                  void __attribute__((__interrupt__)) _DefaultInterrupt(){
9D003854  415DE800   RDPGPR SP, SP
9D003858  401B7000   MFC0 K1, EPC
9D00385C  401A6002   MFC0 K0, SRSCtl
9D003860  27BDFFE0   ADDIU SP, SP, -32
9D003864  AFBB001C   SW K1, 28(SP)
9D003868  401B6000   MFC0 K1, Status
9D00386C  AFBA0018   SW K0, 24(SP)
9D003870  401A6800   MFC0 K0, Cause
9D003874  AFBB0014   SW K1, 20(SP)
9D003878  001AD282   SRL K0, K0, 10
9D00387C  7F5B7A84   INS K1, K0, 10, 6
9D003880  7C1B2044   INS K1, ZERO, 1, 4
9D003884  409B6000   MTC0 K1, Status
9D003888  AFA30004   SW V1, 4(SP)
9D00388C  AFA20000   SW V0, 0(SP)
9D003890  8FA30018   LW V1, 24(SP)
9D003894  3063000F   ANDI V1, V1, 15
9D003898  14600003   BNE V1, ZERO, 0x9D0038A8
9D00389C  00000000   NOP
9D0038A0  AFBE000C   SW S8, 12(SP)
9D0038A4  AFA40008   SW A0, 8(SP)
9D0038A8  03A0F021   ADDU S8, SP, ZERO
18:                      PIN(TIMER, LAT, LAT) = 1; // indicate sampling started
9D0038AC  3C03BF88   LUI V1, -16504
9D0038B0  8C626160   LW V0, 24928(V1)
9D0038B4  24040001   ADDIU A0, ZERO, 1
9D0038B8  7C820844   INS V0, A0, 1, 1
9D0038BC  AC626160   SW V0, 24928(V1)
19:                      if(IFS0bits.T1IF){
9D0038C0  3C02BF88   LUI V0, -16504
9D0038C4  8C421030   LW V0, 4144(V0)
9D0038C8  30420010   ANDI V0, V0, 16
9D0038CC  1040000A   BEQ V0, ZERO, 0x9D0038F8
9D0038D0  00000000   NOP
20:                          IFS0bits.T1IF = 0;
9D0038D4  3C03BF88   LUI V1, -16504
9D0038D8  8C621030   LW V0, 4144(V1)
9D0038DC  7C022104   INS V0, ZERO, 4, 1
9D0038E0  AC621030   SW V0, 4144(V1)
21:                          AD1CON1bits.ASAM = 1; // begin sampling
9D0038E4  3C03BF81   LUI V1, -16511
9D0038E8  8C629000   LW V0, -28672(V1)
9D0038EC  24040001   ADDIU A0, ZERO, 1
9D0038F0  7C821084   INS V0, A0, 2, 1
9D0038F4  AC629000   SW V0, -28672(V1)
22:                      }
23:                      if(IFS1bits.AD1IF){
9D0038F8  3C02BF88   LUI V0, -16504
9D0038FC  8C421040   LW V0, 4160(V0)
9D003900  30420002   ANDI V0, V0, 2
9D003904  10400007   BEQ V0, ZERO, 0x9D003924
9D003908  00000000   NOP
24:                          IFS1bits.AD1IF = 0;
9D00390C  3C03BF88   LUI V1, -16504
9D003910  8C621040   LW V0, 4160(V1)
9D003914  7C020844   INS V0, ZERO, 1, 1
9D003918  AC621040   SW V0, 4160(V1)
25:                          adc_ready = true;
9D00391C  24020001   ADDIU V0, ZERO, 1
9D003920  A3828023   SB V0, -32733(GP)
26:                      }
27:                  
28:                      ++events;
9D003924  8F82801C   LW V0, -32740(GP)
9D003928  24420001   ADDIU V0, V0, 1
9D00392C  AF82801C   SW V0, -32740(GP)
29:                      if(IFS1bits.SPI2RXIF){
9D003930  3C02BF88   LUI V0, -16504
9D003934  8C421040   LW V0, 4160(V0)
9D003938  30420080   ANDI V0, V0, 128
9D00393C  1040000A   BEQ V0, ZERO, 0x9D003968
9D003940  00000000   NOP
30:                          ++rxEvents;
9D003944  8F828010   LW V0, -32752(GP)
9D003948  24420001   ADDIU V0, V0, 1
9D00394C  AF828010   SW V0, -32752(GP)
31:                          IFS1bits.SPI2RXIF = 0;
9D003950  3C03BF88   LUI V1, -16504
9D003954  8C621040   LW V0, 4160(V1)
9D003958  7C0239C4   INS V0, ZERO, 7, 1
9D00395C  AC621040   SW V0, 4160(V1)
32:                          spi_read_flag = 1;
9D003960  24020001   ADDIU V0, ZERO, 1
9D003964  A3828020   SB V0, -32736(GP)
33:                      }
34:                      if(IFS1bits.SPI2TXIF){
9D003968  3C02BF88   LUI V0, -16504
9D00396C  8C421040   LW V0, 4160(V0)
9D003970  30420040   ANDI V0, V0, 64
9D003974  1040000A   BEQ V0, ZERO, 0x9D0039A0
9D003978  00000000   NOP
35:                          ++txEvents;
9D00397C  8F828014   LW V0, -32748(GP)
9D003980  24420001   ADDIU V0, V0, 1
9D003984  AF828014   SW V0, -32748(GP)
36:                          IFS1bits.SPI2TXIF = 0;
9D003988  3C03BF88   LUI V1, -16504
9D00398C  8C621040   LW V0, 4160(V1)
9D003990  7C023184   INS V0, ZERO, 6, 1
9D003994  AC621040   SW V0, 4160(V1)
37:                          spi_write_flag = 1;
9D003998  24020001   ADDIU V0, ZERO, 1
9D00399C  A3828021   SB V0, -32735(GP)
38:                      }
39:                      if(IFS0bits.INT1IF){
9D0039A0  3C02BF88   LUI V0, -16504
9D0039A4  8C421030   LW V0, 4144(V0)
9D0039A8  30420080   ANDI V0, V0, 128
9D0039AC  1040000A   BEQ V0, ZERO, 0x9D0039D8
9D0039B0  00000000   NOP
40:                          ++int1Events;
9D0039B4  8F828018   LW V0, -32744(GP)
9D0039B8  24420001   ADDIU V0, V0, 1
9D0039BC  AF828018   SW V0, -32744(GP)
41:                          IFS0bits.INT1IF = 0;
9D0039C0  3C03BF88   LUI V1, -16504
9D0039C4  8C621030   LW V0, 4144(V1)
9D0039C8  7C0239C4   INS V0, ZERO, 7, 1
9D0039CC  AC621030   SW V0, 4144(V1)
42:                          spi_int_flag = 1;
9D0039D0  24020001   ADDIU V0, ZERO, 1
9D0039D4  A3828022   SB V0, -32734(GP)
43:                      }
44:                      PIN(TIMER, LAT, LAT) = 0; // indicate sampling started
9D0039D8  3C03BF88   LUI V1, -16504
9D0039DC  8C626160   LW V0, 24928(V1)
9D0039E0  7C020844   INS V0, ZERO, 1, 1
9D0039E4  AC626160   SW V0, 24928(V1)
45:                  }
9D0039E8  03C0E821   ADDU SP, S8, ZERO
9D0039EC  8FA20018   LW V0, 24(SP)
9D0039F0  3042000F   ANDI V0, V0, 15
9D0039F4  14400005   BNE V0, ZERO, 0x9D003A0C
9D0039F8  00000000   NOP
9D0039FC  8FBE000C   LW S8, 12(SP)
9D003A00  8FA40008   LW A0, 8(SP)
9D003A04  8FA30004   LW V1, 4(SP)
9D003A08  8FA20000   LW V0, 0(SP)
9D003A0C  41606000   DI ZERO
9D003A10  000000C0   EHB
9D003A14  8FBA001C   LW K0, 28(SP)
9D003A18  8FBB0014   LW K1, 20(SP)
9D003A1C  409A7000   MTC0 K0, EPC
9D003A20  8FBA0018   LW K0, 24(SP)
9D003A24  27BD0020   ADDIU SP, SP, 32
9D003A28  409A6002   MTC0 K0, SRSCtl
9D003A2C  41DDE800   WRPGPR SP, SP
9D003A30  409B6000   MTC0 K1, Status
9D003A34  42000018   ERET

Full command line is here (paths shortened, but otherwise unmodified)

"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF blep_asynch.o.d -o blep_asynch.o blep_asynch.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF interrupt.o.d -o interrupt.o interrupt.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF data_handler.o.d -o data_handler.o data_handler.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF timer.o.d -o timer.o timer.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF acilib.o.d -o acilib.o acilib.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF adc.o.d -o adc.o adc.c 
"...\xc32-gcc.exe" -g -x c -c -mprocessor=32MX440F256H -MMD -MF blep.o.d -o blep.o blep.c 
"...\xc32-gcc.exe"   -mprocessor=32MX440F256H  -o project.production.elf main.o bit_order.o acilib.o blep.o adc.o timer.o interrupt.o blep_asynch.o aci_asynch.o data_handler.o          -Wl,--defsym=__MPLAB_BUILD=1,--defsym=_min_heap_size=128,-Map="project.production.map"

Answer 1

The PIC32 default configuration is bad with regard to performance. One of the stickies on the PIC32 forum on microchip's website address this:

When you start up PIC32 regardless of the oscillator fuse settings that you have specified it starts with

NO Caching turned on

NO Prefetch buffer enabled

7 FLASH wait states

1 SRAM wait states

All of these items will affect the performance of your code and cause it to run significantly slower than you would expect. So as a rule put in the very first line of your main function the following:

SYSTEMConfigPerformance(80000000); 

where the number in brackets is your chosen final instruction clock rate. This function will correctly set up the performance features of the PIC32 with the correct number of FLASH and RAM wait states for the chosen speed and will also enable caching and prefetch. Set this up first and see what speed you get. You should find it much faster. You will then need to tinker with the compiler optimization settings to improve the performance some more.

Try running the config performance routine and see if it helps.

Answer 2

This isn't an answer, bug a debug path. The PIC32's have quite a number of clock options, and IIRC, if the ones you ask for are causing issues, the clocks will do their best to find a way that works.

Step one for me in cases like this is to verify my system clocks by getting rid of all my code other than simple configs, programming in a dirt simple timer interrupt that does nothing but toggle a bit, and make sure what I see makes sense. If it does, then I start adding code, and if it doesn't my problem is usually identified.

Personally, I do something like this whenever I start a project, usually before problems start happening. It's a good habit to get into.

Answer 3

Your FPLLIDIV seems to be way too high. The documentation states that the PLL Input should be between 4 and 5 MHz. With the 8 MHz RC clock, the FPLLIDIV should be 2.

With an input divider of 12, pll multiplier of 24 and an output divider of 256 you get a total divider of 128 - your final clock rate seems to be 8 MHz DIV 128.

And you add also a peripheral divider of 8 - your PIN clock rate seems to be 8 kHz.

This are my settings with the internal fast RC Oscillator. I'm not sure if all items are set to the best value. But it works reasonable:

#pragma config FPLLIDIV = DIV_2         // PLL Input Divider (2x Divider)
#pragma config FPLLMUL = MUL_16         // PLL Multiplier (20x Multiplier)
#pragma config FPLLODIV = DIV_1         // System PLL Output Clock Divider (PLL Divide by 1)
#pragma config FWDTEN = OFF

#pragma config FNOSC = FRCPLL           // Oscillator Selection Bits (Fast RC Osc with PLL)
#pragma config FSOSCEN = OFF            // Secondary Oscillator Enable (Disabled)
#pragma config IESO = OFF               // Internal/External Switch Over (Disabled)
#pragma config POSCMOD = OFF            // Primary Oscillator Configuration (Primary osc disabled)
#pragma config OSCIOFNC = OFF           // CLKO Output Signal Active on the OSCO Pin (Disabled)
#pragma config FPBDIV = DIV_1           // Peripheral Clock Divisor (Pb_Clk is Sys_Clk/1)
#pragma config FCKSM = CSDCMD           // Clock Switching and Monitor Selection (Clock Switch Disable, FSCM Disabled)