[En-Nut-Discussion] How to measure CPU consumption of Threads

[Ernst Stippl]

Hi All!

Sorry for the long message, but it is an interesting (and, just for now)
strange phenomenom:

I tried to find out how much "cpu load" a certain application was generating
for an Ethernut3
under 4.2.1, so I added a (so I thought) simple busy-time measurement
interface 
to the idle-thread in nutinit.c

The idea is to record the time (in form of "ticks") just before and after
the idle thread
does its NutThreadYield call. The time (i.e. difference of ticks "after"
minus "before") spent 
"somewhere else" should be a measure of how busy the app threads keep the
system.

First I added the interface to an app which, when idle, hangs on multiple
NutTcpAccept 
on TCP and HTTP ports. I started it and much to my suprise, it showed 83%
busy.
This was something I did not expect at all.

To verify the result, I added the "measurement code" to the "uart.c" example
app
and ran it with no, 10ms, 100ms, and finally 1000ms delay (after the fprintf
statement)
and it always shows 76 % busy.

Hmm.

I have attached the changes I made to nutinit.c and uart.c and the console
logs for the 
four tests. My expectation would have been 1 digit busy rates on a system
waiting for 
NutTcpAccept to happen, because this is a blocking function.
And as long as these threads wait, they are not ready to run, so the idle
thread gets 
the lion's share of the CPU.

Maybe the granularity of a 1ms tick is not good enough?
But then, on a 1000ms delay in the uart.c example, the granularity should
not play 
a big role.

Any thoughts?

regards
ernst

=================================
changes to nutinit.c:
added before the definition of "THREAD(NutIdle, arg)" 

u_long NutBusyTicks;             //ES the time spent outside the Idle Thread
u_long NutStartTickCount;        //ES total time elapsed since counting was
started
 
u_long NutGetBusyRate (void)     //ES function added
{
return (NutBusyTicks * 100L) / (NutGetTickCount() - NutStartTickCount);
}

u_long NutGetBusyCount (void)    //ES funcion added
{
return NutBusyTicks;
}

u_long NutGetElapsedCount (void) //ES function added
{
return NutGetTickCount() - NutStartTickCount;
}

void NutStartBusyCount (void)    //ES functtion added
{
NutBusyTicks      = 0L;
NutStartTickCount = NutGetTickCount();
}

changes to "THREAD(NutIdle, arg)" :

u_long NutThreadResumeTicks;          // es added

    NutThreadSetPriority(254);        // unchanged
    NutStartBusyCount ();             // ES added
	
    for (;;) {                                                    //
unchanged
	NutThreadResumeTicks = NutGetTickCount();                 //ES added
        NutThreadYield();                                         //
unchanged
	NutBusyTicks += NutGetTickCount() - NutThreadResumeTicks; //ES added
        NutThreadDestroy();                                       //
unchanged
    }

====================================
changes to uart.c

#include <arch/arm/cpubusy.h>      // added to other includes

u_long delaytime = 1000L;          // added to var def's in "main"

NutStartBusyCount ();              // 1st statement in "main"

        if (inbuf[0]) {            // where the input is echoed:
            fprintf(uart, "\nHello %s!\n", inbuf);
	    fprintf (uart, "Delay: %ld\n", delaytime);
            fprintf (uart, "CPU Busy: %ld\n"   , NutGetBusyCount ());
            fprintf (uart, "CPU Elapsed: %ld\n", NutGetElapsedCount ());
            fprintf (uart, "Busy Rate: %ld\n"  , NutGetBusyRate ());
	    NutSleep (delaytime);
	    }


remark: I added the printing of the "delaytime" variable just for the 1000ms
version.

====================================
 console log @ 10ms delay

Nut/OS UART Sample
Press any key...
Enter your name:
Hello ernst!
CPU Busy: 7019
CPU Elapsed: 9129
Busy Rate: 76

Enter your name:
Hello a!
CPU Busy: 11735
CPU Elapsed: 15260
Busy Rate: 76

Enter your name:
Hello stranger!

Enter your name:
Hello b!
CPU Busy: 15884
CPU Elapsed: 20661
Busy Rate: 76

Enter your name:
Hello c!
CPU Busy: 19218
CPU Elapsed: 24999
Busy Rate: 76

Enter your name:

====================================
 console log @ 100ms delay


Nut/OS UART Sample
Press any key...

Enter your name:
Hello ernst!
CPU Busy: 3401
CPU Elapsed: 4427
Busy Rate: 76

Enter your name:
Hello a!
CPU Busy: 5889
CPU Elapsed: 7663
Busy Rate: 76

Enter your name:
Hello stranger!

Enter your name:
Hello b!
CPU Busy: 9738
CPU Elapsed: 12673
Busy Rate: 76

Enter your name:


====================================
 console log @ 1000ms delay


Nut/OS UART Sample
Press any key...

Enter your name:
Hello ernst!
Delay: 1000
CPU Busy: 3783
CPU Elapsed: 4928
Busy Rate: 76

Enter your name:
Hello a!
Delay: 1000
CPU Busy: 7611
CPU Elapsed: 9907
Busy Rate: 76

Enter your name:
Hello stranger!

Enter your name:
Hello b!
Delay: 1000
CPU Busy: 12485
CPU Elapsed: 16249
Busy Rate: 76

Enter your name:

====================================