-
Notifications
You must be signed in to change notification settings - Fork 7.6k
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
Changes from 1 commit
Commits
File filter
Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
There are no files selected for viewing
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
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. | ||
* 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 |
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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 .
There was a problem hiding this comment.
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?