System.OutOfMemoryException - runs fine on Hydra, blows up on Cerberus after one and half cycles of "blue"

stevepresley · August 5, 2012, 11:45pm


A first chance exception of type 'System.OutOfMemoryException' occurred in mscorlib.dll
An unhandled exception of type 'System.OutOfMemoryException' occurred in mscorlib.dll

This is the code I’m using for the Mood Cube project I just put up:


using System;
using GT = Gadgeteer;

namespace MoodLight
{
    public partial class Program
    {

        int i = 0;
        int direction = 1;
        int color = 0;
        // This method is run when the mainboard is powered up or reset.   
        void ProgramStarted()
        {
            multicolorLed.GreenBlueSwapped = true;
            GT.Timer timer = new GT.Timer(5);

            timer.Tick += new GT.Timer.TickEventHandler(timer_Tick);
            timer.Start();
        }

        void timer_Tick(GT.Timer timer)
        {
            // Debug.Print("i: " + i);

            switch (color)
            {
                case 0:
                    multicolorLed.SetBlueIntensity(i);
                    break;
                case 1:
                    multicolorLed.SetGreenIntensity(i);
                    break;
                case 2:
                    multicolorLed.SetRedIntensity(i);
                    break;
            }

            if (i >= 255)
            {
                direction = -5;
            }
            else if (i <= 0)
            {
                direction = 5;
                if (color == 2)
                    color = 0;
                else
                    color += 1;

            }

            i += direction;

        }
    }
}

Any ideas? I’m not doing anything crazy here.

Thanks!
-Steve

Architect · August 6, 2012, 2:35am

Make timer a class member not just a local variable inside ProgramStarted. Doesn’t seem related to that particular exception, but still a right thing to do.

Gralin · August 6, 2012, 2:54am

Will it run without exceptions if you increase the timeout in timer ?

stevepresley · August 6, 2012, 10:17am

It shouldn’t but that’s a good practice. I’ll make that switch tonight.

No, even upping it the timer tick to 500, it still times out in roughly the same spot.

Also, I let the Hydra keep running over night and it eventually locked up as well, although I don’t know at what point. It was within 6 hours though, as I went to bed at 1am and went in the computer room around 7 to find it locked. Will see if moving the timer out of the program start makes a difference and report back.

Thanks for the input!

Gralin · August 6, 2012, 10:39am

Also add this to every iteration

Debug.Print(Debug.GC(true).ToString());

Architect · August 6, 2012, 10:42am

Or every 100th iteration.

Gralin · August 6, 2012, 10:44am

True, so that you get e.g. 1 print each second.

stevepresley · August 6, 2012, 11:08am

I was printing out i on every tick, and it didn’t seem to matter whether debug.print was enabled or not, it still blew up around the same point - thought that may have had something to do with it, but doesn’t look like it.

I will add the GC status and see where that gets us.

Thanks for the suggestions - anything else you can think of, let me know. Think this would make a good intro project, so want it to work without blowing up

stevepresley · August 6, 2012, 11:11am

Every 1000 would be 1 sec, 100 would be every 10th of a second… I’ll try it both ways to narrow it down.

Bec_a_Fuel · August 6, 2012, 11:23am

Did you try commenting out the “multicolorLed.SetXXXXIntensity(i);” lines ?

What I mean here is that maybe your code is not faulty but instead there could be a flaw somewhere else.

stevepresley · August 6, 2012, 11:29am

No, that’s a good point that I was I suppose driving to - I don’t know that the code is at fault, it could be something in the BETA release as well.

I figured by optimizing the code first, we could then narrow it down.

Will definitely see if that makes a different. I’ve got 4 Cerbs to try different variations on in addition to a Hydra and Spider, so hopefully we can figure it out.

stevepresley · August 6, 2012, 10:54pm

Got the hydra to blow up.

All data is here: http://stevepresley.net/Media/Default/models/debug.txt

Last couple of GC’s are here.


GC: 133msec 5046348 bytes used, 1244784 bytes available
Type 0F (STRING              ):   1464 bytes
Type 11 (CLASS               ): 3081756 bytes
Type 12 (VALUETYPE           ):   1500 bytes
Type 13 (SZARRAY             ): 397428 bytes
  Type 03 (U1                  ):    156 bytes
  Type 04 (CHAR                ):    780 bytes
  Type 07 (I4                  ):   1044 bytes
  Type 0F (STRING              ):     60 bytes
  Type 11 (CLASS               ): 395304 bytes
  Type 12 (VALUETYPE           ):     84 bytes
Type 15 (FREEBLOCK           ): 1244784 bytes
Type 17 (ASSEMBLY            ):  30276 bytes
Type 18 (WEAKCLASS           ):     96 bytes
Type 19 (REFLECTION          ):    168 bytes
Type 1B (DELEGATE_HEAD       ): 1151532 bytes
Type 1D (OBJECT_TO_EVENT     ):    312 bytes
Type 1E (BINARY_BLOB_HEAD    ): 373704 bytes
Type 1F (THREAD              ):   1536 bytes
Type 20 (SUBTHREAD           ):    144 bytes
Type 21 (STACK_FRAME         ):   2052 bytes
Type 22 (TIMER_HEAD          ):    144 bytes
Type 27 (FINALIZER_HEAD      ):    120 bytes
Type 31 (IO_PORT             ):    180 bytes
Type 34 (APPDOMAIN_HEAD      ):     72 bytes
Type 36 (APPDOMAIN_ASSEMBLY  ):   3864 bytes
GC: performing heap compaction...
1244784
GC: 135msec 5113668 bytes used, 1177464 bytes available
Type 0F (STRING              ):   1464 bytes
Type 11 (CLASS               ): 3130716 bytes
Type 12 (VALUETYPE           ):   1500 bytes
Type 13 (SZARRAY             ): 397428 bytes
  Type 03 (U1                  ):    156 bytes
  Type 04 (CHAR                ):    780 bytes
  Type 07 (I4                  ):   1044 bytes
  Type 0F (STRING              ):     60 bytes
  Type 11 (CLASS               ): 395304 bytes
  Type 12 (VALUETYPE           ):     84 bytes
Type 15 (FREEBLOCK           ): 1177464 bytes
Type 17 (ASSEMBLY            ):  30276 bytes
Type 18 (WEAKCLASS           ):     96 bytes
Type 19 (REFLECTION          ):    168 bytes
Type 1B (DELEGATE_HEAD       ): 1169892 bytes
Type 1D (OBJECT_TO_EVENT     ):    312 bytes
Type 1E (BINARY_BLOB_HEAD    ): 373704 bytes
Type 1F (THREAD              ):   1536 bytes
Type 20 (SUBTHREAD           ):    144 bytes
Type 21 (STACK_FRAME         ):   2052 bytes
Type 22 (TIMER_HEAD          ):    144 bytes
Type 27 (FINALIZER_HEAD      ):    120 bytes
Type 31 (IO_PORT             ):    180 bytes
Type 34 (APPDOMAIN_HEAD      ):     72 bytes
Type 36 (APPDOMAIN_ASSEMBLY  ):   3864 bytes
GC: performing heap compaction...
1177464
    #### Exception System.OutOfMemoryException - CLR_E_OUT_OF_MEMORY (5) ####
    #### Message: 
    #### System.Collections.Queue::Enqueue [IP: 0000] ####
    #### Microsoft.SPOT.Dispatcher::BeginInvoke [IP: 001e] ####
    #### Microsoft.SPOT.DispatcherTimer::Callback [IP: 0010] ####
A first chance exception of type 'System.OutOfMemoryException' occurred in mscorlib.dll
An unhandled exception of type 'System.OutOfMemoryException' occurred in mscorlib.dll

Test code:


using System;
using Microsoft.SPOT;
using GT = Gadgeteer;

namespace TimerMemoryLeakTest
{
    public partial class Program
    {

        int i = 0;
        int direction = 1;
        
        void ProgramStarted()
        {
            GT.Timer timer = new GT.Timer(5);
            timer.Tick += new GT.Timer.TickEventHandler(timer_Tick);
            timer.Start();
        }

        void timer_Tick(GT.Timer timer)
        {
            multicolorLed.SetBlueIntensity(i);

            if (i >= 255)
            {
                direction = -1;

            }
            else if (i <= 0)
            {
                Debug.Print(Debug.GC(true).ToString());

                direction = 1;         
            }

            i += direction;

        }
    }
}

Mike · August 6, 2012, 11:05pm

You are getting 200 interrupts per second queued. If it takes more than 5ms to execute the

multicolorLed.SetBlueIntensity(i);

statement you will overflow memory.

If GC happens, which is taking 133ms, you will fall way behind.

The Debug Print will also delay things. It is slow.

stevepresley · August 6, 2012, 11:15pm

Mike:

You are getting 200 interrupts per second queued. If it takes more than 5ms to execute the
multicolorLed.SetBlueIntensity(i);
statement you will overflow memory.

If GC happens, which is taking 133ms, you will fall way behind.

The Debug Print will also delay things. It is slow.

so what is the recommended timer tick to set a single LED value? 100 or higher than that?

Brett · August 6, 2012, 11:52pm

They say eyes believe that a LED is lit solid if it’s flashing on/off at 50hz.

If you’re just doing this for jollies and wanting to cycle up and down, then you should do the “double-down” rule and try 10 or 20 as a step-point, but I think you can safely assume that changing intensity in 1-step increments will not be noticeable to the eye and you need to think about this as potentially a larger step change, less often, depending on how fast you want the change to go from off to on and back again.

Gralin · August 7, 2012, 2:40am

Mike:

You are getting 200 interrupts per second queued. If it takes more than 5ms to execute the
multicolorLed.SetBlueIntensity(i);
statement you will overflow memory.

If GC happens, which is taking 133ms, you will fall way behind.

The Debug Print will also delay things. It is slow.

I have suggestied earlier that he increases the timeout but this is what @ stevepresley wrote:

stevepresley · August 7, 2012, 11:45am

The actual code was using a counter of 5 or 10 to fade the color up to max intensity and then back down to zero before switching to the next. I switched it to 1 as the increment both for illustration purposes as well as to try and make it blow up “sooner” for debugging purposes.

Gralin:

Mike:
You are getting 200 interrupts per second queued. If it takes more than 5ms to execute the
multicolorLed.SetBlueIntensity(i);
statement you will overflow memory.

If GC happens, which is taking 133ms, you will fall way behind.

The Debug Print will also delay things. It is slow.
I have suggestied earlier that he increases the timeout but this is what @ stevepresley wrote:

No, even upping it the timer tick to 500, it still times out in roughly the same spot.

So a combination of moving the GT.Timer declaration out of the ProgramStarted thread and upping the Timer’s tick milliseconds to 50+ seem to be the trick, at least on the Hydra. It does run longer, but still ends up blowing up with the GT.Timer declaration in ProgramStarted.

This combination ran all night long (and is actually still running at the house) and here is the new GC collect status:


GC: 2msec 433080 bytes used, 5858052 bytes available
Type 0F (STRING              ):   1464 bytes
Type 11 (CLASS               ):  12552 bytes
Type 12 (VALUETYPE           ):   1500 bytes
Type 13 (SZARRAY             ):   4260 bytes
  Type 03 (U1                  ):    156 bytes
  Type 04 (CHAR                ):    780 bytes
  Type 07 (I4                  ):   1044 bytes
  Type 0F (STRING              ):     60 bytes
  Type 11 (CLASS               ):   2136 bytes
  Type 12 (VALUETYPE           ):     84 bytes
Type 15 (FREEBLOCK           ): 5858052 bytes
Type 17 (ASSEMBLY            ):  30276 bytes
Type 18 (WEAKCLASS           ):     96 bytes
Type 19 (REFLECTION          ):    168 bytes
Type 1B (DELEGATE_HEAD       ):    576 bytes
Type 1D (OBJECT_TO_EVENT     ):    312 bytes
Type 1E (BINARY_BLOB_HEAD    ): 373764 bytes
Type 1F (THREAD              ):   1536 bytes
Type 20 (SUBTHREAD           ):    144 bytes
Type 21 (STACK_FRAME         ):   2052 bytes
Type 22 (TIMER_HEAD          ):    144 bytes
Type 27 (FINALIZER_HEAD      ):    120 bytes
Type 31 (IO_PORT             ):    180 bytes
Type 34 (APPDOMAIN_HEAD      ):     72 bytes
Type 36 (APPDOMAIN_ASSEMBLY  ):   3864 bytes
GC: performing heap compaction...
5858052

It’s been hovering here since the first or second GC, which went down, but then came back up after the ProgramStarted thread exited and got cleaned up by the GC.

I’m going to try it tonight on the Cerberus and see if it has similar performance.

I also realize the MultiColorLED can use the on-board processor to do the fade in and out on its own, but wanted to make sure for demo code to teach the basics of how to fade in/out a LED that doesn’t have an on-board chip, that the code was accurate.

Appreciate everyone’s input so far.

“Good” code:



using System;
using Microsoft.SPOT;
using GT = Gadgeteer;

namespace TimerMemoryLeakTest
{
    public partial class Program
    {

        int i = 0;
        int direction = 1;
         GT.Timer timer = new GT.Timer(50);

        void ProgramStarted()
        {
            multicolorLed.GreenBlueSwapped = true;
            timer.Tick += new GT.Timer.TickEventHandler(timer_Tick);
            timer.Start();
        }

        void timer_Tick(GT.Timer timer)
        {            

            if (i >= 255)
            {
                direction = -5;

            }
            else if (i <= 0)
            {
                Debug.Print(Debug.GC(true).ToString());

                direction = 5;         
            }

            i += direction;

            multicolorLed.SetBlueIntensity(i);

        }
    }
}

Mike · August 7, 2012, 11:56am

I am not clear on whether it is working or not?

I would also remove the Debug.Print and Debug.GC calls. Let GC happen naturally.

It is also important to know how long it is taking to execute the multicolorLed.SetBlueIntensity(i); statement.

stevepresley · August 7, 2012, 12:05pm

Yep, it is. We added those to see when (and how long) the GCs were taking.

It’s stable now on the Hydra, want to see if I need to go to a higher tick value on the Cerb since it has less memory.

Mike · August 7, 2012, 12:31pm

The timer interval value should not be a function of the processor memory but rather the processor speed.

If properly set, the event queue does not grow, and the size of the memory is not a factor.