buserror / simavr

simavr is a lean, mean and hackable AVR simulator for linux & OSX
GNU General Public License v3.0
1.59k stars 369 forks source link

Wrong TWSR status when sending address #137

Open 20Mhz opened 9 years ago

20Mhz commented 9 years ago

Hi, When doing a write transaction, I'm getting the wrong status in TWSR after sending the address. I'm reading 0x28 which stands for data write w ack, I was expecting 0x18, sda+w w ack, which is also what the silicon is replying. How is this status register updated?

_avr_vcd_notify log size runnaway (255) flush problem? Supply Voltage: 3292 mV.. avr_twi_write a4 START:1 STOP:0 ACK:0 INT:1 TWSR:f8 (state 00)

I2C start _avr_twi_status_set 08 avr_twi_write 85 START:0 STOP:0 ACK:0 INT:1 TWSR:08 (state 11) I2C Master address 80 eeprom received start avr_twi_irq_input 01800800 I2C received ACK:1 _avr_twi_status_set 28

Cheers, Ronald

TheCrazyT commented 9 years ago

I'm no expert but it sounds to me like a bug in avr_twi.c . Depends if it stops at : https://github.com/buserror/simavr/blob/master/simavr/sim/avr_twi.c#L281 or at: https://github.com/buserror/simavr/blob/master/simavr/sim/avr_twi.c#L316

Maybe you should try to checkout the commit: 6e6a04b2fa2c16099b8eb6365fa6915340dfb2a6 and see if you still have the problem?

Please let us know. Maybe there was a bug introduced with one of my commits.(id: 47cb0b9b645c98578eb9ec3554cf5d63bdc8b2ab) (but i hope not ...)

20Mhz commented 9 years ago

When I click on 6e6a04b, it seems related to the PDF manual source code. On the other hand, as I mentioned in my comment at 47cb0b9, that looks more suspicious. It may be that there was a previous bug, but it seems the solution you implemented is not covering the case for SDA+W (0x18)... I'll review further when I find the time. Thanks for commenting, Btw, isn't simavr cool piece of software? Cheers, Ronald

20Mhz commented 9 years ago

Maybe we have to set a precedence rule for TWI_COND_ADDR & TWI_COND_WRITE to return TWI_MTX_ADR_ACK... I can try this later today... I remember p->state was 0x1d so it kind of make sense... EDITED: I'm suggesting the following at avr_twi.c:311 ...

                if(p->state & (TWI_COND_WRITE | TWI_COND_ADDR) ){
                    _avr_twi_delay_state(p, 9,
                        p->state & TWI_COND_ACK ?
                                TWI_MTX_ADR_ACK : TWI_MTX_ADR_NACK);
                } else if(p->state & TWI_COND_WRITE){
                    _avr_twi_delay_state(p, 0,
                            p->state & TWI_COND_ACK ?
                                    TWI_MTX_DATA_ACK : TWI_MTX_DATA_NACK);
                }

some code is rising my start bit now and I can't figure out where... I tried to add a watch point with lldb but for some reason it doesn't catch it (I getting the REstart message).

I2C start
_avr_twi_status_set 08
avr_twi_write 85 START:0 STOP:0 ACK:0 INT:1 TWSR:08 (state 11)
I2C Master address 80
eeprom received start
avr_twi_irq_input 01800800
I2C received ACK:1
_avr_twi_status_set 18
Supply Voltage: 3292 mV..
avr_twi_write a4 START:1 STOP:0 ACK:0 INT:1 TWSR:18 (state 0d)
I2C REstart
I did:
b avr_twi.c:192 
run -v -v -t -m atmega128 -f 8000000 ./build/test_i2c.elf 
w s e -w write -- (uint32_t *) &p->twsta
Watchpoint created: Watchpoint 1: addr = 0x101807ae4 size = 8 state = enabled type = w
new value: 0x0000187400001a74

but somehow its not breaking when the reg value is changing... any clue???

Regards, Ronald

TheCrazyT commented 9 years ago

To be honest ... i never worked with watch points. Are you shure that gdb can handle a watchpoint on structures?

According to:

https://github.com/buserror/simavr/blob/65dcb8859503dd85ebc251b16f5528cc8a180a3e/simavr/sim/sim_avr_types.h#L45

it has properties like reg, bit and mask. Maybe try to create a watchpoint on twsta.reg instead?

