Skip to content

I2C debugging and Log Dump Explaination #2325

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Jan 22, 2019
Merged
Changes from 1 commit
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
267 changes: 267 additions & 0 deletions libraries/Wire/doc/i2c_debugging.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,267 @@
# Debugging I2C

With the release of Arduino-ESP32 V1.0.0 the I2C subsystem contains code to exhaustively report communication errors.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

which version? the old one or the new one?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is valid for all version since V1.0.0rc3 .

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the way I understand it is that in v 1.0.0 this is fixed, not that it's fixed starting from rc3 or whatever later on. Maybe change to 1.0.1 to avoid confusion?

* 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***

The Enhanced debug features are enabled by uncommenting the `\\#define ENABLE_I2C_DEBUG_BUFFER` at line 45 of `esp32-hal-i2c.c`.
```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
```c++
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