I2C debugging and Log Dump Explaination (#2325)

* I2C debugging and Log Dump Explaination

Create a help file for I2C debugging and interpretation of log dumps

* Update i2c_debugging.md

version

* add formatting, file locations
This commit is contained in:
chuck todd 2019-01-22 02:24:51 -07:00 committed by Me No Dev
parent fa6f75952d
commit 3350476d1d

View File

@ -0,0 +1,276 @@
# Debugging I2C
With the release of Arduino-ESP32 V1.0.1 the I2C subsystem contains code to exhaustively report communication errors.
* Basic debugging can be enable by setting the *CORE DEBUG LEVEL* at or above *ERROR*. All errors will be directed the the *DEBUG OUTPUT* normally connected to `Serial()`.
* Enhanced debugging can be used to generate specified information at specific positions during the i2c communication sequence. Increase *CORE DEBUG LEVEL* to ***DEBUG***
## Enable Debug Buffer
The Enhanced debug features are enabled by uncommenting the `\\#define ENABLE_I2C_DEBUG_BUFFER` at line 45 of `esp32-hal-i2c.c`.
* When Arduino-Esp32 is installed in Windows with Arduino Boards Manager, `esp32-hal-i2c.c` can be found in:
`C:\Users\{user}\AppData\Local\Arduino15\packages\esp32\hardware\esp32\1.0.1\cores\esp32\`
* When Arduino-Esp32 Development version is installed from GitHub, `esp32-hal-i2c.c` can be found in:
`{arduino Sketch}\hardware\espressif\esp32\cores\esp32\`
```c++
//#define ENABLE_I2C_DEBUG_BUFFER
```
Change it to:
```c++
#define ENABLE_I2C_DEBUG_BUFFER
```
and recompile/upload the resulting code to your ESP32.
Enabling this `#define` will consume an additional 2570 bytes of RAM and include a commensurate amount of code FLASH. If you see the message `"Debug Buffer not Enabled"` in your console log I would suggest you un-comment the line and regenerate the error. Additional information will be supplied on the log console.
## Manually controlled Debugging
Manual logging of the i2c control data buffers can be accomplished by using the debug control function of `Wire()`:
```c++
uint32_t setDebugFlags( uint32_t setBits, uint32_t resetBits);
```
`setBits`, and `resetBits` manually cause output of the control structures to the log console. They are bit fields that enable/disable the reporting of individual control structures during specific phases of the i2c communications sequence. The 32bit values are divided into four 8bit fields. Currently only five bits are defined. ***If an error is detected during normal operations, the relevant control structure will bit added to the log irrespective of the current debug flags.***
* **bit 0** causes DumpI2c to execute
header information about current communications event,
and the dataQueue elements showing the logical i2c transaction commands
* **bit 1** causes DumpInts to execute
Actual sequence of interrupts handled during last communications event, cleared on entry into `ProcQueue()`.
* **bit 2** causes DumpCmdqueue to execute
The last block of commands to the i2c peripheral.
* **bit 3** causes DumpStatus to execute
A descriptive display of the 32bit i2c peripheral status word.
* **bit 4** causes DumpFifo to execute
A buffer listing the sequence of data added to the txFifo of the i2c peripheral.
Of the four division, only three are currently implemented:
* 0xXX - - - - - - : at entry of ProcQueue (`bitFlags << 24`)
* 0x - - XX - - - - : at exit of ProcQueue (`bitFlags << 16`)
* 0x - - - - - - XX : at entry of Flush (`bitFlags`)
For example, to display the sequence of Interrupts processed during the i2c communication transaction, **bit 1** would be set, and, since this information on Interrupt usage would only be valid after the communications have completed, the locus would be *at exit of ProcQueue*. The following code would be necessary.
### code
```c++
uint8_t flag = 1 << 1; // turn on bit 1
uint32_t debugFlag = flag << 16; // correctly position the 8bits of flag as the second byte of setBits.
Wire.setDebugFlags(debugFlag,0);// resetBits=0 says leave all current setBits as is.
Wire.requestFrom(id,byteCount); // read byteCount bytes from slave at id
Wire.setDebugFlags(0,debugFlag); // don't add any new debug, remove debugFlag
```
### output of log console
```
[I][esp32-hal-i2c.c:437] i2cTriggerDumps(): after ProcQueue
[I][esp32-hal-i2c.c:346] i2cDumpInts(): 0 row count INTR TX RX Tick
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x005baac5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x005baac5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [03] 0x0001 0x0080 0x0000 0x0008 0x005baac6
```
# Debug Log example
### Code
To read eight bytes of data from a DS1307 RTCC
```
uint32_t debugFlag = 0x001F0000;
uint8_t ID = 0x68;
uint8_t block=8;
if(debugFlag >0){
Wire.setDebugFlags(debugFlag,0);
}
Wire.beginTransmission(ID);
Wire.write(lowByte(addr));
if((err=Wire.endTransmission(false))!=0) {
Serial.printf(" EndTransmission=%d(%s)",Wire.lastError(),Wire.getErrorText(Wire.lastError()));
if(err!=2) {
Serial.printf(", resetting\n");
if( !Wire.begin()) Serial.printf(" Reset Failed\n");
if(debugFlag >0) Wire.setDebugFlags(0,debugFlag);
return;
} else {
Serial.printf(", No Device present, aborting\n");
currentCommand= NO_COMMAND;
return;
}
}
err = Wire.requestFrom(ID,block,true);
if(debugFlag >0){
Wire.setDebugFlags(0,debugFlag);
}
```
### output of log console
```
[I][esp32-hal-i2c.c:437] i2cTriggerDumps(): after ProcQueue
[E][esp32-hal-i2c.c:318] i2cDumpI2c(): i2c=0x3ffbdc78
[I][esp32-hal-i2c.c:319] i2cDumpI2c(): dev=0x60013000 date=0x16042000
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): lock=0x3ffb843c
[I][esp32-hal-i2c.c:323] i2cDumpI2c(): num=0
[I][esp32-hal-i2c.c:324] i2cDumpI2c(): mode=1
[I][esp32-hal-i2c.c:325] i2cDumpI2c(): stage=3
[I][esp32-hal-i2c.c:326] i2cDumpI2c(): error=1
[I][esp32-hal-i2c.c:327] i2cDumpI2c(): event=0x3ffb85c4 bits=10
[I][esp32-hal-i2c.c:328] i2cDumpI2c(): intr_handle=0x3ffb85f4
[I][esp32-hal-i2c.c:329] i2cDumpI2c(): dq=0x3ffb858c
[I][esp32-hal-i2c.c:330] i2cDumpI2c(): queueCount=2
[I][esp32-hal-i2c.c:331] i2cDumpI2c(): queuePos=1
[I][esp32-hal-i2c.c:332] i2cDumpI2c(): errorByteCnt=0
[I][esp32-hal-i2c.c:333] i2cDumpI2c(): errorQueue=0
[I][esp32-hal-i2c.c:334] i2cDumpI2c(): debugFlags=0x001F0000
[I][esp32-hal-i2c.c:288] i2cDumpDqData(): [0] 7bit 68 W buf@=0x3ffc04b2, len=1, pos=1, ctrl=11101
[I][esp32-hal-i2c.c:306] i2cDumpDqData(): 0x0000: . 00
[I][esp32-hal-i2c.c:288] i2cDumpDqData(): [1] 7bit 68 R STOP buf@=0x3ffc042c, len=8, pos=8, ctrl=11111
[I][esp32-hal-i2c.c:306] i2cDumpDqData(): 0x0000: 5P...... 35 50 07 06 13 09 18 00
[I][esp32-hal-i2c.c:346] i2cDumpInts(): 0 row count INTR TX RX Tick
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000073d5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000073d5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [03] 0x0001 0x0080 0x0000 0x0008 0x000073d6
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 0] Y RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 1] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 2] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 3] Y RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 4] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 5] Y READ val[0] exp[0] en[0] bytes[7]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 6] Y READ val[1] exp[0] en[0] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 7] Y STOP val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 8] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 9] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [10] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [11] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [12] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [13] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [14] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [15] N RSTART val[0] exp[0] en[0] bytes[0]
[I][esp32-hal-i2c.c:385] i2cDumpStatus(): ack(0) sl_rw(0) to(0) arb(0) busy(0) sl(1) trans(0) rx(0) tx(0) sclMain(5) scl(6)
[I][esp32-hal-i2c.c:424] i2cDumpFifo(): WRITE 0x68 0
[I][esp32-hal-i2c.c:424] i2cDumpFifo(): READ 0x68
```
## Explaination of log output
### DumpI2c
```
[I][esp32-hal-i2c.c:437] i2cTriggerDumps(): after ProcQueue
[E][esp32-hal-i2c.c:318] i2cDumpI2c(): i2c=0x3ffbdc78
[I][esp32-hal-i2c.c:319] i2cDumpI2c(): dev=0x60013000 date=0x16042000
[I][esp32-hal-i2c.c:321] i2cDumpI2c(): lock=0x3ffb843c
[I][esp32-hal-i2c.c:323] i2cDumpI2c(): num=0
[I][esp32-hal-i2c.c:324] i2cDumpI2c(): mode=1
[I][esp32-hal-i2c.c:325] i2cDumpI2c(): stage=3
[I][esp32-hal-i2c.c:326] i2cDumpI2c(): error=1
[I][esp32-hal-i2c.c:327] i2cDumpI2c(): event=0x3ffb85c4 bits=10
[I][esp32-hal-i2c.c:328] i2cDumpI2c(): intr_handle=0x3ffb85f4
[I][esp32-hal-i2c.c:329] i2cDumpI2c(): dq=0x3ffb858c
[I][esp32-hal-i2c.c:330] i2cDumpI2c(): queueCount=2
[I][esp32-hal-i2c.c:331] i2cDumpI2c(): queuePos=1
[I][esp32-hal-i2c.c:332] i2cDumpI2c(): errorByteCnt=0
[I][esp32-hal-i2c.c:333] i2cDumpI2c(): errorQueue=0
[I][esp32-hal-i2c.c:334] i2cDumpI2c(): debugFlags=0x001F0000
```
variable | description
---- | ----
**i2c** | *memory address for control block*
**dev** | *memory address for access to i2c peripheral registers*
**date** | *revision date of peripheral silicon 2016, 42 week*
**lock** | *hal lock handle*
**num** | *0,1 which peripheral is being controlled*
**mode** | *configuration of driver 0=none, 1=MASTER, 2=SLAVE, 3=MASTER and SLAVE*
**stage** | *internal STATE of driver 0=not configured, 1=startup, 2=running, 3=done*
**error** | *internal ERROR status 0=not configured, 1=ok, 2=error, 3=address NAK, 4=data NAK, 5=arbitration loss, 6=timeout*
**event** | *handle for interprocess FreeRTOS eventSemaphore for communication between ISR and APP*
**intr_handle** | *FreeRTOS handle for allocated interrupt*
**dq** | *memory address for data queue control block*
**queueCount** | *number of data operations in queue control block*
**queuePos** | *last executed data block*
**errorByteCnt** | *position in current data block when error occured -1=address byte*
**errorQueue** | *queue that was executing when error occurred*
**debugFlags** | *current specified error bits*
### DQ data
```
[I][esp32-hal-i2c.c:288] i2cDumpDqData(): [0] 7bit 68 W buf@=0x3ffc04b2, len=1, pos=1, ctrl=11101
[I][esp32-hal-i2c.c:306] i2cDumpDqData(): 0x0000: . 00
[I][esp32-hal-i2c.c:288] i2cDumpDqData(): [1] 7bit 68 R STOP buf@=0x3ffc042c, len=8, pos=8, ctrl=11111
[I][esp32-hal-i2c.c:306] i2cDumpDqData(): 0x0000: 5P...... 35 50 07 06 13 09 18 00
```
variable | description
--- | ---
**[n]** | *index of data queue element*
**i2c address** | *7bit= 7bit i2c slave address, 10bit= 10bit i2c slave address*
**direction** | *W=Write, R=READ*
**STOP** | *command issued a I2C STOP, else if blank, a RESTART was issued by next dq element.*
**buf@** | *pointer to data buffer*
**len** | *length of data buffer*
**pos** | *last position used in buffer*
**ctrl** | *bit field for data queue control, this bits describe if all necessary commands have been added to peripheral command buffer. in order(START,ADDRESS_Write,DATA,STOP,ADDRESS_value*
**0xnnnn** | *data buffer content, displayable followed by HEX, 32 bytes on a line.*
### DumpInts
```
[I][esp32-hal-i2c.c:346] i2cDumpInts(): 0 row count INTR TX RX Tick
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [01] 0x0001 0x0002 0x0003 0x0000 0x000073d5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [02] 0x0001 0x0200 0x0000 0x0000 0x000073d5
[I][esp32-hal-i2c.c:350] i2cDumpInts(): [03] 0x0001 0x0080 0x0000 0x0008 0x000073d6
```
variable | description
---- | ----
**row** | *array index*
**count** | *number of consecutive, duplicate interrupts*
**INTR** | *bit value of active interrupt (from ..\esp32\tools\sdk\include\soc\soc\i2c_struct.h)*
**TX** | *number of bytes added to txFifo*
**RX** | *number of bytes read from rxFifo*
**Tick** | *current tick counter from xTaskGetTickCountFromISR()*
### DumpCmdQueue
```
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 0] Y RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 1] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 2] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 3] Y RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 4] Y WRITE val[0] exp[0] en[1] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 5] Y READ val[0] exp[0] en[0] bytes[7]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 6] Y READ val[1] exp[0] en[0] bytes[1]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 7] Y STOP val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 8] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [ 9] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [10] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [11] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [12] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [13] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [14] N RSTART val[0] exp[0] en[0] bytes[0]
[E][esp32-hal-i2c.c:243] i2cDumpCmdQueue(): [15] N RSTART val[0] exp[0] en[0] bytes[0]
```
Column | description
---- | ----
**command** | *RSTART= generate i2c START sequence, WRITE= output byte(s), READ= input byte(s), STOP= generate i2c STOP sequence, END= continuation flag for peripheral to pause execution waiting for a refilled command list*
**val** | *value for ACK bit, 0 = LOW, 1= HIGH*
**exp** | *test of ACK bit 0=no, 1=yes*
**en** | *output of val, 0=no, 1=yes*
**bytes** | *number of byte to send(WRITE) or receive(READ) 1..255*
### DumpStatus
```
[I][esp32-hal-i2c.c:385] i2cDumpStatus(): ack(0) sl_rw(0) to(0) arb(0) busy(0) sl(1) trans(0) rx(0) tx(0) sclMain(5) scl(6)
```
variable | description
---- | ----
**ack** | *last value for ACK bit*
**sl_rw** | *mode for SLAVE operation 0=write, 1=read*
**to** | *timeout*
**arb** | *arbitration loss*
**busy** | *bus is inuse by other Master, or SLAVE is holding SCL,SDA*
**sl** | *last address on bus was equal to slave_addr*
**trans** | *a byte has moved though peripheral*
**rx** | *count of bytes in rxFifo*
**tx** | *count of bytes in txFifo*
**sclMain** | *state machine for i2c module. 0: SCL_MAIN_IDLE, 1: SCL_ADDRESS_SHIFT, 2: SCL_ACK_ADDRESS, 3: SCL_RX_DATA, 4: SCL_TX_DATA, 5: SCL_SEND_ACK, 6 :SCL_WAIT_ACK*
**scl** | *SCL clock state. 0: SCL_IDLE, 1: SCL_START, 2: SCL_LOW_EDGE, 3: SCL_LOW, 4: SCL_HIGH_EDGE, 5: SCL_HIGH, 6:SCL_STOP*
### DumpFifo
```
[I][esp32-hal-i2c.c:424] i2cDumpFifo(): WRITE 0x68 0
[I][esp32-hal-i2c.c:424] i2cDumpFifo(): READ 0x68
```
Mode | datavalues
--- | ---
**WRITE** | the following bytes added to the txFifo are in response to a WRITE command
**READ** | the following bytes added to the txFifo are in response to a READ command