vc64web / virtualc64web

vc64web - Commodore C64 Emulator for iPad iPhone Android and the Web with CSDb access for thousands of demos at your fingertip.
https://vc64web.github.io/doc/about.html
GNU General Public License v3.0
45 stars 5 forks source link

SID underflow / overflows #17

Closed mithrendal closed 4 years ago

mithrendal commented 4 years ago

to check the last consumer🤗 of mach_absolute_time I enabled c64->sid.setDebugLevel(2);

when running vc64web ... this interestingly logs overflows in the sid every second or so 😳

SIDBridge: SID RINGBUFFER OVERFLOW (r: 10240 w: 9545) vC64.html:1:528
stdlib_now: 1587285309152000000, emsdk_now: 37160, fake_now: 36 vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 7498) vC64.html:1:528
stdlib_now: 1587285310500000000, emsdk_now: 38508, fake_now: 37 vC64.html:1:368
SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528
ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44100 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11637) vC64.html:1:528
stdlib_now: 1587285312270000000, emsdk_now: 40277, fake_now: 38 vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 2048 w: 1657) vC64.html:1:528
stdlib_now: 1587285313706000000, emsdk_now: 41714, fake_now: 39 vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6144 w: 5435) vC64.html:1:528

when vc64web is halted it logs many many underruns per second ... watch out for MSG_HALT where the underruns wave begins

SIDBridge: SID RINGBUFFER OVERFLOW (r: 6144 w: 5508) vC64.html:1:528
stdlib_now: 1587285373442000000, emsdk_now: 101449, fake_now: 85 vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 2048 w: 1671) vC64.html:1:528
stdlib_now: 1587285375024000000, emsdk_now: 103030, fake_now: 86 vC64.html:1:368
SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528
ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44100 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 7370) vC64.html:1:528
stdlib_now: 1587285377947000000, emsdk_now: 105953, fake_now: 87 vC64.html:1:368
wasm_halt vC64.html:1:368
Calling emscripten_pause_main_loop vC64.html:1:368
Called emscripten_pause_main_loop vC64.html:1:368
vC64 message=MSG_HALT, data=0 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 1784) vC64.html:1:528
stdlib_now: 1587285378321000000, emsdk_now: 106327, fake_now: 88 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 5880) vC64.html:1:528
stdlib_now: 1587285378414000000, emsdk_now: 106419, fake_now: 89 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 9976) vC64.html:1:528
stdlib_now: 1587285378507000000, emsdk_now: 106513, fake_now: 90 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 1784) vC64.html:1:528
stdlib_now: 1587285378599000000, emsdk_now: 106606, fake_now: 91 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 5880) vC64.html:1:528
stdlib_now: 1587285378692000000, emsdk_now: 106698, fake_now: 92 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 9976) vC64.html:1:528
stdlib_now: 1587285378785000000, emsdk_now: 106791, fake_now: 93 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 1784) vC64.html:1:528

Question for the underruns... does that mean that when I put the c64web to halt, that I have to stop reading samples from the SID in my web audio stream ?

Question for the overruns ... does the web Audio has to read more often or a larger amount to prevent these ?

is it ok when I only read mono samples like in the current implementation?

void MyAudioCallback(void*  thisC64,
                       Uint8* stream,
                       int    len)
{
    C64 *c64 = (C64 *)thisC64;
    c64->sid.readMonoSamples((float *)stream,len /  sizeof(float) );
}

Is the the over and underruns a bad thing that has to be corrected or should I just don't care about it ? Sound for my ears is fine anyway...

What is strange though is that the core periodcally likes to change sample rate from ... well ... 44100 to 44100 🙄... why did it want to do that ?🤔

SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528 ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528 FastSID: Setting sample rate to 44100 vC64.html:1:528

dirkwhoffmann commented 4 years ago

I need to give you some background information first. In earlier versions of VirtualC64, I had lots of trouble with buffer underflows and overflows. That was because the emulator and the audio engine needed to be synced perfectly to avoid these issues. Eventually I came up with the idea to get both in sync by slightly adjusting the sample rate when an overflow or underflows occurred.

Let’s have a look at the relevant code snippet. Hot stuff, buckle up 😬:

void
SIDBridge::handleBufferOverflow()
{
    // There are two common scenarios in which buffer overflows occur:
    //
    // (1) The consumer runs slightly slower than the producer.
    // (2) The consumer is halted or not startet yet.

    debug(2, "SID RINGBUFFER OVERFLOW (r: %ld w: %ld)\n", readPtr, writePtr);

    // Determine the elapsed seconds since the last pointer adjustment.
    uint64_t now = mach_absolute_time();
    double elapsedTime = (double)(now - lastAlignment) / 1000000000.0;
    lastAlignment = now;

    // Adjust the sample rate, if condition (1) holds.
    if (elapsedTime > 10.0) {

        bufferOverflows++;

        // Decrease the sample rate based on what we've measured.
        int offPerSecond = (int)(samplesAhead / elapsedTime);
        setSampleRate(getSampleRate() - offPerSecond);
    }

    // Reset the write pointer
    alignWritePtr();
}

As mentioned in the code, there are two common situations for buffer overflows to occur. Situation (1) is the one we want to use for sample rate adjustment. In situation (2), we don’t want to change the sample rate.

Hence, the function needs to find out if situations (1) or (2) holds. The main idea is to compute the elapsed time between two consecutive buffer overflows (variable elapsedTime represents this value in seconds). If the last buffer overrun was more than 10 seconds ago, the function assumes situation (1) and slightly adjust the sample rate. In original VirtualC64, this code works pretty well, so I think we should keep it for the web version 🤤.

This means that I have to reject my previous claim that the timing stuff is irrelevant for the web version. I simply forgot about the fact that the timing stuff is needed for making sampling rate adjustment to work.

the core periodically likes to change sample rate from ... well ... 44100 to 44100

This is, because the timing related variables have wrong units. In your implementation, I presume that elapsedTime is a very large number (it should be seconds). As a result, VirtualC64 thinks that the last buffer overflow was years ago and to fix that, it has to change the sampleRate by an amount that is smaller than 1 Hz. Because the sample rate is an integer, it is clamped to 0 Hz.

If my explanation was clear enough, the answers to the following questions should be superfluous.

does the web Audio has to read more often or a larger amount to prevent these ?

Nope. If you start with a sample rate that is roughly correct (first buffer exception is more than 10 sec away), the adjustment code does the rest for you 😎.

does that mean that when I put the c64web to halt, that I have to stop reading samples from the SID in my web audio stream ?

No, you can keep on reading samples. Buffer underflows will occur frequently, but the handler won’t screw up anything (it’ll detect situation (2)). The only annoying thing is the large amount of debug messages in level 2.

mithrendal commented 4 years ago

This is, because the timing related variables have wrong units. In your implementation, I presume that elapsedTime is a very large number (it should be seconds).

I added the following line to debug


 // Determine the elapsed seconds since the last pointer adjustment.
    uint64_t now = mach_absolute_time();

    double elapsedTime = (double)(now - lastAlignment) / 1000000000.0;
    lastAlignment = now;

    debug(2, "elapsed %lf \n", elapsedTime);  //<------ this line

    // Adjust the sample rate, if condition (1) holds.
    if (elapsedTime > 10.0) {

and yes ... somtimes elaspsed 1.232 or so and then very very big values ...

I put my new 😎mach_absolute_time() emulation in place and changed the return type from long to uint64_t

look at that beauty 😍

/* emulation of macos mach_absolute_time() function. */
uint64_t mach_absolute_time()
{
    uint64_t nano_now = (uint64_t)(emscripten_get_now()*1000000.0);
    //printf("emsdk_now: %lld\n", nano_now);
    return nano_now; 
}

now a complete different story

SIDBridge: SID RINGBUFFER OVERFLOW (r: 10240 w: 10210) vC64.html:1:528
SIDBridge: elapsed 2.087000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 10240 w: 10167) vC64.html:1:528
SIDBridge: elapsed 1.666000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 4037) vC64.html:1:528
SIDBridge: elapsed 1.820000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 7735) vC64.html:1:528
SIDBridge: elapsed 2.035000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 8159) vC64.html:1:528
SIDBridge: elapsed 3.622000 vC64.html:1:528
Window 1 gained keyboard focus vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 8179) vC64.html:1:528
SIDBridge: elapsed 2.238000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 9982) vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11726) vC64.html:1:528
SIDBridge: elapsed 2.598000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 10240 w: 9905) vC64.html:1:528
SIDBridge: elapsed 2.184000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11772) vC64.html:1:528
SIDBridge: elapsed 2.839000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11916) vC64.html:1:528
SIDBridge: elapsed 3.621000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 2048 w: 1714) vC64.html:1:528
SIDBridge: elapsed 1.987000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 3330) vC64.html:1:528
SIDBridge: elapsed 1.446000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11853) vC64.html:1:528
SIDBridge: elapsed 1.020000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 3916) vC64.html:1:528
SIDBridge: elapsed 1.488000 vC64.html:1:528

do you know from which game the log is ???

SPOILER: fort apocalypse

no more change 44100 to 44100 messages anymore ...

but but that means it assumes now case (2) The consumer is halted or not startet yet. Right ? And therefore it does not adjust the sample rate ... But the assupmtion is wrong ... I played fort apocalypse ... and heard the sound 😳

dirkwhoffmann commented 4 years ago

changed the return type from long to uint64_t

