Wednesday 27 July 2016

Part 20: Debbuging the garbled game screen

Foreword

In the previous blog we added joystick emulation to our emulator and managed to start the game.

However, with the start of the game we were faced with a garbled screen.
In this blog we will investigate why we are presented with a garbled screen.

I will using an interesting debugging technique where we will compare the state of our emulator with the state of another known working emulator in order to isolate the issue in our emulator.

This is a bit of a lengthy blog, so maybe have a cup of coffee handy when reading :-)

Enjoy!

Initial round of debugging

Let us do an initial round of debugging to get some pointers into which direction we should go to find out why the game screen is garbled.

Let us have a look again at the problem screen of the previous blog:

We haven't got a change to properly test the multicolor text mode that we have implemented in a previous blog. Could it be that there is still some bugs in that functionality causing this rendering issues?

A quick sanity check for this is to inspect the screen character memory. There is something concrete we can look for, for the instance the out of place A in the top right corner. If we get that character in the same position in character memory, we know that our theory on a rendering bug in the multicolor text mode doesn't carry much weight.

From the looks of it we can see that the characters displayed is definitely custom defined characters and we are not guaranteed that it use standard PET screen codes. To get an idea what screen codes it is using, we can look at a sequence of screen characters, like DAN LANDED THE ANASTASIA.

The above mentioned sequence of screen codes is more less at the beginning of the second screen line.

So lets do some memory inspection:

 The second screen line starts at memory location 427h. We see they are using code A0 for a space and 81 for an A. From that point they use the ordinal position in the alphabet. So, the characters 84 81 8E A0 8C 81 8E 84 85 84 corresponds to DAN LANDED.

The out of place A is at the end of the second line which is at location 44E. Indeed, the code at that location is 81, which is an A!

So, something in the machine code program is populating the screen RAM incorrectly, but what?

At this point it would be really useful to do some comparisons against a second emulator that does render this screen correctly. The emulator I am going to use for this purpose will be VICE.

VICE by the way, gives you some nice debugging facilities. One of these facilities is that it allows you to break when the contents of a specific memory location change.

Fire up the loading of Dan Dare in Vice. As soon as the intro screen appears, hit ALT+H to activate the monitor.


Time to set a breakpoint. We would like to break as soon as an instruction writes to location 427. So enter the following in the monitor:

watch store 427

The monitor will give you a confirmation that the breakpoint is set. Enter goto to resume the emulator:



Now hit the firebutton to start the game. Your breakpoint will trigger in a flash of a second.

We know single step s couple of times to determine where the data comes from which is populated to the screen:

Looks like we hit a loop that is busy clearing the screen. Not exactly what we are looking for. So, type in goto to resume the emulator.

After a flash, our breakpoint gets triggered again. So lets single step a couple of times again.

This time it looks more promising:


Looks like it is literally copying data from the location 1C00. So lets us inspect this memory area. In the Vice Monitor you just need to issue m 1c00 to inspect this area:


And indeed, at memory location 1c27, we can make out the familiar DAN DARE LANDED THE ANASTASIA.

So, what populates the memory area at 1C00? To answer this question, we need to follow the above mentioned debug process, but with watch point at address 1C00.

Restarting the debug process with the new watch point will again break in loop filling the area with the value 20. So give it another goto.

When it breaks again, we give it a couple of single steps, yielding the following screen:


So, it retrieves the data via stored address at $96 and store the data via address stored at A8.

I think next we should determine what manipulate the contents of address $96. This yield the following:


I think this is a nice point to actually compare with our JavaScript emulator to see if our emulator comes up with the same register values when address 5358 is hit the first time.

Just to make sure we are not chasing out own tale, I have restarted the Vice emulator 3 times hitting breakpoint 5358 each time and verify that the register values is the same each time.

We start our JavaScript emulator with a breakpoint at 5358. When it hits this our breakpoint, our register values is a follows:

Acc:40 X:ae Y:02SP: f1 PC:5358 Z:0 N:0 C:0 V:0 D:0

Register X is clearly different!

