Arduino-esp32: [ESP32] I2C Interrupt problem since uprade to Espressif 1.1.0

[cyberman54]

I'm using u8x8 on ESP32 boards, programmed with Arduino Espressif32 core.
I2C display handling using driver U8X8_SSD1306_128X64_NONAME_HW_I2C

This worked perfectly until last days the Espressif32 core was updated from v1.0.2 to v1.1.0.

Since then i get this error during runtime:
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0

And the display write speed is significantly reduced.

I'm not sure if this is a problem with u8x8 or the Espressif32 core. I'm not using any other I2C communication on the board.

Cross reference to u8x8:
https://github.com/olikraus/u8g2/issues/646#issuecomment-402372457

[cyberman54]

Wrong assignment, re-opened this issue at
https://github.com/platformio/platform-espressif32/issues/107

[cyberman54]

Platformio owner pointed me back to here, so i reopen this issue here.

[stickbreaker]

@cyberman54 I just answered your issue on the platformio repo 107
updating to the newest core will solve most of that error message. The 'injection' error has only been caused by overlapping multi-task use of Wire() review your code to verify that all access to Wire() are single-threaded.

Chuck.

[cyberman54]

@stickbreaker Problem with the confusing debug messages is now solved, thanks to your pull request.
But it still have the problem with the interrupt injections with Espressif32 core 1.1.x, while the same code on the same device runs with Espressif32 core 1.0.2 without this problem.

[stickbreaker]

@cyberman54 the injection error is showing that the ISR was call, but the control structure was not configured for operation, there is a stage variable that has three possible values, STARTUP, RUNNING, and DONE. as you can see by the debug message, it's value was DONE. so the ISR should not have be triggered. Stage is set to done in three places of my code.

• first During ISR init(i2cProcQueue)
• second when the i2c transaction queue has completed (i2cExit)
• Third If the i2c transaction exceed the configured Timeout, (i2cProcQueue)
  Either a Bus Busy error
  Or a Gross Timeout error

Of these three sections of code, the first one was the source I traced down when Wire() was call by multiple tasks in a 'Ardunio' as Component under IDF, the MUTEX was disabled when Arduino is used as a component.

I cannot imagine how the second could result in an injection event. (it happens during interrupt context)

The Third could only happen if the timeout expired, the foreground task started cleaning up the timeout, but before it output the log messages of the failure (Gross timeout, Bus Busy) an i2c interrupt triggered. I cannot see this happening: here is the code. The interrupt would have to trigger before int_ena.val=0 but after stage=I2C_DONE. Well, It couldn't because it would have had to trigger after the int_ena.val=0 for 0x00 to be shown in the debug message. But int_ena controls the hardware interrupt generation. If it is cleared, no hardware interrupt can be generated by the i2c peripheral.
I'm confused. Something else is happening. My best guess is multi-tasking of Wire()

    } else { // GROSS timeout, shutdown ISR , report Timeout
        i2c->stage = I2C_DONE;
        i2c->dev->int_ena.val =0;
        i2c->dev->int_clr.val = 0x1FFF;
        if((i2c->queuePos==0)&&(i2c->byteCnt==0)) { // Bus Busy no bytes Moved
            reason = I2C_ERROR_BUSY;
            eBits = eBits | EVENT_ERROR_BUS_BUSY|EVENT_ERROR|EVENT_DONE;
#if ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_ERROR
            log_e(" Busy Timeout start=0x%x, end=0x%x, =%d, max=%d error=%d",tBefore,tAfter,(tAfter-tBefore),ticksTimeOut,i2c->error);
            i2cDumpI2c(i2c);
            i2cDumpInts(i2c->num);
#endif
        } else { // just a timeout, some data made it out or in.
            reason = I2C_ERROR_TIMEOUT;
            eBits = eBits | EVENT_ERROR_TIMEOUT|EVENT_ERROR|EVENT_DONE;

#if ARDUHAL_LOG_LEVEL >= ARDUHAL_LOG_LEVEL_ERROR
            log_e(" Gross Timeout Dead start=0x%x, end=0x%x, =%d, max=%d error=%d",tBefore,tAfter,(tAfter-tBefore),ticksTimeOut,i2c->error);
            i2cDumpI2c(i2c);
            i2cDumpInts(i2c->num);
#endif
        }
    }

Code that generated the Debug message "injection":

// sync between dispatch(i2cProcQueue) and worker(i2c_isr_handler_default)
typedef enum {
    //I2C_NONE=0,
    I2C_STARTUP=1,
    I2C_RUNNING,
    I2C_DONE
} I2C_STAGE_t;

    if(p_i2c->stage==I2C_DONE) { //get Out
        log_e("eject int=%p, ena=%p",activeInt,p_i2c->dev->int_ena.val);
        p_i2c->dev->int_ena.val = 0;
        p_i2c->dev->int_clr.val = activeInt; //0x1FFF;
        return;
}

As you can see this if() will only trigger if state==I2C_DONE. The only time I have seen this happen was when Wire() was called by multiple task simultaneously. The two hex value printed in the message show the interrupt that generated this call NONE, and the interrupts that are enabled to trigger this ISR NONE. This only happens when code to clear / disable interrupts is called during an active interrupt cycle.

I don't have a clue how the ISR was called out of sequence.

Chuck.

[cyberman54]

Hmm, sounds difficult. As my application code runs under espressif32 v1.0.2 without this i2c problem, i assume that this behaviour is caused by something that came in by upgrade Espressif32 to v1.1.x.

In my application code i don't use Wire() directly. But i am using u8g2 library to control an OLED I2C display. The author of u8g2 pointed out, that his library is using Wire.h in Arduino style.

