Unexpected and different results between compiler versions...

[Mochilote]

Doing some tests I found these strange differences between multiple versions of the compiler, the same code shows different results in execution.

I have tested with versions v1.8 (official), v1.9 (official), Nightly build v20111101.

The code is basically a infinite loop that measures time (and loops counter) and shows a text every second (measure time don't include printf time). For measuring time i have used a Amstrad firmware function (KL TIME PLEASE) that returns the time that has elapsed since the computer was switched on or reset (in 1/300ths of a second). From my experience I think that this counter does not increase with interrupts disabled.

Results:
z88dk v1.8: Every second the printf shows about 2600 loops (works as expected)
z88dk v1.9: Every 7 seconds shows about 19000 loops
z88dk v20111101: Every 3 seconds shows about 8400 loops

All the programs runs at 'same velocity' (2600 * 7 = 18000 loops, 2600 * 3 = 7800 loops), but only in v1.8 Amstrad firmware function (KL TIME PLEASE) works as expected, the others 'must disable interrupts longer'.

The code:

Code: Select all

#include <stdio.h>

////////////////////////////////////////////////////////////////////////
unsigned char char1,char2,char3,char4;

unsigned int GetTime()
{
        unsigned int nTime = 0;
        
        #asm
                CALL $BD0D //KL TIME PLEASE
                PUSH HL
                /*
                LD HL, _char1
                LD (HL), D
                LD HL, _char2
                LD (HL), E
                */
                POP DE
                LD HL, _char3
                LD (HL), D
                LD HL, _char4
                LD (HL), E
        #endasm
        
        nTime = (char3 << 8) + char4;

        return nTime;
}
////////////////////////////////////////////////////////////////////////

main()
{
        unsigned int nFPS = 0;
        unsigned int nTimeLast = 0;
        unsigned int nTimeDiff = 0;

        nTimeLast = GetTime();

        while(1)
        {
                nFPS++;
                nTimeDiff = GetTime() - nTimeLast;
                if(nTimeDiff >= 300)
                {
                        printf("Fps %u, time %u\n", nFPS, nTimeDiff);

                        nTimeLast = GetTime();
                        nFPS = 0;
                }
        }

}

[Mochilote]

Results:
z88dk v1.8: Every second the printf shows about 2600 loops (works as expected)
z88dk v1.9: Every 7 seconds shows about 19000 loops
z88dk v20111101: Every 3 seconds shows about 8400 loops

Hi again, i finally managed to compile it on SDCC 3.1.0 and it works perfectly, every second the printf shows about 4860 loops, about 40% faster code than generated by z88dk...

[stefano]

Sorry I still couldn't experiment myself.
Are you sure the timer is active 'all the time' ?
Couldn't it just depend on the way the interrputs are managed ? I vaguely remember some aggressive patch having to do with the interrupts or so.. but if you actually see the code running slower, then you must be right.

[Mochilote]

Are you sure the timer is active 'all the time' ? Couldn't it just depend on the way the interrputs are managed ?

As I said in the first message "I think that this counter does not increase with interrupts disabled", so I guess that interrupts are disabled several times more than 3ms and therefore does not increase the time counter.

But this works perfectly in z88dk v1.8 and SDCC 3.1.0, on z88dk v1.9 and v20111101 costs them 7 and 3 seconds respectively (measured visually for me in the emulator) to increase the timer on what is supposed to be one second. It is also interesting that in each version of z88dk, the same code behaves differently.

Furthermore, in cases in which it works well, it is interesting to note the difference of loops that achieves SDCC against z88dk .

Cheers.

[Mochilote]

My suspicions are confirmed:

The following code, compiled in the three versions of z88dk give us the same result:

Code: Select all

#include <stdio.h>

////////////////////////////////////////////////////////////////////////
unsigned char char1,char2,char3,char4;

unsigned int GetTime()
{
        unsigned int nTime = 0;
        
        #asm
                CALL $BD0D //KL TIME PLEASE
                PUSH HL
                /*
                LD HL, _char1
                LD (HL), D
                LD HL, _char2
                LD (HL), E
                */
                POP DE
                LD HL, _char3
                LD (HL), D
                LD HL, _char4
                LD (HL), E
        #endasm
        
        nTime = (char3 << 8) + char4;

        return nTime;
}
////////////////////////////////////////////////////////////////////////

main()
{
        unsigned int nCounter = 0;
        unsigned int nLoops = 0;

        printf("time %u\n", GetTime());

        for(nCounter = 0; nCounter < 65535; nCounter++)
                nLoops++;

        printf("time %u, loops %u\n", GetTime(), nLoops);

        while (getk() != 13) {};
}

Result:


Between one printf and the other, program spends about 4 seconds, so the second time value should be at least of 1200.

If you compile the same code in sdcc obtain the following result:


Between one printf and the other, program spends less than a second, impressive difference.

Now, if I disable interrupts for just before the 'for' and enable them again after the 'for', we obtain the following result (in SDCC, of course):


So the question is why in this code z88dk are disabling interrupts all the time?

Cheers.

[stefano]

I can't recall exactly but it happened in May 2008, with the creation of the CP/M compatible lib and the firmware niterposer. I suppose it had to do with something discovered on the 6128.. I'll re-enable the interrupts making them disabled on option only.

http://z88dk.cvs.sourceforge.net/viewvc ... 8&view=log

[stefano]

CRT0 file updated. This new version disables the interrupts only if the '-startup=2' parameter is added in the compiler command line.

[Mochilote]

I have used snapshot 20120208 to compile it, but i get unstable results:

-The program freezes when calling GetTime
-If I delete calls to GetTime, however, the display is corrupted...

[stefano]

Could you please try one more thing ?
Remove the semicolon in line 68 of cpc_crt0.asm (di instruction), it will disable the soft interrupts but the hard ones will be kept, as it was in origin.
Honestly I'd still expect some instability, if so we'll just need to understand which registers the Amstrad(s) need to keep untouched and protect them.

[stefano]

Forget my last post
I just realized some BIOS calls just need to have the interrupts disabled to run correctly, so the fix should be applied onto the libs rather than on the startup code.

[violadavis]

Yeah, I have seen this before. The same code shows different results in execution if we use different compiler versions. I don't know which result to trust. This is really a serious problem associated with the same. Actually the compiler version should not affect the results!



_________________________________
www.omnitechsupport.com

[maschinist]

At first, the observations and statements are right.

-->But it's not a problem with the compiler at all, it just rocks.

It is an issue with the stdio and the startup code.
But it could easily be fixed.



Remember:
A system friendly, stable program on the cpc must never touch the shadow registers
(reserved by the OS) nor should it disable interrupts, since all keyboard processing, color blinking and sound depends on it.

Therefore, a very simple cpc_crt0.asm without DI, without EXX is just right for the cpc.

To make your code above run, at least fput_cons() and printf() must be a improved
to not use Z80 shadow registers, I did that, see below.

Well, its worth to be discussed with stefano and dom and the others if we can provide stdio to support the CPC this (cpc friendly) way.

I attached the dsk, makefile and src of your example
[http://rst.in-chemnitz.de/cpc/z88dkdemos/demo2/]right here...[/url]


I want to say, Z88DK is really brilliant for the CPC. Thanky you guys. Great Job.

[maschinist]

I forgot to mention, this post relates to the actual release

z88dk-1.10.1

[alvin]

Remember:
A system friendly, stable program on the cpc must never touch the shadow registers
(reserved by the OS) nor should it disable interrupts, since all keyboard processing, color blinking and sound depends on it.

In the existing (ie 1.10) libraries the exx set is used in numerous places. For example, long arithmetic and multiplication and division code even for integers is substantially sped up by using the exx set. I think most of the rest of the libraries are not using it, except perhaps the graphics library.

The new library is using the exx set extensively. stdio is using one side of the registers to generate messages (the printf / scanf side, etc) and the other side is used as a state machine by the device driver to qualify stream input. Again all math is using it.

For the ROM interrupts do we also need to save the exx set? If we have to maybe we can instead provide an interrupt shell that saves registers and jumps to the ROM entry. There will also be an option to run ROMless so that interrupts can be disabled or used for other purposes.

When making other firmware calls (eg DOS calls) is it possible to set the EXX registers to a known set of values before making the call?

[maschinist]

Yes. To use both, the ROM and the LIB and without crashing the cpc could work this way:

Code: Select all

main:
disable interrupts
save rom exx registers
..
use lib functions
..
save lib exx registers
restore rom exx registers
enable interrupts
-->call CPC ROM function
disable interrupts
save rom exx registers
restore lib exx registers
..
use lib functions
..

restore rom exx registers
enable interrupts
return to basic ($c9)

So, either all ROM calls or all LIB calls must be wrapped with exx register and interrupt management.
When in standard ROM mode, interrupts should be on.
When in LIB mode, interrupts must be off. As a consequence key strokes get lost, the software clock freezes, music and sound freeze.

As another workaround of this, the cpc interrupt handler could be wrapped to restore
the rom content of the exx registers on entry.

Its tricky and probably faulty, but its probably worth a try to get both, ROM and LIB covered this way.

Alternatively, at the moment I am very happy with the z88dk in CPC-ROM
friendly mode (not using exx at all) since I managed to use all the integer and floating point
math and trigonometric functions, the graphics and ROM functions, some stdio functions and malloc.
It does really nicely interoperate with the system and with BASIC etc.
Im providing my example programs here.

Isn't there a way to provide printf, scanf, fopen, fgets... for cpc users not using the shadow registers?
I'd really like to support that. :-)

[alvin]

As another workaround of this, the cpc interrupt handler could be wrapped to restore
the rom content of the exx registers on entry.

Its tricky and probably faulty, but its probably worth a try to get both, ROM and LIB covered this way.

I'm pretty confident we can do that.

We can just set aside some bytes to hold the ROM's current exx set.

On interrupt, we save the exx set and load up the ROM's exx set before jumping to the ROM isr. I don't know if that means we're supplying an im2 handler or if the cpc allows alternate code to be run on interrupt.

The library will only call the firmware through one or a few entry points and it's easy to restore the ROM exx set just before the firmware call. There's a race condition if an int occurs while the exx set is being loaded so I guess we'll have to di around that briefly.

Alternatively, at the moment I am very happy with the z88dk in CPC-ROM
friendly mode (not using exx at all) since I managed to use all the integer and floating point
math and trigonometric functions, the graphics and ROM functions, some stdio functions and malloc.
It does really nicely interoperate with the system and with BASIC etc.
Im providing my example programs here.

Long integer math will probably not work and that includes simple addition and subtraction. Long math is sped up considerably by using the exx set and there is no alternative code in the z88dk codebase for that currently.

The floating point is working because stef added the cpc rom fp routines as the default option for float library on the cpc target. The native z88dk float library is called 'genmath' and it also uses the exx set so it probably won't work too. You can select genmath on the compile line with -lmz (my memory is really bad here -- I hope I got that right!).

But I'm glad there is finally something that works nearly correctly on the cpc. Sometimes it's hard to know what is going wrong when you're not an expert on a particular system The changes you've made should be added for the cpc on the 1.10 libraries.

Isn't there a way to provide printf, scanf, fopen, fgets... for cpc users not using the shadow registers?
I'd really like to support that. :-)

Do these things not yet work with 1.10? I don't recall there being use of the exx set in the 1.10 stdio?

The new library is a parallel library that is aiming to be more C11 compliant; you'll be able to select between the current and the new one on the compile line. The new one has been designed from the ground up to use the exx set in order to eliminate the need for high-level buffering (setvbuf sort of thing) and to improve performance. This decision will show up in all the drivers (block, character, terminal) but I don't think it's an issue. I'm pretty sure we can do what is suggested above to make things work without any kind of penalty.

[stefano]

Back to this topic, I never managed to get a stable way to call the firmware functions in a stable way when interrupts are enabled.

I'd like to try it again, what I have in mind is, as suggested to:

restore rom exx registers
enable interrupts
-->call CPC ROM function
disable interrupts
save rom exx registers


So, here are the questions:
Is it necessary to save the rom exx registers everytime or it is enough to set them as they are at startup ?
Are such registers BC' and AF' only ?
What about SP ? we're just lowering by 6k at the moment, should it be set differently ? What to do while in interrupts ?

[Timmy]

I'm resurrecting this thread because I was testing out the performance of the z88dk code, and this is a code I wrote/ported a few months ago (so it's not based on the new interrupts and such, and I haven't tried this code on the latest nightlies yet.)

As you can see if you run this code, it is still slow compared to the sdcc version. And I still haven't added the get_time function yet, I can't remember whether it didn't work or that I couldn't port this with our setup.

Code: Select all

// test 20221114
// CPC program #5 now :)

// based on code from 
// http://www.cpcmania.com/Docs/Programming/Measuring_times_and_optimizing_2D_Starfield.htm

// I've built this with:
// zcc +cpc -lndos -lm -subtype=dsk -create-app -zorg=16384 -o 5 cpctest5.c

// run this in emulator with:
// run"5.cpc"

#include <cpc.h>
#include <stdio.h>
#include <strings.h>

unsigned int add = 0xc280;
unsigned int y = 64;
unsigned int x = 0;

void SetMode0PixelColor(unsigned char *pByteAddress, unsigned char nColor, unsigned char nPixel)
{
  unsigned char nByte = *pByteAddress;

  if(nPixel == 0)
  {
    nByte &= 85;

    if(nColor & 1)
      nByte |= 128;

    if(nColor & 2)
      nByte |= 8;

    if(nColor & 4)
      nByte |= 32;

    if(nColor & 8)
      nByte |= 2;
  }
  else
  {
    nByte &= 170;

    if(nColor & 1)
      nByte |= 64;

    if(nColor & 2)
      nByte |= 4;

    if(nColor & 4)
      nByte |= 16;

    if(nColor & 8)
      nByte |= 1;
  }

  *pByteAddress = nByte;
}

void PutPixelMode0(unsigned char nX, unsigned char nY, unsigned char nColor)
{
  unsigned char nPixel = 0;
  unsigned int nAddress = 0xC000 + ((nY / 8) * 80) + ((nY % 8) * 2048) + (nX / 2);
  nPixel = nX % 2;

  SetMode0PixelColor((unsigned char *)nAddress, nColor, nPixel);
}

struct _tStar
{
  unsigned char nX;
  unsigned char nY;
  unsigned char nStarType;
};

#define STARS_NUM 40
struct _tStar aStars[STARS_NUM];

main(){
	unsigned char nStar = 0;
	memset(aStars, 0, sizeof(aStars));

	#asm
	ei
	halt
	halt
	#endasm
	
	  //SCR_SET_MODE 0
	  #asm
	  EXTERN firmware
	  
		ld a, 0
		call firmware
		defw 0xBC0E

	  //PALETE
		ld a, 0
		ld b, 0 ;black
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 1
		ld b, 15; 12 ;Yellow
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 2
		ld b, 17; 25 ;Pastel Yellow    
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 3
		ld b, 24 ;Bright Yellow
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

	  //SCR SET BORDER 0
		ld b, 0 ;black
		ld c, b
		call firmware
		defw 0xBC38
		
		ei
		halt
	  #endasm

	//cpc_DisableFirmware();
	
	//Init
	for(nStar = 0; nStar < STARS_NUM; nStar++)
	{
		aStars[nStar].nX = rand() % 160;
		aStars[nStar].nY = rand() % 200;
		aStars[nStar].nStarType = rand() % 3;
	}

	while(1)
	{

		for(nStar = 0; nStar < STARS_NUM; nStar++)
		{
			//delete star
			PutPixelMode0(aStars[nStar].nX, aStars[nStar].nY, 0);

			//move star
			switch(aStars[nStar].nStarType)
			{
				case 0: //slow star
					aStars[nStar].nX += 1;
					break;
				case 1: //medium star
					aStars[nStar].nX += 2;
					break;
				case 2: //fast star
					aStars[nStar].nX += 3;
					break;
			}
			  
			if(aStars[nStar].nX >= 160)
			{
				aStars[nStar].nX = 0;
				aStars[nStar].nY = rand() % 200;
				aStars[nStar].nStarType = rand() % 3;
				continue;
			}

			  //paint star
			PutPixelMode0(aStars[nStar].nX, aStars[nStar].nY, aStars[nStar].nStarType + 1);
		}
	}
}

[DarkSchneider]

Try to compile with "-O2 --opt-code-speed=all" options.

[Timmy]

So I finally have time to make the GetTime() function work. And I've added the "-O2 --opt-code-speed=all" options, too.

This is the resulting code:

Anyway, I've compared it with the result shown on the indicated page, and this version shows "16" instead of the SDCC image there with the number "29". So I can conclude that the version before our recent changes didn't made it any faster.

I still need to verify this on the nightly, but that might take some more time.

Code: Select all

// test 20230328 Timmy
// CPC program #5a now :)

// based on code from 
// http://www.cpcmania.com/Docs/Programming/Measuring_times_and_optimizing_2D_Starfield.htm

// I've built this with:
// zcc +cpc -lndos -lm -subtype=dsk -create-app -zorg=16384 -O2 --opt-code-speed=all -o 5 cpctest5a.c

// run this in emulator with:
// run"5.cpc"

#include <cpc.h>
#include <stdio.h>
#include <strings.h>

unsigned int add = 0xc280;
unsigned int y = 64;
unsigned int x = 0;

void SetMode0PixelColor(unsigned char *pByteAddress, unsigned char nColor, unsigned char nPixel)
{
  unsigned char nByte = *pByteAddress;

  if(nPixel == 0)
  {
    nByte &= 85;

    if(nColor & 1)
      nByte |= 128;

    if(nColor & 2)
      nByte |= 8;

    if(nColor & 4)
      nByte |= 32;

    if(nColor & 8)
      nByte |= 2;
  }
  else
  {
    nByte &= 170;

    if(nColor & 1)
      nByte |= 64;

    if(nColor & 2)
      nByte |= 4;

    if(nColor & 4)
      nByte |= 16;

    if(nColor & 8)
      nByte |= 1;
  }

  *pByteAddress = nByte;
}

void PutPixelMode0(unsigned char nX, unsigned char nY, unsigned char nColor)
{
  unsigned char nPixel = 0;
  unsigned int nAddress = 0xC000 + ((nY / 8) * 80) + ((nY % 8) * 2048) + (nX / 2);
  nPixel = nX % 2;

  SetMode0PixelColor((unsigned char *)nAddress, nColor, nPixel);
}

////////////////////////////////////////////////////////////////////////
unsigned char char1,char2,char3,char4;

unsigned int GetTime()
{
  unsigned int nTime = 0;

  #asm
  EXTERN firmware
	call firmware
    defw 0xBD0D ;KL TIME PLEASE
    PUSH HL
    POP DE
    LD HL, _char3
    LD (HL), D
    LD HL, _char4
    LD (HL), E
  #endasm;

  nTime = (char3 << 8) + char4;

  return nTime;
}
////////////////////////////////////////////////////////////////////////

struct _tStar
{
  unsigned char nX;
  unsigned char nY;
  unsigned char nStarType;
};

#define STARS_NUM 40
struct _tStar aStars[STARS_NUM];

main(){
	unsigned int nFPS = 0;
	unsigned char nStar = 0;
	unsigned int nTimeLast = 0;
	memset(aStars, 0, sizeof(aStars));

	#asm
	ei
	halt
	halt
	#endasm
	
	  //SCR_SET_MODE 0
	  #asm
	  EXTERN firmware
	  
		ld a, 0
		call firmware
		defw 0xBC0E

	  //PALETTE
		ld a, 0
		ld b, 0 ;black
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 1
		ld b, 15; 12 ;Yellow
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 2
		ld b, 17; 25 ;Pastel Yellow    
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

		ld a, 3
		ld b, 24 ;Bright Yellow
		ld c, b
		call firmware
		defw 0xBC32 ;SCR SET INK

	  //SCR SET BORDER 0
		ld b, 0 ;black
		ld c, b
		call firmware
		defw 0xBC38
		
		ei
		halt
	  #endasm

	//cpc_DisableFirmware();
	
	//Init
	for(nStar = 0; nStar < STARS_NUM; nStar++)
	{
		aStars[nStar].nX = rand() % 160;
		aStars[nStar].nY = rand() % 200;
		aStars[nStar].nStarType = rand() % 3;
	}

	nTimeLast = GetTime();
	
	while(1)
	{

		for(nStar = 0; nStar < STARS_NUM; nStar++)
		{
			//delete star
			PutPixelMode0(aStars[nStar].nX, aStars[nStar].nY, 0);

			//move star
			switch(aStars[nStar].nStarType)
			{
				case 0: //slow star
					aStars[nStar].nX += 1;
					break;
				case 1: //medium star
					aStars[nStar].nX += 2;
					break;
				case 2: //fast star
					aStars[nStar].nX += 3;
					break;
			}
			  
			if(aStars[nStar].nX >= 160)
			{
				aStars[nStar].nX = 0;
				aStars[nStar].nY = rand() % 200;
				aStars[nStar].nStarType = rand() % 3;
				continue;
			}

			  //paint star
			PutPixelMode0(aStars[nStar].nX, aStars[nStar].nY, aStars[nStar].nStarType + 1);
		}
		
		nFPS++;

		if(GetTime() - nTimeLast >= 300)
		{
		  //TXT SET CURSOR 0,0
		  #asm
		  EXTERN firmware
			ld h, 1
			ld l, 1
			call firmware
			defw 0xBB75
		  #endasm;

		  printf("%u  ", nFPS);

		  nTimeLast = GetTime();
		  nFPS = 0;
		}
	}
}

[dom]

It's an interesting one that shows the benefit of code analysis and a couple of compiler techniques that sccz80 doesn't use: first of all knowing what value is held in registers and secondly hoisting up a common sub-expression and keeping that value live in a register.

You can get a benefit for both compilers by emulating it and doing this within the for loop:

Code: Select all

static struct _tStar *st;
st  = &aStars[nStar];

Another win comes from doing this:

Code: Select all

void PutPixelMode0(unsigned char nX, unsigned char nY, unsigned char nColor) __z88dk_callee
{
  SetMode0PixelColor((unsigned char *)0xC000 + ((nY / 8) * 80) + ((nY % 8) * 2048) + (nX / 2), nColor, nX % 2);
}

Those auto variables aren't used apart from for passing into the function. sdcc has applied some analysis to get rid of them whereas sccz80 dutifully stores them, then gets them back and given that that function is called called say 1600 times a second it all adds up.

Given that plotting is the main consumer of CPU time (for both compilers), the usual z88dk way of this is delegating to assembler written library routine to do the heavy lifting. It's unfortunate in this case that no one has written mode 0 plotting yet.

BTW the code is actually defective with sdcc - there's an erroneous warning that an expression always evaluates to false with the result the stars vanish about 2/3 across the screen the second time round.

[Timmy]

Thanks! I'm glad this mystery has been solved (it's bugging me for a while).

Also, we now get the KL TIME PLEASE function working with the firmware. So this will not be a problem in the future.

Now that I know what was causing the the slowness, and because it's just some unfortunate optimalisations, I can see how to move forward.

1) I could write these new functions in (inline) assembly, or
2) I could try to look at the missing parts of cpcrslib.

My suggestion is obviously (1) because it's much less work, and it's much easier to support, and it will be more useful for games.

But I believe the first thing I will be doing is another flying saucer type of demo for the CPC, without the firmware, to just show how to make games using the z88dk. That's going to be in a separate thread though.

[stefano]

The second option is intriguing but challenging.
It requires to extend the build options at the earlier stage, e.g. by substituting code blocks in the crt0 startup code.

[Timmy]

My problem with the second option is that cpcrslib is no longer being supported, so I'm not sure if we should spend a lot of effort for something that might never be used.

[stefano]

In my opinion an open source project has good chances to survive to its original programmer, if someone works on it, it means it is still useful (and somehow "supported").