gnupic: Thread: Re: Trace logging in gpsim

For some time (like 2 years) I've wanted to add trace logging to gpsim. Right
now, gpsim logs nearly everything it does to a rather larger (but compile time
defined) circular buffer. I would like to enhance this so that the circular
buffer is periodically dumped to a file. Furthermore, I'd like to create some
tool that can parse this log file and produce profiles or waveforms. 

But before proceeding, I'd like to get some feed back. 

First of all, is this going to be useful?

Second, what are some of the things you'd like to see in the profiler? The wave
viewer?


For the profiler, I was thinking of something simple like a histogram plot. The
x-axis would be the program memory location, the y-axis would be the number of
times that address was encountered. A similar plot could be created for the
register memory.

For the waveform viewer, I was thinking of something that would allow you to
plot things like the value of a register as a function of time or perhaps the
value of a bit in a register as a function of time.

Some of the packages I'm thinking about using or at least investigating are:

gtkplot: http://www.ifir.edu.ar/grupos/gtk/
This is another of Adrian Feiguin widgets. We already use his gtksheet widget
for the register viewer and program memory viewer.

gtkwave: http://daggit.pagecreator.com/ver/wave/
This is a full featured waveform viewer used to view the output of Verilog
simulations. I'm almost tempted to convert the gpsim log files to verilog format
just so that they may be viewed with gtkwave! The only thing it lacks is a way
to view data as an analog waveform. In other words, if the data is more than one
bit wide, then it is lumped together and a number is printed (within the
waveform). (This is useful for viewing an address bus, but not the value of A/D
conversion register.)

gwave: http://www.geda.seul.org/tools/gwave/index.html
This a waveform viewer for spice outputs. It's the opposite extreme from gtkwave
in that it only plots analog data.

-----------------

Another feature I'd like to see in the viewer is a waveform editor. I'd like
this to be capable of creating stimulus files that can be fed back into gpsim.


If anyone has any opinions or ideas I'd like to hear them!

Scott

Scott Dattalo wrote:

> 
> Another feature I'd like to see in the viewer is a waveform editor. I'd like
> this to be capable of creating stimulus files that can be fed back into gpsim.
> 
> If anyone has any opinions or ideas I'd like to hear them!
> 
> Scott
Have you considered:
   http://plasma-gate.weizmann.ac.il/Grace/
It uses Motif/Lesstif for the GUI (xmgrace) but has a console mode
(grace)
It was suggested to me (possibly you :) to plot my PIC digitized analog
data.

BTW, my scenix to PIC port is almost there. Much bigger job than I
expected.
Garst

On Tue, Sep 05, 2000 at 09:39:18PM -0500, Scott Dattalo wrote:
> 
> For some time (like 2 years) I've wanted to add trace logging to gpsim. Right
> now, gpsim logs nearly everything it does to a rather larger (but compile time
> defined) circular buffer. I would like to enhance this so that the circular
> buffer is periodically dumped to a file. Furthermore, I'd like to create some
> tool that can parse this log file and produce profiles or waveforms. 
> 
> But before proceeding, I'd like to get some feed back. 
> 
> First of all, is this going to be useful?
> 
> Second, what are some of the things you'd like to see in the profiler? The wave
> viewer?

hello everybody!

i'd suggest it this way:

gpsim can create a log file in a ascii based human readable language
that supports all the processors cleanly, that gpsim supports.
this file just contains everything that is available.
i.e. it does not show a+b, but it shows a and b :)

and then one can write arbitrary tools to parse those files.
for example:

* please give me the output value of portb bit 3 starting at cpu cycle
  10000 until cycle 20000. write 1000 values per second one value a line.
  
  then this can be fed into gnuplot.

* or arbitrary other checks! for example i could write a program that
  checks if some output bits are always consistently set.
  maybe i have connected some hardware that dies if a certain sequence
  is output. then i can write program that checks the log for this.

* i could also write a shell script that starts gpsim 100 times, always
  the same pic program, but every time different stimuli. then the
  log is analyzed for correctness.

