Marus / cortex-debug

Visual Studio Code extension for enhancing debug capabilities for Cortex-M Microcontrollers
MIT License
985 stars 238 forks source link

RTT Only Prints To Console When it is Stopped and Started Again #871

Closed bebebib closed 1 year ago

bebebib commented 1 year ago

I am debugging an AM6548 SoC, specifically the Cortex-R5 core of the SoC, I am using the development board's (AM65x_GP_EVM) integrated XDS110 debugger. I have been able to integrate SEGGER print statements into my code as well, and configuring the cortex-debug extension of VS code I am able to see the _SEGGER_RTT symbol and find the control block.

The issue is that the RTT console that spawns in VS Code does not print out data in real time, I have to monitor rtt stop then monitor rtt start in the debug console, and then all the print data that was in the RTT control block is printed out. This behavior is pretty consistent.

This is my environment.

Here is my launch.json

{
    "configurations": [
    {
        "cwd": "${workspaceRoot}",
        "executable": "<PATH_TO_EXE>",
        "name": "openocd-gdb attach",
        "request": "attach",
        "type": "cortex-debug",
        "servertype": "openocd",
        "configFiles": ["board/ti_am654evm.cfg"],
        "searchDir": [],
        "showDevDebugOutput": "none",
        "gdbPath": "/usr/bin/gdb-multiarch",
        "objdumpPath": "/opt/arm-none-eabi/bin/arm-none-eabi-objdump",
        "openOCDPreConfigLaunchCommands": ["tcl_port 6666","telnet_port 4444"],
        "openOCDLaunchCommands": ["am654.cpu.mcu_r5.0 configure -gdb-port 3338"],
        "preAttachCommands": ["target extended-remote localhost:3338"],
        "breakAfterReset": true,
        "rttConfig": {
            "enabled": true,
            "address": "auto",
            "decoders": [
                {
                    "label": "",
                    "port": 0,
                    "type": "console"
                }
            ],
        }
    },
    ]
}

Here is the output from my debug console when I attach to the process on the Cortex-R5F core

Created RTT terminal for channel 0 on tcp port 60000
Listening on port 60000 for rtt connections
rtt: Searching for control block 'SEGGER RTT'
rtt: Control block found at 0xa0411ab0

This debug session is an "attach". Is there any reason that RTT is behaving this way?

haneefdm commented 1 year ago

I need to see the entire Debug Console output. With Debug enabled please (showDevDebugOutput = raw)

bebebib commented 1 year ago

Sure, here is me attaching with that on debugLog.txt

haneefdm commented 1 year ago

You are doing something that is severly interfering with what we do. If you override the ports the way you did, many many features will not work. I am surprised anything works (you got lucky for now)

        "openOCDPreConfigLaunchCommands": ["tcl_port 6666","telnet_port 4444"],
        "openOCDLaunchCommands": ["am654.cpu.mcu_r5.0 configure -gdb-port 3338"],
        "preAttachCommands": ["target extended-remote localhost:3338"],

None of these commands are approriate as we are talking to openocd in the 50000+ range.

Your above commands cause this command line

Launching gdb-server: openocd -c "gdb_port 50000" -c "tcl_port 50001" -c "telnet_port 50002" -s /home/broytburd/GIT/ESW-474/redstone -c "tcl_port 6666" -c "telnet_port 4444" -f /home/broytburd/.vscode-server/extensions/marus25.cortex-debug-1.10.0/support/openocd-helpers.tcl -f board/ti_am654evm.cfg -c "am654.cpu.mcu_r5.0 configure -gdb-port 3338"

We are trying to talk to openocd on very different ports but you have taken over that responsibility. Even our newest feature Live Watch will not work.

bebebib commented 1 year ago

There is a reason that I have to override those ports, when openocd is launched it opens a bunch of gdb ports, like so

