search

antmicro-labs / voice-assistant

Apache License 2.0
0 stars 1 forks source link

Zephyr don't seem to start the application #23

Closed zawadzki-dawid closed 4 years ago

zawadzki-dawid commented 4 years ago

Today together with @plonajakub and @Marzecki we tried to debug our application and we approached the problem we don't know how to solve. We set up breakpoints in our code, then we tried to go step by step but it looks like it halts somewhere in zephyrproject files, debugger don't get through to our code. We use debugger which can be found under zephyr-sdk-0.11.2/riscv64-zephyr-elf/bin/riscv64-zephyr-elf-gdb and our project can be found in micro-speech-build-fix branch.

Loading files to renode Screenshot from 2020-04-23 16-39-32

Continue don't seem to do anything Screenshot from 2020-04-23 16-39-44

Same here Screenshot from 2020-04-23 16-42-36

The last log is being logged endlessly Screenshot from 2020-04-23 16-40-08

pgielda commented 4 years ago

Screenshots are very useful. I am guessing your memory map does not match. You can execute "sysbus.cpu LogFunctionNames True" in monitor before you start. (more info here: https://renode.readthedocs.io/en/latest/basic/logger.html) You will then see a trace. Another question is what is at 0xB0001XXX and at 0xE0009834. The last thing looks like a peripheral (not defined in Renode) that is being polled.

I am adding @mateusz-holenko from Renode team to the conversation

mateusz-holenko commented 4 years ago

@zawadzki-dawid Could you share resc/repl files, a binary you are using (elf would be best) and a configuration file generated by LiteX (csr.csv or csr.json or headers mem.h/csr.h)?

zawadzki-dawid commented 4 years ago

@mateusz-holenko Everything can be found here.

zawadzki-dawid commented 4 years ago

@mateusz-holenko I forgot to add that we commented out the last instruction in .resc file. Instead we used a binary that was generated from our code you can find here under /tensorflow/lite/micro/tools/make/gen/zephyr_vexriscv_x86_64/micro_speech/CMake/zephyr/zephyr.elf as you can see on the first screenshot.

mateusz-holenko commented 4 years ago

I was just writing that there seems to be something off with the binaries :P

Could you share the binary as well (as on the repo the gen is gitignored) - or is it the binary in arty_led_vexriscv.full.zip (checksum would indicate so)?

If that's the one then I get the following output locally:

❯ /mnt/Antmicro-Local/master/renode/renode -d litex_buildenv.resc
11:25:09.1085 [INFO] Loaded monitor commands from: /mnt/Antmicro-Local/master/renode/./scripts/monitor.py
11:25:10.3147 [INFO] Including script: /home/houen/Pobrane/arty_led_vexriscv/rundir/litex_buildenv.resc
11:25:10.3422 [INFO] System bus created.
11:25:11.4296 [DEBUG] Segment size automatically calculated to value 64KiB (2)
11:25:11.4305 [DEBUG] Segment size automatically calculated to value 16MiB
11:25:11.4305 [DEBUG] Segment size automatically calculated to value 1MiB
11:25:12.2162 [INFO] litex-vexriscv: GDB server with all CPUs started on port :10001
11:25:12.2731 [DEBUG] sysbus: Loading binary /home/houen/Pobrane/arty_led_vexriscv/rundir/bios.bin at 0x0.
11:25:12.2932 [DEBUG] sysbus: Binary loaded.
11:25:12.7157 [DEBUG] sysbus: Loading binary /home/houen/Pobrane/arty_led_vexriscv/rundir/zephyr.bin at 0xD0228008.
11:25:12.7167 [DEBUG] sysbus: Binary loaded.
11:25:13.7590 [INFO] litex-vexriscv: Machine started.
11:25:13.9039 [DEBUG] uart: [+1,65s host +0s virt 0s virt from start]
11:25:13.9207 [DEBUG] uart: [+16,84ms host +0s virt 0s virt from start]   [1m        __   _ __      _  __[0m
11:25:13.9342 [DEBUG] uart: [+13,51ms host +0s virt 0s virt from start]   [1m       / /  (_) /____ | |/_/[0m
11:25:13.9461 [DEBUG] uart: [+11,9ms host +0s virt 0s virt from start]   [1m      / /__/ / __/ -_)>  <[0m
11:25:13.9595 [DEBUG] uart: [+13,38ms host +0s virt 0s virt from start]   [1m     /____/_/\__/\__/_/|_|[0m
11:25:13.9857 [DEBUG] uart: [+26,13ms host +0,1ms virt 0,1ms virt from start]   [1m   Build your hardware, easily![0m
11:25:13.9865 [DEBUG] uart: [+0,94ms host +0s virt 0,1ms virt from start]
11:25:14.0006 [DEBUG] uart: [+14,03ms host +0s virt 0,1ms virt from start]    (c) Copyright 2012-2020 Enjoy-Digital
11:25:14.0128 [DEBUG] uart: [+12,22ms host +0s virt 0,1ms virt from start]    (c) Copyright 2007-2015 M-Labs
11:25:14.0137 [DEBUG] uart: [+0,78ms host +0s virt 0,1ms virt from start]
11:25:14.0259 [DEBUG] uart: [+12,25ms host +0s virt 0,1ms virt from start]    BIOS built on Apr 13 2020 23:38:25
11:25:14.0616 [DEBUG] uart: [+35,77ms host +1,8ms virt 1,9ms virt from start]    BIOS CRC passed (6ac5e691)
11:25:14.0625 [DEBUG] uart: [+0,88ms host +0s virt 1,9ms virt from start]
11:25:14.0741 [DEBUG] uart: [+11,48ms host +0s virt 1,9ms virt from start]    Migen git sha1: 3f9809b
11:25:14.0836 [DEBUG] uart: [+9,61ms host +0s virt 1,9ms virt from start]    LiteX git sha1: 536ae0e6
11:25:14.0845 [DEBUG] uart: [+0,86ms host +0s virt 1,9ms virt from start]
11:25:14.1032 [DEBUG] uart: [+18,71ms host +0,1ms virt 2ms virt from start]   --=============== [1mSoC[0m ==================--
11:25:14.1216 [DEBUG] uart: [+18,37ms host +0s virt 2ms virt from start]   [1mCPU[0m:       VexRiscv @ 100MHz
11:25:14.1305 [DEBUG] uart: [+7,93ms host +0s virt 2ms virt from start]   [1mROM[0m:       32KB
11:25:14.1442 [DEBUG] uart: [+14,71ms host +0s virt 2ms virt from start]   [1mSRAM[0m:      32KB
11:25:14.1529 [DEBUG] uart: [+8,65ms host +0s virt 2ms virt from start]   [1mL2[0m:        8KB
11:25:14.1631 [DEBUG] uart: [+10,31ms host +0,1ms virt 2,1ms virt from start]   [1mMAIN-RAM[0m:  262144KB
11:25:14.1640 [DEBUG] uart: [+0,86ms host +0s virt 2,1ms virt from start]
11:25:14.1811 [DEBUG] uart: [+17,09ms host +0s virt 2,1ms virt from start]   --========== [1mInitialization[0m ============--
11:25:14.1886 [DEBUG] uart: [+7,5ms host +0s virt 2,1ms virt from start]   Initializing SDRAM...
11:25:14.2322 [DEBUG] uart: [+43,44ms host +1,8ms virt 3,9ms virt from start]   SDRAM now under software control
11:25:14.2397 [DEBUG] uart: [+7,61ms host +0,1ms virt 4ms virt from start]   Read leveling:
11:25:14.2986 [DEBUG] uart: [+59ms host +0,3ms virt 4,3ms virt from start]   m0, b0: |00000000000000000000000000000000| delays: -
11:25:14.3416 [DEBUG] uart: [+42,91ms host +0,3ms virt 4,6ms virt from start]   m0, b1: |00000000000000000000000000000000| delays: -
11:25:14.3891 [DEBUG] uart: [+47,52ms host +0,3ms virt 4,9ms virt from start]   m0, b2: |00000000000000000000000000000000| delays: -
11:25:14.4356 [DEBUG] uart: [+46,52ms host +0,3ms virt 5,2ms virt from start]   m0, b3: |00000000000000000000000000000000| delays: -
11:25:14.4787 [DEBUG] uart: [+43,06ms host +0,3ms virt 5,5ms virt from start]   m0, b4: |00000000000000000000000000000000| delays: -
11:25:14.5249 [DEBUG] uart: [+46,21ms host +0,3ms virt 5,8ms virt from start]   m0, b5: |00000000000000000000000000000000| delays: -
11:25:14.5735 [DEBUG] uart: [+48,5ms host +0,3ms virt 6,1ms virt from start]   m0, b6: |00000000000000000000000000000000| delays: -
11:25:14.6190 [DEBUG] uart: [+45,56ms host +0,3ms virt 6,4ms virt from start]   m0, b7: |00000000000000000000000000000000| delays: -
11:25:14.6444 [DEBUG] uart: [+25,46ms host +0,1ms virt 6,5ms virt from start]   best: m0, b0 delays: -
11:25:14.6920 [DEBUG] uart: [+47,63ms host +0,3ms virt 6,8ms virt from start]   m1, b0: |00000000000000000000000000000000| delays: -
11:25:14.7449 [DEBUG] uart: [+52,83ms host +0,3ms virt 7,1ms virt from start]   m1, b1: |00000000000000000000000000000000| delays: -
11:25:14.7923 [DEBUG] uart: [+47,32ms host +0,3ms virt 7,4ms virt from start]   m1, b2: |00000000000000000000000000000000| delays: -
11:25:14.8365 [DEBUG] uart: [+44,09ms host +0,3ms virt 7,7ms virt from start]   m1, b3: |00000000000000000000000000000000| delays: -
11:25:14.8837 [DEBUG] uart: [+47,43ms host +0,3ms virt 8ms virt from start]   m1, b4: |00000000000000000000000000000000| delays: -
11:25:14.9319 [DEBUG] uart: [+48,24ms host +0,3ms virt 8,3ms virt from start]   m1, b5: |00000000000000000000000000000000| delays: -
11:25:14.9762 [DEBUG] uart: [+44,22ms host +0,3ms virt 8,6ms virt from start]   m1, b6: |00000000000000000000000000000000| delays: -
11:25:15.0255 [DEBUG] uart: [+49,33ms host +0,3ms virt 8,9ms virt from start]   m1, b7: |00000000000000000000000000000000| delays: -
11:25:15.0510 [DEBUG] uart: [+25,46ms host +0,1ms virt 9ms virt from start]   best: m1, b0 delays: -
11:25:15.0638 [DEBUG] uart: [+12,83ms host +0,1ms virt 9,1ms virt from start]   SDRAM now under hardware control
11:25:15.6891 [DEBUG] uart: [+0,63s host +59,1ms virt 68,2ms virt from start]   Memtest OK
11:25:15.7025 [WARNING] timer0: Unhandled write to offset 0x4. Unhandled bits: [8-15] when writing value 0xFFFF.
11:25:15.7027 [WARNING] timer0: Unhandled write to offset 0x8. Unhandled bits: [8-23] when writing value 0xFFFFFF.
11:25:15.7028 [WARNING] timer0: Unhandled write to offset 0xC. Unhandled bits: [8-31] when writing value 0xFFFFFFFF.
11:25:16.1669 [DEBUG] uart: [+0,48s host +42,1ms virt 0,11s virt from start]   Memspeed Writes: 640Mbps Reads: 1068Mbps
11:25:16.1682 [DEBUG] uart: [+1,32ms host +0s virt 0,11s virt from start]
11:25:16.1923 [DEBUG] uart: [+24,02ms host +0,1ms virt 0,11s virt from start]   --============== [1mBoot[0m ==================--
11:25:16.2001 [DEBUG] uart: [+7,86ms host +0s virt 0,11s virt from start]   Booting from serial...
11:25:16.2138 [DEBUG] uart: [+13,63ms host +0s virt 0,11s virt from start]   Press Q or ESC to abort boot completely.
11:25:16.2194 [DEBUG] uart: [+5,67ms host +0s virt 0,11s virt from start]   sL5DdSMmkekro
11:25:16.2201 [WARNING] timer0: Unhandled write to offset 0x4. Unhandled bits: [8] when writing value 0x17D.
11:25:16.2203 [WARNING] timer0: Unhandled write to offset 0x8. Unhandled bits: [8, 10-14, 16] when writing value 0x17D78.
11:25:16.2205 [WARNING] timer0: Unhandled write to offset 0xC. Unhandled bits: [11-14, 16, 18-22, 24] when writing value 0x17D7840.
11:25:17.5118 [DEBUG] uart: [+1,29s host +4,7ms virt 0,12s virt from start]   Cancelled
11:25:17.5151 [DEBUG] uart: [+3,29ms host +0s virt 0,12s virt from start]
11:25:17.5386 [DEBUG] uart: [+23,46ms host +0s virt 0,12s virt from start]   --============= [1mConsole[0m ================--
11:25:17.5438 [WARNING] Unimplemented SGR code 92.
11:25:18.9791 [DEBUG] uart: [+1,44s host +98,3ms virt 0,21s virt from start]   [92;1mlitex[0m> flashboot
11:25:18.9905 [DEBUG] uart: [+11,47ms host +0s virt 0,21s virt from start]   Booting from flash...
11:25:19.0500 [DEBUG] uart: [+59,43ms host +4,9ms virt 0,22s virt from start]   Loading 58280 bytes from flash...
11:25:19.1420 [DEBUG] uart: [+91,82ms host +4,2ms virt 0,22s virt from start]   Executing booted program at 0x40000000
11:25:19.1429 [DEBUG] uart: [+1,09ms host +0s virt 0,22s virt from start]
11:25:19.1603 [DEBUG] uart: [+17,43ms host +0s virt 0,22s virt from start]   --============= [1mLiftoff![0m ===============--
11:25:19.2004 [WARNING] sysbus: [cpu: 0x4000AC88] ReadDoubleWord from non existing peripheral at 0xE0005000.
11:25:19.2014 [WARNING] sysbus: [cpu: 0x4000AC90] WriteDoubleWord to non existing peripheral at 0xE0005000, value 0x7.
11:25:19.2023 [WARNING] sysbus: [cpu: 0x4000ACF8] WriteDoubleWord to non existing peripheral at 0xE0007000, value 0x1.
11:25:19.2253 [DEBUG] uart: [+64,93ms host +0,2ms virt 0,22s virt from start]   *** Booting Zephyr OS build zephyr-v2.2.0-1396-gd280660792c2  ***
11:25:19.2290 [WARNING] sysbus: [cpu: 0x40000764] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:25:43.6376 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:26:09.3250 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:26:36.0014 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:27:05.2690 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:27:35.1259 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:28:02.1259 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:28:29.1777 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:28:56.2497 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:29:23.0501 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:29:49.6055 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:30:14.5717 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.
11:30:38.9808 [WARNING] sysbus: [cpu: 0x40000784] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x10.
11:31:05.0600 [WARNING] sysbus: [cpu: 0x40000790] WriteDoubleWord to non existing peripheral at 0x82005800, value 0x8.

Writing to 0x82005800 looks like blinking the rgb led.

zawadzki-dawid commented 4 years ago

@mateusz-holenko It's not that one, I uploaded our zephyr.elf on this branch.

mateusz-holenko commented 4 years ago

Thanks. With this new zephyr.bin I get the following output:

❯ /mnt/Antmicro-Local/master/renode/renode litex_buildenv.resc
12:38:38.1425 [INFO] Loaded monitor commands from: /mnt/Antmicro-Local/master/renode/./scripts/monitor.py
12:38:39.3023 [INFO] Including script: /home/houen/Pobrane/arty_led_vexriscv/rundir/litex_buildenv.resc
12:38:39.3295 [INFO] System bus created.
12:38:40.4031 [DEBUG] Segment size automatically calculated to value 64KiB (2)
12:38:40.4037 [DEBUG] Segment size automatically calculated to value 16MiB
12:38:40.4040 [DEBUG] Segment size automatically calculated to value 1MiB
12:38:41.1796 [INFO] litex-vexriscv: GDB server with all CPUs started on port :10001
12:38:41.2370 [DEBUG] sysbus: Loading binary /home/houen/Pobrane/arty_led_vexriscv/rundir/bios.bin at 0x0.
12:38:41.2601 [DEBUG] sysbus: Binary loaded.
12:38:41.6849 [DEBUG] sysbus: Loading binary /home/houen/Pobrane/arty_led_vexriscv/rundir/zephyr.bin at 0xD0228008.
12:38:41.6879 [DEBUG] sysbus: Binary loaded.
12:38:43.0607 [INFO] litex-vexriscv: Machine started.
12:38:43.2104 [DEBUG] uart: [+1,99s host +0s virt 0s virt from start]
12:38:43.2344 [DEBUG] uart: [+24,42ms host +0s virt 0s virt from start]   [1m        __   _ __      _  __[0m
12:38:43.2808 [DEBUG] uart: [+46,44ms host +0s virt 0s virt from start]   [1m       / /  (_) /____ | |/_/[0m
12:38:43.3191 [DEBUG] uart: [+38,33ms host +0s virt 0s virt from start]   [1m      / /__/ / __/ -_)>  <[0m
12:38:43.3523 [DEBUG] uart: [+33,11ms host +0s virt 0s virt from start]   [1m     /____/_/\__/\__/_/|_|[0m
12:38:43.3789 [DEBUG] uart: [+26,6ms host +0,1ms virt 0,1ms virt from start]   [1m   Build your hardware, easily![0m
12:38:43.3801 [DEBUG] uart: [+1,28ms host +0s virt 0,1ms virt from start]
12:38:43.3964 [DEBUG] uart: [+16,24ms host +0s virt 0,1ms virt from start]    (c) Copyright 2012-2020 Enjoy-Digital
12:38:43.4083 [DEBUG] uart: [+11,92ms host +0s virt 0,1ms virt from start]    (c) Copyright 2007-2015 M-Labs
12:38:43.4096 [DEBUG] uart: [+1,38ms host +0s virt 0,1ms virt from start]
12:38:43.4244 [DEBUG] uart: [+14,73ms host +0s virt 0,1ms virt from start]    BIOS built on Apr 13 2020 23:38:25
12:38:43.4521 [DEBUG] uart: [+27,65ms host +1,8ms virt 1,9ms virt from start]    BIOS CRC passed (6ac5e691)
12:38:43.4532 [DEBUG] uart: [+1,2ms host +0s virt 1,9ms virt from start]
12:38:43.4678 [DEBUG] uart: [+14,58ms host +0s virt 1,9ms virt from start]    Migen git sha1: 3f9809b
12:38:43.4840 [DEBUG] uart: [+11,74ms host +0s virt 1,9ms virt from start]    LiteX git sha1: 536ae0e6
12:38:43.4842 [DEBUG] uart: [+0,71ms host +0s virt 1,9ms virt from start]
12:38:43.5007 [DEBUG] uart: [+20,43ms host +0,1ms virt 2ms virt from start]   --=============== [1mSoC[0m ==================--
12:38:43.5232 [DEBUG] uart: [+16,97ms host +0s virt 2ms virt from start]   [1mCPU[0m:       VexRiscv @ 100MHz
12:38:43.5284 [DEBUG] uart: [+10,64ms host +0s virt 2ms virt from start]   [1mROM[0m:       32KB
12:38:43.5400 [DEBUG] uart: [+11,52ms host +0s virt 2ms virt from start]   [1mSRAM[0m:      32KB
12:38:43.5572 [DEBUG] uart: [+17,27ms host +0s virt 2ms virt from start]   [1mL2[0m:        8KB
12:38:43.5687 [DEBUG] uart: [+11,4ms host +0,1ms virt 2,1ms virt from start]   [1mMAIN-RAM[0m:  262144KB
12:38:43.5702 [DEBUG] uart: [+1,66ms host +0s virt 2,1ms virt from start]
12:38:43.5894 [DEBUG] uart: [+19,13ms host +0s virt 2,1ms virt from start]   --========== [1mInitialization[0m ============--
12:38:43.6021 [DEBUG] uart: [+12,87ms host +0s virt 2,1ms virt from start]   Initializing SDRAM...
12:38:43.6391 [DEBUG] uart: [+36,87ms host +1,8ms virt 3,9ms virt from start]   SDRAM now under software control
12:38:43.6463 [DEBUG] uart: [+7,24ms host +0,1ms virt 4ms virt from start]   Read leveling:
12:38:43.7046 [DEBUG] uart: [+58,39ms host +0,3ms virt 4,3ms virt from start]   m0, b0: |00000000000000000000000000000000| delays: -
12:38:43.7462 [DEBUG] uart: [+41,56ms host +0,3ms virt 4,6ms virt from start]   m0, b1: |00000000000000000000000000000000| delays: -
12:38:43.7914 [DEBUG] uart: [+45,18ms host +0,3ms virt 4,9ms virt from start]   m0, b2: |00000000000000000000000000000000| delays: -
12:38:43.8391 [DEBUG] uart: [+47,71ms host +0,3ms virt 5,2ms virt from start]   m0, b3: |00000000000000000000000000000000| delays: -
12:38:43.8894 [DEBUG] uart: [+50,26ms host +0,3ms virt 5,5ms virt from start]   m0, b4: |00000000000000000000000000000000| delays: -
12:38:43.9413 [DEBUG] uart: [+51,91ms host +0,3ms virt 5,8ms virt from start]   m0, b5: |00000000000000000000000000000000| delays: -
12:38:43.9884 [DEBUG] uart: [+47,09ms host +0,3ms virt 6,1ms virt from start]   m0, b6: |00000000000000000000000000000000| delays: -
12:38:44.0353 [DEBUG] uart: [+46,86ms host +0,3ms virt 6,4ms virt from start]   m0, b7: |00000000000000000000000000000000| delays: -
12:38:44.0562 [DEBUG] uart: [+21,01ms host +0,1ms virt 6,5ms virt from start]   best: m0, b0 delays: -
12:38:44.1006 [DEBUG] uart: [+44,4ms host +0,3ms virt 6,8ms virt from start]   m1, b0: |00000000000000000000000000000000| delays: -
12:38:44.1473 [DEBUG] uart: [+46,58ms host +0,3ms virt 7,1ms virt from start]   m1, b1: |00000000000000000000000000000000| delays: -
12:38:44.1907 [DEBUG] uart: [+43,44ms host +0,3ms virt 7,4ms virt from start]   m1, b2: |00000000000000000000000000000000| delays: -
12:38:44.2387 [DEBUG] uart: [+48ms host +0,3ms virt 7,7ms virt from start]   m1, b3: |00000000000000000000000000000000| delays: -
12:38:44.2870 [DEBUG] uart: [+48,29ms host +0,3ms virt 8ms virt from start]   m1, b4: |00000000000000000000000000000000| delays: -
12:38:44.3305 [DEBUG] uart: [+43,61ms host +0,3ms virt 8,3ms virt from start]   m1, b5: |00000000000000000000000000000000| delays: -
12:38:44.3781 [DEBUG] uart: [+46,77ms host +0,3ms virt 8,6ms virt from start]   m1, b6: |00000000000000000000000000000000| delays: -
12:38:44.4254 [DEBUG] uart: [+48,03ms host +0,3ms virt 8,9ms virt from start]   m1, b7: |00000000000000000000000000000000| delays: -
12:38:44.4461 [DEBUG] uart: [+20,72ms host +0,1ms virt 9ms virt from start]   best: m1, b0 delays: -
12:38:44.4615 [DEBUG] uart: [+15,43ms host +0,1ms virt 9,1ms virt from start]   SDRAM now under hardware control
12:38:44.8451 [DEBUG] uart: [+0,38s host +59,1ms virt 68,2ms virt from start]   Memtest OK
12:38:44.8581 [WARNING] timer0: Unhandled write to offset 0x4. Unhandled bits: [8-15] when writing value 0xFFFF.
12:38:44.8582 [WARNING] timer0: Unhandled write to offset 0x8. Unhandled bits: [8-23] when writing value 0xFFFFFF.
12:38:44.8583 [WARNING] timer0: Unhandled write to offset 0xC. Unhandled bits: [8-31] when writing value 0xFFFFFFFF.
12:38:45.2119 [DEBUG] uart: [+0,37s host +42,1ms virt 0,11s virt from start]   Memspeed Writes: 640Mbps Reads: 1068Mbps
12:38:45.2132 [DEBUG] uart: [+1,29ms host +0s virt 0,11s virt from start]
12:38:45.2333 [DEBUG] uart: [+20,04ms host +0,1ms virt 0,11s virt from start]   --============== [1mBoot[0m ==================--
12:38:45.2412 [DEBUG] uart: [+7,96ms host +0s virt 0,11s virt from start]   Booting from serial...
12:38:45.2546 [DEBUG] uart: [+13,35ms host +0s virt 0,11s virt from start]   Press Q or ESC to abort boot completely.
12:38:45.2602 [DEBUG] uart: [+5,6ms host +0s virt 0,11s virt from start]   sL5DdSMmkekro
12:38:45.2608 [WARNING] timer0: Unhandled write to offset 0x4. Unhandled bits: [8] when writing value 0x17D.
12:38:45.2609 [WARNING] timer0: Unhandled write to offset 0x8. Unhandled bits: [8, 10-14, 16] when writing value 0x17D78.
12:38:45.2610 [WARNING] timer0: Unhandled write to offset 0xC. Unhandled bits: [11-14, 16, 18-22, 24] when writing value 0x17D7840.
12:38:45.8889 [DEBUG] uart: [+0,63s host +2,3ms virt 0,11s virt from start]   Cancelled
12:38:45.8901 [DEBUG] uart: [+1,25ms host +0s virt 0,11s virt from start]
12:38:45.9161 [DEBUG] uart: [+25,95ms host +0s virt 0,11s virt from start]   --============= [1mConsole[0m ================--
12:38:45.9204 [WARNING] Unimplemented SGR code 92.
12:38:47.3862 [DEBUG] uart: [+1,47s host +0,23s virt 0,34s virt from start]   [92;1mlitex[0m> flashboot
12:38:47.3989 [DEBUG] uart: [+14,37ms host +0s virt 0,34s virt from start]   Booting from flash...
12:38:47.4408 [DEBUG] uart: [+41,95ms host +4,9ms virt 0,34s virt from start]   Loading 58280 bytes from flash...
12:38:47.4875 [DEBUG] uart: [+46,69ms host +4,2ms virt 0,35s virt from start]   Executing booted program at 0x40000000
12:38:47.4887 [DEBUG] uart: [+1,15ms host +0s virt 0,35s virt from start]
12:38:47.5094 [DEBUG] uart: [+20,75ms host +0s virt 0,35s virt from start]   --============= [1mLiftoff![0m ===============--
12:38:47.5145 [ERROR] cpu: CPU abort [PC=0x400127CC]: tlib/tcg/tcg.c:1399: tcg fatal error.
12:39:05.9648 [INFO] litex-vexriscv: Machine paused.
12:39:06.0321 [DEBUG] litex-vexriscv: Disposing sysbus.cpu.
12:39:06.0363 [DEBUG] litex-vexriscv: Disposing sysbus.
12:39:06.0375 [DEBUG] litex-vexriscv: Disposing sysbus.rom.
12:39:06.0381 [DEBUG] litex-vexriscv: Disposing sysbus.sram.
12:39:06.0382 [DEBUG] litex-vexriscv: Disposing sysbus.main_ram.
12:39:06.0403 [DEBUG] litex-vexriscv: Disposing sysbus.spiflash.
12:39:06.0417 [INFO] litex-vexriscv: Disposed.

CPU abort means the emulation is stopped due to some serious problem. Do you see the same in your logs (btw. could you share Renode logs as well?).

Which version of Renode do you use?

zawadzki-dawid commented 4 years ago

@mateusz-holenko That's my renode version Renode, version 1.9.0.41914 (2960e691-202004202317). For me the Renode window is empty, nothing is being logged.

mateusz-holenko commented 4 years ago

Logs are usually printed in the terminal where you start Renode (issue renode command). This is the window with yellow WARNINGs in the screenshots above. You can always also dump logs to the file using logFile @/tmp/log.txt command in monitor.

Monitor is the window with Renode logo and red (monitor)/ yellow litex-vexriscv prompts. This is a console you use to control the simulation. NB. there is Renode version displayed at the top - I could've checked that in the screenshot.

There might be other windows opened as well - like UART analyzers that allows to interact with UART device (displays text printed by the software and allows to send input from the user).

In the screenshots I can't see any UART analyzer output - do you see a window with LiteX logo at all?

zawadzki-dawid commented 4 years ago

@mateusz-holenko I have UART window but I didin't upload it in the first place because it's empty and I thought it's not important.

This are all windows I have Screenshot from 2020-04-24 14-46-19

mateusz-holenko commented 4 years ago

Now I see that you load elf file after including the resc script, so you overwrite the LiteX BIOS completely (and that's why you don't see LiteX logo on UART). That's not bad per se, but I didn't test this configuration.

You have warnings in log, so the simulation didn't abort in your case. I'll try to reproduce this scenario.

mateusz-holenko commented 4 years ago

OK, now I can reporoduce your setup.

After enabling logging of function names (cpu LogFunctionNames true in monitor) I have the following output in log:

...
15:05:07.2589 [WARNING] sysbus: [cpu: 0x40012484] ReadByte from non existing peripheral at 0xE0009834.
15:05:07.2590 [INFO] cpu: Entering function eth_tx at 0x40012488
15:05:07.2592 [INFO] cpu: Entering function eth_tx at 0x4001248C
15:05:07.2594 [INFO] cpu: Entering function eth_tx at 0x40012484
15:05:07.2596 [WARNING] sysbus: [cpu: 0x40012484] ReadByte from non existing peripheral at 0xE0009834.
15:05:07.2597 [INFO] cpu: Entering function eth_tx at 0x40012488
15:05:07.2598 [INFO] cpu: Entering function eth_tx at 0x4001248C
15:05:07.2600 [INFO] cpu: Entering function eth_tx at 0x40012484
15:05:07.2601 [WARNING] sysbus: [cpu: 0x40012484] ReadByte from non existing peripheral at 0xE0009834.
...

It looks like Zephyr is trying to talk to the ethernet controller.

Most probably you are using the default LiteX VexRisc DTS in Zephyr (https://github.com/zephyrproject-rtos/zephyr/blob/master/dts/riscv/riscv32-litex-vexriscv.dtsi) with an incompatible platform.

You need to generate the overlay for Zephyr DTS from the current LiteX configuration to enable only peripherals that are actually present in your SoC and to set proper offsets. Take a look at: https://github.com/timvideos/litex-buildenv/blob/master/scripts/build-zephyr.sh#L99. The generate-zephyr-dts.py is hosted here: https://github.com/litex-hub/litex-renode.

plonajakub commented 4 years ago

Now I see that you load elf file after including the resc script, so you overwrite the LiteX BIOS completely (and that's why you don't see LiteX logo on UART). That's not bad per se, but I didn't test this configuration.

So after issuing include <script> in renode we erase script setup by executing LoadELF? The tool doesn't keep the configuration from the script in this case? If so would it be a proper way to just simply overwrite path to .elf on the last line of .resc?

You need to generate the overlay for Zephyr DTS from the current LiteX configuration to enable only peripherals that are actually present in your SoC and to set proper offsets. Take a look at: https://github.com/timvideos/litex-buildenv/blob/master/scripts/build-zephyr.sh#L99. The generate-zephyr-dts.py is hosted here: https://github.com/litex-hub/litex-renode.

Thank you for the links. We certainly will look at the dts generation script and post results here.

mateusz-holenko commented 4 years ago

So after issuing include <script> in renode we erase script setup by executing LoadELF? The tool doesn't keep the configuration from the script in this case? If so would it be a proper way to just simply overwrite path to .elf on the last line of .resc?

Issuing commands after include doesn't erase the state, but LoadELF command overwrites memory and reconfigures CPU (sets starting PC). Now that I think about it you probably don't overwrite the LiteX BIOS binary in memory this time (as it's loaded under 0x0 and zephyr.elf goes under 0x40000000), but you definiately change PC and the simulation jumps to Zephyr directly (omitting the bootloader).

As for changing the resc file, sure - you can load elf there as well - it doesn't matter. Beware that there are two separate commands for loading bare binaries (LoadBinary) and elfs (LoadELF).

Thank you for the links. We certainly will look at the dts generation script and post results here.

There is, unfortunately, a small conflict between Zephyr and LiteX. Zephyr need DTS to be available during compilation as it's parsed staticly - therefore we needed to provide some DTS in the tree. There is, however, no Single LiteX Platform - it's a dynamic generator that output different SoC's depending on the provided configuration. That's why we have this helper script to automatically patch DTS to match the currently generated platform.

zawadzki-dawid commented 4 years ago

@mateusz-holenko @szymon-filipiak and @plonajakub have fallowed your instructions and they successfuly loaded binary on the board. Everything is working as expected. Thank you for your help!

mateusz-holenko commented 4 years ago

Great. Good luck with your project!