C# Performance Test

[spld]

Hi All,

We are facing performance issues using C# program and norrowed down to very simple program. Here is program and its output as well. Can you please have a look and explain me why there is periodic delay of 15 milliseconds?

Please run it on your system and see if you observe same delay ( may be some policy on my system causing it to sleep for 15 milliseconds). Appreciate your help.

Source Code:

// PInvokeTest.cs
using System;
using System.Runtime.InteropServices;
using System.Threading;
 
class PlatformInvokeTest
{
    static DateTime stdt;
 
    public static void dateandTime(string str)
    {
        DateTime dt = DateTime.Now;
        TimeSpan t = dt.Subtract(stdt);
        Console.WriteLine("difference from previous print : "+t.Milliseconds.ToString("000"));
 
        stdt = dt;
        if (str != null)
        {
            Console.WriteLine(str + dt.Hour + ":" + dt.Minute + ":" + dt.Second + ":" + dt.Millisecond.ToString("000"));
        }
        else
        {
            Console.WriteLine(dt.Hour + ":" + dt.Minute + ":" + dt.Second + ":" + dt.Millisecond.ToString("000"));
        }
    }
    public static void abc(string str1)
    {
        if(str1 !=null)
        {
 
        }
    }
 
    public static void Main() 
    {
 
        stdt = DateTime.Now;
 
        int i = 0;
        while (i < 100)
        {
             dateandTime("Before ");
            //abc("abc");
             dateandTime("After ");
 
            i++;
        }
    }
}

Output with 100:

difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
Before 14:0:21:359
difference from previous print : 000
After 14:0:21:359
difference from previous print : 000
 Before 14:0:21:359
difference from previous print : 015
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375
difference from previous print : 000
Before 14:0:21:375
difference from previous print : 000
After 14:0:21:375

[vekipeki]

If your thread has a normal priority, then it is normal that it gets interrupted by the OS every now and then to give other threads some processor time. You can give your thread a higher priority to make those interruptions less frequent, but I believe .Net CLR is not exactly intended for real-time applications.

For example, since String is immutable in C#, and every string addition in C# creates a new String instance, you can see that your "dateandTime" method allocates 14 new strings on every call (if I didn't count it wrong) - one new string for each .ToString(), and one new string for each addition. This means that GC will have to kick in sooner or later to clean up that stuff.

Calling Console.WriteLine also takes some time. You can try creating a static StringBuilder object and append all your strings to it using Append and AppendLine (without any "+" operators), and then write the resulting string to the Console at the end - it would certainly improve performance and decrease the number of unnecessary allocations.

What is the actual problem you would like to solve, that would need 100% of your processor time?

[spld]

Hi Vekipeki,

Application intend to send replies to a communication driver at least 1000 times per second. Communication driver is in C++. In the original code delay of 15 milliseconds is experienced every 7th or 8th call from C# to C++. Data transfer is 248 bytes. Time delay is constant and it is 015 milliseconds. Which is very high for any application to loose ( real , non-real time).