TriggerFx sometimes gets stuck on a note

Topics related to the API, programming discussions & questions, coding tips, bugs, etc. should go here.
User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Mon Aug 03, 2015 10:02 pm

Hmmm, very interesting...indeed I don't know why I have a more permissive top-level condition with

Code: Select all

if(... && track->patchCurrDeltaTime>=track->patchNextDeltaTime){	
then not covering cases where patchCurrDeltaTime > patchNextDeltaTime. So your fix is good and covers all cases. I still can't figure out why patchCurrDeltaTime can become greater patchNextDeltaTime. Perhaps if there's some reentrancy or something due to the next frame processing interrupting the current frame's. That's easy to test though by putting an interrupt level flag. I can check that.

User avatar
Artcfox
Posts: 1060
Joined: Thu Jun 04, 2015 5:35 pm
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by Artcfox » Mon Aug 03, 2015 11:40 pm

So a further test with the following modifications to the sound engine:

Code: Select all

diff --git a/kernel/uzeboxSoundEngine.c b/kernel/uzeboxSoundEngine.c
index 380c723..6913e5d 100644
--- a/kernel/uzeboxSoundEngine.c
+++ b/kernel/uzeboxSoundEngine.c
@@ -774,11 +774,10 @@ void ProcessMusic(void){
                //process patch command stream
                if((track->flags & TRACK_FLAGS_HOLD_ENV)==0){   //patchEnvelopeHold==false
 
-                       if(track->patchCommandStreamPos!=NULL && 
-                               track->patchCurrDeltaTime>=track->patchNextDeltaTime){                  
+                       if(track->patchCommandStreamPos!=NULL){                 
 
                                //process all simultaneous events
-                               while(track->patchCurrDeltaTime==track->patchNextDeltaTime){    
+                               while(track->patchCurrDeltaTime>=track->patchNextDeltaTime){    
                                        
                                        c1=pgm_read_byte(track->patchCommandStreamPos++);
                                        if(c1==0xff){                                   
eventually resulted in a stuck note :( but I do have a .hex and .cap file that can reproduce it. Unfortunately it takes a long time for the stuck note to occur. The trigger seems to be if I keep hitting start to reload the levels, which in my current build doesn't have any extra calls to WaitVsync(1), so doing that causes a lot of vsync misses while it decodes the level. If I have my "stack highwater" debug display enabled, then I can tell when it misses vsync, because I can see extra RAM getting used (I'm guessing to push the registers to stack?)

I then made a build that prints all of the tracks[1] and tracks[2] debugging info, and started making another capture. The sounds got a tiny bit glitchy (I could hear some notes being held for slightly longer than they should be held), which made me think that I would soon see another stuck note, but instead uzem crashed with the message:
invalid insn 9188
which makes me think that there is definitely another bug lurking somewhere in the sound code. Surprisingly, I also got a valid capture file from that run, which when played back will reliably crash uzem. The plot thickens…

User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Tue Aug 04, 2015 6:22 am

Debugging in the dark drove me crazy so it reminded me uzem can output data if you do some OUT at specific unused ports. Just add the following to kernel.h:

Code: Select all

	#define UZEMCHR _SFR_IO8(26) //uzem whisper port for outputting characters to the console
	#define UZEMHEX _SFR_IO8(25) //uzem whisper port for outputting hex bytes values to the console

Then you can sprinkle debugging info to the console window with something like this (we need string functions!):

Code: Select all

UZEMCHR='2';
UZEMCHR='.';
UZEMHEX=(vsync_counter>>8);
UZEMHEX=(vsync_counter&0xff);
UZEMCHR=',';
UZEMHEX=triggerCount;
UZEMCHR=',';
UZEMHEX=trackNo;
UZEMCHR=',';
UZEMHEX=track->fxPatchNo;
UZEMCHR=',';
UZEMHEX=track->flags;
UZEMCHR=',';
UZEMHEX=(track->patchCurrDeltaTime);
UZEMCHR=',';
UZEMHEX=(track->patchNextDeltaTime);
UZEMCHR='\n';
The following is an output of debugging code put all over. The lines beginning with 1. are in TriggerFX. Lines 2.are in note cut command, 3.are the errors giving sound glitches where you put the tentative fix.

Code: Select all

2.0a1e,48,02,00,10,01,01
1.0a3b,49,01,03,b0,00,00-01,00,00
2.0a40,49,01,03,10,01,01
1.0a41,4a,01,03,b0,00,00-01,00,00
2.0a44,4a,01,00,10,01,01
1.0a72,4b,01,00,b0,00,00-01,00,00
2.0a77,4b,01,03,10,01,01
1.0a8b,4c,01,03,b0,00,00-01,00,00
2.0a90,4c,01,02,10,01,01
1.0ab5,4d,01,02,b0,@0ab6@01,00-01,01,00
3.0ab7,4d,01,00,b0,01,00*
3.0ab8,4d,01,00,b0,02,00*
3.0ab9,4d,01,00,b0,03,00*
In the dump, the statement with @xx@ means an VSYNC interrupt occured precisely during the TriggerFx, in the middle of the setup. It's late and I'm tired but it seems the interrupt started playing the patch that had incomplete setup resulting in undefined behavior. The only way I can see to fix this is to set the patch starting flag as the very the very last assignment. Did that and it seems to have resolved the issue. Attached is the hex with debugging info and your cap file. No more sound glitches....so far! :) I'll do more checks in the code to find other places where this could happen and commit the code.

So the fix is really to have:

Code: Select all

	track->flags|=TRACK_FLAGS_PLAYING;
at the end of TriggerCommon() and

Code: Select all

	// Process patches command streams & final volume
	//	
	for(unsigned char trackNo=0;trackNo<CHANNELS;trackNo++){
		track=&tracks[trackNo];

		//process patch command stream
		if(track->flags & TRACK_FLAGS_PLAYING && (track->flags & TRACK_FLAGS_HOLD_ENV)==0){	//patchEnvelopeHold==false


			if(track->patchCommandStreamPos!=NULL && 
				track->patchCurrDeltaTime==track->patchNextDeltaTime){	
I still don't know why not more peoples had this issue before. It was a bug just waiting to happen.
Attachments
physics-fix.zip
(31.36 KiB) Downloaded 131 times

User avatar
Artcfox
Posts: 1060
Joined: Thu Jun 04, 2015 5:35 pm
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by Artcfox » Tue Aug 04, 2015 8:58 am

That's brilliant! :D

I really like that debugging info PORT trick! It's like having a built in logic analyzer, and the way it so clearly shows the problem with the vsync is perfect.

Thank you so much for taking the time to help me debug this!

Also, this new 60fps uzem that can capture and replay the buttons is extremely useful for performing deterministic A/B testing.

Just so I'm 100% clear on the fixes, here is a diff of what my uzeboxSoundEngine.c looks like now:

Code: Select all

diff --git a/kernel/uzeboxSoundEngine.c b/kernel/uzeboxSoundEngine.c
index 380c723..6f4f89b 100644
--- a/kernel/uzeboxSoundEngine.c
+++ b/kernel/uzeboxSoundEngine.c
@@ -772,13 +772,12 @@ void ProcessMusic(void){
                track=&tracks[trackNo];
 
                //process patch command stream
-               if((track->flags & TRACK_FLAGS_HOLD_ENV)==0){   //patchEnvelopeHold==false
+               if(track->flags & TRACK_FLAGS_PLAYING && (track->flags & TRACK_FLAGS_HOLD_ENV)==0){     //patchEnvelopeHold==false
 
-                       if(track->patchCommandStreamPos!=NULL && 
-                               track->patchCurrDeltaTime>=track->patchNextDeltaTime){                  
+                       if(track->patchCommandStreamPos!=NULL){                 
 
                                //process all simultaneous events
-                               while(track->patchCurrDeltaTime==track->patchNextDeltaTime){    
+                               while(track->patchCurrDeltaTime>=track->patchNextDeltaTime){    
                                        
                                        c1=pgm_read_byte(track->patchCommandStreamPos++);
                                        if(c1==0xff){                                   
@@ -897,7 +896,6 @@ void TriggerCommon(u8 channel,u8 patch,u8 volume,u8 note){
        track->envelopeVol=0xff; 
        track->noteVol=volume;
        track->patchPlayingTime=0;
-       track->flags|=TRACK_FLAGS_PLAYING;
        track->flags&=(~(TRACK_FLAGS_HOLD_ENV|TRACK_FLAGS_SLIDING));
        track->tremoloLevel=0;
        track->tremoloPos=0;
@@ -979,6 +977,9 @@ void TriggerCommon(u8 channel,u8 patch,u8 volume,u8 note){
                track->patchCommandStreamPos=pos;
        }
 
+       //this memory barrier prevents the optimizing compiler from reordering the last statement in this function
+        __asm__ volatile ("" ::: "memory");
+       track->flags|=TRACK_FLAGS_PLAYING;
 }

Since the compiler is free to reorder things that have no dependencies on each other as it chooses, I added a memory barrier to ensure that the

Code: Select all

track->flags|=TRACK_FLAGS_PLAYING;
line can not be reordered to before the track variable is fully initialized. The generated assembly may look fine without it now, but a future version of the compiler may perform more aggressive optimizations, and the memory barrier guarantees us the required ordering.

I've been testing my latest build with this fix for quite some time now, and so far, so good!

User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Tue Aug 04, 2015 3:35 pm

The memory barriers are interesting, didn't know about those. Though I read this article and it may not guarantee we won't have problems:
http://www.atmel.com/webdoc/AVRLibcRefe ... order.html

The real fix is probably to push the flag set at the end of the TriggerFx()/TriggerNote() functions. To be checked.

User avatar
Artcfox
Posts: 1060
Joined: Thu Jun 04, 2015 5:35 pm
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by Artcfox » Tue Aug 04, 2015 6:18 pm

uze6666 wrote:The memory barriers are interesting, didn't know about those. Though I read this article and it may not guarantee we won't have problems:
http://www.atmel.com/webdoc/AVRLibcRefe ... order.html

The real fix is probably to push the flag set at the end of the caller function. To be checked.
Oh right, I forgot that when I've used memory barriers in the past that the variable I was protecting against reordering was volatile.

Another option, since the spec for C (prior to C11) is unclear on whether code reordering can happen across function boundaries, would be to set that flag from a piece of ASM.

What about the voice stealing algorithm? If both tracks are already playing an effect, and it has to steal one of the tracks, is it possible that the TRACK_FLAGS_PLAYING flag be can still be set (leftover from the track that got stolen) before the new track data has been written? Put another way, when the voice stealing algorithm determines that it needs to steal a track, does it explicitly clear the TRACK_FLAGS_PLAYING flag before it starts monkeying with the other track variables, and then only set it at the very end?

User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Tue Aug 04, 2015 7:20 pm

Yeah both those functions needs to be be checked carefully for race conditions, don't want to have to come back to that again down the road.

User avatar
Artcfox
Posts: 1060
Joined: Thu Jun 04, 2015 5:35 pm
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by Artcfox » Tue Aug 04, 2015 7:30 pm

It doesn't look like TriggerFx clears that flag before it steals a track, so I think we'll need to add:

Code: Select all

tracks[channel].flags&=(~TRACK_FLAGS_PLAYING);
right before the call to TriggerCommon.

User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Tue Aug 04, 2015 8:35 pm

Artcfox wrote:It doesn't look like TriggerFx clears that flag before it steals a track, so I think we'll need to add:

Code: Select all

tracks[channel].flags&=(~TRACK_FLAGS_PLAYING);
right before the call to TriggerCommon.
Good catch, I'll add this too. Same for TriggerNote().

User avatar
uze6666
Site Admin
Posts: 4488
Joined: Tue Aug 12, 2008 9:13 pm
Location: Montreal, Canada
Contact:

Re: TriggerFx sometimes gets stuck on a note

Post by uze6666 » Wed Aug 05, 2015 4:52 pm

I've done the fix and while at it some refactoring, optimizations and cleanup. Though it seems I introduced a regression regarding the PCM channel some time ago. I will fix it before I commit everything back.

One other thing I noticed is the code generated in TriggerFx,TriggerCommon is far from efficient specially when there is pgm_read_byte macros. For some reasons the compiler will not use LPM with displacement to efficiently address structrure members. Well, on my version of GCC at least. If will test on 4.9.2. If I still get the same, I may just rewrite those function is assembler. Since they are called a lot of calls to those functions, that could add up to a lot of cpu savings, specially when music is playing. And it will assure the compiler wont reorganize things.

Post Reply

Who is online

Users browsing this forum: No registered users and 4 guests