$ openocd -f board/ti_am654evm.cfg  -c "gdb_port 50000"
Open On-Chip Debugger 0.12.0-rc1+dev-00924-gae937791d (2022-09-29-09:21)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
adapter speed: 2500 kHz

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Info : XDS110: connected
Info : XDS110: vid/pid = 0451/bef3
Info : XDS110: firmware version = 3.0.0.20
Info : XDS110: hardware version = 0x002f
Info : XDS110: connected to target via JTAG
Info : XDS110: TCK set to 2500 kHz
Info : clock speed 2500 kHz
Info : JTAG tap: am654.cpu tap/device found: 0x0bb5a02f (mfg: 0x017 (Texas Instruments), part: 0xbb5a, ver: 0x0)
Info : starting gdb server for am654.cpu.sysctrl on 50000
Info : Listening on port 50000 for gdb connections
Info : starting gdb server for am654.cpu.a53.0 on 50001
Info : Listening on port 50001 for gdb connections
Info : starting gdb server for am654.cpu.a53.1 on 50002
Info : Listening on port 50002 for gdb connections
Info : starting gdb server for am654.cpu.a53.2 on 50003
Info : Listening on port 50003 for gdb connections
Info : starting gdb server for am654.cpu.a53.3 on 50004
Info : Listening on port 50004 for gdb connections
Info : starting gdb server for am654.cpu.mcu_r5.0 on 50005
Info : Listening on port 50005 for gdb connections
Info : starting gdb server for am654.cpu.mcu_r5.1 on 50006
Info : Listening on port 50006 for gdb connections

As you can see 50001 and 50002 are assigned to cores of the SoC I am using. So I have to at least specify a different gdb port.

bebebib commented 1 year ago

This configuration works as well

{
    "configurations": [
    {
        "cwd": "${workspaceRoot}",
        "executable": "<BINARY PATH>",
        "name": "openocd-gdb attach",
        "request": "attach",
        "type": "cortex-debug",
        "servertype": "openocd",
        "configFiles": ["board/ti_am654evm.cfg"],
        "searchDir": [],
        "showDevDebugOutput": "none",
        "gdbPath": "/usr/bin/gdb-multiarch",
        "objdumpPath": "/opt/arm-picolibc-eabi/bin/arm-picolibc-eabi-objdump",
        "openOCDPreConfigLaunchCommands": ["tcl_port 6666","telnet_port 4444"],
        "preAttachCommands": ["target extended-remote localhost:50005"],
        "breakAfterReset": true,
        "rttConfig": {
            "enabled": true,
            "address": "auto",
            "decoders": [
                {
                    "label": "",
                    "port": 0,
                    "type": "console"
                }
            ],
        }
    },
    ]
}

But I still need to override the TCL and Telnet ports, is there a way for me to tell cortex-debug to use these ports as well?

PhilippHaefele commented 1 year ago

Hi,

Just guessing that it could help to add the numberOfProcessors and targetProcessor arguments. If i remember right this is needed for Cortex-Debug to know how many ports to reserve. This maybe (i do not use OpenOCD often and never did on a multi-core system) also needs adaption of your cfg file as i assume you currently most likely do set the target core in there.

See https://github.com/Marus/cortex-debug/wiki/Multi-core-debugging for a more detailed description on how to handle multi core debugging in Cortex-Debug (if you ever need to debug more than one R5).

bebebib commented 1 year ago

Wow! Well that solved one problem lol

Those arguments let me get rid of my overrides, thanks Philipp!

{
    "configurations": [
    {
        "cwd": "${workspaceRoot}",
        "executable": "<BINARY PATH>",
        "numberOfProcessors": 7,
        "targetProcessor": 5,
        "name": "openocd-gdb attach",
        "request": "attach",
        "type": "cortex-debug",
        "servertype": "openocd",
        "configFiles": ["board/ti_am654evm.cfg"],
        "searchDir": [],
        "showDevDebugOutput": "none",
        "gdbPath": "/usr/bin/gdb-multiarch",
        "objdumpPath": "/opt/arm-picolibc-eabi/bin/arm-picolibc-eabi-objdump",
        "breakAfterReset": true,
        "rttConfig": {
            "enabled": true,
            "address": "auto",
            "decoders": [
                {
                    "label": "",
                    "port": 0,
                    "type": "console"
                }
            ]
        }
    },
    ]
}

RTT is still not printing in "real time" though.

haneefdm commented 1 year ago