* maybe i have a complex program with complex interrupt driven timing.
  it does RS232 output on one pin. then i can write a program that
  analyzes the log if the generated rs232 signal is correctly timed.
  this would be VERY useful ;)
  i could then also reuse it. look:
  ./analyze_rs232 portb bit3 positive_logic \\
      baud115200 8n1 10MHz && echo RS232 signal is OK \!
  of course the analyzer can also write out the actual data sent via
  RS232 which again is VERY useful.

the logfile language must be carefully thought about.
perhaps it is possible to make it in a way that some things can even
be done with grep, sed and awk :)
on the other hand it should not be ugly just to make easy use
of grep possible.


but then i wonder why there are the plugins in gpsim. they are more
powerful than the logfile, because they can adjust inputs and scan
outputs in realtime! the log cannot do that.
so why not drop the log and instead write a plugin that dumps the value
of some pins over the time in a ascii file and feeds it into gnuplot?


well that's just my 5 cents.

cu
erik :-)

-- 
Name:  Erik Thiele                                       \\\\
Email: ####@####.####                                o `QQ'_
IRC:   erikyyy                                            /   __8
WWW:   http://www.erikyyy.de/                             '  `

On Wed, 6 Sep 2000, Garst R. Reese wrote:

> Scott Dattalo wrote:
> 
> > 
> > Another feature I'd like to see in the viewer is a waveform editor. I'd like
> > this to be capable of creating stimulus files that can be fed back into gpsim.
> > 
> > If anyone has any opinions or ideas I'd like to hear them!
> > 
> > Scott
> Have you considered:
>    http://plasma-gate.weizmann.ac.il/Grace/
> It uses Motif/Lesstif for the GUI (xmgrace) but has a console mode
> (grace)
> It was suggested to me (possibly you :) to plot my PIC digitized analog
> data.

No, I hadn't considered it because I didn't know about it. Someone else probably
suggested it to you. 

I took a quick look at it and it appears to be something like the `MicroCal
Origin' emulation program that Adrian was working on at one time (but not as
pretty). It also appears that Grace allows you manipulate data as well. I'll
take a closer look.

> 
> BTW, my scenix to PIC port is almost there. Much bigger job than I
> expected.

Isn't it always? :)

Scott

On Wed, 6 Sep 2000, Erik Thiele wrote:

> hello everybody!
> 
> i'd suggest it this way:
> 
> gpsim can create a log file in a ascii based human readable language
> that supports all the processors cleanly, that gpsim supports.
> this file just contains everything that is available.
> i.e. it does not show a+b, but it shows a and b :)

The only problem with ASCII is that it will dramatically slow the simulation
down. My idea was to copy the raw (binary) trace log buffer to a file. Having to
parse through the log during simulation will take a relatively long time. 

OTOH, an option for either type of logging could be added. In fact, the current
trace dump could modified to redirect its output to a file instead of
stdout. This way, a human readable trace would be produced. But this will create
an enormous file!

> 
> and then one can write arbitrary tools to parse those files.
> for example:
> 
> * please give me the output value of portb bit 3 starting at cpu cycle
>   10000 until cycle 20000. write 1000 values per second one value a line.
>   
>   then this can be fed into gnuplot.
> 
> * or arbitrary other checks! for example i could write a program that
>   checks if some output bits are always consistently set.
>   maybe i have connected some hardware that dies if a certain sequence
>   is output. then i can write program that checks the log for this.
> 
> * i could also write a shell script that starts gpsim 100 times, always
>   the same pic program, but every time different stimuli. then the
>   log is analyzed for correctness.
> 
> * maybe i have a complex program with complex interrupt driven timing.
>   it does RS232 output on one pin. then i can write a program that
>   analyzes the log if the generated rs232 signal is correctly timed.
>   this would be VERY useful ;)
>   i could then also reuse it. look:
>   ./analyze_rs232 portb bit3 positive_logic \\
>       baud115200 8n1 10MHz && echo RS232 signal is OK \!
>   of course the analyzer can also write out the actual data sent via
>   RS232 which again is VERY useful.
> 
> the logfile language must be carefully thought about.
> perhaps it is possible to make it in a way that some things can even
> be done with grep, sed and awk :)
> on the other hand it should not be ugly just to make easy use
> of grep possible.

Hmm. I hadn't thought about parsing the logfile in the ways you suggest. I was
thinking about some kind of gui that would graphically present the data and
provide ways to query and manipulate it. A good analogy would be an Osciloscope
or Logic Analyzer. Somehow, you choose a signal to display and it magically
appears in a graph. Cursor bars could allow you to make measurements like
amplitudes, frequencies, periods, etc.


> 
> 
> but then i wonder why there are the plugins in gpsim. they are more
> powerful than the logfile, because they can adjust inputs and scan
> outputs in realtime! the log cannot do that.
> so why not drop the log and instead write a plugin that dumps the value
> of some pins over the time in a ascii file and feeds it into gnuplot?

Exactly! 

Scott

I think this is a great idea in one form or another.

Personally, I want some kind of scope/logic analyzer functionality.  I
want this to work either in real time or from a saved file.  Being able
to verify serial IO, or I2C, or interrupt response time would be great. 
Dumping things in hex format would be easy to work with without wasting
too much time on formatting.

The other trace feature that I want is to be able to back step through
the instruction sequence.  I want to be able to set a breakpoint at an
"abandonAllHope" point, and then back trace to figure out how it got
there (and why).

I don't care so much about logging everything as being able to dump the
log to a file.  Of course, this works fine as long as the fixed trace
buffer is "big enough".

I modified the trace output to put out one line for every cycle.  This
is far from perfect, but I find it much more readable than the current
style.  I can easily see all the things that happened during that
cycle.  It can get really wide.  I better form would break the line and
indent properly.  Let me know if you want the patch.

Would there be a way to extend the trace mechanism?  As you add modules,
you may want a way to catch new internal state.

One other question.  Can gpsim actually handle a multi-processor
system?  The JRKerr servo controllers use two PICs (one for control and
one just to count the encoders).  There are situation where this is just
what you want to do to get guaranteed response times.  Debugging the
interaction could be tricky unless you could simulate both at the same
time.

-Dan Christian

On Wed, 6 Sep 2000, Daniel Christian wrote:

> I think this is a great idea in one form or another.
> 
> Personally, I want some kind of scope/logic analyzer functionality.  I
> want this to work either in real time or from a saved file.  Being able
> to verify serial IO, or I2C, or interrupt response time would be great. 
> Dumping things in hex format would be easy to work with without wasting
> too much time on formatting.
> 
> The other trace feature that I want is to be able to back step through
> the instruction sequence.  I want to be able to set a breakpoint at an
> "abandonAllHope" point, and then back trace to figure out how it got
> there (and why).

One of the early features I had in gpsim was a `step backwards' operation. It's
purpose was for what you just describe. I also envisioned it being used to test
`what-if' scenarios. For example, some times it's difficult to get the program
into a certain state (by manually manipulating registers etc.). So I thought
it'd be useful to set break points at these hard-to-reach states, step
backwards, manipulate something, and then step forwards. Implementing the step
backwards function is fairly easy if all you're simulating is the pic
instruction set. However, when you begin throwing in stimuli, tmr0 and the other
peripherals, it becomes much more difficult. So I abandoned that.

Now, it could be useful to `play back' a log file. In other words, I could see
the gui being fooled into believing that it was simulating a pic when in fact
the trace log is being fed to it instead. This way you could move the cycle
counter to any value and have an instant image of the simulation state. Single
stepping would consist of fetching a cycle's worth of simulation data. 

> 
> I don't care so much about logging everything as being able to dump the
> log to a file.  Of course, this works fine as long as the fixed trace
> buffer is "big enough".

Early on I did some profiling comparing different tracing techniques. I found
that it was faster to trace everything than to make an effort to trace only
certain things. The reason is that the decision takes extra code. The tracing
operation itself turns out to be very fast. It typically goes like this:

  inline void register_write (unsigned int address, unsigned int value)
  {
    trace_buffer[trace_index] = REGISTER_WRITE | (address << 8) | value;
    trace_index = (trace_index + 1) & TRACE_BUFFER_MASK;
  }

The `inline' option means that the trace `calls' are not really calls. The code
is placed directly inline. In this case the accompanying x86 assembly code is:

/home/scott/gnupic/gpsim/src/trace.h:87
     1da:	8b 93 00 00 00 00    	movl   0x0(%ebx),%edx
/home/scott/gnupic/gpsim/src/trace.h:88
     1e0:	8b 8a 00 40 00 00    	movl   0x4000(%edx),%ecx
     1e6:	8d 34 8d 00 00 00 00 	leal   0x0(,%ecx,4),%esi
     1ed:	8b 4f 08             	movl   0x8(%edi),%ecx
     1f0:	c1 e1 08             	shll   $0x8,%ecx
     1f3:	8b 47 04             	movl   0x4(%edi),%eax
     1f6:	0d 00 00 00 03       	orl    $0x3000000,%eax
     1fb:	09 c8                	orl    %ecx,%eax
     1fd:	89 04 16             	movl   %eax,(%esi,%edx,1)
/home/scott/gnupic/gpsim/src/trace.h:89
     200:	8b 82 00 40 00 00    	movl   0x4000(%edx),%eax
     206:	40                   	incl   %eax
     207:	25 ff 0f 00 00       	andl   $0xfff,%eax
     20c:	89 82 00 40 00 00    	movl   %eax,0x4000(%edx)


> I modified the trace output to put out one line for every cycle.  This
> is far from perfect, but I find it much more readable than the current
> style.  I can easily see all the things that happened during that
> cycle.  It can get really wide.  I better form would break the line and
> indent properly.  Let me know if you want the patch.

Sure!

> Would there be a way to extend the trace mechanism?  As you add modules,
> you may want a way to catch new internal state.

I've thought about it, but haven't done too much. The LCD module does do some
tracing but it is not too complete.

> One other question.  Can gpsim actually handle a multi-processor
> system?  The JRKerr servo controllers use two PICs (one for control and
> one just to count the encoders).  There are situation where this is just
> what you want to do to get guaranteed response times.  Debugging the
> interaction could be tricky unless you could simulate both at the same
> time.

Again, the mulit-processor feature was designed into gpsim at the outset. I've
never made use of it. However, I've been very diligent in not making assumptions
about which pic is being simulated. For example, each register for the pic is a
c++ object. One of the members of this object is a pointer to the cpu to which
the register belongs. As you might imagine, the pointer to the cpu is copied
many times over. But so what. My Linux box has much more memory than a pic!

The problem that needs to be addressed before multiple pics can be simulated is
the way gpsim handles time. I've got a solution, but there hasn't been a need to
invoke it. But the problem basically is that the cycle counter serves as the
time keeper for gpsim. This forces everything in the simulation to conform to
the pic's cycle counter. If you have more than one pic then things start to get
confusing. In fact, I argue that timing any event aynchronous to the pic is
confusing.

The way to get around is to provide another timer based on 'simulated real
time'. I'm envisioning a 64-bit counter with resolution down to 10's of
pico-seconds. 1pS resolution with a 64-bit counter still gives 512 hours of
simulation time. The cycle counter will then be based on this new timer. If two
pics are being simulated, then the one whose cycle counter is scheduled to
increment next will gain control.


Scott

Check out the "Trace Analyser" on Forest Electronics web page:

http://www.fored.co.uk/Eindex.htm

Something like this is what I had in mind. Any opinions?

Scott

Last night I got the first portion of trace logging finally implemented. It's a
good news/bad news result. First, the good news - it works! Bad news - I don't
on stock in any disk drive manufacturing companies.

How it works:
gpsim maintains an internal circular buffer for holding all trace events. A
trace event is anything like a register read/write, cycle counter increment,
opcode execution, skipped instructions, etc. Each of these events is efficiently
encoded into a 32 bit integer and copied to the circular buffer.

For trace logging, the internal trace buffer is periodically written to disk.


I did a couple of experiments. In the first I wrote the trace buffer 32 integers
out in ASCII. In other words, each 32 bit value took 9 bytes in the trace log
file (8 for the 8 nibbles and 1 for the \n). This slowed the simulation down
dramatically. In fact, after 10 seconds of running gpsim would did not even
break the 1-million cycle barrier. OTOH, the log file was 27Meg! I ran this
through bzip2 and 30 seconds later compressed it to 840k.

The second experiment consisted of writing the raw trace buffer to the disk. In
other words, the trace buffer was written using fwrite(). There was no ascii
conversion so the result was much faster. In fact, for the first few seconds
there was no noticable delay in the simulation. But once the internal (OS)
memory buffers were exhausted, the simulation slowed dramatically. In fact, once
the simulation stopped it took several seconds to write the buffered data to
disk. I guess in about 5 seconds 72Megs worth of simulation data was
accumulated! That's a lot of data.

--------

So now I have the question: is this really desirable?

I'm inclined to say no. Perhaps a better approach is to significantly increase
the internal trace buffer and provide some kind of IPC interface to gpsim to
obtain access to this data. This sounds like something that can be done with the
module approach.

Another idea is to provide a mechanism of logging specific data. For example,
log only register writes to a particular register. Or perhaps create triggers
that analogous to break points but enable trace logging instead of halting
execution.

Any ideas here?

Scott

On Tue, Sep 12, 2000 at 05:11:05PM -0500, Scott Dattalo wrote:
> 
> The second experiment consisted of writing the raw trace buffer to the disk. In
> other words, the trace buffer was written using fwrite(). There was no ascii
> conversion so the result was much faster. In fact, for the first few seconds
> there was no noticable delay in the simulation. But once the internal (OS)
> memory buffers were exhausted, the simulation slowed dramatically. In fact, once
> the simulation stopped it took several seconds to write the buffered data to
> disk. I guess in about 5 seconds 72Megs worth of simulation data was
> accumulated! That's a lot of data.
> 
> --------
> 
> So now I have the question: is this really desirable?
> 
> I'm inclined to say no. Perhaps a better approach is to significantly increase
> the internal trace buffer and provide some kind of IPC interface to gpsim to
> obtain access to this data. This sounds like something that can be done with the
> module approach.
> 
> Another idea is to provide a mechanism of logging specific data. For example,
> log only register writes to a particular register. Or perhaps create triggers
> that analogous to break points but enable trace logging instead of halting
> execution.
> 
> Any ideas here?

i never really looked at the gpsim source or the module interface :)
so i don't know if i correctly assume what it looks like :)

i suggest you add the possibility for a module to get the logging data.
i.e. not those integers but it must be easily possible for a module
to get all information.

then you place your new logger as a module for the persons who need it.

all the others that know some tricks to reduce output (by knowing that
logging is only needed if PORTA bit 2 = hi for example) can then write
their own logging module by adjusting your code.

writing code into gpsim is not the worst idea.
there is a philosophical question here :)
my friend and mine always tried to write computer games.
there you could move your ships and tanks around. of course
there are several kinds of ships and tanks. so we thought they had
to be configurable through config files.
what we did in the end was to create a language to describe those tanks.
instead we could have used the source code of the game and just added
the tanks in there. that would have been much easier :)

so what i want to say is perhaps it's more easy to have a good module
interface which makes me able to write my own modules, than to try
to create some logger with multi multi features which in the end
will be more complicated for the end user than the
write-your-own-module-approach :)


cu
erik

PS: just my 5 cents :)

-- 
Name:  Erik Thiele                                       \\\\
Email: ####@####.####                                o `QQ'_
IRC:   erikyyy                                            /   __8
WWW:   http://www.erikyyy.de/                             '  `