Please note as of Wednesday, August 15th, 2018 this wiki has been set to read only. If you are a TI Employee and require Edit ability please contact x0211426 from the company directory.

Accessing DSP/BIOS Logs Without JTAG

From Texas Instruments Wiki
Jump to: navigation, search

Many developers use the DSP/BIOS LOG_printf() or LOG_event() functions to instrument their applications with debug information. In many cases, especially for telecom or video infrastructure applications, developers may wish to leave the instrumentation in the production code base to enable easier isolation of errors that occur in testing laboratory or field trial situation. One challenge is such situations is that access to DSP/BIOS logs generally requires an emulator to be connected to the malfunctioning DSP. This may be physically impossible in densely-packed board racks or practically impossible if the equipment is at a remote customer site.

Although some recent DSP devices (e.g., DM6437 and DM648) enable DSP/BIOS logs to be retrieved over TCP/IP for viewing in the SoC Analyzer, this capability is not yet available on many devices. An alternative approach for developers is to write some code that retrieves the logs remotely via whatever communication mechanisms are available to the DSP (often via an host microcontroller) and then display the log contents either on the developer's desktop or on a debug console attached to the equipment. To achieve this, it is necessary to understand how to access the log buffers and the format of the log records. This information is summarized below.


Introduction

When a LOG_printf() is executed from your target program, it is written into memory in such a way that the host can grab the entries and output them on the PC. The way the LOG_printf() information is stored is using LOG_Event's in a particular location in memory associated with the log that you’re printing to. This location can be found by taking your log name and concatenating a "$buf" to the end of it. For the trace log you would look for the location in memory associated with the following symbol: "trace$buf". One thing to note when looking at this information directly in memory is that it will be cleared by the RTA plug-in when it is read at run time as well as when it is read via stop mode (i.e., at a breakpoint). The memory location is then filled with 0xFFFF to signify that there is no relevant LOG_printf()> data in memory at that location.

Contents of memory address {log name}$buf

Each four word LOG_Event has the following elements in each log buffer entry:

  • ADDR (first word): SEQNUM – sequence number of the particular LOG_printf statement. This number starts at 2 and counts upwards by two (and this should be divided by two for sequential numbers).
  • ADDR+1 (second word): Arg0 – argument passed to LOG_printf to be used in conjunction with the format string
  • ADDR+2 (third word): Arg1 – argument passed to LOG_printf to be used in conjunction with the format string
  • ADDR+3 (fourth word): STRING – this is the format string address passed to LOG_printf. This string is stored in the .const/.printf sections of the COFF file. To read the string, take the address from the fourth word of the appropriate LOG_Event and read the string at that location in the COFF file up until the NULL character.
The number of LOG_Event entries in the {log name}$buf depends upon the configured size of that particular log buffer. If you wish to look this up, you can either reference your .tcf file (which you can also do using the GConf tool) or grep the COFF file symbol table for the {log name}$size symbol and check its value (for DSP/BIOS v5.10 or later). If you are using DSP/BIOS 4.90 or earlier you will need to look directly at the configuration with the GConf tool under the list of logs and reference the properties for the size field of the log in question.There are some exceptions to the above format. The 28x and 55x are slightly more complicated in terms of interpreting the LOG_Events. They generally stick to the above format but have minor variations based upon the addressing size and where the
LOG_printf()
came from (assembly or C).

Record format on 28x and 55x

There are two main differences in the format of the records on 28x and 55x targets.

1. The records are still 16 bytes each, but the sequence number is only 16-bits instead of 32-bits. The format of a LOG_printf record on the 28x and 55x is as follows:

  • 16-bit pad
  • 16-bit sequence number
  • 32-bit arg0
  • 32-bit arg1
  • 32-bit format address

2. The arguments may be "packed" into the space of arg0 and arg1. When the log record is written, the arguments are copied directly from the stack to the record. For example, if a Log_printf had two arguments, an integer (16-bits) and a pointer (32-bits), the record would have the following format:

  • 16-bit pad
  • 16-bit sequence number
  • 16-bit arg0
  • 32-bit arg1
  • 16-bit empty
  • 32-bit format address

In order to decode the record correctly, you need to know the size of the arguments. This can be done generically by parsing the format string to determine the argument types.

Decoding example for C6x

For illustration purposes we can show how a pseudo-C program on the host could decode a LOG record obtained from a C6000 DSP:

struct LOG_event {
    UInt32 seq;
    UInt32 arg0;
    UInt32 arg1;
    UInt32 formatPtr;
};
 
struct LOG_event log;
char chr;
char format[];
int i = 0;
 
/* ... copy current LOG entry into log ... */
 
do {
    chr = /* ... read a byte from address (log.formatPtr+i) in COFF file ... */;
    format[i] = chr;
    i++;
} while (chr != '\0');
 
