Stack backtrace on MEGA65 using MOS-LLVM

For the MEGAphone, I wanted to make my software debugging on the MEGA65 easier.  Stack back-traces are a great way to help debug errors, but we don't have gdb or lldb or anything like that on the MEGA65.  m65dbg and related tools can help here, but they don't have an easy way to provide the complete call stack.

To solve this for my needs, I added function instrumentation using the following in my Makefile:

COPT_M65=    -Iinclude    -Isrc/telephony/mega65 -Isrc/mega65-libc/include

COMPILER=llvm
COMPILER_PATH=/usr/local/bin
CC=   $(COMPILER_PATH)/mos-c64-clang -mcpu=mos45gs02 -Iinclude -Isrc/telephony/mega65 -Isrc/mega65-libc/include -DLLVM -fno-unroll-loops -ffunction-sections -fdata-sections -mllvm -inline-threshold=0 -fvisibility=hidden -Oz -Wall -Wextra -Wtype-limits

# Uncomment to include stacktraces on calls to fail()
CC+=    -g -finstrument-functions -DWITH_BACKTRACE

LD=   $(COMPILER_PATH)/ld.lld
CL=   $(COMPILER_PATH)/mos-c64-clang -DLLVM -mcpu=mos45gs02
HELPERS=        src/helper-llvm.c

LDFLAGS += -Wl,-Map,bin65/unicode-font-test.map
LDFLAGS += -Wl,-T,src/telephony/asserts.ld

# Uncomment to include stacktraces on calls to fail()
CC+=    -g -finstrument-functions -DWITH_BACKTRACE
 

Then for the build target, I run it twice, first to generate a map file with the memory addresses of all the functions in it, and then generate a C structure with the address of each function and its name listed:

# For backtrace support we have to compile twice: Once to generate the map file, from which we
# can generate the function list, and then a second time, where we link that in.
bin65/unicode-font-test.llvm.prg:    src/telephony/unicode-font-test.c $(NATIVE_TELEPHONY_COMMON)
    mkdir -p bin65
    rm -f src/telephony/mega65/function_table.c
    echo "struct function_table function_table[]={}; int function_table_count=0;" > src/telephony/mega65/function_table.c
    $(CC) -o bin65/unicode-font-test.llvm.prg -Iinclude -Isrc/mega65-libc/include src/telephony/unicode-font-test.c src/telephony/attr_tables.c src/telephony/helper-llvm.s src/telephony/mega65/hal.c src/telephony/mega65/hal_asm_llvm.s $(SRC_TELEPHONY_COMMON) $(SRC_MEGA65_LIBC_LLVM) $(LDFLAGS)
    tools/function_table.py bin65/unicode-font-test.map src/telephony/mega65/function_table.c
    $(CC) -o bin65/unicode-font-test.llvm.prg -Iinclude -Isrc/mega65-libc/include src/telephony/unicode-font-test.c src/telephony/attr_tables.c src/telephony/helper-llvm.s src/telephony/mega65/hal.c src/telephony/mega65/hal_asm_llvm.s $(SRC_TELEPHONY_COMMON) $(SRC_MEGA65_LIBC_LLVM) $(LDFLAGS)

The tool that generates the function list is fairly simple:

#!/usr/bin/env python3
import sys
import re

if len(sys.argv) != 3:
    print(f"usage: {sys.argv[0]} <mapfile> <output.c>")
    sys.exit(1)

mapfile, outfile = sys.argv[1], sys.argv[2]

entries = []
in_text = False

with open(mapfile) as f:
    for line in f:
        if ".text" in line and line.strip().endswith(".text"):
            in_text = True
            continue
        if ".rodata" in line:
            break
        if not in_text:
            continue
        # match lines like: " a7b      a7b     196b     1                 main"
        m = re.match(r"\s*([0-9a-fA-F]+)\s+[0-9a-fA-F]+\s+[0-9a-fA-F]+\s+\d+\s+(\S+)$", line)
        if m:
            addr = int(m.group(1), 16)
            name = m.group(2)
            # skip synthetic names if you want
            if name.startswith("bin") or name.endswith(".o:"):
                continue
            entries.append((addr, name))