This means WASM emulates a virtual 32 bit architecture. OMG 😱. Fortunately, most variables use fixed size data types in VirtualC64, but there are some functions that do not. Whenever a function returns a long, I expect it to be a 64 bit value, because I never thought somebody is going to compile VirtualC64 on a 32 bit architecture. I thought 32 bit is ancient history. Until now where WASM comes along 😧.

This means we need to check all functions that utilize long variables 🥵.

But the assupmtion is wrong ... I played fort apocalypse ... and heard the sound 😳

I think the problem is that the initial sampling frequency doesn't fit well with the SDL audio unit. The first buffer exception needs to be 10 seconds away to make the auto adjustment code to work.

Here is what you're gonna do:

Ups, sorry, I got distracted. I'll try again:

Here is what you're gonna do:

dirkwhoffmann commented 4 years ago

🙄 We didn't consider the fact that SDL calls executeOneFrame() 60 times a second (TFT frequency), but PAL is only 50 Hz, did we?

Bildschirmfoto 2020-04-19 um 13 42 16

Fun fact: It differs slightly from 50 Hz in the case of the C64.

mithrendal commented 4 years ago

You nailed it !! When running 50 Hz

        emscripten_set_main_loop_arg(draw_one_frame_into_SDL, thisC64, 50, 1);

It logs only buffer underflows ... every second one underflow ...

SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 10123) vC64.html:1:528
SIDBridge: elapsed 1.486000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 1872) vC64.html:1:528
SIDBridge: elapsed 0.929000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10240 w: 12156) vC64.html:1:528
SIDBridge: elapsed 1.346000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2048 w: 3949) vC64.html:1:528
SIDBridge: elapsed 1.208000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 1887) vC64.html:1:528
SIDBridge: elapsed 1.068000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 5997) vC64.html:1:528
SIDBridge: elapsed 1.207000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2048 w: 3964) vC64.html:1:528
SIDBridge: elapsed 1.347000 vC64.html:1:528

Fun fact: CPU load goes down from 63% to 52% (macbook 2007, I hear no fans anymore)

dirkwhoffmann commented 4 years ago

SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2048 w: 3934) vC64.html:1:528

OMG 😱

In VirtualC64mac, there shouldn't be an underflow here. The read pointer isn't close to the write pointer yet. There are roughly 2000 samples left to read.

Have a look at the code here:

void
SIDBridge::readMonoSamples(float *target, size_t n)
{
    // Check for buffer underflow
    if (samplesInBuffer() < n) {
        handleBufferUnderflow();
    }

    // Read samples
    for (size_t i = 0; i < n; i++) {
        float value = readData();
        target[i] = value;
    }
}

I guess SDL is picking very large portions at once. Can you figure out how big the value of n is? We must then adjust the lead the write pointer has over the read pointer in the buffer. Two important items are involved (SIDBridge.h):

   //! @brief   Number of sound samples stored in ringbuffer
    static constexpr size_t bufferSize = 12288;

    /*! @brief    Aligns the write pointer.
     *  @details  This function puts the write pointer somewhat ahead of the
     *            read pointer. With a standard sample rate of 44100 Hz, 735
     *            samples is 1/60 sec.
     */
    const uint32_t samplesAhead = 8 * 735;
    void alignWritePtr() { writePtr = (readPtr  + samplesAhead) % bufferSize; }

I guess the 8 * 735 offset is too small for SDL. I don't expect that we need to increase the overall buffer size though.

mithrendal commented 4 years ago

do you think n is the samples value which I specify here ?

SDL_AudioSpec want, have;
    SDL_AudioDeviceID device_id;

    SDL_memset(&want, 0, sizeof(want)); /* or SDL_zero(want) */
    want.freq = 44100;
    want.format = AUDIO_F32;
    want.channels = 1;
    want.samples = 1024*2;//2048;
    want.callback = MyAudioCallback;
    want.userdata = thisC64;   //will be passed to the callback
    device_id = SDL_OpenAudioDevice(NULL, 0, &want, &have, SDL_AUDIO_ALLOW_FORMAT_CHANGE);

void MyAudioCallback(void*  thisC64,
                       Uint8* stream,
                       int    len)
{
    C64 *c64 = (C64 *)thisC64;
    c64->sid.readMonoSamples((float *)stream,len /  sizeof(float) );
}

n = len/ sizeof(float)

I added a debug line in


void
SIDBridge::readMonoSamples(float *target, size_t n)
{
    debug(2, "readMonoSamples n=%ld\n", n);
    // Check for buffer underflow
    if (samplesInBuffer() < n) {
        handleBufferUnderflow();
    }

it logs readMonoSamples n=2048

dirkwhoffmann commented 4 years ago

do you think n is the samples value which I specify here ?

Yes, most likely. It seems like SDL let's you specify the size of the audio chunk that is read in as a whole. I've checked what macOS is doing. MacOS requests audio data in chunks of 512 samples.

SIDBridge: read: 5120 write: 10695 Reading 512
SIDBridge: read: 5632 write: 10695 Reading 512
SIDBridge: read: 6144 write: 11653 Reading 512
SIDBridge: read: 6656 write: 12229 Reading 512
SIDBridge: read: 7168 write: 322 Reading 512

Try to use 512 for want.samples.

mithrendal commented 4 years ago

want.samples = 512

FIREFOX

SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2560 w: 2925) vC64.html:1:528
SIDBridge: elapsed 1.250000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 124 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 5067) vC64.html:1:528
SIDBridge: elapsed 1.434000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 124 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 6656 w: 7115) vC64.html:1:528
SIDBridge: elapsed 1.436000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 124 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8704 w: 9164) vC64.html:1:528
SIDBridge: elapsed 1.439000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 148 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10752 w: 11240) vC64.html:1:528
SIDBridge: elapsed 1.719000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 124 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 512 w: 972) vC64.html:1:528
SIDBridge: elapsed 1.440000 vC64.html:1:528
SIDBridge: readMonoSamples n=512 3 vC64.html:1:528

the value right after the n=512 is the white number in blue in this picture which means the number of the same log output ... which means round about every 100 read gets an underrun...

grafik

SAFARI 11.1

grafik

here the other way around: round about every 100 read gets an overrun ...

SAFARI 13.1 (modern machine 2014) nearly constantly every 320 +-10 readsamples gets an underflow ... best result ...

SAFARI 13.1 (another machine from 2014) nearly constantly every 290 readsamples +-10 read gets an underflow ... second best result ...

SAFARI 13 (iphone 6s) sound got problems (distortions every 3 seconds or so) with n=512. n=2048 seems to be better... no logs

dirkwhoffmann commented 4 years ago

OK, let’s consider the underflow case. By looking at the numbers, we get an underflow every 100 rounds (roughly). 100 rounds is 51200 samples. The write pointer is approx. 6000 samples ahead. This means that the producer produces about 51200 samples at the same time in which the consumer reads 51200 + 6000 = 57200 samples.

This means that the consumer and the producer differ by a factor of 57200 / 51200 = 1,11. In other words: The consumer is 10% faster than the producer. This is too much to explain it by rounding errors 😳.

dirkwhoffmann commented 4 years ago

Thinking out loud: SDL calls your handler 50 times a seconds (60 before). Sum up the requested samples and print out the sum every 50th time your handler is called. The requested samples must sum up to 44100. If this is correct, there must be an error on the C64 side. If not, there must be an error on the SDL side.

mithrendal commented 4 years ago
void draw_one_frame_into_SDL(void *thisC64) 
{
 ...
  if(frame_count % 50 == 0)
  {
      printf("sum=%d\n", sum_samples);
      sum_samples=0;
  }
}

void MyAudioCallback(void*  thisC64,
                       Uint8* stream,
                       int    len)
{
    C64 *c64 = (C64 *)thisC64;

    int n = len /  sizeof(float);
    c64->sid.readMonoSamples((float *)stream, n);
    sum_samples += n;
}

FIREFOX

constructing C64 ...
adding a listener to C64 message queue...
vC64 message=MSG_PAL, data=0
vC64 message=MSG_VC1541_ATTACHED_SOUND, data=1
vC64 message=MSG_VC1541_ATTACHED, data=1
vC64 message=MSG_VC1541_RED_LED_OFF, data=1
vC64 message=MSG_VC1541_MOTOR_OFF, data=1
vC64 message=MSG_VC1541_NO_DISK, data=1
vC64 message=MSG_DISK_SAVED, data=1
vC64 message=MSG_PAL, data=0
vC64 message=MSG_NO_CARTRIDGE, data=0
vC64 message=MSG_CART_SWITCH, data=0
vC64 message=MSG_IEC_BUS_IDLE, data=0
vC64 message=MSG_VC1541_ATTACHED, data=1
vC64 message=MSG_VC1541_RED_LED_OFF, data=1
vC64 message=MSG_VC1541_MOTOR_OFF, data=1
vC64 message=MSG_VC1541_NO_DISK, data=1
vC64 message=MSG_DISK_SAVED, data=1
vC64 message=MSG_VC1541_DETACHED, data=2
vC64 message=MSG_VC1541_RED_LED_OFF, data=2
vC64 message=MSG_VC1541_MOTOR_OFF, data=2
vC64 message=MSG_VC1541_NO_DISK, data=2
vC64 message=MSG_DISK_SAVED, data=2
vC64 message=MSG_VC1530_NO_TAPE, data=0
vC64 message=MSG_VC1530_PROGRESS, data=0
vC64 message=MSG_WARP_OFF, data=0
vC64 message=MSG_ALWAYS_WARP_OFF, data=0
set SID to freq= 44100
can not get hardware accelerated renderer going with software renderer instead...
wrapper calls 4x c64->loadRom(...) method
vC64 message=MSG_READY_TO_RUN, data=0
wrapper calls run on c64->run() method
vC64 message=MSG_RUN, data=0
Calling emscripten_set_main_loop
vC64 message=MSG_IEC_BUS_BUSY, data=0
vC64 message=MSG_IEC_BUS_IDLE, data=0
sum=49152
vC64 message=MSG_VC1541_RED_LED_ON, data=1
vC64 message=MSG_VC1541_MOTOR_ON, data=1
vC64 message=MSG_VC1541_HEAD_DOWN, data=1
vC64 message=MSG_VC1541_RED_LED_OFF, data=1
vC64 message=MSG_VC1541_MOTOR_OFF, data=1
vC64 message=MSG_IEC_BUS_BUSY, data=0
vC64 message=MSG_IEC_BUS_IDLE, data=0
sum=47104
sum=49152
sum=45056
sum=47104
sum=47104
sum=49152
sum=47104
sum=49152

consumer and the producer differ by a factor of 57200 / 51200 = 1,11.

49152/44100= 1,11

Why is it doing that ?😳

dirkwhoffmann commented 4 years ago

Why is it doing that ?😳

Sometimes the other side is just mean. For no reason.

marsattacks

There might be a reason though 🤔. But I have no idea which one...

mithrendal commented 4 years ago

Lets test safari on iPhone


constructing C64 ...
...
set SID to freq= 44100
...
sum=45056
sum=47104
sum=45056
sum=45056
sum=47104
sum=45056
sum=45056
sum=45056
sum=47104
sum=45056
sum=45056
sum=47104
sum=45056
sum=47104
sum=45056

did you spot the output

    printf("set SID to freq= %d\n", have.freq);
    c64->sid.setSampleRate(have.freq);

this is not the want.freq but what the system validates and passes us back ...

want.freq = 44100; 
...    
device_id = SDL_OpenAudioDevice(NULL, 0, &want, &have, SDL_AUDIO_ALLOW_FORMAT_CHANGE);
...
printf("set SID to freq= %d\n", have.freq);
c64->sid.setSampleRate(have.freq);
mithrendal commented 4 years ago

and another one

SAFARI 13.1 (on modern mac)

constructing C64 ...
...
set SID to freq= 44100
...
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=47104
sum=45056
sum=45056
sum=45056
sum=45056
sum=45056
sum=47104

I know ... maybe it runs with 60 Hz? 60/50 = 1.2 . No that is also not the case ...

dirkwhoffmann commented 4 years ago

In SIDBridge::handleBufferUnderflow(), try to change

if (elapsedTime > 10.0)

to

if (elapsedTime > 1.0)

and see if it stabilizes to a certain frequency.

dirkwhoffmann commented 4 years ago

One more thought... Could you verify that draw_one_frame_into_SDL is really called 50 times a seconds (by reading and comparing the system clock inside this function every 50th run).

emscripten_set_main_loop_arg(draw_one_frame_into_SDL, thisC64, 50, 1);

Maybe, the 44.1kHz is working, but the 50Hz loop isn't 🤔.

mithrendal commented 4 years ago

with if (elapsedTime > 1.0)

FIREFOX it stabilizes at 480xx and no more underruns / overruns

xx some value not necessarily 00

SAFARI IPhone clean sound ...

dirkwhoffmann commented 4 years ago

it stabilizes at 480xx and no more underruns / overruns

Cutting edge Auto Sampling Rate Adjustment technology (ASRA(TM)) 😎 (patent pending).

Still we need to find out what's happening here 🤔.

mithrendal commented 4 years ago
void draw_one_frame_into_SDL(void *thisC64) 
{
 ...
  if(frame_count % 50 == 0)
  {
      double now = emscripten_get_now();
      double passed_time=  now - last_time;
      last_time = now;

      printf("sum=%d, time[ms]=%lf\n", sum_samples, passed_time);
      sum_samples=0;
  }
}
...
set SID to freq= 44100
...
sum=47104, time[ms]=1077.000000
sum=49152, time[ms]=1100.000000
sum=47104, time[ms]=1078.000000
sum=47104, time[ms]=1070.000000
sum=47104, time[ms]=1072.000000
sum=47104, time[ms]=1073.000000
sum=47104, time[ms]=1065.000000
sum=47104, time[ms]=1075.000000
sum=47104, time[ms]=1074.000000
sum=49152, time[ms]=1085.000000
sum=45056, time[ms]=1053.000000
sum=47104, time[ms]=1069.000000
sum=47104, time[ms]=1073.000000
sum=49152, time[ms]=1080.000000
sum=47104, time[ms]=1065.000000
sum=49152, time[ms]=1141.000000
sum=47104, time[ms]=1068.000000
sum=47104, time[ms]=1061.000000
sum=47104, time[ms]=1060.000000

isn't it supposed to be 1000ms ?

dirkwhoffmann commented 4 years ago

See what I've found out on macOS. When I launch VirtualC64, it eventually executes

 let hardwareFormat = audiounit.outputBusses[0].format
    let channels = hardwareFormat.channelCount
    let sampleRate = hardwareFormat.sampleRate
    let stereo = (channels > 1)

    // Tell SID to use the correct sample rate
    sid?.setSampleRate(UInt32(sampleRate))

Now guess what the value is...

Bildschirmfoto 2020-04-19 um 20 29 03

Are you running Catalina like I do? I am pretty sure that macOS returned 44100 in previous OS revisions.

dirkwhoffmann commented 4 years ago

isn't it supposed to be 1000ms ?

Yes. 1 sec is 1000ms. I learned that in school back in the day. I don't think they changed it since then. 🤔

mithrendal commented 4 years ago

IOS, Catalina and El Capitan all sum=45000 - 48000 ...😳

but SDL have.freq reported 44100

dirkwhoffmann commented 4 years ago

44100 would fit if the loop would run at 50Hz. I think we should focus on why

emscripten_set_main_loop_arg(draw_one_frame_into_SDL, thisC64, 50, 1);

doesn't work properly. Is there also some want / have mechanism here? 🤔

dirkwhoffmann commented 4 years ago

One more idea... Let's try to revert to the 60Hz main loop. If this loop really runs at 60Hz, we could implement the 50Hz manually (by skipping a frame from time to time). This would enable us to emulate the correct PAL frequency later (which is 50,125, I think).

mithrendal commented 4 years ago

just tested iOS which reports 1400ms where it should be 1000ms ... Maybe this explains why in the beginning of vC64web iOS always had a bit problems with sound ... which some how healed a bit by setting the sample size to a higher value than 512 . from 2048 it was acceptable ...

going back to the default 60hz with emscripten_set_main_loop_arg(draw_one_frame_into_SDL, thisC64, 0, 1);

yes 0 ... the doc says ... The JavaScript environment will call that function at a specified number of frames per second. If called on the main browser thread, setting 0 or a negative value as the fps will use the browser’s requestAnimationFrame mechanism to call the main loop function. This is HIGHLY recommended if you are doing rendering, as the browser’s requestAnimationFrame will make sure you render at a proper smooth rate that lines up properly with the browser and monitor. If you do not render at all in your application, then you should pick a specific frame rate that makes sense for your code.

Ok ... we understand HIGHLY recommended not only highly 🤓

VALUES for 60Hz alias parameter 0 in the setmainloop() method and measuring time all 60 frames

FIREFOX

sum=47104, time[ms]=1067.000000
sum=47104, time[ms]=1036.000000
sum=43008, time[ms]=1014.000000
sum=67584, time[ms]=1540.000000
sum=47104, time[ms]=1033.000000
sum=45056, time[ms]=1051.000000
sum=45056, time[ms]=1018.000000
sum=45056, time[ms]=1013.000000
sum=45056, time[ms]=1021.000000
sum=45056, time[ms]=1017.000000

iPhone iOS

constructing C64 ...
...
set SID to freq= 44100
...
sum=0, time[ms]=1039.000000
sum=6144, time[ms]=1147.000000
sum=47104, time[ms]=1040.000000
sum=45056, time[ms]=1043.000000
sum=45056, time[ms]=1028.000000
sum=45056, time[ms]=1036.000000
sum=47104, time[ms]=1034.000000
sum=45056, time[ms]=1039.000000
sum=45056, time[ms]=1033.000000
sum=45056, time[ms]=1029.000000
sum=47104, time[ms]=1046.000000
sum=45056, time[ms]=1039.000000
mithrendal commented 4 years ago

Maybe that simply means that it does not call us 60 times per 1000ms but only 57 or 58 ?

dirkwhoffmann commented 4 years ago

Maybe that simply means that it does not call us 60 times per 1000ms but only 57 or 58 ?

Yes, this seems to be the case. But we can trick it out by adding our own time management (like original VirtualC64). Read the clock at the beginning of the handler and determine if a new frame is due. If yes, call executeOneFrame(). If no, do nothing. As long as the handler is called more frequently than 50.125 times per sec, we'll be fine.

Before doing that, we should check that executeOneFrame() is not the culprit. If executing this function took longer than 1/50th sec occasionally, this could be the reason why iterations are dropped. But I don't see a convincing reason why executeOneFrame() should take so long occasionally, because the CPU load is below 60%.

mithrendal commented 4 years ago

If executing this function took longer than 1/50th sec occasionally, this could be the reason why iterations are dropped.

Commander I checked that.. ranges from 8 to 11 ms on my slowest ship from 2007.

mithrendal commented 4 years ago

Ok I try to recapitulate all pieces

  1. we saw the buffer overflows in the beginning, because the core did run with max framerate ... NTSC 60hz and therefore produced too much for consumers sample rate of 44100Hz...

  2. When configuring the SDL to 50hz it calls us not 50 frames per second but maybe only 48 or 49 frames per second. And therefore the producer produces 10% less what the consumer wants to have. Therefore we see buffer underflows every 100 read of samples.

our plan is

which will prevent both overruns AND underruns at a samplerate of 44100Hz ...

correct ? Did I miss something ?

Sidenote: but what about the 48k which you saw in XCode MacOS ... is that somehow relevant for the web version ?

dirkwhoffmann commented 4 years ago

we saw the buffer overflows in the beginning, because the core did run with max framerate ... NTSC 60hz and therefore produced to much for sample rate of 44100Hz...

👍

When configuring the SDL to 50hz it calls us not 50 frames per second but maybe only 48 or 49 frames per second. And therefore the producer produces 10% less what the consumer wants to have. Therefore we see buffer underflows every 100 read of samples.

👍

our plan is

go by max frame rates as possible -> 60Hz SDL gives us -> 58 calls

👍

manage to call c64->doExecuteFrame() 50.125 times per sec by measureing time inside the method. drawOneFrameIntoSDL()

👍

-resestablish the original elapsed time threshhold to 10 sec which will prevent both overruns AND underruns at a samplerate of 44100Hz ...

👍

correct ? Did I miss something ?

You got it all right, Sir 😎. Engines ready to start. Thunderbirds are Go.

mithrendal commented 4 years ago

Admiral ... Me executed the plan ...

first I starred at the blue start screen and let it just run the blinking cursor and then I loaded fort apocalypse ...

here is what the executed plan does to the under-/overflows ...

for the 50.125 frames I let it every 8th second execute an additional "schalt"-frame ...

Me took out some uninteresting parts of da log ...


constructing C64 ... vC64.html:1:368
C64: Creating virtual C64[0x17f3a78] vC64.html:1:528
SIDBridge: Setting clock frequency to 985249 vC64.html:1:528
ReSID: Setting clock frequency to 985249 cycles per second. vC64.html:1:528
Drive1: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
Drive2: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
C64: Resetting virtual C64[0x17f3a78] vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:528
adding a listener to C64 message queue... vC64.html:1:368
vC64 message=MSG_PAL, data=0 vC64.html:1:368
...
set SID to freq= 44100 vC64.html:1:368
SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528
ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44100 vC64.html:1:528
wrapper calls 4x c64->loadRom(...) method vC64.html:1:368
vC64 message=MSG_RUN, data=0 vC64.html:1:368
vC64 message=MSG_IEC_BUS_BUSY, data=0 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7168 w: 7639) vC64.html:1:528
SIDBridge: elapsed 2.631000 vC64.html:1:528
vC64 message=MSG_IEC_BUS_IDLE, data=0 vC64.html:1:368
time[ms]=3650.000000, audio samples=47104, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6144 w: 5306) vC64.html:1:528
SIDBridge: elapsed 1.496000 vC64.html:1:528
vC64 message=MSG_IEC_BUS_IDLE, data=0 vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1000.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=997.000000, audio samples=43520, frames [executed=51, skipped=7] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] 2 vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 9728 w: 10116) vC64.html:1:528
SIDBridge: elapsed 23.819000 vC64.html:1:528
SIDBridge: Changing sample rate from 44100 to 44346 vC64.html:1:528
ReSID: Setting sample rate to 44346 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44346 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 11264 w: 11478) vC64.html:1:528
SIDBridge: elapsed 0.815000 vC64.html:1:528
time[ms]=1285.000000, audio samples=56832, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 9216 w: 9280) vC64.html:1:528
SIDBridge: elapsed 0.248000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1024 w: 1234) vC64.html:1:528
SIDBridge: elapsed 0.633000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 9216 w: 9656) vC64.html:1:528
SIDBridge: elapsed 0.465000 vC64.html:1:528
time[ms]=1328.000000, audio samples=58368, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1024 w: 1137) vC64.html:1:528
SIDBridge: elapsed 0.371000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8704 w: 8771) vC64.html:1:528
SIDBridge: elapsed 0.456000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 5048) vC64.html:1:528
SIDBridge: elapsed 0.461000 vC64.html:1:528
time[ms]=1373.000000, audio samples=60928, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7680 w: 8128) vC64.html:1:528
SIDBridge: elapsed 0.915000 vC64.html:1:528
time[ms]=1120.000000, audio samples=48640, frames [executed=50, skipped=0] vC64.html:1:368
time[ms]=1005.000000, audio samples=44544, frames [executed=50, skipped=6] vC64.html:1:368
load file=Fort_Apocalypse_(Synapse_Software_1982).crt len=16480 vC64.html:1:368
isCRT vC64.html:1:368
CRTFile: readFromBuffer: checksum = d1f1e72a365a4cb6 vC64.html:1:528
CRTFile: CRT fingerprint: d1f1e72a365a4cb6 vC64.html:1:528
Cartridge: Fort Apocalypse vC64.html:1:528
   Header: 00000040 bytes long (normally 0x40) vC64.html:1:528
   Type:   5 vC64.html:1:528
   Game:   1 vC64.html:1:528
   Exrom:  0 vC64.html:1:528
CRTFile: CRT file imported successfully (2 chips) vC64.html:1:528
Cartridge: Creating cartridge at address 0x1be5c18... vC64.html:1:528
vC64 message=MSG_CARTRIDGE, data=0 vC64.html:1:368
Expansion port: Cartridge attached to expansion port vC64.html:1:528
Cartridge vC64.html:1:528
--------- vC64.html:1:528
        Cartridge type: 5 vC64.html:1:528
 Game line in CRT file: 1 vC64.html:1:528
Exrom line in CRT file: 0 vC64.html:1:528
 Number of Rom packets: 2 vC64.html:1:528
              Chip   0: 8 KB starting at $8000 vC64.html:1:528
              Chip   1: 8 KB starting at $8000 vC64.html:1:528
<empty string> vC64.html:1:528
C64: Resetting virtual C64[0x17f3a78] vC64.html:1:528
C64 memory: Grabbing reset vector from source 2 vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:528
time[ms]=999.000000, audio samples=44032, frames [executed=50, skipped=0] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 3317) vC64.html:1:528
SIDBridge: elapsed 4.101000 vC64.html:1:528
schalt frame vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=5] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=998.000000, audio samples=43520, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 4851) vC64.html:1:528
SIDBridge: elapsed 13.105000 vC64.html:1:528
SIDBridge: Changing sample rate from 44346 to 44794 vC64.html:1:528
ReSID: Setting sample rate to 44794 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44794 vC64.html:1:528
time[ms]=1107.000000, audio samples=48640, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 9728 w: 9649) vC64.html:1:528
SIDBridge: elapsed 1.235000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 4381) vC64.html:1:528
SIDBridge: elapsed 0.146000 vC64.html:1:528
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8704 w: 8690) vC64.html:1:528
SIDBridge: elapsed 1.787000 vC64.html:1:528
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=7] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1011.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1004.000000, audio samples=44544, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 5120 w: 4464) vC64.html:1:528
SIDBridge: elapsed 9.106000 vC64.html:1:528
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 500) vC64.html:1:528
SIDBridge: elapsed 0.161000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 11776 w: 11745) vC64.html:1:528
SIDBridge: elapsed 0.829000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 6144 w: 6428) vC64.html:1:528
SIDBridge: elapsed 0.145000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 6494) vC64.html:1:528
SIDBridge: elapsed 0.856000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1024 w: 1308) vC64.html:1:528
SIDBridge: elapsed 0.142000 vC64.html:1:528
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 10240 w: 10089) vC64.html:1:528
SIDBridge: elapsed 0.775000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 8466) vC64.html:1:528
SIDBridge: elapsed 0.225000 vC64.html:1:528
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 7680 w: 7648) vC64.html:1:528
SIDBridge: elapsed 0.829000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3072 w: 3226) vC64.html:1:528
SIDBridge: elapsed 0.169000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 6046) vC64.html:1:528
SIDBridge: elapsed 1.760000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 8291) vC64.html:1:528
SIDBridge: elapsed 0.306000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 512 w: 499) vC64.html:1:528
SIDBridge: elapsed 0.665000 vC64.html:1:528
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] 2 vC64.html:1:368
time[ms]=996.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=999.000000, audio samples=44032, frames [executed=51, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=1] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 7443) vC64.html:1:528
SIDBridge: elapsed 9.929000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=5] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 5798) vC64.html:1:528
SIDBridge: elapsed 7.208000 vC64.html:1:528
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 5120 w: 5610) vC64.html:1:528
SIDBridge: elapsed 0.240000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 7168 w: 6308) vC64.html:1:528
SIDBridge: elapsed 0.608000 vC64.html:1:528
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1004.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6144 w: 5444) vC64.html:1:528
SIDBridge: elapsed 8.062000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 8672) vC64.html:1:528
SIDBridge: elapsed 0.317000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4608 w: 4017) vC64.html:1:528
SIDBridge: elapsed 1.596000 vC64.html:1:528
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
schalt frame vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=6] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2560 w: 2886) vC64.html:1:528
SIDBridge: elapsed 6.079000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 11776 w: 12237) vC64.html:1:528
SIDBridge: elapsed 0.522000 vC64.html:1:528
Mouse entered window 1 vC64.html:1:368
time[ms]=1301.000000, audio samples=55808, frames [executed=50, skipped=0] vC64.html:1:368
Window 1 lost keyboard focus vC64.html:1:368
Mouse left window 1 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 0 w: 453) vC64.html:1:528
SIDBridge: elapsed 0.571000 vC64.html:1:528
time[ms]=1188.000000, audio samples=52736, frames [executed=50, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1024 w: 1187) vC64.html:1:528
SIDBridge: elapsed 0.878000 vC64.html:1:528
time[ms]=1086.000000, audio samples=47616, frames [executed=50, skipped=0] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1035.000000, audio samples=45568, frames [executed=50, skipped=0] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=0] vC64.html:1:368
dirkwhoffmann commented 4 years ago

OK, let’s analyze the log 🤤…

At the beginning, it looks pretty good. VC64web runs for 14 seconds, increases the sample rate, runs for 19 seconds and increases the sample rate again. So far so good. Let’s do a little math: 19 seconds between 2 buffer underflows means that the consumer consumes 6000 samples more than the producer produces in 19 seconds. This is about 300 samples per second. VC64web reacts on this by increasing the sample frequency of the producer by approx. this about (from 4495 to 44798). This is correct, but then everything goes haywire.

I think it’s related to the „Schalt frame“ approach. If I understand it correctly, you simply drop every 8th call to executeOneFrame() with the idea to reduce the 57 Hz (which we got instead instead of the requested 60 Hz) to roughly 50.125 Hz.

I think this is not robust enough, because it relies on a stable frequency of the SDL loop. It might also be that future browser versions give us 60 Hz stable.

To decouple from SDL timing oddities, use the system clock in combination with a frame counter.

For simplicity, let’s assume we want to have 50 Hz and everything is measured in seconds. Here are our variables:

Now, inside the loop do the following:

This is somewhat similar to what VirtualC64 is doing with the targetNanos and the sleep calls. The difference is that VC64mac schedules its own wakeup whereas VC64web is woken up by the SDL (in strange intervals though).

There should also be some reset logic. If the number of frames needed to cope up with the system clock is way off (a very high positive value or a very low negative value), you should reset the counters. VC64mac already uses such a logic. The check is done inside C64::synchronizeTiming and the reset is done in restartTimer():

void
C64::synchronizeTiming()
{
    const uint64_t earlyWakeup = 1500000; /* 1.5 milliseconds */

    // Get current time in nano seconds
    uint64_t nanoAbsTime = abs_to_nanos(mach_absolute_time());

    // Check how long we're supposed to sleep
    int64_t timediff = (int64_t)nanoTargetTime - (int64_t)nanoAbsTime;
    if (timediff > 200000000 || timediff < -200000000 /* 0.2 sec */) {

        // The emulator seems to be out of sync, so we better reset the
        // synchronization timer

        debug(2, "Emulator lost synchronization (%lld). Restarting timer.\n", timediff);
        restartTimer();
    }

void
C64::restartTimer()
{
    uint64_t kernelNow = mach_absolute_time();
    uint64_t nanoNow = abs_to_nanos(kernelNow);

    nanoTargetTime = nanoNow + vic.getFrameDelay();
}
mithrendal commented 4 years ago

If I understand your idea then the algorithm which has produced the above log already works as you have in mind

SDL calls us 60 times per second ... well a bit less maybe 59
the algorithm simply executes the first 50 frames and after that it skipped execution for the remaining 9 SDL-Calls

an extra schalt frame is executed every 8th seconds (0.125s = 1s / 8) that means every 8th second 51 frames are executed instead of only 50 frames.

Now I have seen that this approach results in little stops (the video is not smooth) at the end of the second (because it skips there 9 successively frames)

Therefore now I altered the algorithm to spread a bit more evenly over the complete second ... I do every 10 second a skip now ... and if that was not enough after 50 /51 frames the rest of the skips ...

but it looks maybe too complicated, no ?


bool bSkip=false;
bool bSkipInBetween=false;

double last_time = 0 ;
int sum_samples=0;
unsigned int executed_frame_count=0;
unsigned int skipped_frame_count=0;
unsigned long schalt_frame_count = 0; //every 8th round execute an extra frame PAL = 50.125Hz
bool bSchaltFrameRound = false;
bool bSchaltFramExecuted = false;
// The emscripten "main loop" replacement function.
void draw_one_frame_into_SDL(void *thisC64) 
{
  //this method is triggered by
  //emscripten_set_main_loop_arg(em_arg_callback_func func, void *arg, int fps, int simulate_infinite_loop) 
  //which is called inside te c64.cpp
  //fps Setting int <=0 (recommended) uses the browser’s requestAnimationFrame mechanism to call the function.

  //The number of callbacks is usually 60 times per second, but will 
  //generally match the display refresh rate in most web browsers as 
  //per W3C recommendation. requestAnimationFrame() 

  /* spread skips on every tenth frame so we have a reserve at the end 
     in case it does not reach the goal of 50 frames in total per second
  */
  if(bSkipInBetween == false && executed_frame_count % 10 /*(50/10)*/ == 0)
  {
    bSkipInBetween=true;
  }
  else
  {
    bSkipInBetween=false;
  }

  if(executed_frame_count >= (bSchaltFrameRound ? 51 : 50))
  {
    bSkip=true;
  }

  //are we nearing the 50th frame?
  if(executed_frame_count >10)
  {
    //test whether we already reached nearly 1 second
    double now = emscripten_get_now();
    if(now-last_time>= 1000.0 - ((1000.0/60.0)/2.0))
    { 
      //oh we ended the skip .. 1 second, in this case we have to remember last_time 
      //and reset all other counters
      bSkip=false;
      bSkipInBetween=false;
      double passed_time=  now - last_time;
      last_time = now;
      printf("time[ms]=%lf, audio samples=%d, frames [executed=%u, skipped=%u]\n", passed_time, sum_samples, executed_frame_count, skipped_frame_count);
      sum_samples=0;
      executed_frame_count=0;
      skipped_frame_count=0;

      if(bSchaltFrameRound)
      {
        schalt_frame_count=0;
        bSchaltFrameRound=false;
      }
      schalt_frame_count++;  
      if(schalt_frame_count == 8)
      {
//        printf("schalt frame round\n");
        bSchaltFrameRound=true;
        bSchaltFramExecuted=false;
      }
    }
  }

  if((bSkip || bSkipInBetween))
  {
    if(bSchaltFrameRound && !bSchaltFramExecuted)
    {
//      printf("skipped skip frame %u\n", executed_frame_count+1);
      bSchaltFramExecuted=true;
    }
    else
    {
//      printf("skipped frame %u\n", executed_frame_count+1);
      skipped_frame_count++;
      return;
    }
  }

  executed_frame_count++;

  EM_ASM({
      if (typeof draw_one_frame === 'undefined')
          return;
      draw_one_frame();
  });

  C64 *c64 = (C64 *)thisC64;
  c64->executeOneFrame();

  Uint8 *texture = (Uint8 *)c64->vic.screenBuffer();

  int surface_width = window_surface->w;
  int surface_height = window_surface->h;

//  SDL_RenderClear(renderer);
  SDL_Rect SrcR;
  SrcR.x = xOff;
  SrcR.y = yOff;
  SrcR.w = clipped_width;
  SrcR.h = clipped_height;
  SDL_UpdateTexture(screen_texture, &SrcR, texture+ (4*emu_width*SrcR.y) + SrcR.x*4, 4*emu_width);

  SDL_RenderCopy(renderer, screen_texture, &SrcR, NULL);

  SDL_RenderPresent(renderer);
}

void MyAudioCallback(void*  thisC64,
                       Uint8* stream,
                       int    len)
{
    C64 *c64 = (C64 *)thisC64;

    int n = len /  sizeof(float);
    c64->sid.readMonoSamples((float *)stream, n);
    sum_samples += n;
}

new log ... same scenario ...

constructing C64 ... vC64.html:1:368
C64: Creating virtual C64[0x17f3a68] vC64.html:1:528
SIDBridge: Setting clock frequency to 985249 vC64.html:1:528
ReSID: Setting clock frequency to 985249 cycles per second. vC64.html:1:528
Drive1: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
Drive2: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
C64: Resetting virtual C64[0x17f3a68] vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:5280 vC64.html:1:368

set SID to freq= 44100 vC64.html:1:368

SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528
ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44100 vC64.html:1:528
vC64 message=MSG_READY_TO_RUN, data=0 vC64.html:1:368
wrapper calls run on c64->run() method vC64.html:1:368
vC64 message=MSG_RUN, data=0 vC64.html:1:368
vC64 message=MSG_IEC_BUS_BUSY, data=0 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7168 w: 7639) vC64.html:1:528
SIDBridge: elapsed 2.442000 vC64.html:1:528
time[ms]=2687.000000, audio samples=12800, frames [executed=11, skipped=2] vC64.html:1:368
time[ms]=994.000000, audio samples=44032, frames [executed=50, skipped=4] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=49, skipped=4] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=8] 2 vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] 2 vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=993.000000, audio samples=43520, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=996.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] 2 vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=993.000000, audio samples=43520, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=996.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 9216 w: 9702) vC64.html:1:528
SIDBridge: elapsed 43.658000 vC64.html:1:528
SIDBridge: Changing sample rate from 44100 to 44234 vC64.html:1:528
ReSID: Setting sample rate to 44234 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44234 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1536 w: 1992) vC64.html:1:528
SIDBridge: elapsed 0.362000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=36, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 6656 w: 6667) vC64.html:1:528
SIDBridge: elapsed 0.670000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 6144 w: 6425) vC64.html:1:528
SIDBridge: elapsed 0.267000 vC64.html:1:528
time[ms]=1005.000000, audio samples=44544, frames [executed=36, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 512 w: 685) vC64.html:1:528
SIDBridge: elapsed 0.473000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2560 w: 2996) vC64.html:1:528
SIDBridge: elapsed 0.564000 vC64.html:1:528
time[ms]=1016.000000, audio samples=44544, frames [executed=37, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7168 w: 7624) vC64.html:1:528
SIDBridge: elapsed 0.384000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3072 w: 3541) vC64.html:1:528
SIDBridge: elapsed 0.743000 vC64.html:1:528
time[ms]=1017.000000, audio samples=44544, frames [executed=40, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 4606) vC64.html:1:528
SIDBridge: elapsed 0.302000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 2560 w: 3050) vC64.html:1:528
SIDBridge: elapsed 0.526000 vC64.html:1:528
time[ms]=1005.000000, audio samples=44544, frames [executed=37, skipped=2] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8192 w: 8573) vC64.html:1:528
SIDBridge: elapsed 0.681000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7680 w: 7962) vC64.html:1:528
SIDBridge: elapsed 0.273000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3072 w: 3103) vC64.html:1:528
SIDBridge: elapsed 0.460000 vC64.html:1:528
time[ms]=1043.000000, audio samples=46080, frames [executed=36, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7680 w: 8137) vC64.html:1:528
SIDBridge: elapsed 0.370000 vC64.html:1:528
time[ms]=1001.000000, audio samples=44032, frames [executed=39, skipped=3] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 512 w: 523) vC64.html:1:528
SIDBridge: elapsed 0.673000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=4] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=5] vC64.html:1:368
load file=Fort_Apocalypse_(Synapse_Software_1982).crt len=16480 vC64.html:1:368
isCRT vC64.html:1:368
CRTFile: readFromBuffer: checksum = d1f1e72a365a4cb6 vC64.html:1:528
CRTFile: CRT fingerprint: d1f1e72a365a4cb6 vC64.html:1:528
Cartridge: Fort Apocalypse vC64.html:1:528
   Header: 00000040 bytes long (normally 0x40) vC64.html:1:528
   Type:   5 vC64.html:1:528
   Game:   1 vC64.html:1:528
   Exrom:  0 vC64.html:1:528
