blob: 69de785f998c931628e3b3a4825c64b33efc3441 (
plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
|
* Track down the I²C lag.
The "- 0" markers are the number of milliseconds a log output to
serial took, so also convienently show when the log did its output to
serial. It doesn't seem like logging is the problem here.
Each write -> stopped is sub-milliscend, but write -> write has a
millisecond lag.
But the weirdest thing is the "i2c data" bit, which is where the main
loop has pulled the I²C data from its ring bufffer. From previous logs
(not shown) the time at the end of pulling from the ring buffer is the
same at the start. So somewhere there's at least 1ms being lost
between the stopped event and the start of the main loop.
This may need to wait for a logic analyzer to get more accurate
timings.
In the mean-time we can add number-of-calls counters and time-inside
logs from interrupt handlers that we can dump every second or so to
try and figure out where the clock cycles are going.
#+BEGIN
[0] TRACE ble::rtc -- setting up clock
[0] TRACE ble::rtc -- set prescaler!
[0] INFO ble::uarte1 -- setting up dma: p: 20000008, maxcnt: 128
[0] INFO ble::uarte1 -- rxstarted
- 0[2] INFO ble -- - 0Bootstrap complete.
- 0
[11121] TRACE ble::i2c -- i²c write
[11121] TRACE ble::i2c -- write done
[11121] TRACE ble::i2c -- i²c stopped: 2
- 0[11122] TRACE ble::i2c -- i²c write
[11122] TRACE ble::i2c -- write done
[11122] TRACE ble::i2c -- i²c stopped: 8
- 0[11125] INFO ble -- i2c data
- 0[11138] TRACE ble::i2c -- i²c write
[11138] TRACE ble::i2c -- write done
[11138] TRACE ble::i2c -- i²c stopped: 2
- 0[11139] TRACE ble::i2c -- i²c write
[11139] TRACE ble::i2c -- write done
[11139] TRACE ble::i2c -- i²c stopped: 8
- 0[11141] INFO ble -- - 0i2c data
- 0
#+END
|