with open(outfile, "w") as out:
    out.write("/* auto-generated from map file */\n")
    out.write("const struct function_table function_table[] = {\n")
    for addr, name in entries:
        out.write(f"  {{ 0x{addr:04x}, \"{name}\" }},\n")
    out.write("};\n")
    out.write(f"const unsigned function_table_count = {len(entries)};\n")

Then in an include file, I have:

#ifdef WITH_BACKTRACE
#define STR_HELPER(x) #x
#define STR(x)        STR_HELPER(x)

#define fail(X) mega65_fail(__FILE__,__FUNCTION__,STR(__LINE__),X)
void mega65_fail(const char *file, const char *function, const char *line, unsigned char error_code);
#else
#define fail(X)
#endif

struct function_table {
  const uint16_t addr;
  const char *function;
};

#endif

The last bit of setup then is to have a C file that includes the function table and implements the helper functions:

#include "includes.h"

extern const unsigned char __stack; 

#ifdef WITH_BACKTRACE
#include "function_table.c"
#endif

void dump_backtrace(void);

#ifdef WITH_BACKTRACE

__attribute__((no_instrument_function))
void mega65_uart_print(const char *s)
{  
  while(*s) {
    asm volatile (
        "sta $D643\n\t"   // write A to the trap register
        "clv"             // must be the very next instruction
        :
        : "a"(*s) // put 'error_code' into A before the block
        : "v", "memory"   // CLV changes V; 'memory' blocks reordering across the I/O write
    );

    // Wait a bit between chars
    for(char n=0;n<2;n++) {
      asm volatile(
           "ldx $D012\n"
           "1:\n"
           "cpx $D012\n"
           "beq 1b\n"
           :
           :
           : "x"   // X is clobbered
           );
    }
    
    s++;
  }

}

__attribute__((no_instrument_function))
void mega65_uart_printhex(const unsigned char v)
{
  char hex_str[3];

  hex_str[0]=to_hex(v>>4);
  hex_str[1]=to_hex(v&0xf);
  hex_str[2]=0;
  mega65_uart_print(&hex_str[0]);
}

__attribute__((no_instrument_function))
void mega65_uart_printptr(const void *v)
{
  mega65_uart_print("0x");
  mega65_uart_printhex(((unsigned int)v)>>8);
  mega65_uart_printhex(((unsigned int)v));
}

__attribute__((no_instrument_function))
void mega65_fail(const char *file, const char *function, const char *line, unsigned char error_code)
{

  POKE(0x0428,PEEK(0x02));
  POKE(0x0429,PEEK(0x03));

  mega65_uart_print(file);

  mega65_uart_print(":");

  mega65_uart_print(line);
  mega65_uart_print(":");
  mega65_uart_print(function);
  mega65_uart_print("():0x");

  mega65_uart_printhex(error_code);
  mega65_uart_print("\n\r");

  dump_backtrace();

  while(PEEK(0xD610)) POKE(0xD610,0);
  while(!PEEK(0xD610)) POKE(0xD021,PEEK(0xD012));

}

/*
  Stack back-trace facility to help debug error locations.

*/

#define MAX_BT 32
struct frame { const void *site, *stack_pointer; };
static struct frame callstack[MAX_BT];
static uint8_t depth, sp;

__attribute__((no_instrument_function))
void __cyg_profile_func_enter(void) {
  if (depth>=MAX_BT) depth--;
  
  // Get SPL into sp variable declared above.
  __asm__ volatile ("tsx" : "=x"(sp));
  // Now convert that in
  const uint8_t *stack_pointer = (void *)(0x0100 + sp);
  
  void *call_site = (void *)((*((uint16_t *)&stack_pointer[1])) - 1);
  
  callstack[depth] = (struct frame){ call_site, &__stack };
  depth++;
}

__attribute__((no_instrument_function))
void __cyg_profile_func_exit(void) {
  if (depth) --depth; // simple, assumes well-nested calls
}