CRTFile: CRT file imported successfully (2 chips) vC64.html:1:528
Cartridge: Creating cartridge at address 0x1be5c60... vC64.html:1:528
vC64 message=MSG_CARTRIDGE, data=0 vC64.html:1:368
Expansion port: Cartridge attached to expansion port vC64.html:1:528
Cartridge vC64.html:1:528
--------- vC64.html:1:528
        Cartridge type: 5 vC64.html:1:528
 Game line in CRT file: 1 vC64.html:1:528
Exrom line in CRT file: 0 vC64.html:1:528
 Number of Rom packets: 2 vC64.html:1:528
              Chip   0: 8 KB starting at $8000 vC64.html:1:528
              Chip   1: 8 KB starting at $8000 vC64.html:1:528
<empty string> vC64.html:1:528
C64: Resetting virtual C64[0x17f3a68] vC64.html:1:528
C64 memory: Grabbing reset vector from source 2 vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:528
...
time[ms]=1003.000000, audio samples=44032, frames [executed=41, skipped=4] vC64.html:1:368
...
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
vC64 message=MSG_IEC_BUS_IDLE, data=0 vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1004.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1009.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1000.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=51, skipped=6] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=995.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] 2 vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] 2 vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=994.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=6] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=997.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=4] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1004.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1009.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
time[ms]=998.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368

the underflows kicked in when I opened the file dialog ... to choose the CRT file ... that put the emulation under stress ... on my slowest ship .. but after the CRT was loaded it stabilizes .. no underflows/overflows ...

dirkwhoffmann commented 4 years ago

but it looks maybe too complicated, no ?

Hmmm... yes, I'm a little overwhelmed with your code 🤔...

440px-DeutschesUhrenmuseum_WeckerModell

The major problem I see here (despite the complexity) is that it still relies on the SDL timer to fire at a certain frequency. The code would fail if your request for a 60Hz timer would result in a timer that really fires at 60Hz, wouldn't it? (Because you would still start dropping frames. No?)

mithrendal commented 4 years ago

The major problem I see here (despite the complexity) is that it still relies on the SDL timer to fire at a certain frequency. The code would fail if your request for a 60Hz timer would result in a timer that really fires at 60Hz, wouldn't it? (Because you would still start dropping frames. No?)

Hmm I don't understand or I don't see yet where the code relies on the SDL timer ... when SDL would call us with the exact amount of 60 times then I have to drop exactly 10 frames for 50Hz, no ? The code would still do this fine.

The complicated part (which made the above code that complex) was with the (more or less) equidistant spreading of the drops over the second... but this had to be done

without equidistant spreading and the additional 0.125 Hz the code was very simple...

But when we would drop only all frames which exceed the goal of 50 after the first 50 have been executed (that is at the end of an second .. (in a perfect 60Hz world at 1000ms - (1000ms/60)*(60-50)= 833ms ) then the Heli would stutter when flying ... because of microbreaks caused by the clustering of the frame drops at th end (after 833ms nothing is executed/drawn anymore) ...

What about the second log is it not good enough yet ?

Another problem with the equidistant spreading is, that you don't know exactly how many frames to drop before you reached the end of the second ... in a perfect world (very fast computer) this is of cause 60-50=10 (ok 60-50.125=9.875) but that can vary because the computer is too slow

60 frames / 10 frame drops means after 6 frames a drop should occur (in a perfect world) for being really equidistant but when the computer is too slow it may not reach the 50 executions at the end of the 1000ms. Therefore the algorithm only drops every 10th frame to have a reserve at the end of the 1000ms....

dirkwhoffmann commented 4 years ago

OK, I see. I didn’t look at the code long enough.

But isn’t it much simpler to do it like this?

targetFrameCount = elapsedTimeInSeconds * 50.125;
While (frameCount < targetFrameCount) {
    executeOneFrame();
    frameCount++; 
}
mithrendal commented 4 years ago

I am in love with these 4 lines of code 😍. Looks much more adaptive 🤤then my approach (with the reserve at the end 🙄)... will try it this evening...

mithrendal commented 4 years ago

New simplified method in place ...

int sum_samples=0;
double last_time = 0.0 ;
unsigned int executed_frame_count=0;
unsigned int skipped_frame_count=0;
unsigned long total_executed_frame_count=0;
double start_time=emscripten_get_now();

void draw_one_frame_into_SDL(void *thisC64) 
{
  double now = emscripten_get_now();  

  double elapsedTimeInSeconds = (now - start_time)/1000.0;
  double targetFrameCount = elapsedTimeInSeconds * 50.125;

  if(now-last_time>= 1000.0)
  { 
    double passed_time= now - last_time;
    last_time = now;
    printf("\ntime[ms]=%lf, audio samples=%d, frames [executed=%u, skipped=%u]\n", passed_time, sum_samples, executed_frame_count, skipped_frame_count);
    sum_samples=0;
    skipped_frame_count=0;
    executed_frame_count=0;
  }

  if (total_executed_frame_count >= (unsigned long)round(targetFrameCount)) {
    skipped_frame_count++;
    return;
  }

  executed_frame_count++;
  total_executed_frame_count++;

  C64 *c64 = (C64 *)thisC64;
  c64->executeOneFrame();

  ...
}

brought it to the combat zone ... same old scenario ... first 30 seconds blue start screen then fort apocalypse ...

SIDBridge: Setting clock frequency to 985249 vC64.html:1:528
ReSID: Setting clock frequency to 985249 cycles per second. vC64.html:1:528
Drive1: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
Drive2: Duration a CPU cycle is 10149 1/10 nsec. vC64.html:1:528
C64: Resetting virtual C64[0x17f3a78] vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:528
adding a listener to C64 message queue... vC64.html:1:368
set SID to freq= 44100 vC64.html:1:368
SIDBridge: Changing sample rate from 44100 to 44100 vC64.html:1:528
ReSID: Setting sample rate to 44100 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44100 vC64.html:1:528
wrapper calls run on c64->run() method vC64.html:1:368
vC64 message=MSG_RUN, data=0 vC64.html:1:368
time[ms]=2028.000000, audio samples=0, frames [executed=0, skipped=0] vC64.html:1:368
vC64 message=MSG_IEC_BUS_BUSY, data=0 vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10752 w: 11188) vC64.html:1:528
SIDBridge: elapsed 2.696000 vC64.html:1:528
vC64 message=MSG_IEC_BUS_IDLE, data=0 vC64.html:1:368
time[ms]=1012.000000, audio samples=38912, frames [executed=37, skipped=0] vC64.html:1:368
time[ms]=1014.000000, audio samples=44544, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 9728 w: 8889) vC64.html:1:528
SIDBridge: elapsed 1.371000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 5120 w: 4288) vC64.html:1:528
SIDBridge: elapsed 0.729000 vC64.html:1:528
time[ms]=1002.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=54, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 512 w: 12026) vC64.html:1:528
SIDBridge: elapsed 1.290000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 1024 w: 351) vC64.html:1:528
SIDBridge: elapsed 0.849000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 11264 w: 10511) vC64.html:1:528
SIDBridge: elapsed 0.784000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 9216 w: 8492) vC64.html:1:528
SIDBridge: elapsed 1.070000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1012.000000, audio samples=45056, frames [executed=58, skipped=0] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=53, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 10752 w: 9993) vC64.html:1:528
SIDBridge: elapsed 1.431000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 3553) vC64.html:1:528
SIDBridge: elapsed 0.686000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=52, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=44544, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=10] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=44544, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1015.000000, audio samples=44544, frames [executed=50, skipped=10] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1000.000000, audio samples=44032, frames [executed=50, skipped=10] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=44544, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1018.000000, audio samples=45056, frames [executed=50, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=51, skipped=2] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=10] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=44544, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=10] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1015.000000, audio samples=45056, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1017.000000, audio samples=45056, frames [executed=48, skipped=5] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 4724) vC64.html:1:528
SIDBridge: elapsed 33.718000 vC64.html:1:528
SIDBridge: Changing sample rate from 44100 to 44274 vC64.html:1:528
ReSID: Setting sample rate to 44274 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44274 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10240 w: 10565) vC64.html:1:528
SIDBridge: elapsed 0.407000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1033.000000, audio samples=45056, frames [executed=35, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 5632 w: 5677) vC64.html:1:528
SIDBridge: elapsed 0.454000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 1536 w: 1952) vC64.html:1:528
SIDBridge: elapsed 0.479000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44544, frames [executed=37, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10752 w: 11027) vC64.html:1:528
SIDBridge: elapsed 0.474000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4096 w: 4422) vC64.html:1:528
SIDBridge: elapsed 0.405000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1016.000000, audio samples=45056, frames [executed=38, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3584 w: 3948) vC64.html:1:528
SIDBridge: elapsed 0.545000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3072 w: 3437) vC64.html:1:528
SIDBridge: elapsed 0.546000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7680 w: 8147) vC64.html:1:528
SIDBridge: elapsed 0.383000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1020.000000, audio samples=44544, frames [executed=36, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 3584 w: 4000) vC64.html:1:528
SIDBridge: elapsed 0.464000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 9216 w: 9541) vC64.html:1:528
SIDBridge: elapsed 0.406000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1030.000000, audio samples=45568, frames [executed=37, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 4653) vC64.html:1:528
SIDBridge: elapsed 0.458000 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 8704 w: 8799) vC64.html:1:528
SIDBridge: elapsed 0.367000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=35, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 4608 w: 5102) vC64.html:1:528
SIDBridge: elapsed 0.743000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=43, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 10240 w: 10644) vC64.html:1:528
SIDBridge: elapsed 0.685000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1023.000000, audio samples=45056, frames [executed=46, skipped=0] vC64.html:1:368
load file=Fort_Apocalypse_(Synapse_Software_1982).crt len=16480 vC64.html:1:368
isCRT vC64.html:1:368
CRTFile: readFromBuffer: checksum = d1f1e72a365a4cb6 vC64.html:1:528
CRTFile: CRT fingerprint: d1f1e72a365a4cb6 vC64.html:1:528
Cartridge: Fort Apocalypse vC64.html:1:528
   Header: 00000040 bytes long (normally 0x40) vC64.html:1:528
   Type:   5 vC64.html:1:528
   Game:   1 vC64.html:1:528
   Exrom:  0 vC64.html:1:528