printf(format, log.arg0, log.arg1);
</syntaxhighligh>
 
The statements in `backticks` above are loosely specified because there are varied methods with which to accomplish those actions. For example, there are utilities (libraries) available with which to read COFF files.
 
=== Decoding BIOS events ===
The BIOS events ("SWI: post", "TSK: ready", etc.) found in LOG_system$buf are decoded differently from the LOG_printf ones. The third argument is interpreted as an "event id" instead of the address of a string. There are 16 different event ids, that each have a hardcoded meaning.
 
Unfortunately, there is no tool available for decoding these events outside of CCS. The following excerpt of JavaScript code, however, may be useful as a reference in attempting to decode a BIOS event. Based on the event id, it constructs the formatted message using the other arguments.
 
Note: In this code, calls to "getNickName" APIs are used to try and retrieve a label for the object at the specified 'addr'. Be sure to add the DSP/BIOS repository to your package path so the "xdc.useModule()"
functions will find the respective modules. Example: export XDCPATH=c:/ti/bios_5_41_10_06/packages
 
<syntaxhighlight lang='javascript'>
 
    var TSK = xdc.useModule('ti.bios.rov.TSK');
    var KNL = xdc.useModule('ti.bios.rov.KNL');
    var LOG = xdc.useModule('ti.bios.rov.LOG');
    var MBX = xdc.useModule('ti.bios.rov.MBX');
    var MEM = xdc.useModule('ti.bios.rov.MEM');
    var QUE = xdc.useModule('ti.bios.rov.QUE');
    var ROV = xdc.useModule('ti.bios.rov.ROV');
    var SEM = xdc.useModule('ti.bios.rov.SEM');
    var SWI = xdc.useModule('ti.bios.rov.SWI');
    var TSK = xdc.useModule('ti.bios.rov.TSK');
 
    /* Decode the event based on rec.val3 */
    switch (Number(rec.val3)) {
 
        case 0:
            /*
             * _log.h: #define _LOG_PRDBEGIN    0   // handle = prd, arg0 = 0
             * _VSM_systemFormats[_LOG_PRDBEGIN] = "PRD: begin %s (0x%04x)%s";
             * example: "PRD: begin prdClock0 (0x13de8)"
             *
             * PRD doesn't have dynamic name.
             */
            var addr = Number(rec.val2);
            var nickName = ROV.getNickName(ROV.getStaticName(addr), addr);
            return("PRD: begin " + nickName);
 
        case 1:
            /*
             * _log.h: #define _LOG_PRDEND    1   // handle = 0, arg0 = 0
             * _VSM_systemFormats[_LOG_PRDEND]   = "PRD: end";
             * example: "PRD: end"
             */
            return("PRD: end");
 
        case 2:
            /*
             * _log.h: #define _LOG_SWIPOST    2   // handle = swi, arg0 = 0
             * _VSM_systemFormats[_LOG_SWIPOST]  = "SWI: post  %s (0x%04x)%s";
             * example: "SWI: post PRD_swi (0x13a4c)"
             */
             var addr = Number(rec.val2);
             return("SWI: post " + SWI.getNickName(addr));
 
        case 3:
            /*
             * _log.h: #define _LOG_SWIBEGIN   3   // handle = swi, arg0 = 0
             * _VSM_systemFormats[_LOG_SWIBEGIN] = "SWI: begin %s (0x%04x)%s";
             * example:  SWI: begin KNL_swi (TSK scheduler) (0x13a20)
             */
            var handle = SWI.fxnToHandle(Number(rec.val2));
            return("SWI: begin " + SWI.getNickName(handle));
 
        case 4:
            /*
             * _log.h: #define _LOG_SWIEND   4   // handle = swi, arg0 = swi->lock
             * _VSM_systemFormats[_LOG_SWIEND]   = "SWI: end   %s (0x%04x) state = %s";
             * example: SWI: end   PRD_swi (0x13a4c) state = done
             *
             * From vsm.c:
             *   elem->arg2 = (Arg)(event->asa.system.asa.thread.arg0 == 0 ? "still ready" : "done");
             */
            var handle = SWI.fxnToHandle(Number(rec.val2));
            var state = (rec.val1 == 0) ? "still ready" : "done";
            return("SWI: end " + SWI.getNickName(handle) + " state = " + state);
 
        case 5:
            /*
             * _log.h: #define _LOG_PRDTICK    5   // tick.high = PRD_D_timh, tick.low = PRD_D_timl
             * _VSM_systemFormats[_LOG_PRDTICK]  = "PRD: tick count = %d (0x%08x)%s";
             * example: PRD: tick count = 5 (0x00000005)
             */
            var tickCount;
            /* 28x and 55x are 16-bit value in rec.val2 */
            if ((ROV.getISA() == '55') || (ROV.getISA() == '28')) {
                tickCount = Number(rec.val2);
            }
            /* 6x is 32-bit value in rec.val1 */
            else {
                tickCount = Number(rec.val1);
            }
            return("PRD: tick count = " + tickCount + " (" + countToHex(tickCount) + ")");
 
        case 6:
            /*
             * _log.h: #define _LOG_CLKINT    6   // tick.high = CLK_R_timh, tick.low = CLK_R_timl
             * _VSM_systemFormats[_LOG_CLKINT]   = "CLK: current time = %d (0x%08x)%s";
             * example: CLK: current time = 6 (0x00000006)
             */
            var tickCount;
            /* 28x and 55x are 16-bit value in rec.val2 */
            if ((ROV.getISA() == '55') || (ROV.getISA() == '28')) {
                tickCount = Number(rec.val2);
            }
            /* 6x is 32-bit value in rec.val1 */
            else {
                tickCount = Number(rec.val1);
            }
            return("CLK: current time = " + tickCount + " (" + countToHex(tickCount) + ")");
 
        case 7:
            /*
             * This event does not appear to be implemented in BIOS 5.
             * _log.h: #define _LOG_HWIBEGIN  7   // handle = hwi id, arg0 = 0
             * _VSM_systemFormats[_LOG_HWIBEGIN] = "HWI: begin";
             */
            return("HWI: begin");
 
        case 8:
            /*
             * _log.h: #define _LOG_USRMSG  8   // user message (format arg0)
             * exmple:
             */
            var args = [Number(rec.val1)];
            var msg = getMessage(rec.val2, args);
            return(msg);
 
        case 9:
            /*
             * _log.h: #define _LOG_USRERR  9   // user error (format arg0)
             * example: SYS_error called: error id = 0x1
             */
            var args = [Number(rec.val1)];
            var msg = getMessage(rec.val2, args);
            return(msg);
 
        case 10:
            /*
             * _log.h: #define _LOG_TSKBLOCKED  10  // handle = tsk, arg0 = 0
             * _VSM_systemFormats[_LOG_TSKBLOCKED] = "TSK: blocked %s (0x%08x) on %s";
             * example: TSK: blocked task1 (0x000137b0) on <unknown handle> SEM
             */
            var addr = Number(rec.val2)
            return("TSK: blocked " + TSK.getNickName(addr));
 
        case 11:
            /*
             * _log.h: #define _LOG_TSKDONE  11  // handle = tsk, arg0 = 0
             * _VSM_systemFormats[_LOG_TSKDONE] = "TSK: terminated %s (0x%08x)%s";
             * example: TSK: terminated task0 (0x0001170c)
             */
            var addr = Number(rec.val2);
            return ("TSK: terminated " + TSK.getNickName(addr));
 
        case 12:
            /*
             * _log.h: #define _LOG_TSKRUNNING  12  // handle = tsk, arg0 = 0
             * _VSM_systemFormats[_LOG_TSKRUNNING] = "TSK: running %s (0x%08x)%s";
             * example: TSK: running task1 (0x000137b0)
             */
            return("TSK: running " + TSK.getNickName(Number(rec.val2)));
 
        case 13:
            /*
             * _log.h: #define _LOG_TSKREADY  13  // handle = tsk, arg0 = 0
             * _VSM_systemFormats[_LOG_TSKREADY] = "TSK: ready %s (0x%08x)%s";
             * example: TSK: ready task1 (0x000137b0)
             */
            return ("TSK: ready " + TSK.getNickName(Number(rec.val2)));
 
        case 14:
            /*
             * _log.h: #define _LOG_SEMPOST  14  // handle = sem, arg0 = sem count
             * _VSM_systemFormats[_LOG_SEMPOST] = "SEM: post %s (0x%04x) count = %d";
             * example: SEM: post <unknown handle> (0x13dc8) count = 0
             */
            var addr = Number(rec.val2);
            return ("SEM: post " + SEM.getNickName(addr));
 
        case 15:
            /*
             * _log.h: #define _LOG_TSKYIELD  15  // handle = tsk, arg0 = 0
             * _VSM_systemFormats[_LOG_TSKYIELD] = "TSK: yield %s (0x%08x)%s";
             * example: TSK: yield task0 (0x0001170c)
             */
            var addr = Number(rec.val2);
            return ("TSK: yield " + TSK.getNickName(addr));
 
        case 16:
            /*
             * This event does not appear to be handled by VBD.
             * _log.h: #define _LOG_PWRMRSRCCHNG  16  // arg0 = id, arg1 = 0(off) or 1(on)
             * example:
             */
            var off = (rec.val2 == 0) ? "off" : "on";
            return ("PWRM: Source Change id: " + rec.val1 + " " + off);
 
        default:
            return ("Unknown event id " + rec.val3);
    }