Getting a second board to work with current µTVM

tgall_foo · December 14, 2020, 8:48pm

I’ve been trying to get µTVM working on physical hardware, in this case an STM32F746 discovery board with zephyr.

I’m not quite the point where I’ve been able to successfully perform inference using a trivial model.

Python: https://github.com/tom-gall/utvm-examples

Slightly hacked up zephyr project: https://github.com/tom-gall/zephyr-runtime.git

With debug DEBUG:tvm.micro.transport.base:micro-rpc: opening transport DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 1 B]: fe . DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 4 B]: 03 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 3 B]: 00 00 02 … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 2 B]: 66 77 fw DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 4 B]: 04 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 3 B]: 83 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 1 B]: 01 . DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s} <- [ 2 B]: cf 9f … DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s} 128 B -> [ 11 B]: ff fd 04 00 00 00 83 a6 01 01 c2 … DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s} 128 B -> [ 1 B]: a3 . DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 30 00 00 00 0… DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 45 B]: 0000 25 00 00 00 00 00 00 00 09 00 00 00 01 00 00 00 %… 0010 0b 00 00 00 11 00 00 00 00 00 00 00 72 75 6e 74 …runt 0020 69 6d 65 2e 53 79 73 74 65 6d 4c 69 62 ime.SystemLib DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 01 52 .R DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 8 B]: ff fd 1f 00 00 00 83 a6 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 10 14 00 00 00 00 00 00 00 04 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 01 00 00 00 03 00 00 00 00 80 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 02 80 ff ff ff ff ff ff ff ff 33 …3 DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 1 B]: a1 . DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 1b 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 28 B]: 0000 10 00 00 00 00 00 00 00 03 00 00 00 00 80 02 80 … 0010 ff ff ff ff ff ff ff ff 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 38 00 8. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 3 B]: ff fd 2b …+ DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 00 83 a6 10 20 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 00 04 00 00 00 02 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 00 03 00 00 00 09 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 00 00 00 80 00 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 2 B]: 5d bd ]. DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 2b 00 00 00 +… DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 44 B]: 0000 20 00 00 00 00 00 00 00 0a 00 00 00 02 00 00 00 … 0010 03 00 00 00 00 00 00 00 00 80 02 80 ff ff ff ff … 0020 ff ff ff ff 0a 00 00 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 20 e9 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 10 B]: ff fd 17 00 00 00 83 a6 10 0c … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 00 00 00 00 00 04 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 10 B]: 01 00 00 00 04 00 00 00 50 90 …P. DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 3f 00 00 00 ?.. DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 60 B]: 0000 34 00 00 00 00 00 00 00 09 00 00 00 01 00 00 00 4… 0010 0b 00 00 00 20 00 00 00 00 00 00 00 74 76 6d 2e …tvm. 0020 72 70 63 2e 73 65 72 76 65 72 2e 4d 6f 64 75 6c rpc.server.Modul 0030 65 47 65 74 46 75 6e 63 74 69 6f 6e eGetFunction DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 16 4f .O DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 3 B]: ff fd 1f … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 00 83 a6 10 14 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 00 04 00 00 00 01 00 00 00 03 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 00 01 80 02 80 ff ff ff ff … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 6 B]: ff ff ff ff 46 a2 …F. DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 53 00 00 00 S… DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 84 B]: 0000 48 00 00 00 00 00 00 00 03 00 00 00 01 80 02 80 H… 0010 ff ff ff ff ff ff ff ff 03 00 00 00 09 00 00 00 … 0020 0b 00 00 00 00 00 00 00 00 80 00 00 00 00 00 00 … 0030 14 00 00 00 00 00 00 00 5f 6c 6f 6f 6b 75 70 5f …lookup 0040 6c 69 6e 6b 65 64 5f 70 61 72 61 6d 00 00 00 00 linked_param… 0050 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 6b 82 k. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 4 B]: ff fd 23 00 …#. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 83 a6 10 18 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 04 00 00 00 02 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 00 04 00 00 00 04 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 5 B]: 00 00 00 d5 a4 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 53 00 00 00 S… DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 84 B]: 0000 48 00 00 00 00 00 00 00 03 00 00 00 01 80 02 80 H… 0010 ff ff ff ff ff ff ff ff 03 00 00 00 09 00 00 00 … 0020 0b 00 00 00 00 00 00 00 00 80 00 00 00 00 00 00 … 0030 14 00 00 00 00 00 00 00 5f 6c 6f 6f 6b 75 70 5f …lookup 0040 6c 69 6e 6b 65 64 5f 70 61 72 61 6d 00 00 00 00 linked_param… 0050 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 6b 82 k. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 4 B]: ff fd 23 00 …#. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 83 a6 10 18 00 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 11 B]: 00 04 00 00 00 02 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 12 B]: 00 00 04 00 00 00 04 00 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [ 4 B]: 00 00 d5 a4 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: ff fd … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 4 B]: 53 00 00 00 S… DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 3 B]: 83 a6 10 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 84 B]: 0000 48 00 00 00 00 00 00 00 03 00 00 00 01 80 02 80 H… 0010 ff ff ff ff ff ff ff ff 03 00 00 00 09 00 00 00 … 0020 0b 00 00 00 00 00 00 00 00 80 00 00 00 00 00 00 … 0030 14 00 00 00 00 00 00 00 5f 6c 6f 6f 6b 75 70 5f …lookup 0040 6c 69 6e 6b 65 64 5f 70 61 72 61 6d 00 00 00 00 linked_param… 0050 00 00 00 00 … DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s} <- [ 2 B]: 6b 82 k. DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s} 128 B -> [err: SerialException]