It would be nice if we could go back to previous instructions executed to see where the world went pair shape.

In the next two sections I will show how to setup Vice and our JavaScript emulator respectively to log the state of each instructions executed. We can then do some comparisons against the two logs to see where we went wrong.

Enabling Instruction tracing in Vice

As mentioned in the previous section, it would be nice if we could log the state of the registers after each and every instruction execution.

How do you enable this in Vice? Reading through the documentation of Vice and consulting web resources is not very explicit about such a kind of functionality.

However, if you browse the source code of Vice, you do in fact see debug logging statements after executing a 6502 instruction.

So, it looks like the functionality that we want is within Vice. It is just a matter of knowing how to enable it.

After some further investigations I found that one is out of luck with pre-compiled Vice binaries. However, if you compile Vice yourself, your luck is in :-)

Ok, I am going to make one assumption at this point, and this is that you do have a workable environment for building Vice from source. Typically for a Debian/Ubuntu environment this would mean having installed the build-essential package, together with some GUI libraries like GTK2 development library.

Now, if you open up a terminal window, navigate to the Vice source and type:

./configure -help

You will see that one of the options is --enable-debug-code

This is the option we are looking for, so run configure with the following options:

./configure --enable-debug-code --enable-gnomeui

The --enable-gnomeui  option compiles your version of Vice with Gnome support, suitable for Debian/Ubuntu.

Kick off the building of Vice with:

make

We will not bother to install this version of Vice, since it is a debug version anyway. So, after the make process is finished, just navigate to the src folder and kick off the emulator with:

./x64


On startup, you might get some warning messages that the sound system could not be started. Not a problem in our scenario.

You will notice an extra menu category Debug in the Vice window:

In this category, the menu item of interest is Main CPU Trace. When you select this menu item, you will see the terminal window from which you invoked Vice will get cluttered with log items:

The most left hand column is the address, and the column on the right hand side is the status of the registers in the following order: Accumulator, X register, Y register and SP.

Typically your terminal window is limited by the number of lines it can store in the scroll back history, so it would be better to log the trace the a file to avoid possible loss of lines.

The following command will enable logging to a file for you:

./x64 -logfile log.txt

This will log console output to the file log.txt.

One thing that you will notice when you enable this logging, is that the performance of the emulator drop dramatically. On my desktop it performs at about 6% of the original speed. So it is advisable to only switch on logging at the point you need it. Luckily you can toggle this logging on and off while the emulator is running.

Enabling Instruction tracing for our Emulator

For our JavaScript Emulator we would like to enable the same kind of logging as we did for Vice in the previous section.

We already have two methods in emulator that will provide you a string representation of the state of the registers and the current instruction disassembled. So the only thing you need to do is to write these values with to write these values to the console with console.log.

In the previous section we learned an important lesson. This kind of logging slow down the emulator dramatically. We cannot bargain that our emulator would perform any better, so we also need to built in a functionality that you can enable/disable this logging at any time.

So, let us start by adding a checkbox to our index page for enabling/disabling logging.

<input type="file" id="file" name="myfile"/>
<button onclick="myTape.attachTape(document.getElementById('file').files[0])">Attach</button>
<br/>
<button onclick="mymem.togglePlayPresed()">Play</button>
<br/>
<input type="checkbox" id="allowDebug"/> Allow logging<br/>
<textarea id="registers" name="reg" rows="1" cols="60"></textarea>
<br/>
<textarea id="memory" name="mem" rows="15" cols="60"></textarea>
From Location:
<input type="text" id="frommem">
<button onclick="showMem()">Refresh Dump</button>
<br/>


Next, we add a property to our Cpu class for indicating whether logging is on or off:

function cpu(memory) {
...
  var allowLogging = false;
...
  this.setAllowLogging = function(flag) {
    allowLogging = flag;
  }
...
}

Next we need to add a check in the runBatch method that will check whether the checkbox is checked and set the applicable property in the cpu class.

      function runBatch() {
        if (!running)
          return;
        mycpu.setAllowLogging(document.getElementById("allowDebug").checked);
        while (true) { 
        ...
        }
        ...
      }

Next, we need add the method log_debug within the Cpu class, that will only log if logging is enabled:

  function log_debug(value) {
    if (allowLogging) {
      console.log(value);
    }
  }


And, we need to use this method within the step method:

  this.step = function () {
    log_debug(this.getDecodedStr() + "  " + this.getDebugReg());
    if ((myInterruptController.getCpuInterruptOcurred() | myvideo.vicIntOccured()) & (interruptflag == 0)) {
    ...
    }
    ...
  }

Now let us take this new functionality for a test drive. I was testing this functionality within the Google Chrome browser. To see the console it import that you have the Inspect an element view open. In Google Chrome you enable this view with Cntrl+Shift+I.


One thing I should mention is that Google console also have a limit on the number of lines it can display. We can also get around this limitation by enable file logging by starting chrome from the command line in the following way:

google-chrome --enable-logging

This create a file called chrome_debug.log in some folder in you user directory. The specific folder for this file differs from platform to platform. In Linux, you will find this file in the folder ~/.config/google-chrome.

So, in short, the file chrome_debug.log will contain  the un-truncated version for our instruction state logging for our JavaScript emulator.

Reconciling the two logs

With the logging capability added to both Vice and our emulator in the previous two sections, it is time we create a log for both systems doing the same action.

Do the following on both systems, and keep the logs:


  • Start off the loading of Dan Dare
  • Once you see the intro screen, enable logging
  • Press and hold the firebutton, until you see the game has started
  • Stop logging
In this section we will use our Vice log for reference and refer to our emulator log when necessary.

In the initial round of debugging we decided that the starting point for our debugging should be address

5358.

So within the Vice log search for .5358:



This log allows us to trace back to determine where register X got its value from. And we see the X register got its value from memory location AA.

So, what populated location AA? To answer this search for $AA:


And we spot the place where the initial value is assigned to memory location $AA.

Let us pause for a moment and compare the same snippet with the log of our own emulator:


If you compare the logs you will actually see that the register states are in sync between the two logs till it hits the instruction at 5343, which is LDA($aa),y

You might have a moment of despair, thinking: Know we need to do a similar exercise to find what is populating the effective address of ($aa),y

But, hang on, we are almost at the root of the problem. The effective address of ($aa), y is B000. What is special about the address B000? It falls within the address space of basic ROM! This screams: Bank switching!

And in fact, we haven't implemented bank switching of the Basic ROM within our emulator.

Well, I fully agree, we could have avoided this ugly detour by implementing all bank switching at once when we were busy implementing bank switching for the KERNEL ROM. But, I thought this is a nice debugging technique to use, should hit a brickwall.

Implementing Basic Bank Switching

Let us implement bank switching for the Basic ROM.

First we create a method within the memory class that tell if the Basic ROM is visible by looking at memory location 1:

  function basicEnabled() {
    temp = mainMem[1] & 3;
    return (temp == 3);
  }


Next, we should modify the readMem function:

  this.readMem = function (address) {
    if ((address >= 0xa000) & (address <=0xbfff) & basicEnabled())
      return basicRom[address & 0x1fff];
    else if ((address >= 0xe000) & (address <=0xffff) & kernelEnabled())
      return kernalRom[address & 0x1fff];
    else if ((address >= 0xd000) & (address <= 0xdfff) & IOEnabled()) {
      return IORead(address);
    } else if (address == 1) {
      var temp = mainMem[address] & 239;
      if (!playPressed)
        temp = temp | 16;
      return temp;
    }
    return mainMem[address];
  }


With all this changes let us give out emulator a test run again:



It already looks better, although Dan is still missing and something is wrong with the colors. We will cover these issues in the next blog.

In Summary

In this blog we fixed the garbled screen we were presented with when starting the game.

In the debugging process we used a technique where we compared the state of our emulator with the state of another emulator which renders the screen in question correctly.

In the next blog we will be fixing the remaining rendering issues like invisible Dan Dare, and the invisible Treen.

Till next Time!


1 comment: