Exceptions, timing and impact on threads

The following program starts a main thread and two worker threads. In the second worker thread every 10 seconds an exception is thrown.

The mechanism is used in a program where the first worker thread is reading from serial port and puts the data into a Queue that is shared with the main thread.
Main thread does some processing before it’s send to over network. The second worker process is used for all network communication.

Once in a while the serial input was missing characters, indicating the FEZ can’t keep up with the data that is received.
After optimizing some parts of the code all data is received completely.
Except in the situation when the network thread is excepting for some reason (internet gone, server offline, etc).
The reasons for the exception I cannot solve, so the exception will be thrown.
The data received at 9600 baud is a block between 20kB and 100kB, received without any flow control or resend mechanism. It’s far from ideal, but that’s the situation…

Using multiple threads I expected that the thread where the exception occurs will only suffer from the exception, but actually it has effect on all threads.
In the example below the “loop” times within the while loop are displayed for each thread.
When an exception occurs in W02, it will take about 500ms before it’s catched. And it will also increase the delay in the other two threads, sometimes with almost the same amount of time.
UsbToSerial (Prolific and FTDI) and UART are used to test if the serial thread could keep up, but on all methods received data is lost because it cannot keep up.

Questions

  • How is an exception handled in the framework? Does it overrule the different threads until the exception is handled?
  • Can the time for exception handling be reduced in some way? 500+ms is relative a lot of time.
  • And maybe the most important is there another way to decrease the “loop” time of the W01 thread, so no incoming data will be dropped.

Program code


using System;
using System.Threading;

using Microsoft.SPOT;
using Microsoft.SPOT.Hardware;

using GHIElectronics.NETMF.FEZ;

namespace MultithreadTest
{
    public class Program
    {
        private static int _threadSleepTime = 50;

        public static void Main()
        {
            while (true)
            {
                Thread _w01 = new Thread(Worker01);
                _w01.Start();
                Thread _w02 = new Thread(Worker02);
                _w02.Start();

                DateTime d0 = DateTime.Now;
                DateTime d1;

                while(true)
                {
                    d1 = DateTime.Now;
                    Debug.Print("M      " + ((d1 - d0).Ticks / TimeSpan.TicksPerMillisecond).ToString());
                    d0 = d1;
                    Thread.Sleep(_threadSleepTime);
                }
            }
        }

        public static void Worker01()
        {
            DateTime d0 = DateTime.Now;
            DateTime d1;
            while(true)
            {
                d1 = DateTime.Now;
                Debug.Print("W01    " + ((d1 - d0).Ticks / TimeSpan.TicksPerMillisecond).ToString());
                d0 = d1;
                Thread.Sleep(_threadSleepTime);
            }
        }

        public static void Worker02()
        {
            DateTime d0 = DateTime.Now;
            DateTime d1;
            DateTime dEx = DateTime.Now.AddMilliseconds(10000);
            DateTime dExThrown = new DateTime(0);
            DateTime dExCatched;
            while(true)
            {
                try
                {
                    d1 = DateTime.Now;
                    if (d1 > dEx)
                    {
                        dExThrown = DateTime.Now;
                        throw new Exception();
                    }
                    Debug.Print("W02    " + ((d1 - d0).Ticks / TimeSpan.TicksPerMillisecond).ToString());
                    d0 = d1;
                    Thread.Sleep(_threadSleepTime);
                }
                catch
                {
                    dExCatched = DateTime.Now;
                    Debug.Print("W02 EX " + ((dExCatched - dExThrown).Ticks / TimeSpan.TicksPerMillisecond).ToString());
                    dEx = DateTime.Now.AddMilliseconds(10000);
                }
            }
        }

    }
}

Output shows something like



M      52
W02    52
W01    52
M      52
W02    52
W01    52
M      52
W02    52
W01    52
...
M      52
GC: 3msec 12684 bytes used, 51696 bytes available
Type 0F (STRING              ):    108 bytes
Type 11 (CLASS               ):    696 bytes
Type 12 (VALUETYPE           ):     60 bytes
Type 13 (SZARRAY             ):    108 bytes
Type 15 (FREEBLOCK           ):  51696 bytes
Type 16 (CACHEDBLOCK         ):    132 bytes
Type 17 (ASSEMBLY            ):   7440 bytes
Type 18 (WEAKCLASS           ):     48 bytes
Type 19 (REFLECTION          ):     24 bytes
Type 1B (DELEGATE_HEAD       ):    144 bytes
Type 1D (OBJECT_TO_EVENT     ):    120 bytes
Type 1E (BINARY_BLOB_HEAD    ):    156 bytes
Type 1F (THREAD              ):   1152 bytes
Type 20 (SUBTHREAD           ):    144 bytes
Type 21 (STACK_FRAME         ):   1716 bytes
Type 27 (FINALIZER_HEAD      ):     24 bytes
Type 31 (IO_PORT             ):     36 bytes
Type 34 (APPDOMAIN_HEAD      ):     72 bytes
Type 36 (APPDOMAIN_ASSEMBLY  ):    504 bytes
W01    90
W02    52
M      92
W01    52
W02    95
...
M      52
W01    52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W01    156
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
W01    150
W01    149
W02 EX 455
W02    510
M      510
W01    52
W02    52

M      52
W01    52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W01    164
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
M      323
W01    153
M      149
W01    149
W02 EX 464
W02    519
M      52
W01    52
W02    52

M      52
W02    52
W01    52
M      52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
M      204
W01    210
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
M      150
W01    150
M      150
W01    150
W02 EX 462
W02    516

M      52
W01    52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
M      164
W01    163
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
M      150
W01    150
M      150
W01    150
W02 EX 463
W02    518

M      52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W01    161
M      161
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
W01    151
M      151
W01    148
M      148
W02 EX 460
W02    515
...
M      52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W01    204
M      163
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
W01    149
M      150
W01    150
M      150
W02 EX 463
W02    517
...
M      52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W01    157
M      157
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
W01    149
M      149
W01    150
M      150
W02 EX 457
W02    511
W01    52
...
M      52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
M      155
W01    205
A first chance exception of type 'System.Exception' occurred in FEZ Domino Application.exe
M      150
W01    150
M      150
W01    150
W02 EX 457
W02    511
M      52
W01    52
W02    52
...


@ pas2812
I don’t have an answer to your question, but your test and the results are very interesting.
I hope one of the smart people on this forum sees this thread and posts a reply.

Are you sure that 500ms delay is not caused by the fact that you have a debugger attached? I can imagine that, when an exception occurs, a stack frame or other info is transmitted to the debugger.

@ WouterH, thank you for pointing into the right direction.

When I deploy the program and attach the serial output to a serial port monitor (e.g. HyperTerminal) times are much better.


...
M      52
W01    52
W02    52
...
M      52
W01    52
W02    52
M      52
W01    52
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W02 EX 15
W02    71
M      53
W01    53
W02    53
...
M      53
W01    53
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W02 EX 15
W02    71
M      70
W01    52
M      52
W02    57
W01    53
M      53
W02    53
W01    53
...
M      53
W02    53
W01    53
M      53
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W02 EX 15
W02    71
W01    65
M      53
W01    52
W02    57
M      53
W01    53
W02    53
...
M      53
W01    53
    #### Exception System.Exception - 0x00000000 (4) ####
    #### Message: 
    #### MultithreadTest.Program::Worker02 [IP: 0031] ####
W02 EX 15
W02    71
M      53
W01    53
W02    53 

You’re welcome.