@areusch any thoughts?

areusch · December 14, 2020, 9:04pm

hi @tgall_foo, which revision of the TVM repo are you using?

tgall_foo · December 14, 2020, 9:26pm

I’m on main, looks like a Dec 6th pull. Good enough time as any to get to the latest.

tgall_foo · December 14, 2020, 10:35pm

Moving forward to current on Main seems a bit worse.

Info : Unable to match requested speed 2000 kHz, using 1800 kHz
shutdown command invoked
DEBUG:tvm.micro.contrib.zephyr:zephyr transport: found UART baudrate from devicetree: 115200
DEBUG:tvm.micro.transport.base:micro-rpc: opening transport
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  1 B]: fe                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  4 B]: 03 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  3 B]: 00 00 02                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: 66 77                                            fw
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  4 B]: 04 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  3 B]: 83 00 00                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  1 B]: 01                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: cf 9f                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s}  128 B -> [  3 B]: ff fd 04                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s}  128 B -> [  9 B]: 00 00 00 83 a6 01 01 c2 a3                       .........
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 30 00 00 00                                      0...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 45 B]:
0000  25 00 00 00 00 00 00 00 09 00 00 00 01 00 00 00  %...............
0010  0b 00 00 00 11 00 00 00 00 00 00 00 72 75 6e 74  ............runt
0020  69 6d 65 2e 53 79 73 74 65 6d 4c 69 62           ime.SystemLib
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 01 52                                            .R
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 83 a6 10 14 00 00 00 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 04 00 00 00 01 00 00 00 03 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 80 02 80 ff ff ff ff ff ff ff              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  3 B]: ff 33 a1                                         .3.
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [IoTimeoutError 30.00s]
DEBUG:tvm.micro.transport.base:micro-rpc: closing transport
Traceback (most recent call last):
  File "./utvm-stm32f746-tflite.py", line 78, in <module>
  File "/home/tgall/tvm/tvm/python/tvm/micro/session.py", line 97, in get_system_lib
    return self._rpc.get_function("runtime.SystemLib")()
  File "/home/tgall/tvm/tvm/python/tvm/rpc/client.py", line 73, in get_function
    return self._sess.get_function(name)
  File "/home/tgall/tvm/tvm/python/tvm/runtime/module.py", line 84, in get_function
    check_call(
  File "/home/tgall/tvm/tvm/python/tvm/_ffi/base.py", line 344, in check_call
    raise get_last_ffi_error()
tvm._ffi.base.TVMError: MicroSessionTimeoutError: failed to read reply message after timeout 30s

areusch · December 14, 2020, 11:25pm

this almost looks like dropped serial bytes to me. I don’t see the micro’s packet header reply after “runtime.SystemLib.” I think there are 5 missing bytes “ff fd xx xx xx.”

tgall_foo · December 14, 2020, 11:50pm

Rerunning it a few times (or maybe I’m hitting the return key harder seems to get about this far most of the time however it does stop earlier occasionally.

Am I reading this right it is doing a function look up ?

shutdown command invoked
DEBUG:tvm.micro.contrib.zephyr:zephyr transport: found UART baudrate from devicetree: 115200
DEBUG:tvm.micro.transport.base:micro-rpc: opening transport
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  1 B]: fe                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  4 B]: 03 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  3 B]: 00 00 02                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: 66 77                                            fw
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  4 B]: 04 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  3 B]: 83 00 00                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  1 B]: 01                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: write {10.00s}        <- [  2 B]: cf 9f                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s}  128 B -> [  9 B]: ff fd 04 00 00 00 83 a6 01                       .........
DEBUG:tvm.micro.transport.base:micro-rpc: read { 5.00s}  128 B -> [  3 B]: 01 c2 a3                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 30 00 00 00                                      0...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 45 B]:
0000  25 00 00 00 00 00 00 00 09 00 00 00 01 00 00 00  %...............
0010  0b 00 00 00 11 00 00 00 00 00 00 00 72 75 6e 74  ............runt
0020  69 6d 65 2e 53 79 73 74 65 6d 4c 69 62           ime.SystemLib
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 01 52                                            .R
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  7 B]: ff fd 1f 00 00 00 83                             .......
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: a6 10 14 00 00 00 00 00 00 00 04 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 00 01 00 00 00 03 00 00 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 80 02 80 ff ff ff ff ff ff ff ff 33              ...........3
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  1 B]: a1                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 1b 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 28 B]:
0000  10 00 00 00 00 00 00 00 03 00 00 00 00 80 02 80  ................
0010  ff ff ff ff ff ff ff ff 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 38 00                                            8.
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  1 B]: ff                                               .
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: fd 2b 00 00 00 83 a6 10 20 00 00 00              .+..........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 00 00 04 00 00 00 02 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 00 00 00 03 00 00 00 09 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 00 00 00 00 80 00 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  3 B]: 00 5d bd                                         .].
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 2b 00 00 00                                      +...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 44 B]:
0000  20 00 00 00 00 00 00 00 0a 00 00 00 02 00 00 00  ................
0010  03 00 00 00 00 00 00 00 00 80 02 80 ff ff ff ff  ................
0020  ff ff ff ff 0a 00 00 00 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 20 e9                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 10 B]: ff fd 17 00 00 00 83 a6 10 0c                    ..........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 00 00 00 00 00 04 00 00 00 01              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  9 B]: 00 00 00 04 00 00 00 50 90                       .......P.
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 3f 00 00 00                                      ?...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 60 B]:
0000  34 00 00 00 00 00 00 00 09 00 00 00 01 00 00 00  4...............
0010  0b 00 00 00 20 00 00 00 00 00 00 00 74 76 6d 2e  ............tvm.
0020  72 70 63 2e 73 65 72 76 65 72 2e 4d 6f 64 75 6c  rpc.server.Modul
0030  65 47 65 74 46 75 6e 63 74 69 6f 6e              eGetFunction
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 16 4f                                            .O
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  3 B]: ff fd 1f                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 00 83 a6 10 14 00 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 00 04 00 00 00 01 00 00 00 03                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  8 B]: 00 00 00 01 80 02 80 ff                          ........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  9 B]: ff ff ff ff ff ff ff 46 a2                       .......F.
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 53 00 00 00                                      S...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 84 B]:
0000  48 00 00 00 00 00 00 00 03 00 00 00 01 80 02 80  H...............
0010  ff ff ff ff ff ff ff ff 03 00 00 00 09 00 00 00  ................
0020  0b 00 00 00 00 00 00 00 00 80 00 00 00 00 00 00  ................
0030  14 00 00 00 00 00 00 00 5f 6c 6f 6f 6b 75 70 5f  ........_lookup_
0040  6c 69 6e 6b 65 64 5f 70 61 72 61 6d 00 00 00 00  linked_param....
0050  00 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 6b 82                                            k.
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  5 B]: ff fd 23 00 00                                   ..#..
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 83 a6 10 18 00 00 00 00 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 04 00 00 00 02 00 00 00 00 00 00              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 04 00 00 00 04 00 00 00 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [  4 B]: 00 00 d5 a4                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: ff fd                                            ..
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  4 B]: 53 00 00 00                                      S...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  3 B]: 83 a6 10                                         ...
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [ 84 B]:
0000  48 00 00 00 00 00 00 00 03 00 00 00 01 80 02 80  H...............
0010  ff ff ff ff ff ff ff ff 03 00 00 00 09 00 00 00  ................
0020  0b 00 00 00 00 00 00 00 00 80 00 00 00 00 00 00  ................
0030  14 00 00 00 00 00 00 00 5f 6c 6f 6f 6b 75 70 5f  ........_lookup_
0040  6c 69 6e 6b 65 64 5f 70 61 72 61 6d 00 00 00 00  linked_param....
0050  00 00 00 00                                      ....
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}        <- [  2 B]: 6b 82                                            k.
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 10 B]: ff fd 23 00 00 00 83 a6 10 18                    ..#.......
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 12 B]: 00 00 00 00 00 00 00 04 00 00 00 02              ............
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [ 11 B]: 00 00 00 00 00 00 00 04 00 00 00                 ...........
DEBUG:tvm.micro.transport.base:micro-rpc: read {30.00s}  128 B -> [IoTimeoutError 30.00s]
DEBUG:tvm.micro.transport.base:micro-rpc: closing transport
Traceback (most recent call last):
  File "./utvm-stm32f746-tflite.py", line 77, in <module>
    graph_mod = tvm.micro.create_local_graph_runtime(
  File "/home/tgall/tvm/tvm/python/tvm/micro/session.py", line 216, in create_local_graph_runtime
    fcreate(graph_json_str, mod, lookup_remote_linked_param, *device_type_id)
  File "/home/tgall/tvm/tvm/python/tvm/_ffi/_ctypes/packed_func.py", line 237, in __call__
    raise get_last_ffi_error()
tvm._ffi.base.TVMError: Traceback (most recent call last):
  [bt] (6) /home/tgall/tvm/tvm/build/libtvm.so(TVMFuncCall+0x63) [0x7f2e10d9b1c3]
  [bt] (5) /home/tgall/tvm/tvm/build/libtvm.so(+0x1b833f8) [0x7f2e10e193f8]
  [bt] (4) /home/tgall/tvm/tvm/build/libtvm.so(+0x1b82e98) [0x7f2e10e18e98]
  [bt] (3) /home/tgall/tvm/tvm/build/libtvm.so(tvm::runtime::GraphRuntimeCreate(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, tvm::runtime::Module const&, std::vector<DLContext, std::allocator<DLContext> > const&, tvm::runtime::PackedFunc)+0xfe) [0x7f2e10e18cfe]
  [bt] (2) /home/tgall/tvm/tvm/build/libtvm.so(tvm::runtime::GraphRuntime::Init(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, tvm::runtime::Module, std::vector<DLContext, std::allocator<DLContext> > const&, tvm::runtime::PackedFunc)+0x325) [0x7f2e10e187d5]
  [bt] (1) /home/tgall/tvm/tvm/build/libtvm.so(tvm::runtime::GraphRuntime::SetupStorage()+0x955) [0x7f2e10e16965]
  [bt] (0) /home/tgall/tvm/tvm/build/libtvm.so(+0xbcf3d9) [0x7f2e0fe653d9]
  File "/home/tgall/tvm/tvm/python/tvm/_ffi/_ctypes/packed_func.py", line 81, in cfun
    rv = local_pyfunc(*pyargs)
  File "/home/tgall/tvm/tvm/python/tvm/micro/session.py", line 181, in lookup_remote_linked_param
    lookup_linked_param = mod.get_function("_lookup_linked_param")
  File "/home/tgall/tvm/tvm/python/tvm/runtime/module.py", line 84, in get_function
    check_call(
  File "/home/tgall/tvm/tvm/python/tvm/_ffi/base.py", line 344, in check_call
    raise get_last_ffi_error()
MicroSessionTimeoutError: failed to read reply message after timeout 30s
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}       <- [  2 B]: [err: AttributeError]
Traceback (most recent call last):
  File "/home/tgall/tvm/tvm/python/tvm/micro/transport/base.py", line 266, in write
    bytes_written = self.child.write(data, timeout_sec)
  File "/home/tgall/tvm/tvm/python/tvm/micro/transport/serial.py", line 123, in write
    self._port.write_timeout = timeout_sec
AttributeError: 'NoneType' object has no attribute 'write_timeout'
DEBUG:tvm.micro.transport.base:micro-rpc: write {30.00s}       <- [  2 B]: [err: AttributeError]
Traceback (most recent call last):
  File "/home/tgall/tvm/tvm/python/tvm/micro/transport/base.py", line 266, in write
    bytes_written = self.child.write(data, timeout_sec)
  File "/home/tgall/tvm/tvm/python/tvm/micro/transport/serial.py", line 123, in write
    self._port.write_timeout = timeout_sec
AttributeError: 'NoneType' object has no attribute 'write_timeout'

areusch · December 15, 2020, 1:12am

Yeah that’s correct. This happened to me before as well, and my conclusion was that there was a problem with the way I’d attached my board to the reference VM. Could you tell me more about how you’re running TVM (I.e. in a VM or natively)?

tgall_foo · December 16, 2020, 4:45pm

Catching everyone up from the slack discussion

pop_OS 20.04 - no modem manager or anything to get int the way.

The fun part is this is the same setup I have been using for awhile. Maybe time to go back to RTOSless and make sure that is working.

areusch · December 16, 2020, 7:06pm

one thing you may try is updating the ST-LINK VCP firmware.

this could also be a bug in the serial transport’s receive code. you could try to disable receive timeouts with:

with tvm.micro.Session(..., timeout_override=tvm.micro.transport.debug_transport_timeouts(5)) as sess: