Re: [ECOS] Kernel instrumentation question

[Andrew Lunn <andrew dot lunn at ascom dot ch>]

On Wed, Oct 10, 2001 at 05:49:51PM -0500, Grant Edwards wrote:
> On Wed, Oct 10, 2001 at 03:10:34PM -0500, Grant Edwards wrote:
> 
> > I configured my kernel to instrument clock, thread, alarm class
> > events.  Should the timestamps in the buffer be in
> > non-decreasing order?
> 
> Apparently not.  Further source code perusal reveals The
> timestamps to be the number of hardware timer ticks since the
> last 10ms system interrupt. 
> 
> However, if you are instrumenting clock events, you see each of
> the tick events, so you can construct a "real" timestamp for
> the other events if you want. I've got a Python program that
> post-processes the instrument buffer, so it can do that.  It
> sure would be nice to be able to "print" a variable to a file
> from the gdb prompt...

I wrote and contributed a C program to do the same. Its in the
kernel/current/host directory. Attached is a newer version is adds the
'real' time stuff. It needs modified CDL code....

cdl_component CYGDBG_KERNEL_INSTRUMENT_HOST_DUMP {
    display       "Build the host tool to print out a dump"
    requires 1 == CYGDBG_KERNEL_INSTRUMENT_MSGS
    default_value 1
    description   "
        Generate a host program which can dump the instrumentation
        data in a human readable format. You have to somehow get the
        instrumemtation buffer into a file on the host"

    make -priority 51 {
        <PREFIX>/bin/dump_instr: <PREFIX>/include/cyg/kernel/instrument_desc.h 
        @sh -c "mkdir -p $(dir $@)"   
        cc -g -I $(PREFIX)/include/cyg/kernel -idirafter $(PREFIX)/include $(REPOSITORY)/$(PACKAGE)/support/dump_instr.c -o $(PREFIX)/bin/dump_instr
    }
}  

This program assumes you can get the raw instrumentation buffer off
the target. I use the TFTP server code which works well.

    Andrew

PS 

-idirafter is really nice when you want to use both host and eCos
 include files. I have stdlib.h from the host and pkgconf/kernel.h
 from eCos. 
#include <stdio.h>
#include <stdlib.h>
#include <pkgconf/kernel.h>

#define NELEM(x) (sizeof(x)/sizeof*(x))

typedef short CYG_WORD16;
typedef long  CYG_WORD;
typedef long long CYG_WORD64;

#include <instrument_desc.h>

#define CYG_INSTRUMENT_EVENT_CLOCK_TICK_END     2
#define CYG_INSTRUMENT_CLASS_CLOCK              0x0800
#define CYG_INSTRUMENT_CLOCK_TICK_END \
   (CYG_INSTRUMENT_EVENT_CLOCK_TICK_END|CYG_INSTRUMENT_CLASS_CLOCK)

// Instrumentation record.

struct Instrument_Record
{
    CYG_WORD16  type;                   // record type
    CYG_WORD16  thread;                 // current thread id
    CYG_WORD    timestamp;              // 32 bit timestamp
    CYG_WORD    arg1;                   // first arg
    CYG_WORD    arg2;                   // second arg
};

static long rtc_resolution[] = CYGNUM_KERNEL_COUNTERS_RTC_RESOLUTION;
static CYG_WORD64 ns_per_tick;
static CYG_WORD64 ps_per_hal_clock;
static CYG_WORD64 ticks = 0;

char * cyg_instrument_msg(CYG_WORD16 type) {
  struct instrument_desc_s *record;
  struct instrument_desc_s *end_record;
  CYG_WORD cl, event;

  record = instrument_desc;
  end_record = &instrument_desc[NELEM(instrument_desc)];
  cl = type & 0xff00;
  event = type & 0x00ff;

  while ((record != end_record) && (record->num != cl)) {
    record++;
  }

  if (record->num == cl) {
    record++;
    while ((record != end_record) && (record->num != event) &&
           (record->num < 0xff)) {
      record++;
    }

    if (record->num == event) {
      return (record->msg);
    }
  }
  return("Unknown event");
}

void usage(char *myname) 
{
  fprintf(stderr,"Usage: %s <filename>\n",myname);
  fprintf(stderr,"where filename is that of the instrumentation data");
}

/* Return the time in ns */
CYG_WORD64 cvt_time(CYG_WORD timestamp) 
{
  return ((ticks * ns_per_tick) + 
          ((CYG_WORD64)timestamp * ps_per_hal_clock)/1000);
}

int main(int argc, char * argv[]) 
{
  
  FILE * file;
  char * filename;
  struct Instrument_Record record;
  int cnt=0;

  ns_per_tick = 1000000/rtc_resolution[1];
  ps_per_hal_clock = ns_per_tick * 1000 / CYGNUM_KERNEL_COUNTERS_RTC_PERIOD;
     
  if (argc != 2) {
    usage(argv[0]);
    exit(1);
  }

  filename = argv[1];

  file = fopen(filename, "r");
  if (!file) {
    fprintf(stderr,"Error opening file %s: ",filename);
    perror("");
    exit(1);
  }
  
  while (!feof(file)) {
    fread(&record,sizeof(record),1,file);
    if (record.type == 0) {
      break;
    }

    if (record.type == CYG_INSTRUMENT_CLOCK_TICK_END) {
      ticks = ((CYG_WORD64)record.arg2 << 32) + ((CYG_WORD64)record.arg1);
    }

    printf("%4d Record type (0x%04x): %-20s thread %2d, ",
           cnt++,record.type,cyg_instrument_msg(record.type), 
           record.thread);

    printf("time %10lld, arg1 0x%08x, arg2 0x%08x\n",
           cvt_time(record.timestamp), record.arg1,
           record.arg2);
  }

  fclose(file);
  return (0);
}