My application uses RTos tasks, but u8g2 calls are centralized in one main task. But the main task will be interrupted by other tasks (which don't call Wire()).

[stickbreaker]

@cyberman54 are you using ANY other i2c code? mixing IDF i2c and Arduino i2c?

Chuck.

[cyberman54]

No. Only I2C component is the OLED display, controlled by u8g2 library.

[bartoszbielawski]

I have exactly the same problem. One I2C display that is controlled from a separate FreeRTOS task.
The class for the display does something and from the same thread I change Wire pin assignments and speed. Otherwise no other accesses.

[stickbreaker]

@cyberman54 @bartoszbielawski are you both using Platformio? I use Arduino. Can either or both of you make a small /simple example that shows this problem?

If I need to set up a Platformio environment I will, but I will probably need some help :grin:

Chuck.

[cyberman54]

Chuck, you may just look to my repo:

https://github.com/cyberman54/ESP32-Paxcounter/tree/development?files=1

[bartoszbielawski]

@stickbreaker
Yes, I use PIO as well.
I have already written a minimal test program and I think it should be easy to run it in Arduino IDE:
https://gist.github.com/bartoszbielawski/bf9a03d6eb505b299c7fd6a8b641021c

The screen itself has some extra random dots and the printed number sometime jump few pixels back and forth + the error messages - check the end of the gist.

[stickbreaker]

@bartoszbielawski try changing the xTaskCreate to:

void setup() 
{
    Serial.begin(115200);
    xTaskCreatePinnedToCore(displayThread, "DT", 8192, NULL, 5, NULL,1);    
}

You are starting this task at priority 5, the basic Arduino loop runs at 1. And possibly the interrupt is triggering on the wrong core?

Chuck.

[stickbreaker]

@bartoszbielawski can you make a change in cores\exp32\p32-hal-i2c.c about line 593

   if(p_i2c->stage==I2C_DONE) { //get Out
        log_e("eject int=%p, ena=%p core=%d",activeInt,p_i2c->dev->int_ena.va,xPortGetCoreID());
        p_i2c->dev->int_ena.val = 0;
        p_i2c->dev->int_clr.val = activeInt; //0x1FFF;
        return;
}

Changing the log_e() line to add the coreID.

Chuck.

[bartoszbielawski]

@stickbreaker
Okay, I have done some tests and here are my conclusions:

1. it doesn't matter on which code the task runs - I tested it both on core 0 and core 1, the error message always comes from the corresponding core.
2. (clock rate <= 400 kHz) or (priority == 0) fixes the problem.
3. For clock rates >= 400 kHz (tested with 800 kHz) priority == 0 helps but the bus is very slow.

I guess I will reduce I2C speed to the regular 400 kHz.
Does it mean that in some cases (clocks >= 400 kHz) the result arrives faster than the software expects it?

[stickbreaker]

@bartoszbielawski let me think about this. So, when you pin it to core1 the Eject says core=1 and if you pin it to core0, eject says core=0.

I have ran my test bed that has 10 i2c devices on a 18" bus at 1,000,000hz for 10k+ operations. But I haven't tried from a separate task, just the prime arduino core.

No, the ISR responds to the interrupts, if they are slower it just takes longer. The ISR is designed to handle concurrent interrupts. the ESP32 won't dispatch while it is in an interrupt.

The Stage==Done is saying Either it completed or a Timeout happened.

another change:
add debug code to display the prior interrupt list:

    if(p_i2c->stage==I2C_DONE) { //get Out
        log_e("eject int=%p, ena=%p",activeInt,p_i2c->dev->int_ena.val);
        i2cDumpInts(p_i2c->num);
        p_i2c->dev->int_ena.val = 0;
        p_i2c->dev->int_clr.val = activeInt; //0x1FFF;
        return;

Chuck

[cyberman54]

@stickbreaker I added both of your above debug modifications to esp32-hal-i2c.c and i'm getting this result:

[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000001ad
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000001ad
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000001ae
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000001ae
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x00000e80
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000e80
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x00000e81
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000e81
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x00000ed0
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000ed0
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x00000ed1
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000ed1
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000022ca
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000022ca
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000022cb
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000022cb
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x000022ec
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000022ec
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x000022ed
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000022ed
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x0000232f
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x0000232f
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x00002330
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00002330

[cyberman54]

sorry, i forgot the core=%d in the log statement, here we go again:

[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x000001bd
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000001bd
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x000001be
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000001be
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x000001df
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000001df
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x000001e0
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000001e0
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x00000218
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000218
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x00000219
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000219
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x00000244
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000244
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x00000245
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000245
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x00000287
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000287
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x00000288
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000288
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000002c8
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000002c8
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000002c9
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000002c9
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x0000233c
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x0000233c
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x0000233d
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x0000233d

So, code runs on core1. This is as expected, since i control the i2c display from arduino main loop, and this runs on core1 with RTos.

[cyberman54]

And after some seconds i get a Guru Meditation Error:

[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0, core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x000030a7
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000030a7
[D]Guru Meditation Error: Core  1 panic'ed (Interrupt wdt timeout on CPU1)
Core 1 register dump:
PC      : 0x40094a96  PS      : 0x00060534  A0      : 0x80092636  A1      : 0x3ffc0ac0
A2      : 0x3ffd6590  A3      : 0x3ffd8784  A4      : 0x00000001  A5      : 0x00000001
A6      : 0x00060523  A7      : 0x00000000  A8      : 0x3ffd8784  A9      : 0x3ffd8784
A10     : 0x00000019  A11     : 0x00000019  A12     : 0x00000001  A13     : 0x00000001
A14     : 0x00060521  A15     : 0x00000000  SAR     : 0x00000004  EXCCAUSE: 0x00000006
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffc
Core 1 was running in ISR context:
EPC1    : 0x4000beb4  EPC2    : 0x00000000  EPC3    : 0x4000921a  EPC4    : 0x40094a96

Backtrace: 0x40094a96:0x3ffc0ac0 0x40092633:0x3ffc0ae0 0x400911f7:0x3ffc0b00 0x400d78d0:0x3ffc0b40 0x4018eb2f:0x3ffc0ba0 0x4008638e:0x3ffc0be0 0x400819dd:0x3ffc0c10 0x401b929f:0x00000000

Core 0 register dump:
PC      : 0x40091bde  PS      : 0x00060034  A0      : 0x800922fb  A1      : 0x3ffc0590
A2      : 0x3ffc28d0  A3      : 0x0000cdcd  A4      : 0xb33fffff  A5      : 0x00000001
A6      : 0x00060021  A7      : 0x0000abab  A8      : 0x0000abab  A9      : 0x3ffc0590
A10     : 0x00000003  A11     : 0x00060023  A12     : 0x00060021  A13     : 0x3ffc64c8
A14     : 0x0000002a  A15     : 0x3ffdd8e0  SAR     : 0x00000015  EXCCAUSE: 0x00000006
EXCVADDR: 0x00000000  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffd

Backtrace: 0x40091bde:0x3ffc0590 0x400922f8:0x3ffc05c0 0x40093487:0x3ffc05e0 0x4009318d:0x3ffc0600 0x400819e6:0x3ffc0610 0x40009217:0x00000000

The dump resolves to:

Decoding 23 results
0x40094a96: vListInsert at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/list.c line 188
0x40094a96: vListInsert at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/list.c line 188
0x40094a96: vListInsert at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/list.c line 188
0x40092633: vTaskPlaceOnEventList at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 3564
0x400911f7: xQueueGenericReceive at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/queue.c line 2520
0x400d78d0: log_printf at ?? line ?
0x4018eb2f: i2cDumpInts at ?? line ?
0x4008638e: i2c_isr_handler_default at esp32-hal-i2c.c line ?
0x400819dd: _xt_lowint1 at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/xtensa_vectors.S line 1105
0x401b929f: esp_vApplicationWaitiHook at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/esp32/freertos_hooks.c line 66
0x40091bde: uxPortCompareSet at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 3564
:  (inlined by) vPortCPUAcquireMutexIntsDisabledInternal at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/portmux_impl.inc.h line 86
:  (inlined by) vPortCPUAcquireMutexIntsDisabled at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/portmux_impl.h line 98
:  (inlined by) vTaskEnterCritical at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 4254
0x40091bde: uxPortCompareSet at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 3564
:  (inlined by) vPortCPUAcquireMutexIntsDisabledInternal at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/portmux_impl.inc.h line 86
:  (inlined by) vPortCPUAcquireMutexIntsDisabled at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/portmux_impl.h line 98
:  (inlined by) vTaskEnterCritical at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 4254
0x400922f8: xTaskIncrementTick at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/tasks.c line 3564
0x40093487: xPortSysTickHandler at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/port.c line 326 (discriminator 1)
0x4009318d: _frxt_timer_int at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/portasm.S line 303
0x400819e6: _xt_lowint1 at /Users/ficeto/Desktop/ESP32/ESP32/esp-idf-public/components/freertos/xtensa_vectors.S line 1105

[stickbreaker]

@bartoszbielawski

[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject int=0x0, ena=0x0
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row count INTR TX RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000001ad
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000001ad
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000001ae
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000001ae

That is weird, nothing is showing up a wrong, just that you are seeing a unserviced interrupt.
That shows a total of 6 interrupts, a TxFifoEmpty, StartTransaction, 3 bytes moved, EndTransaction.

More Debug, lets see the time frame between the last interrupt and this spurious interrupt.

    if(p_i2c->stage==I2C_DONE) { //get Out
        log_e("eject tick=0x%8x int=%p, ena=%p core=%d", xTaskGetTickCountFromISR(),activeInt,p_i2c->dev->int_ena.val,xPortGetCoreID());
        i2cDumpInts(p_i2c->num);
        p_i2c->dev->int_ena.val = 0;
        p_i2c->dev->int_clr.val = activeInt; //0x1FFF;
        return;

Chuck

[stickbreaker]

@bartoszbielawski ignore the core dump, too much debug output during an interrupt, Watchdog died of starvation.

[bartoszbielawski]

Sorry guys, I'm out for today. I have a long drive tomorrow and have to be
rested...

Bartosz

[stickbreaker]

@bartoszbielawski Thanks for trying.

Chuck.

[cyberman54]

i will check tommorow.

[stickbreaker]

@bartoszbielawski Thru more research we might be having a pullup problem. if this is your board Heltec WiFi kit 32 It shows only 10k pullups on the SDA and SCL lines. Try adding 3.3k pullups. That should drop the effective pullups to 2.3k. We might be having pullup issues at higher data rates.

Chuck.

[cyberman54]

@bartoszbielawski does is work with Espressif32 v1.0.2 and same.board?

@stickbreaker SDA/SCL are muxed in the ESP32 and can be switched to different GPIOs

[bartoszbielawski]

@cyberman54 It does work on 1.0.2 on the same board.
@stickbreaker I could understand the problem happens due to weak pull-ups but how does setting priority of the task to 0 fix the problem? I'm willing to tinker with the board but I don't have access to my lab at the moment.

[stickbreaker]

@bartoszbielawski It looks like we are running into some kind of race condition. the pullup will change the performance of the i2c transmission. The i2c peripheral measures signal level after the waveform voltage reaches a trigger voltage. With High data rates and weak pullups cause a very unsymmetrical waveform.
Electrically I know 10k is too weak for any clock rate above 100kHz at 3.3v. I wrote a article in my repo's wiki about pullup value considerations if you are interested.

Another debug change you can do, change the 'inject' of show the raw interrupt value instead of the filtered one:
c++ if(p_i2c->stage==I2C_DONE) { //get Out log_e("eject tick=0x%8x rawint=%p, ena=%p core=%d", xTaskGetTickCountFromISR(), p_i2c->dev->int_raw.val, p_i2c->dev->int_ena.val,xPortGetCoreID()); i2cDumpInts(p_i2c->num); p_i2c->dev->int_ena.val = 0; p_i2c->dev->int_clr.val = activeInt; //0x1FFF; return;

Chuck.

[cyberman54]

@stickbreaker Here's my output logging the raw interrupts:

[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     1da rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000001d9
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000001d9
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000001da
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000001da
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     23f rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x0000023e
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x0000023e
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x0000023f
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x0000023f
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     275 rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x00000274
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000274
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x00000275
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000275
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     8b8 rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000008b7
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000008b7
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000008b8
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000008b8
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     eec rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x00000eeb
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000eeb
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x00000eec
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000eec
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x     f5a rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x00000f59
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00000f59
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x00000f5a
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00000f5a
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x    233c rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x000a 0x0000 0x0000233b
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x0000233b
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x000a 0x0040 0x0000 0x0000 0x0000233c
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x0000233c
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x    2374 rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x00002374
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x00002374
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x00002374
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x00002374
[E][esp32-hal-i2c.c:594] i2c_isr_handler_default(): eject tick=0x    23a3 rawint=0x2, ena=0x0 core=1
[E][esp32-hal-i2c.c:1438] i2cDumpInts(): 0 row  count   INTR    TX     RX
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000023a2
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000023a2
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [03] 0x0003 0x0040 0x0000 0x0000 0x000023a3
[E][esp32-hal-i2c.c:1442] i2cDumpInts(): [04] 0x0001 0x0080 0x0000 0x0000 0x000023a3

[bartoszbielawski]

Yeah, I get the problem we could have with the pullups but why would
setting task priority to 0 solve the problem? The HW I2C would be still
sending data at the fixed (high speed)...

2018-07-09 1:29 GMT+02:00 chuck todd [e-mail]:

@bartoszbielawski https://github.com/bartoszbielawski Thru more
research we might be having a pullup problem. if this is your board
Heltec WiFi kit 32
https://github.com/Heltec-Aaron-Lee/WiFi_Kit_series/blob/master/SchematicDiagram/WIFI_Kit_32_Schematic_diagram.PDF
It shows only 10k pullups on the SDA and SCL lines. Try adding 3.3k
pullups. That should drop the effective pullups to 2.3k. We might be having
pullup issues at higher data rates.

Chuck.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/espressif/arduino-esp32/issues/1588#issuecomment-403325679,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AD2sEP16WSsWbjncQBzM5oWh3cJq0pIeks5uEpXugaJpZM4VCBhO
.

[cyberman54]

@bartoszbielawski if this issue is caused by a race condition, i think it depends on the individual application environment if and what sort of influence task priorities have on interrupts.
In my application it makes no difference if i run the main task (which controls a i2c display) on core 1 with prio 0 or prio 1, in both cases the error occurs.

In my opinion the question is: why didn't this happen with Espressif32 1.0.2 core? Regardless of dimensions of pullups. Because the same hardware with same pullups now with Espressif32 1.1.x triggers the error.

[cyberman54]

I checked the schematic of the board i am using for above tests, a TTGO ESP32 v2.1.
This board uses GPIO21 (SDL) and GPIO22 (SCLK) of ESP32 for i2c bus. Each pin is tied with a 4,7k ohm pullup to Vcc.

[stickbreaker]

@bartoszbielawski @cyberman54 the Raw 0x2 is a TxFifo empty, which is a true interrupt. The Tx Fifo is empty, but i'll have to look at the STOP interrupt handling. I need to verify the order that I shut down the peripheral when the end of the command queue is reached. I might have to stuff a few null bytes into the txFifo to prevent this interrupt. These null bytes wouldn't cause any problem, because when I setup for the next transaction the first thing I do is reset the Fifo's. These null bytes will never exit the peripheral because the peripheral command buffer includes the number of bytes to move, this number of bytes is detached from the fill level of the fifo, if I tell it to send 5 bytes, but only put 4 bytes in the fifo, the fifth byte sent is 0xff.

The 4.7k pulls will work with 100kHz, but I would measure the signal to calculate the bus capacitance before I increased speed. With 4.7k to 3.3v the drive current is only 0.702mA, I like 1 ~ 1.5mA. Standard I2C devices usually spec a 3mA max drive. With 2.4k I get a 1.375mA. With a 5v i2c 4.7k gives 1.064mA.

I'll do some testing to see how the TxFifo empty could be generating an interrupt after/during the STOP. Normally, the txFifo is filled with all available out bound characters or 32(fifo max). If all characters will fit in fifo, the txEmpty interrupt is disabled. We could be having a Read/Modify/Update problem with the int_ena register.

That new debug output is showing the spurious interrupt is being generated just after the 0x80 (STOP).

I'll see if I can regenerate this problem tomorrow.

Chuck.

[stickbreaker]

@bartoszbielawski @cyberman54 What Exact ESP32 board are you using? I don't have one with a SSD1306 display, I might have to purchase one to test.

Chuck.

[cyberman54]

i tested the issue with different ESP32 LoRa OLED boards, all show same error:- Heltec Wifi Lora Kit32- TTGO T3 v2.1 (4k7 pullups)- TTGO T3 v2Am 10.07.2018 05:41 schrieb chuck todd [e-mail]:@bartoszbielawski @cyberman54 What Exact ESP32 board are you using? I don't have one with a SSD1306 display, I might have to purchase one to test.
Chuck.

—You are receiving this because you were mentioned.Reply to this email directly, view it on GitHub, or mute the thread.

[bartoszbielawski]

@cyberman54 I have Heltec without LoRa. That one has SSD1306 (128x64). For
the resistors I agree. I could measure it myself but I left for looong
holidays and ESP32 board to carry with me is fine but a scope is not ;)

2018-07-10 5:41 GMT+02:00 chuck todd [e-mail]:

@bartoszbielawski https://github.com/bartoszbielawski @cyberman54
https://github.com/cyberman54 What Exact ESP32 board are you using? I
don't have one with a SSD1306 display, I might have to purchase one to test.

Chuck.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/espressif/arduino-esp32/issues/1588#issuecomment-403690304,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AD2sEAxmXYOrh7517elRIOGzoTZ-FLXIks5uFCJ6gaJpZM4VCBhO
.

[cyberman54]

@stickbreaker if this helps, i can express air mail you a test board (Heltec) which shows the issue.

[stickbreaker]

@cyberman54 sure, I have found them on BangGood 7~20 day delivery. That would probably speed up my fix. I'll send you and email with my address.

Chuck.

[cyberman54]

@stickbreaker Got it. Tomorrow by 8 PM the postman will hand over a gift with 1 piece Heltec Lora 32 board with i2c OLED to you.

[stickbreaker]

@cyberman54 Thanks,
I've been looking at the adafruit ssd1306 code, I can see where I think I can dramatically speed it up.

With the new Wire() code, a screen refresh can happen with one i2c call. It will require a slight change to the SSD1306 screen buffer. I'll have to add one byte at the beginning of the buffer, It will be fun to see if my idea works.

Currently the SSD1306 code sends 16byte blocks of the screen at a time. So a full refresh takes 64 loops. each loop is built one byte at a time with all the buffer position, bounds checking, data copying.
By changing the screen buffer, and using different Wire() commands one function calls should suffice.

  //@stickBreaker for big blocks and ISR model
    i2c_err_t writeTransmission(uint16_t address, uint8_t* buff, uint16_t size, bool sendStop=true);
    i2c_err_t readTransmission(uint16_t address, uint8_t* buff, uint16_t size, bool sendStop=true, uint32_t *readCount=NULL);

This code from AdaFruits SSD1306

 {
    // save I2C bitrate
#ifdef TWBR
    uint8_t twbrbackup = TWBR;
    TWBR = 12; // upgrade to 400KHz!
#endif

    //Serial.println(TWBR, DEC);
    //Serial.println(TWSR & 0x3, DEC);

    // I2C
    for (uint16_t i=0; i<(SSD1306_LCDWIDTH*SSD1306_LCDHEIGHT/8); i++) {
      // send a bunch of data in one xmission
      Wire.beginTransmission(_i2caddr);
      WIRE_WRITE(0x40);
      for (uint8_t x=0; x<16; x++) {
        WIRE_WRITE(buffer[i]);
        i++;
      }
      i--;
      Wire.endTransmission();
    }
#ifdef TWBR
    TWBR = twbrbackup;
#endif
  }
}

Becomes this under ESP32

uint32_t oldClock = Wire.getClock();
Wire.setClock(400000);

i2c_err_t err=Wire.writeTransmission(_i2cAddress, buffer,(SSD1306_LCDWIDTH*SSD1306_LCDHEIGHT/8)+1);
if(err != I2C_ERROR_OK){ // say what went wrong
  log_e("Screen Update Failed =%d %s",err,Wire.getErrorText(err));
}

Wire.setClock(oldClock);   

There is a net saving of 30 transmitted bytes also. Only one i2c block( one _i2cAddress, one Command/data byte)

It might also be possible to increase performance of the command calls.

Well, hopefully I will see the 'injection' errors tomorrow with the original library code, after I solve that problem, it should be fun to see if these potential optimizations are valuable.

Chuck.

[cyberman54]

Still the question what is the root cause and why did it not happen with Espressif32 1.0.2?

[stickbreaker]

@cyberman54 I think the issue is going to be a change in interrupt allocation. I don't know how deep I am going to have to dive. I've got some Idea where to look, It could be a Shared interrupt issue( I allocate the interrupt as Edge with isn't allowed when using a Shared interrupt.) I don't specifically ask for a Shared interrupt, and by specifying Edge triggering it should not assign it to a Shared interrupt, Maybe something changed. Or it could be that an interrupt was added to the dispatcher queue before the code disabled interrupts. I might need to prevent an interrupt instead of masking it. Or it could be the order of execution inside the ISR. I found that I need to specifically order the sequence for servicing simultaneous interrupts.
When I can recreate the errors I will have a path to follow to fix them.

I have been working on some new code to increase performance by no longer needing process each byte with I2C_MASTER_TRAN_COMP_INT_ST interrupts. this should really reduce load on the CPU. the ISR code will only be invoked on START, STOP, FifoEmpty/Full or errors.

Chuck.

[dpharris]

Thank you for you ongoing work for us all! Kudos.

David

On Tue, Jul 10, 2018, 15:03 chuck todd [e-mail] wrote:

@cyberman54 https://github.com/cyberman54 I think the issue is going to
be a change in interrupt allocation. I don't know how deep I am going to
have to dive. I've got some Idea where to look, It could be a Shared
interrupt issue( I allocate the interrupt as Edge with isn't allowed when
using a Shared interrupt.) I don't specifically ask for a Shared interrupt,
and by specifying Edge triggering it should not assign it to a Shared
interrupt, Maybe something changed. Or it could be that an interrupt was
added to the dispatcher queue before the code disabled interrupts. I might
need to prevent an interrupt instead of masking it. Or it could be the
order of execution inside the ISR. I found that I need to specifically
order the sequence for servicing simultaneous interrupts.
When I can recreate the errors I will have a path to follow to fix them.

I have been working on some new code to increase performance by no longer
needing process each byte with I2C_MASTER_TRAN_COMP_INT_ST interrupts.
this should really reduce load on the CPU. the ISR code will only be
invoked on START, STOP, FifoEmpty/Full or errors.

Chuck.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub
https://github.com/espressif/arduino-esp32/issues/1588#issuecomment-403980837,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAg4SuqpXz9tM4oZx1S8mbzdsXLhW-pyks5uFSTOgaJpZM4VCBhO
.

[stickbreaker]

@cyberman54 Received it. and It booted. So, now to see if I can make it fail.

Chuck.

[cyberman54]

@stickbreaker for quick & dirty 1st test you may just compile my RTos based application code, flash it and open serial console, then you see the i2c error log and the corresponding esp_calls

https://github.com/cyberman54/ESP32-Paxcounter

[stickbreaker]

@cyberman54 I was able to regenerate the eject error.

Also, the AdaFruit ssd1306 lib does not do any error checking. I have been getting ACK errors during the command sequence calls. That is what is messing up the display, some of the commands are not being accepted by the display.

I did not get eject command until i increased the clock rate from 100k to 400k.

so, now I have something to find. :grinning:

Chuck.

[stickbreaker]

@cyberman54 Definitely speed related, 375000Hz does not cause any 'eject', 500kHz continous.

[stickbreaker]

@cyberman54 625kHz works with no i2c errors, but the Display is having a hard time.

[bartoszbielawski]

On 1.0.2 it was working fine for me at 800 kHz, no I2C error, no problems
with the display.

[cyberman54]

@stickbreaker as yet i had no attention on how fast the i2c in my app is operated, because i use only one i2c slave on the bus, and this is the SSD1306 OLED controller which, in my app, is not performance critical.

Now i checked the u8g2 lib code and found this:

https://github.com/olikraus/u8g2/commit/6c81aaab2658341e9cd3708762405223f40ba11e

The clock speed is set to 400 kHz depending on arduino version greaterequal than 1.6.0.

With last Espressif32 core update i think i saw an uplift of arduino 1.5.3 to 1.6.0, which could point to the above piece of code in u8g2.

Result would be that in former development framework display was running on 100khz without problems and after framework update u8g2 switched to 400khz what triggered the injection issue?

[cyberman54]

Looks like this issue for me is indeed a side effect from versioning in platformio:

https://github.com/platformio/platform-espressif32/commit/a64488026cca484ec2f2210a2476cfd24d4a9772

The arduino version was updated from 1.5.3 to 1.6.0 on July2, 2018. So this could be the reason, why i ran in that i2c speed issue with u8g2.

Now we need to find the root cause of that speed issue.

[stickbreaker]

@cyberman54 @bartoszbielawski Definitely a clock speed issue.

[stickbreaker]

@cyberman54 @bartoszbielawski I changed the pattern displayed on my screen, I fill the screen with the count, once the screen is no longer changing it does not generate the error.

void displayThread(void*)
{
    Wire.begin(OLED_SDA,OLED_SCL,100000);
    Adafruit_SSD1306 display(OLED_RST);
    display.begin(SSD1306_SWITCHCAPVCC, 0x3C); // initialize with the I2C addr 0x3D (for the 128x64)
    display.setTextColor(WHITE);
    display.setTextSize(1);
    display.setFont();
    int x = 0;
    uint32_t speed=100000, newSpeed=0, oldSpeed;
    oldSpeed = speed;
    display.clearDisplay();
    display.setCursor(0, 0);
    while (true)
    {
//        display.clearDisplay();
//        display.setCursor(50, 50);
        display.printf("%d ", x++);
        display.display();
        if((x & 0x0f)==0)Serial.printf("%d\n", x);
        while(Serial.available()){// adjust speed
          char ch = Serial.read();
          if (ch=='+') newSpeed = oldSpeed + 25000;
          if (ch=='-') newSpeed = oldSpeed - 25000;
          if((ch>='0')&&(ch<='9')) {
            newSpeed *=10;
            newSpeed += ch-48;
          }
          if(ch =='\n'){
            speed=newSpeed;
            newSpeed= 0;
            }
          if(speed != oldSpeed){
            Wire.setClock(speed);
            Serial.printf("speed=%d ",speed);
            oldSpeed = speed;
            display.clearDisplay();
            display.setCursor(0, 0);

          }
        }
        delay(2);
    }
}

void setup() 
{
    Serial.begin(115200);
    xTaskCreate(displayThread, "DT", 8192, NULL, 5, NULL);    
}

void loop() {
    delay(1);
}

This could be a POWER issue.

I have to setup a breadboard and plugin my scope.

Try this code. you can change the clock rate from the serial monitor.

Chuck.

[cyberman54]

Allright, for my app it is no problem to go back to 100khz. I need to find out how can i do it with u8g2.

I never knew that it speeded up with the lastet Espressif32 upgrade. What an crazy side effect...

[stickbreaker]

@cyberman54 Well, I seem to have hosed this display, my viewport is only the first 8 rows, I'm going to dig in to the spec sheet and go through all of the init commands. The other seven rows of the screen had a corrupted image, then I powered it off for 5 minutes now it just has a random dot pattern.

It is doing some kind of horizontal scroll instead of incrementing to next line.

I can still make it create the 'eject' error so it is still usable for this problem.

Chuck.

[stickbreaker]

@cyberman54 Recovered the display, the AdaFruit library does not completely configure it.
I have reduced the occurrence of 'eject' by increasing the fifo thresholds with increased clock rate.
The board is unstable with clock>400k

• 650kHz i2c reports errors, the display gets confused.
• 525khz some errors, good display and 45.454 frames/second.
• 500khz continous errors, bad display
• 475kHz more errors, good display 42.66 f/s
• 450kHz no errors, good display 41.53 f/s
• 400kHz no errors, good display 37.037 f/s
• 100khz no error, good display and 10.204 f/s

Tomorrow I'll look at the electrical signals, I'm thinking we are also fighting reflections and weak pullups.

I just posted a pr #1625 that contains my changes so far. It is a work in progress

Chuck.

[stickbreaker]

@cyberman54 @bartoszbielawski
Here is my modified test code, It is a hack.
HelTec test

Chuck.

[stickbreaker]

@helmut64 me-no-dev merged in my interrupt code #1539 Jun 27.

This problem is overactive debug message. The underlying spurious interrupts can be handled by ignoring them. I am working on adjusting the driver so that it does not create circumstances where spurious interrupts are generated.

There is one major difference between my code and the original code: Any ReSTART operation will be queued until the next STOP operation:

Wire.beginTransmission(i2caddr);
Wire.write(highbyte); // setup read addres for EEPROM
Wire.write(lowbyte);
uint8_t err = Wire.endTransmission(false);  //ReSTART
if(err!=0 ){
   Serial.printf(\"Error setting read addess in EEPROM =%d (%s)\n", Wire.lastError(),Wire.getErrorText(Wire.lastError()));
// err will always return 7 in this circumstance to identify this operation is queued (I2C_ERROR_CONTINUE)
} else {
  Wire.requestFrom(i2caddr,10); 
  while(Wire.available()){
    Serial.printf(\"0x02x \",Wire.read());
    }
  Serial.println();
  }

So, this code will not correctly display the EEPROM contents the (err != 0) needs to be (err !=7). Any ReSTART operation will return 7, so any code that uses ReSTART needs to be adjusted.

Chuck.

[stickbreaker]

Wow, @helmut64 your comments disappeared?

Chuck.

[stickbreaker]

This is getting weirder and Weirder! The number of 'eject' occurrences is varies with clockrate, the Pullups.

With the Bare HelTec WiFi Lora 32, the OLED does not function correctly with clock rates above 325khz, if I add 3.3k pullups, I can get reliable communications at 425khz. Above that the the display fritz's out.

When the display starts fritzin, I start seeing the 'eject' errors. I can't tell which one is comes first.

With and optimized ssd1306 library, I can get 40 frames per second update to the screen.

I think these interrupts are caused by glitches on the bus. I think the OLED is doing something. I haven't figured out how to catch these glitches, In my latest run at 430khz with 3.3k pullups, I had an error at refresh 9888, it is currently at 34800 with not errors between. Roughly 26.155MB of data without any problems.

Chuck.

[cyberman54]

@stickbreaker i don't think it's the OLED, because i see the same effect on other boards (TTGO) which have similar OLED, but from different manufacturer.

[helmut64]

@stickbreaker I have not done anything, I don't know why my comment is gone, grade?
Maybe I am not allowed to have our radio shuttle link here, strange. Anyways:
Of course I know the ESP32 Heltec LoRa very well, I had no display problems so far. We can talk about this off-topic when you like.
I will investigate into the I2C problem by simply switching back the ESP32 Arduino releases until it works again. I reviewed the checkins but cannot find possible errors.
I keep you updated.
Helmut

[cyberman54]

@stickbreaker I can confirm: after setting the i2c speed to 100kHz and updating espressif32 core 1.1.x to commit 28a410d which includes pr #1625 i don't get any more interrupt injections. But the OLED speed now is signifant slower as it was before, with espressif32 core 1.0.2 @100 kHz.

In verbose log level mode the only log message i get from the i2c subsystem is

[V][esp32-hal-i2c.c:1362] i2cSetFrequency(): threshold=3

What's the meaning of this?

[cyberman54]

@stickbreaker i checked the specs of a SSD1306 display, it says 2,5us is minimum i2c clock cycle the display can handle. So, 400khz is maximum for SSD1306 operated with i2c interface.

[cyberman54]

@stickbreaker comparing my application code running on espressif32 core v1.0.2 with latest v1.1.x including your pr, i studied that the arduino main loop task seems to run much slower with v1.1.x than 1.0.2.
The main loop of my app is a state machine, which besides other tasks blinks a LED. When the code is compiled with v1.0.2 the LED flashes quickly in a short cycle as i programmed the timer. When i compile it with v1.1.x LED flashing is significantly slowed down, maybe by 5 to 10 times.

It looks like for some reason the code processing speed went down. I assume that this is a starving effect caused by another RTos task which consumes much more cpu time under v1.1.x that v1.0.2.

Maybe the same root cause affects i2c timing. Perhaps the i2c issues discussed here are a side effect?

[stickbreaker]

@cyberman54 the threshold is the trip points for tx and rx fifo interrupts. I added code to adjust the fifo full and fifo empty points. Prior it was fixed. Inside i2cSetFrequency() it calculates where to set trip points. I was noticing problems while debugging. (Too many log messages) causing tx glitches) I had tx threshold set to 2.

I am working on reducing interrupt calls, maybe my i2c is part of the preformance hit.

Do any of you use AdaFruit's SSD1306 library?

I made a modified version that increases the display rate. I'll add it to my repo if anyone is interested.

Chuck.

[cyberman54]

@stickbreaker currently i'm using u8g2 because of it's lightweight footprint of u8x8 class, since my app does not need graphics, just plain text.

[bartoszbielawski]

@stickbreaker Using your copy of the library at 100 kHz works fine - but it was fine before as well.
Going to 400 kHz makes the eject message to appear sometimes but not very often (< 1/s).
I should probably test it with the original test program instead of my code...

[CelliesProjects]

@stickbreaker Hi Chuck, I am interested in that modified SSD1306 lib.

[stickbreaker]

@CelliesProjects it's up. at SSD1306 library repo it is just a replacement for AdaFruit_SSD1306, it needs AdaFruit_GFX to function.

Chuck.

[CelliesProjects]

@stickbreaker Thanks. I will test the lib somewhere this week. Will keep you posted.

[stickbreaker]

@cyberman54 @bartoszbielawski I think I fixed it.
I changed the i2c interrupt driver to no longer need an interrupt for each byte move. This has reduced the interrupt load dramatically.

Now I only need to service START, STOP, FIFO Fills, and errors.

I have my modified SSD1306 library updating the screen in a blur, I am seeing 259f/s at 1,000,000hz.
EDIT: I just realized my quoted f/s is not completely accurate. I modifed SSD1306 to only send the modified bits to the screen, so it is not completely updating the screen at every update, only the changed rectangle.

This is with an 18" i2c bus with 6 24LCxx EEPROMS (with 3.4k pullups) and the SSD1306 OLED(10k pullups).

The signal is an ugly sawtooth waveform, with crosstalk.

But, it works, On this test sequence I have ran 389,000 screen updates at 1MHz with NO 'eject' errors, I only saw 4 NAK on a frame update.

I need to clean up my debug output. Should have this update as a pull request by the week end! Yea!

Chuck.

[stickbreaker]

Decreasing my debug output caused the screen to wig out, at 1MHz, the I2C subsystem is not reporting any errors, but, the display is now spazing out at 900kHz. They only rate it at 400kHz so, anything above that is a bonus!

Chuck.

[me-no-dev]

@stickbreaker ping me on Gitter please :)

[cyberman54]

@stickbreaker thanks for your effort! Sounds like next week i can migrate my code to Espressif32 core v1.1.x 😀

[helmut64]

@stickbreaker Hi Chuck, I investigated into the problem that I2C does not work anymore for my devices (e.g.: Adafruit Si7021, and Rodan DS3231). This are very basic devices, I tried to change the wire speed to 100 kHz, no luck.

Up to the 24th of June (Git 7abd586) it works great.
Starting with the IDF update 27-June (Git a59eafb) it fails.

You did there a lot of I2C changes, unfortunately my gdb ESP32 setup does not work jet on my Mac, how I can help to fix this?

Regards Helmut

[stickbreaker]

@helmut64 there is one change that may be cause you problems, look through your code for a ReSTART operation:

Wire.endTransmission(false);
// or
Wire.requestFrom(id,len,false);

The ESP32 cannot support a naked ReSTART, the hardware has to have a complete i2c transaction or it goes into a timeout cascade.
Complete i2c transactions are bounded by START and STOP. ReSTART operations exist inside.
START -> ReSTART -> STOP

This requires that any Wire() operations that specifies a ReSTART has to be queued until an operation with a STOP is issued. This causes problem with Wire.endTransmission(false) returning an accurate error code, since the operation is queue for later execution it cannot return success (0) as its result. So, to indicate that the operation is queued, Wire.endTransmission(false) always returns 7(I2C_ERROR_CONTINUE). to indicate the operation is pending.

standard Arduino code for using ReStart is similar to this:

Wire.beginTransmission(id);
Wire.write(registerAddress);
uint8_t err =Wire.endTransmission(false); // ReSTART
if(err != 0){// endTransmission failed
  // bad stuff
}
else { //success
  err= Wire.requestFrom(id,10);
  while(Wire.available()){
    Serial.printf("0x%02 ",Wire.read());
  }
Serial.println();
}

to be compatible with the ESP32, the if() if(err != 0) need to be changed to if(err !=7) because of the ReSTART

Chuck.

[stickbreaker]

@cyberman54 @bartoszbielawski Just posted my updated i2c.c as a pull request #1665. Grab it and replace esp32-hal-i2c.c in any of the rc's RC1,RC2, or RC3.

Chuck.

[helmut64]

Hi Chuck, I have seen in the Adafruit_Si7021 multiple Wire.endTransmission(false), without a reason for the false. I removed the false parameter and the I2C works again.

I will continue testing with your patch.

[helmut64]

Update:
The new Pull request #1665 does not work with the Adafruit_Si7021 I2C driver (no Wire.endTransmission false used).
Without this patch it works (without the Wire.endTransmission false parameter).

[stickbreaker]

@helmut64 are you seeing any error messages?
Post a link to the library you are using. I'll look through it.

Chuck.

[helmut64]

The Adafruit_Si7021 is very simple, the code is here: https://github.com/adafruit/Adafruit_Si7021
PS: When I switch your code to Debug-Lebel Verbose there are problems in the log_e code and it does not compile.
Helmut

[stickbreaker]

@helmut64 Post the compile errors, I can't fix what I can't see.

Looking through that si7021 library, I can see why it doesn't work.
Original AdaFruit code

float Adafruit_Si7021::readHumidity(void) {
  Wire.beginTransmission(_i2caddr);
  Wire.write((uint8_t)SI7021_MEASRH_NOHOLD_CMD);
  Wire.endTransmission(false);
  delay(25);

  Wire.requestFrom(_i2caddr, 3);
  uint16_t hum = Wire.read();
  hum <<= 8;
  hum |= Wire.read();
  uint8_t chxsum = Wire.read();

  float humidity = hum;
  humidity *= 125;
  humidity /= 65536;
  humidity -= 6;

  return humidity;
}

This code will not react as assumed. The i2c subsystem will queue the Wire.endTransmission() delay for 25ms then do the Wire.requestFrom() which will return a NAK, without any data being transferred.

  Wire.endTransmission(false);
  bool done = false;
  uint32_t timeout = millis();
  while((millis()-timeout<1000)&&( !done)){ // 1sec timeout
    done = (Wire.requestFrom(_i2caddr, 3) ==3);
    delay(2); // give other tasks a bit of time while sensor samples
  }
  if (done){
    uint16_t hum = Wire.read();
    hum <<= 8;
    hum |= Wire.read();
    uint8_t chxsum = Wire.read();

    float humidity = hum;
    humidity *= 125;
    humidity /= 65536;
    humidity -= 6;

    return humidity;
  }
  else { // error
    return -1.0; // error    
  }
}

This is only one problem, there are more, when I get a chance I'll go through the rest of the library.

Chuck.

[helmut64]

The Compiler problem you see only when you switch within the Arduino IDE the menu the "Core Debug-Level" level to Verbose and click on compile.

[stickbreaker]

@helmut64 It compiles without any errors on my system using Arduino 1.8.5, Core Debug Level NONE -> VERBOSE .

I'm not seeing any problems, capture the Arduino's compile window. Without it I can't do anything.

Chuck.

[stickbreaker]

@helmut64 I modified Adafruit's si7021 library here. It should now work with esp32. It compiles, but I don't have one of these sensors, so it may not actually function. Try it an report any problems.

Chuck.

[stickbreaker]

@cyberman54 If this fix works for you, close this issue. me-no-dev just merged it into the main repo. So, lets see if any new errors crop up.

Chuck.

[cyberman54]

@stickbreaker meanwhile i did some tests with my app, comparing running it unter Espressif 1.0.2 and Espressif 1.1.2 including latest pull requests, also yours. Result is:

• I don't see any more i2c errors, not on log level info and not on log level debug, while running OLED display with u8g2 driver @ 400 KHz. So far looking good.
• But the performance of display refresh and other functions of my app still are significantly slowed down by unknown resson. My app blinks a LED in different flash cycles depending on device status. With 1.1.2 the device is too slow to see short blinks of 50ms, while this works with 1.0.2
• Device functions, including display refresh, sometimes seem to freeze for short time, maybe 50 - 100 milliseconds. This could point to an interrupt problem. I currently have now idea how to debug this, since i'm still not into JTAG debugging.

So, result is that i will continue sticking to Espressif core 1.0.2, until i get rid this performance hit :-(

[cyberman54]

@stickbreaker i did another test and took out the display driver from my app, so that no i2c communication is used. Result is, that the performance issues disappear, i.e. LED blinking is back to normal.
This may be a hint that there is still a problem in the i2c subsystem, maybe some sort of interrupt cascade. But i am far away from being sure, because i have only very limited debug options yet.

[stickbreaker]

@cyberman54 can you post your display driver code? I need something to test.

ssd1306_128x64_i2c.zip
SSD1306.zip

The SSD1306.zip is a modified AdaFruit_SSD1306 that only sends changed bits to the display.
The ssd1306_128x64_i2c.zip has some performance monitoring in it. It needs Adafruit_GFX, and AdaFruit_SSD1306. You can change the comments to switch to my SSD1306 to see the difference.

One of the tests "testStar()" takes 3610ms using Adafruit_SSD1306 only 865ms with SSD1306.

Have you went through your U8X8_SSD1306_128X64_NONAME_HW_I2C verifying that it handles ReSTARTS correctly?
The esp32 hardware handles ReSTARTS differently than AVR (standard Arduino). Possibly the library is having issues.

Chuck.

[cyberman54]

@stickbreaker i'm using u8x8.cpp from the u8g2 library. Did not write any display driver code on my own.

[stickbreaker]

@cyberman54 can you give me a basic sketch that uses this library? Looking through this code is a nightmare. I need a place to start.

Chuck.

[helmut64]

The Updated SI7021 Sensor library works, I understand your while loop around the Wire.requestFrom().
However I believe it still has problems:

• The old readHumidity() was waiting 20ms which is the time the temperature conversion needs in the device, if this delay is not included I believe the previous temperature is being returned, the same for readTemperature. Maybe I am wrong here.
• The read sensor moden and revision function is gone. (API incompatibility).

Thank you for helping out here.
Helmut

[stickbreaker]

@helmut64 my timing was taken from here:

And the NAK protocol from here:

I don't know what you meant here:

The read sensor moden and revision function is gone. (API incompatibility).

I don't have one of these sensors, so I am basing my code on my understanding of the datasheet. I guess, if my code doesn't fit your purpose you'll have to write better code :grinning:

If you have a library that produces accurate values, just modify it to work with the esp32.

Chuck.

[helmut64]

Chuck, you do a great job, and I love to see better I2C support, thank you for your support.

I was talking about the missing functions:

Adafruit_Si7021::readRevision and the variable “model”.

I will do further testing and integrate your changes.

You need a set of our ESP32 ECO Power boards with the sensor, please contact me (via the radioshuttle.de website) with your contact details.
Helmut

[stickbreaker]

@helmut64 just tried the contact link from your website

This message was created automatically by the mail system (ecelerity).

A message that you sent could not be delivered to one or more of its
recipients. This is a permanent error. The following address(es) failed:

[email protected] (after RCPT TO): 550 5.1.1 [e-mail]: Recipient address rejected: >User unknown in virtual alias table

substituted "XXXXXXXX" to protect you address

Chuck.

[helmut64]

@stickbreaker [email protected] should work.

[helmut64]

Hi Chuck, I have another problem with I2C using the Rodan DS3231 RTC driver. The driver is not great, no C++, however it works with D21 MCUs and well with AVRs, it was working with the ESP32 until your patch.
https://github.com/helmut64/ds3231/tree/ESP_ECO_POWER_RTC

There is no endTransmission(false) in this, I plan to use a scope to trace what is going on. Maybe you see something and can point to it.
Regards Helmut

[stickbreaker]

@helmut64 that is the email i used.
I'll try it again.

On the Rtc, I'll look at it tomorrow or saturday. Today was 20+ hrs I'm blitzed.

Chuck

[stickbreaker]

@helmut64 got it.

[helmut64]

FYI: For the Rodan DS3231 library I fixed the I2C ESP32 support, basically via a timeout loop around the Wire.requestFrom() as proposed by you. A "Wire.available()" check is an alternate option I tested, however the timeout loop is better because it avoids hangs. The new Rodan DS3231 library (tested on ARV, D21 and ESP32) is available now.
Regards
Helmut

[copercini]

Fixed on https://github.com/espressif/arduino-esp32/pull/1767 =)