__attribute__((no_instrument_function))
void dump_backtrace(void) {
  // For each frame, either:
  //  - print raw addresses, or
  //  - call your on-target addr2line() to print file:line + function

  mega65_uart_print("Backtrace (most recent call first):\n\r");
  unsigned char d= depth-1;

  for(unsigned char d = depth-1;d!=0xff;d--) {
    mega65_uart_print("[");
    mega65_uart_printhex(d);
    mega65_uart_print("] ");

    // Find function in table
    unsigned int func_num = 0;
    while(func_num<(function_table_count-1) && function_table[func_num+1].addr < (uint16_t)callstack[d].site)
      func_num++;

    // Display offset from function
    mega65_uart_printptr(callstack[d].site);
    mega65_uart_print(" ");
    mega65_uart_print(function_table[func_num].function);
    mega65_uart_print("+");
    mega65_uart_printptr((void*)((uint16_t)callstack[d].site - function_table[func_num].addr));

    // Show stack pointer
    mega65_uart_print(", SP=");
    mega65_uart_printptr(callstack[d].stack_pointer);
    mega65_uart_print("\n\r");
  } 
}
#endif

With all that in place, if you call fail(X) where X is an error code, the MEGA65's serial monitor interface will output something like this, and then wait for a keypress on the MEGA65's keyboard before contininuing:

src/telephony/contacts.c:44:mount_contact_qso():0x03
Backtrace (most recent call first):
[02] 0x312A mount_contact_qso+0x00C5, SP=0xD000
[01] 0x10DB main+0x0660, SP=0xD000
[00] 0x0A89 main+0x000E, SP=0xD000
 

So now I know that fail(3) was called from inside mount_contact_qso(), which was called from main().

 

Migrating to Vivado (Part 3)

Vivado is still refusing to synthesise the various BRAM blocks correctly.

I have, however, had a response to my post on the Xilinx Community Forums asking for more information about the problem, which I have provided.

Let's hope that they can suggest a solution.

Migrating to Vivado (Part 2)

The title says it all.

I have managed to massage the C65GS source so that it synthesis in Vivado.

This involved some silly things that Vivado should really support, like casting ports in a module. Don't worry about what that means. Just understand that it is something really simple, and Vivado chokes on it.

However, that dwarfs into insignificance with the real problem: Vivado fails to detect when to use BRAM (the little RAM blocks in the FPGA), and instead tries to implement them using logic.  This means that Vivado thinks I need an FPGA 5x bigger than I have, even though ISE can synthesise it to fit in less than 1/2 the current one.

Oddly, it does realise that two small memories should be BRAMs, as the following output from Vivado shows (you might need to make your display really wide to see the gory detail).

Start RAM, DSP and Shift Register Reporting
---------------------------------------------------------------------------------

Block RAM:
+------------+-------------------------+------------------------+---+---+------------------------+---+---+--------------+--------+--------+------------------------+
|Module Name | RTL Object              | PORT A (depth X width) | W | R | PORT B (depth X width) | W | R | OUT_REG      | RAMB18 | RAMB36 | Hierarchical Name      | 
+------------+-------------------------+------------------------+---+---+------------------------+---+---+--------------+--------+--------+------------------------+
|framepacker | thumnailbuffer0/ram_reg | 4 K X 8(READ_FIRST)    | W |   | 4 K X 8(WRITE_FIRST)   |   | R | Port A and B | 0      | 1      | framepacker/extram__26 | 
|viciv       | rasterbuffer1/ram_reg   | 2 K X 9(READ_FIRST)    | W |   | 2 K X 9(WRITE_FIRST)   |   | R | Port A and B | 1      | 0      | viciv/extram__42       | 
+------------+-------------------------+------------------------+---+---+------------------------+---+---+--------------+--------+--------+------------------------+