CRTFile: CRT file imported successfully (2 chips) vC64.html:1:528
Cartridge: Creating cartridge at address 0x1bea510... vC64.html:1:528
vC64 message=MSG_CARTRIDGE, data=0 vC64.html:1:368
Expansion port: Cartridge attached to expansion port vC64.html:1:528
Cartridge vC64.html:1:528
--------- vC64.html:1:528
        Cartridge type: 5 vC64.html:1:528
 Game line in CRT file: 1 vC64.html:1:528
Exrom line in CRT file: 0 vC64.html:1:528
 Number of Rom packets: 2 vC64.html:1:528
              Chip   0: 8 KB starting at $8000 vC64.html:1:528
              Chip   1: 8 KB starting at $8000 vC64.html:1:528
<empty string> vC64.html:1:528
C64: Resetting virtual C64[0x17f3a78] vC64.html:1:528
C64 memory: Grabbing reset vector from source 2 vC64.html:1:528
C64: Setting PC to FCE2 vC64.html:1:528
time[ms]=1013.000000, audio samples=44544, frames [executed=49, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4096 w: 3263) vC64.html:1:528
SIDBridge: elapsed 2.932000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1016.000000, audio samples=45056, frames [executed=57, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 512 w: 11976) vC64.html:1:528
SIDBridge: elapsed 0.751000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 8192 w: 7509) vC64.html:1:528
SIDBridge: elapsed 0.735000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4608 w: 3784) vC64.html:1:528
SIDBridge: elapsed 0.753000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11605) vC64.html:1:528
SIDBridge: elapsed 0.733000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 0 w: 11414) vC64.html:1:528
SIDBridge: elapsed 0.835000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 7680 w: 6997) vC64.html:1:528
SIDBridge: elapsed 0.737000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1015.000000, audio samples=44544, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 7680 w: 7523) vC64.html:1:528
SIDBridge: elapsed 0.830000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 1536 w: 1506) vC64.html:1:528
SIDBridge: elapsed 0.711000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 6126) vC64.html:1:528
SIDBridge: elapsed 0.941000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 3072 w: 2968) vC64.html:1:528
SIDBridge: elapsed 0.754000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=58, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 6613) vC64.html:1:528
SIDBridge: elapsed 0.918000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6656 w: 5946) vC64.html:1:528
SIDBridge: elapsed 0.834000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=45056, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 5632 w: 5616) vC64.html:1:528
SIDBridge: elapsed 0.815000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 2048 w: 1390) vC64.html:1:528
SIDBridge: elapsed 0.758000 vC64.html:1:528
SIDBridge: SID RINGBUFFER OVERFLOW (r: 9728 w: 9045) vC64.html:1:528
SIDBridge: elapsed 0.726000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=59, skipped=0] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=5] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=47, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=53, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1000.000000, audio samples=44032, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=45056, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=51, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=46, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 11776 w: 11647) vC64.html:1:528
SIDBridge: elapsed 20.944000 vC64.html:1:528
SIDBridge: Changing sample rate from 44274 to 43994 vC64.html:1:528
ReSID: Setting sample rate to 43994 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 43994 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=55, skipped=4] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=50, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=45056, frames [executed=51, skipped=3] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=51, skipped=8] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=44544, frames [executed=51, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44544, frames [executed=51, skipped=6] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1020.000000, audio samples=44544, frames [executed=50, skipped=8] vC64.html:1:368
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 7680 w: 8152) vC64.html:1:528
SIDBridge: elapsed 12.718000 vC64.html:1:528
SIDBridge: Changing sample rate from 43994 to 44456 vC64.html:1:528
ReSID: Setting sample rate to 44456 samples per second. vC64.html:1:528
FastSID: Setting sample rate to 44456 vC64.html:1:528
SIDBridge: SID RINGBUFFER UNDERFLOW (r: 6656 w: 6722) vC64.html:1:528
SIDBridge: elapsed 0.534000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1013.000000, audio samples=45056, frames [executed=38, skipped=0] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=56, skipped=0] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 6144 w: 5455) vC64.html:1:528
SIDBridge: elapsed 1.665000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=58, skipped=0] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44544, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=44544, frames [executed=51, skipped=7] vC64.html:1:368
SIDBridge: SID RINGBUFFER OVERFLOW (r: 4608 w: 4309) vC64.html:1:528
SIDBridge: elapsed 3.036000 vC64.html:1:528
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1001.000000, audio samples=44544, frames [executed=50, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1004.000000, audio samples=44032, frames [executed=51, skipped=7] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1002.000000, audio samples=44032, frames [executed=50, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1014.000000, audio samples=45056, frames [executed=51, skipped=9] vC64.html:1:368
<empty string> vC64.html:1:368
time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=7] vC64.html:1:368
wasm_halt vC64.html:1:368

I read it so: in the beginning it is behind the target_frame_count and therefore it does not skip any frame ... this lets overflow the audio buffer ... 9 seconds later it reaches the target_frame_count and stabilizes ... begins to skip frames ... no overflows and no underflows for 30 seconds ... then open file dialog puts pressure on my machine ... framerates begin to drop ... and therefore many buffer underruns begin to happen ... after fort apocalypse is loaded and started it does not skip anymore because it wants to reach the target_frame_count .... therefore a lot of overflows happen ... then later stabilizes again ...

any more ideas to optimize this ? This approach is overreacting a bit more then the old complicated one... but code is for sure more simple ... can we reduce the overreacting ? But maybe then it will look more complicated again no ?

Maybe we should reset the start_time every 10 seconds or so ? To cut the history ... and keeping the double values low. When is double value running out of precision ? Or do you think it is not needed?

mithrendal commented 4 years ago

There should also be some reset logic. If the number of frames needed to cope up with the system clock is way off (a very high positive value or a very low negative value), you should reset the counters.

yes the overreacting (core was overheating 😅) was fixed with the proposed reset logic ....

  double now = emscripten_get_now();  

  double elapsedTimeInSeconds = (now - start_time)/1000.0;
  double targetFrameCount = elapsedTimeInSeconds * 50.125;

  //lost the sync
  if(targetFrameCount-total_executed_frame_count > 8)
  {
      printf("lost sync target=%lf, total_executed=%lu\n", targetFrameCount, total_executed_frame_count);

      //reset timer
      start_time=now;
      total_executed_frame_count=0;
  }

  if(now-last_time>= 1000.0)
  { 
    double passed_time= now - last_time;
    last_time = now;
    printf("time[ms]=%lf, audio samples=%d, frames [executed=%u, skipped=%u]\n", passed_time, sum_samples, executed_frame_count, skipped_frame_count);
    sum_samples=0;
    skipped_frame_count=0;
    executed_frame_count=0;
  }

  if (total_executed_frame_count >= (unsigned long)round(targetFrameCount)) {
    skipped_frame_count++;
    return;
  }

  executed_frame_count++;
  total_executed_frame_count++;

  C64 *c64 = (C64 *)thisC64;
  c64->executeOneFrame();
dirkwhoffmann commented 4 years ago

yes the overreacting (core was overheating 😅) was fixed with the proposed reset logic ....

I was just reviewing the log... this means audio is stabilizing? No more buffer exceptions?

mithrendal commented 4 years ago

I was just reviewing the log... this means audio is stabilizing? No more buffer exceptions?

only at the start and when my oldest space ship is under heavy load (opening a file dialog 🙄)

I still spotted another little problem with the octopus in red wine , this demo demands a lot from my oldest battle ship (2007 macbookpro) ...

I see

// blue screen everything is fine 

time[ms]=1003.000000, audio samples=44032, frames [executed=50, skipped=9]
time[ms]=1001.000000, audio samples=44032, frames [executed=51, skipped=6]
time[ms]=1014.000000, audio samples=45056, frames [executed=50, skipped=11]
time[ms]=1003.000000, audio samples=44032, frames [executed=51, skipped=7]
time[ms]=1001.000000, audio samples=44032, frames [executed=50, skipped=3]

//now the octopus puts pressure ...

lost sync target=524.457875, total_executed=516
time[ms]=1000.000000, audio samples=44032, frames [executed=41, skipped=0]
lost sync target=41.002250, total_executed=33
time[ms]=1000.000000, audio samples=44032, frames [executed=41, skipped=1]
lost sync target=48.420750, total_executed=40
time[ms]=1019.000000, audio samples=45056, frames [executed=41, skipped=0]
lost sync target=44.310500, total_executed=36
time[ms]=1019.000000, audio samples=45056, frames [executed=41, skipped=1]
lost sync target=32.029875, total_executed=24
lost sync target=34.085000, total_executed=26
time[ms]=1016.000000, audio samples=44544, frames [executed=39, skipped=0]
lost sync target=43.508500, total_executed=35
time[ms]=1004.000000, audio samples=44544, frames [executed=41, skipped=1]
lost sync target=41.002250, total_executed=33
time[ms]=1015.000000, audio samples=44544, frames [executed=41, skipped=1]
lost sync target=47.568625, total_executed=39
Mouse left window 1
time[ms]=1006.000000, audio samples=44544, frames [executed=40, skipped=0]

the problem/question is ... why is it skipping under pressure ?

Sidenote: fort apocalypse or choplifter don't put much pressure at all on my oldest battle ship ...

dirkwhoffmann commented 4 years ago
if (total_executed_frame_count >= (unsigned long)round(targetFrameCount)) {
    skipped_frame_count++;
    return;
  }

  executed_frame_count++;
  total_executed_frame_count++;

  C64 *c64 = (C64 *)thisC64;
  c64->executeOneFrame();

There might be cases where more than one frame has to be executed. Your code can only skip frames, but it can never cope up if more than one frame is missing. Try to use the while-loop style and try the Octopus again.

Sidenote: fort apocalypse or choplifter don't put much pressure at all on my oldest battle ship ...

Octopus consumes a lot of computation effort, because everything is drawn with sprites and timing-accurate sprite emulation is a nightmare. What does the CPU load say?

mithrendal commented 4 years ago

Octopus consumes a lot of computation effort, because everything is drawn with sprites and timing-accurate sprite emulation is a nightmare. What does the CPU load say?

octopus CPU load is 89 😜

Try to use the while-loop style and try the Octopus again.

is not so good idea, because cooperative multitasking ... executed frame would not be drawn by SDL (what effectively is also a skip ... well an expansive skip)

I think we just have to make it not skip and then we are fine ... it has to do with the timer reset for sure ...

     //reset timer
      start_time=now;
      total_executed_frame_count=0;

maybe I should reset to total_executed_frame_count=-1 ?

dirkwhoffmann commented 4 years ago

is not so good idea, because cooperative multitasking ... executed frame would not be drawn by SDL (what effectively is also a skip ... well an expansive skip)

It's not about drawing frames (it's fine for us if SDL drops the frame). We need to ensure that the C64 keeps running at the right speed. Even if no frame is drawn, the C64 writes the necessary amount of sound samples into the ring buffer.