Let's try a couple of things

  1. Now that we fixed the ports issue, lets try a few things.
  2. In rttConfig object, you can set a property to "rtt_start_retry" to a smaller/different number. We use the telnet port to talk to OpenOCD in the background and try to keep attempting a start. OpenOCD was designed in this dumb way and we documented this. But we try to work around it by periodically attempting a start. JLink is much simpler but limiting in number of channels. OpenOCD even documents that you have to start RTT manually at the right time. Yeah, right.
    See https://github.com/Marus/cortex-debug/blob/master/CHANGELOG.md#v160
  3. There is an undocumented launch.json property to debug OpenOCD issues "pvtOpenOCDDebug": true. This will create a file in <your-os-temp-dir>/cortex-debug-openocd.log. Example '/tmp/cortex-debug-openocd.log' on Linux but it can be different on other systems. Google for your system. You can monitor this file and it prints what is going on in the background. It can be chatty

When you change stuff, I need the output from Debug Console again. I cannot guess what is actually happening. The contents of gdb-server does not hurt either.

Btw, I have my own patched version of OpenOCD that will just auto retry once you call rtt start but something like that will not be accepted by OpenOCD people.

This may very well be an attach specific issue but who knows without proper logs. I never tested on a multi-core system and hopefully it works and that I am not talking to the wrong tcl_port

WHen none of this works, we will have to try the latest version which is still in pre-release but you can enable that within VSCode extensions manager.

bebebib commented 1 year ago

Thank you for the suggestions haneefdm, turning on the hidden cortex debug extension, it does create a log under /tmp. And this super interesting thing popped up

[2023-04-14T00:06:29.308Z] Launching: -c gdb_port 50000 -c tcl_port 50007 -c telnet_port 50014 -s /home/broytburd/GIT/ESW-474/redstone -f /home/broytburd/.vscode-server/extensions/marus25.cortex-debug-1.10.0/support/openocd-helpers.tcl -f board/ti_am654evm.cfg
[2023-04-14T00:06:30.367Z] OpenOCD Output: Output radix now set to decimal 10, hex a, octal 12.
[2023-04-14T00:06:30.368Z] OpenOCD Output: Input radix now set to decimal 10, hex a, octal 12.
[2023-04-14T00:06:30.698Z] OpenOCD Output: Output radix now set to decimal 16, hex 10, octal 20.
[2023-04-14T00:06:30.699Z] OpenOCD Output: Input radix now set to decimal 10, hex a, octal 12.
[2023-04-14T00:06:30.705Z] OpenOCD Output: Listening on port 60001 for rtt connections
[2023-04-14T00:06:30.708Z] OpenOCD Output: rtt: Searching for control block 'SEGGER RTT'
[2023-04-14T00:06:30.738Z] OpenOCD Output: rtt: Control block found at 0xa0411ab0
[2023-04-14T00:06:30.738Z] RTT control block found. Done
[2023-04-14T00:06:30.986Z] RTT Poll requested
[2023-04-14T00:06:30.986Z] RTT Poll not needed

Seems like RTT Poll is not needed? Not sure what RTT Poll is... but I imagine it may have something to do with polling data from the control block?

haneefdm commented 1 year ago

:-) No we are not polling for the control block directly. Message is misleading, sorry. We are forcing OpenOCD to retry for the control block by sending repeated rtt start commands over the TCL port. This is because OpenOCD tries only once and gives up. So, we force it to retry. In this case, it seems to have found the CB at first try (because it is an attach) so we don't waste time

So, technically, it found the control block, connection is open and it should start streaming.

Once we see a message from OpenOCD that it found the control block, we do not retry

RTT is still not printing in "real time" though.

I am curious though. What do you mean by the comment above. Of course, RTT is not real-time. Just because SEGGER called it that, doesn't make it so.

Why it works if you stop and start again manually is beyond me. Everything we do, we have to reverse engineer to peer through other peoples source code to figure out what they hell they are doing.

You can automate your manual steps using TCL code but that will be the last resort, and I cannot teach you TCL either. First priority is since it started already, why are we not getting any data. Almost sounds like an OpenOCD bug.

bebebib commented 1 year ago

By "real time" I mean that when I leave a an application that looks like this running:

int main()
{
    for (;;)
    {
         printf("hi");
         delay(1 second);
    }
}

If I do not set any breakpoints, I should see multiple "hi" strings being printed to the RTT terminal, but in my case I only see these when I stop and start RTT. So if I let the above program run for 10 seconds, I see nothing in my RTT terminal, but if I stop and start said terminal I all of a sudden see all 10 "hi"s at once.

So there is a way to automate the monitor rtt stop and monitor rtt start commands? If this is a bug with OpenOCD, I may have to do that. I got some logs as well from the following configuration if that helps

{
    "configurations": [
    {
        "cwd": "${workspaceRoot}",
        "executable": "<BINARY_FILE>",
        "name": "openocd-gdb attach",
        "request": "attach",
        "type": "cortex-debug",
        "servertype": "openocd",
        "configFiles": ["board/ti_am654evm.cfg"],
        "searchDir": [],
        "showDevDebugOutput": "raw",
        "gdbPath": "/usr/bin/gdb-multiarch",
        "objdumpPath": "/opt/arm-picolibc-eabi/bin/arm-picolibc-eabi-objdump",
        "breakAfterReset": true,
        "numberOfProcessors": 7,
        "targetProcessor": 5,
        "pvtOpenOCDDebug": true,
        "rttConfig": {
            "enabled": true,
            "address": "auto",
            "rtt_start_retry": 10,
            "polling_interval": 5,
            "decoders": [
                {
                    "label": "",
                    "port": 0,
                    "type": "console"
                }
            ]
        }
    },
    ]
}

debugLog2.txt

bebebib commented 1 year ago

I do see this openOCD error, is this relevant? rtt: Failed to read up-channel 0 description --> in the debug log

haneefdm commented 1 year ago

I do see this openOCD error, is this relevant? rtt: Failed to read up-channel 0 description --> in the debug log

That is from OpenOCD. It probably means that when it read the control block (CB), your FW/RTT-memory-SRAM was not in a good state. I have a feeling in the first attempt it found the Control Block (because it is just a string match) but then it was unable to actuall read the contents of the Control Block. Like how many channels, up/down sizes/addresses, etc.

Lets try something. Do your stop/start in the postAttachCommands commands. If that does not work try postStartSessionCommands.

The TCL trick is to do that after a delay but I need to know how comfortable you are with TCL.

haneefdm commented 1 year ago

Question/Survey: Your processor is not in the Cortex-M class simple MCU which is what we declare. Still, embedded though but capable of running Linux. and you using just the Cortex-R's here. But, what made you try this extension?

We are finding that people are using this with so many processors (RISC-V, ARC, Xtensa, etc. even 64-bit ones). I am surprised and confused.

bebebib commented 1 year ago

Lets try something. Do your stop/start in the postAttachCommands commands. If that does not work try postStartSessionCommands

So that I can specify monitor rtt stop and monitor rtt start in those launch.json commands, but it does not solve the issue of prints not being sent while running. It still shows the same behavior of only showing the prints when I detach / attach.

Question/Survey: Your processor is not in the Cortex-M class simple MCU which is what we declare. Still, embedded though but capable of running Linux. and you using just the Cortex-R's here. But, what made you try this extension?

I have used this extension in the past on Cortex-M MCUs, and I do enjoy it a lot. I prefer VS Code as my dev environment and having an embedded debugger built into it is very nice. I imagine this extension is becoming popular because it integrates into VS Code nicely, and VS code is a very popular IDE, even for embedded dev.

haneefdm commented 1 year ago

Thanks for the survey feedback.

All we do is to wait on the TCP channel for any data. If there is none, there is nothing we can do. Why OpenOCD is not sending data is not something I can control. I did everything that the OpenOCD manual asks to do.

I can't investigate this further (busy with my day job) and hopefully, I can duplicate it. Not giving up, but it will be in my queue

bebebib commented 1 year ago

I will make a ticket against OpenOCD itself, will post here when I make it. But thank you for your help so far, hoping we can get this figured out.

Edit: Ticket here https://sourceforge.net/p/openocd/tickets/391/