20Mhz commented 9 years ago

ok, this is what was going on, p->twsta.reg is just giving me the fixed id (index) of the TWCR register (0x74), but actual data is at &avr->data[0x74] location, so this is where I needed to set the watch point, which is now finally breaking: w s e -w write -- (uint8_t *) &avr->data[116] c

Watchpoint 1 hit:
old value: 0x0000000000000085
new value: 0x00000000000000a4
Process 98496 stopped
* thread #1: tid = 0x235475, 0x000000010000528e run_avr`avr_core_watch_write(avr=0x0000000101003c00, addr=116, v='?') + 478 at sim_core.c:143, queue = 'com.apple.main-thread', stop reason = watchpoint 1
    frame #0: 0x000000010000528e run_avr`avr_core_watch_write(avr=0x0000000101003c00, addr=116, v='?') + 478 at sim_core.c:143
   140      }
   141  
   142      avr->data[addr] = v;
-> 143  }
   144  
   145  uint8_t avr_core_watch_read(avr_t *avr, uint16_t addr)
   146  {
(lldb) bt
* thread #1: tid = 0x235475, 0x000000010000528e run_avr`avr_core_watch_write(avr=0x0000000101003c00, addr=116, v='?') + 478 at sim_core.c:143, queue = 'com.apple.main-thread', stop reason = watchpoint 1
  * frame #0: 0x000000010000528e run_avr`avr_core_watch_write(avr=0x0000000101003c00, addr=116, v='?') + 478 at sim_core.c:143
    frame #1: 0x0000000100002f0f run_avr`avr_twi_write(avr=0x0000000101003c00, addr=116, v='?', param=0x0000000101009a80) + 143 at avr_twi.c:140
    frame #2: 0x00000001000055b0 run_avr`_avr_set_r(avr=0x0000000101003c00, r=116, v='?') + 336 at sim_core.c:178
    frame #3: 0x000000010000579c run_avr`_avr_set_ram(avr=0x0000000101003c00, addr=116, v='?') + 60 at sim_core.c:210
    frame #4: 0x00000001000074ed run_avr`avr_run_one(avr=0x0000000101003c00) + 6397 at sim_core.c:862
    frame #5: 0x000000010000abab run_avr`avr_callback_run_raw(avr=0x0000000101003c00) + 27 at sim_avr.c:311 [opt]
    frame #6: 0x000000010000b1ff run_avr`avr_run(avr=0x0000000101003c00) + 15 at sim_avr.c:348 [opt]
    frame #7: 0x000000010000211f run_avr`main(argc=9, argv=0x00007fff5fbff9e0) + 3103 at run_avr.c:207
    frame #8: 0x00007fff8b5fd5c9 libdyld.dylib`start + 1

frame select 4
(lldb) expr -f hex -- opcode
(uint32_t) $3 = 0x00008320
20Mhz commented 9 years ago

Mmmm... apparently is actually getting a store operation to 0x74 which is the TWCR register and data seems to be 0xa4, which flags the start condition... I don't see this on the assembly code generated by gcc though... Do you know how to enable the assembly traces on the simulator? STATE macro looks promising, but is not doing the trick for me...not sure what I'm missing...

According to GCC I should be writing 0x84 (-124) instead:

.L7:
    ldi r24,lo8(115)
    ldi r25,0
    ldd r18,Y+4
    movw r30,r24
    st Z,r18
    ldi r24,lo8(116)
    ldi r25,0
    ldi r18,lo8(-124)
    movw r30,r24
    st Z,r18
    nop

I've just confirmed the sequence using "avr-objdump -d my.elf"

     4be:   94 ea           ldi r25, 0xA4   ; 164
     4c0:   90 93 74 00     sts 0x0074, r25
...
     4e2:   85 e8           ldi r24, 0x85   ; 133
     4e4:   80 93 74 00     sts 0x0074, r24
...
     4fe:   84 e8           ldi r24, 0x84   ; 132
     500:   80 93 74 00     sts 0x0074, r24

But somehow the simulator is getting an 0xa4 on the third one instead of 0x84... I'd really like to see those traces during simulation...

TheCrazyT commented 9 years ago

well i believe for trace stuff you need to enable the following line:

https://github.com/buserror/simavr/blob/master/simavr/Makefile#L31

You might need to set:

avr->log = LOG_TRACE

after that in your program. (just like at: https://github.com/buserror/simavr/blob/65dcb8859503dd85ebc251b16f5528cc8a180a3e/tests/test_atmega2560_uart_echo.c#L8)

But keep in mind that trace info can produce unexpected problems. I myself already noticed that a program with tracing enabled was crashing for some reason (sadly can't remember what happened exactly ...)

Btw: I prefer debugging with a GUI like eclipse cdt for such things. Debugging with pure gdb probably works,too but i guess it takes longer.

20Mhz commented 9 years ago

Hi again, I'm used to working at the console. I think is good for planning and thinking v/s of just point and click..anyway...I followed the assembly only to realize my code was jumping out of the function sooner than I realized. This is the deal, the proposed patch seem to work, but there is still some sort of a race and the TWSR is not getting updated fast enough, let me explain, this is my AVR code:

    // Set pointer  
    TWDR = pointer; 
    TWCR = (1<<TWINT) | (1<<TWEN); // Send DATA+W // 10000100 = -124
    while(!(TWCR & (1<<TWINT))); // Waint for SLA+W to be transmitted
    //printf("write pointer state is: 0x%x\n", 0xFF & (TWSR & 0xF8));
    if((TWSR & 0xF8) != TWI_MTX_DATAW_ACK) // check status
            return -1;

By the time I check TWSR the register is not yet updated, on the other hand if I add the printf there the code runs as expected. I think TWSR should be updated by the time we see the TWINT at TWCR. Do you think some sort of synchronization construct should be used? a mutex maybe? any ideas? Do you know what function is responsible from updating the register value?

Successful communication below (notice that the printed TWSR value after writing the pointer value is still 0x18 but later gets updated to 0x28):

avr_twi_write a4 START:1 STOP:0 ACK:0 INT:1 TWSR:f8 (state 00)
>>>>> I2C start
_avr_twi_status_set 08
address returned state is: 0x8..
avr_twi_write 84 START:0 STOP:0 ACK:0 INT:1 TWSR:08 (state 11)
I2C Master address 80
eeprom received start
avr_twi_irq_input 01800800
I2C received ACK:1
_avr_twi_status_set 18
address returned state is: 0x18..
avr_twi_write 84 START:0 STOP:0 ACK:0 INT:1 TWSR:18 (state 1d)
I2C WRITE byte 00 to 80
state 15 want 10
avr_twi_irq_input 01800800
I2C received ACK:1
_avr_twi_status_set 28
write pointer state is: 0x18..
avr_twi_write 84 START:0 STOP:0 ACK:0 INT:1 TWSR:28 (state 1d)
I2C WRITE byte 39 to 80
state 15 want 10
avr_twi_irq_input 01800800
I2C received ACK:1
eeprom set address to 0x1900
avr_twi_write 84 START:0 STOP:0 ACK:0 INT:1 TWSR:28 (state 1d)
I2C WRITE byte 9f to 80
state 15 want 10
avr_twi_irq_input 01800800
I2C received ACK:1
eeprom WRITE data 0x0100: 9f
avr_twi_write 94 START:0 STOP:1 ACK:0 INT:1 TWSR:28 (state 0d)
<<<<< I2C stop

Regards, Ronald

TheCrazyT commented 9 years ago

Hm "TWSR is not getting updated fast enough".

This reminds me on a pull request where some guy changed the delay to 0: Pull Request: https://github.com/buserror/simavr/pull/102 Commit: https://github.com/dougszumski/simavr/commit/6c6b0835db5a29f7083e8e582711a684f18ae5c6

Maybe you got a similar problem but with other "_avr_twi_delay_state" function calls. Of course i'm not an expert and could be completely wrong :)

vintagepc commented 4 years ago

So this is a hell of a necro but I can confirm a number of these issues trying to debug high-speed TWI at 400Mhz.

I've implemented correct calculation of the TWI clock rate for the status delay function, and fixed a bug where we set the wrong ACK type on writes. (PR coming once I fix the following...)

However, there is still a bug with the TWINT bit in TWSR. Far as I can tell, this should be cleared while the TWI is "busy" and set back to 1 afterwards when the operation is done (and presumably, TWSR is ready to read for NACK/ACK.

However, that does not appear to be the case, and code like this will fail as a result, even with a correct clock rate. Whether the result simulates correctly or not depends purely on how many other things you're doing between setting TWINT and checking it again... e.g. printf debug...

 TWDR = TW_WRITE | (address << 1);
  TWCR = _BV(TWEN) | _BV(TWINT);
  while(!(TWCR & _BV(TWINT)));

in GDB it confirms that bit 7 of TWINT is not cleared and the while loop only executes once:

while(!(TWCR & _BV(TWINT)));
(gdb) x (uint8_t *)0xBC
0x8000bc:       0x00000084

Just wanted to post this here for confirmation to make sure I'm understanding this right, in case anyone else with a stake in this is still interested...

So it's not so much that TWSR is not getting updated in time now, it is that we are not setting the "busy state" of the hardware TWI correctly for the programming pattern it is used in - I believe TWINT should go low until (e.g.) the TX cycle of the master has completed, and return high once the slave has ACKED.

diff --git a/simavr/sim/avr_twi.c b/simavr/sim/avr_twi.c
index 5e351e5..521c03c 100644
--- a/simavr/sim/avr_twi.c
+++ b/simavr/sim/avr_twi.c
@@ -105,12 +105,22 @@ avr_twi_set_state_timer(
        return 0;
 }

+// Quick exponent helper for integer values > 0.
+static uint32_t _avr_twi_quick_exp(uint8_t base, uint8_t exp)
+{
+       uint32_t result = 1;
+       for (uint8_t i=exp; i>0; i--)
+               result *= base;
+       return result;
+}
+
 /*
  * This is supposed to trigger a timer whose duration is a multiple
  * of 'twi' clock cycles, which should be derived from the prescaler
  * (100khz, 400khz etc).
  * Right now it cheats and uses one twi cycle == one usec.
  */
+
 static void
 _avr_twi_delay_state(
                avr_twi_t * p,
@@ -118,9 +128,13 @@ _avr_twi_delay_state(
                uint8_t state)
 {
        p->next_twstate = state;
-       // TODO: calculate clock rate, convert to cycles, and use that
-       avr_cycle_timer_register_usec(
-                       p->io.avr, twi_cycles, avr_twi_set_state_timer, p);
+       uint8_t prescale = avr_regbit_get(p->io.avr, p->twps);
+       uint16_t bitrate =  p->io.avr->data[p->r_twbr];
+       uint32_t clockdiv = 16u+((bitrate<<1u)*_avr_twi_quick_exp(4,prescale));
+       //One TWI cycle is "clockdiv" AVR Cycles. So we can wait in these directly.
+       // printf("Waiting %d cycles\n",clockdiv*twi_cycles);
+       avr_cycle_timer_register(
+                       p->io.avr, twi_cycles*clockdiv, avr_twi_set_state_timer, p);
 }

 static void
@@ -309,14 +323,14 @@ avr_twi_write(
                                                p->state & TWI_COND_ACK ?
                                                                TWI_MRX_ADR_ACK : TWI_MRX_ADR_NACK);
                        } else {
-                               if(p->state & TWI_COND_WRITE){
+                               if(p->state & TWI_COND_ADDR){
                                        _avr_twi_delay_state(p, 0,
                                                        p->state & TWI_COND_ACK ?
-                                                                       TWI_MTX_DATA_ACK : TWI_MTX_DATA_NACK);
+                                                                       TWI_MTX_ADR_ACK : TWI_MTX_ADR_NACK);
                                }else{
                                        _avr_twi_delay_state(p, 9,
                                                        p->state & TWI_COND_ACK ?
-                                                                       TWI_MTX_ADR_ACK : TWI_MTX_ADR_NACK);
+                                                                       TWI_MTX_DATA_ACK : TWI_MTX_DATA_NACK);
                                }
                        }
                }
vintagepc commented 4 years ago

I think the problem is an incorrect use of TWINT as SimAVR's "interrupt raised" handler -

    .twi = {
             .enable = AVR_IO_REGBIT(TWCR, TWIE),
             .raised = AVR_IO_REGBIT(TWCR, TWINT),
             .raise_sticky = 1,
             .vector = TWI_vect,
}

but I'm not entirely familiar with operation in this area so I would appreciate external input on this... is it safe to clear TWINT when _avr_twi_delay_state is called and reset it again when the state actually changes after the timer? (It does have the desired effect - just not sure what the implications are for the rest of the interrupt system).