mithrendal commented 4 years ago

Ah I get your point ... under load your primary goal (first priority) is to keep the soundbuffer filled and you don't care about skipping the video under pressure...

will try the while-loop out this evening ...

But this is only minor ... as it really only affects very slow machines ... I do not see any problems on my newer machines ... On newer machines octopus constantly executes 50/51 frames and skips 10/9 frames... as it is supposed to in a perfect world...

Maybe we should just leave it as it is ? Because of the current simplicity of the code ?

What about the following priority list... 🤔 1.goal code simplicity 2.goal no sound sample drops 3.goal video drops ?

Or do you like 😄 ... 1.goal no sound sample drops 2.goal code simplicity 3.goal video drops more ?

dirkwhoffmann commented 4 years ago

Or do you like ...

🤔 OK, let's ask somebody smart:

Bildschirmfoto 2020-04-22 um 10 36 43

Hence this is the way to go 😃:

  1. goal no sound sample drops
  2. goal code simplicity

Using the while-Approach doesn't make it more complicated though. Just replace

  if (total_executed_frame_count >= (unsigned long)round(targetFrameCount)) {
    skipped_frame_count++;
    return;
  }

  executed_frame_count++;
  total_executed_frame_count++;

  C64 *c64 = (C64 *)thisC64;
  c64->executeOneFrame();

by

    C64 *c64 = (C64 *)thisC64;

    while (total_executed_frame_count < (unsigned long)round(targetFrameCount)) {
         c64->executeOneFrame();
         executed_frame_count++;
         total_executed_frame_count++;
    }

The skipped_frame_count is not needed, I think. You can further simplify it a bit by using a uint64_t for targetFrameCount. The additional accuracy of a double shouldn't be needed here.

mithrendal commented 4 years ago

cool thanks for the code will try it this evening ... SID first 😎🤘!!! I like SID sound 🤤....

but theoretical🤔 ... I mean what is the impact on game play ?

SCENARIO: me in my old space ship🐰 and enemy👹 launches hellfires

when I play under maximal CPU load pressure on my good old battle ship ... the first natural step would be to fire off some rockets on the enemy ... of course that teases the enemy and he will immediatly respond 👻with counter measures like hellfire rockets💥 ....

and then this happens ... max pressure on the video system of my battle ship(2007 ship) .... video system off (due to skips) ... failure ... failure... but sound still on (while loop)

yeah I can hear the detonation of the rockets .... I am dead ... because I did not see the current frames and had no information how to react ?

Hmm lets think 🙋🏻loud... for gameplay, priority 1 seems not to be the SID but the joystick ... because I must move out of the danger zone ... Ahh 🤗 this still works because I do the doExecute in the while loop ... cool second priority ... I have to move to a safer area ... but but ...I see nothing ... don't know whether to pull joystick up or down ... hmm

Maybe for the old ship from a gameplay perspective only ... it would be better to stop execution or to slow down execution (slow motion) so that I have a chance to move from the danger zone into a safer area in slow motion 🤔...

Conclusion: I see two approaches to handle max. system pressure on slow machines like the 2007 battle horse:

  1. sound quality ... I want to see and listen cool music demos and I hate crippled sound while-loop doExecute is the way to go

  2. gameplay first .... I want to enter the next level I don't care about sound skip doExecution on pressure which results in slow motion and sound gets crippled but I see every computed frame ... current implementation

Maybe an option from javascript ? wasm_handlePressureApproach("slomo"); or wasm_handlePressureApproach("soundquality");

🕺🏾we could put them in a dropdownlist so that the user can choose...

Like to know whether I am completely wrong on this... or if that makes sense

I tried it on modern machines... there the type of the approach is nearly irrelevant. But on a ... raspberry pie?😎

dirkwhoffmann commented 4 years ago

Maybe an option from javascript ? wasm_handlePressureApproach("slomo"); wasm_handlePressureApproach("soundquality");

I don't think we should go down this road, for the following reasons:

mithrendal commented 4 years ago

wow can not sell it to you ... and now these three strong reasons ... I think you convinced me ... I will follow your advice and drop that idea ...

but but .. look here https://www.youtube.com/watch?v=ERyVAL5mt7E they do the slomo thing too 🙆 it is still unconventional I see .... maybe too modern ... in the end nobody would appreciate it except me? ... well we can do it still later ... in three years it will be a hit ... for this evening I will implement the standard approach skipping frames in favour of sound and game speed with the while approach 🤗... Its just the pilot of the blue heli which plays sooo well, I bet he has never heard of frame drops... so with the slomo approach I wanted to give him some drops 😎 slomo is the way to let the reality of the computer pilot (the one who lives in the c64) run quicker than our physical world