Note: The table shows RAMs generated at current stage. Some RAM generation could be reversed due to later optimizations. Multiple instantiated RAMs are reported only once. "Hierarch
ical Name" reflects the hierarchical modules names of the RAM and only part of it is displayed.
Distributed RAM: 
+--------------+--------------------------+--------------------+----------------------+--------------------------------+----------------------+
|Module Name   | RTL Object               | Inference Criteria | Size (depth X width) | Primitives                     | Hierarchical Name    | 
+--------------+--------------------------+--------------------+----------------------+--------------------------------+----------------------+
|gs4510        | shadowram0/ram_reg       | Implied            | 128 K X 8            | RAM256X1S x 4096               | gs4510/ram__25       | 
|iomapper__GC0 | kickstartrom/ram_reg     | Implied            | 16 K X 8             | RAM256X1S x 512                | ram__26              | 
|framepacker   | videobuffer0/ram_reg     | Implied            | 4 K X 8              | RAM64X1D x 128  RAM64M x 128   | framepacker/ram__28  | 
|ethernet      | rxbuffer0/ram_reg        | Implied            | 4 K X 8              | RAM64X1D x 128  RAM64M x 128   | ethernet/ram__29     | 
|ethernet      | rrnet_rxbuffer/ram_reg   | Implied            | 4 K X 8              | RAM64X1D x 128  RAM64M x 128   | ethernet/ram__30     | 
|ethernet      | txbuffer0/ram_reg        | Implied            | 4 K X 8              | RAM64X1D x 128  RAM64M x 128   | ethernet/ram__31     | 
|sdcardio      | sdsectorbuffer0/ram_reg  | Implied            | 512 X 8              | RAM64X1D x 16  RAM64M x 16     | sdcardio/ram__32     | 
|sdcardio      | sdsectorbuffer1/ram_reg  | Implied            | 512 X 8              | RAM64X1D x 16  RAM64M x 16     | sdcardio/ram__33     | 
|sdcardio      | f011sectorbuffer/ram_reg | Implied            | 512 X 8              | RAM64X1D x 16  RAM64M x 16     | sdcardio/ram__34     | 
|uart_monitor  | membuf_reg               | Implied            | 16 X 8               | RAM16X1S x 8                   | uart_monitor/ram__35 | 
|uart_monitor  | historyram0/ram_reg      | Implied            | 1 K X 177            | RAM256X1S x 708                | uart_monitor/ram__37 | 
|viciv         | chipram0/ram_reg         | Implied            | 128 K X 9            | RAM128X1D x 9216               | viciv/ram__38        | 
|viciv         | colourram1/ram_reg       | Implied            | 64 K X 8             | RAM128X1D x 4096               | viciv/ram__39        | 
|viciv         | paletteram0/ram_reg      | Implied            | 1 K X 32             | RAM256X1S x 128                | viciv/ram__40        | 
|viciv         | charrom1/ram_reg         | Implied            | 4 K X 8              | RAM256X1S x 128                | viciv/ram__41        | 
|viciv         | sprite_x_reg             | Implied            | 8 X 8                | RAM16X1S x 8                   | viciv/ram__42        | 
|viciv         | sprite_data_offsets_reg  | Implied            | 8 X 6                | RAM32M x 1                     | viciv/ram__43        | 
|viciv         | sprite_colours_reg       | Implied            | 8 X 8                | RAM16X1S x 8                   | viciv/ram__44        | 
|viciv         | sprite_y_reg             | Implied            | 8 X 8                | RAM16X1S x 8                   | viciv/ram__45        | 
|viciv         | buffer1/ram_reg          | Implied            | 512 X 8              | RAM64X1D x 16  RAM64M x 16     | viciv/ram__46        | 
+--------------+--------------------------+--------------------+----------------------+--------------------------------+----------------------+

All the rest are being implemented as various types of fabric-based RAM.

I have asked for help on the Xilinx Community Forums to see if anyone knows whats going wrong, and how I can work around it.

But for now, it looks like I am using ISE for a bit longer still.

Migrating from ISE to Vivado (Part 1)

I am in the process of attempting to migrate C65GS development from Xilinx's old ISE development environment to their new Vivado.  The promise is a much better synthesis tool chain, with shorter synthesis times, better timing, and it should be easier to describe timing constraints which are a black art in ISE.

Vivado is only a couple of years old, which means that it is still quite unstable as these things go.

Just getting it to install can be interesting.

After downloading the 4.8GB (!) tarball, extracting it and running the xsetup program, it got stuck showing just the splash startup window.

Fortunately I was able to find the solution in the following thread:

http://forums.xilinx.com/t5/Installation-and-Licensing/Vivado-hangs-forever-with-white-window-during-startup-Linux/td-p/479058

Basically it boils down to setting the following shell variable, ideally in your .bashrc or similar ( don't forget to log out and in again or source the file for it to take effect after you have changed it).

export _JAVA_AWT_WM_NONREPARENTING=1

I am unable to comment on why this works, but simply confirm that it lets me at least see the installer.

Now to see if installation works ...