NXC Profiler

Back to projects index

Project Title Author / Institution
NXC Profiler (Weblink) Linus Atorf (Toolbox Developer Member), Germany
(!) This particular page is not directly affiliated with the RWTH - Mindstorms NXT Toolbox

NXC Profiler

On this page I present a preview / proof-of-concept of a profiler-like tool for NXC. Fore more details and concepts, see here:  http://forums.nxtasy.org/index.php?showtopic=4496

Sourcecode for all of this can be found here.

  • Profiler01.nxc is the NXC part of the demo, it has to be included by the application to be profiled.
  • sample.nxc and sample2 .nxc are example applications with profiler-code included.
  • After running the profiled program, the results file has to be manually retrieved from the NXT and copied into the directory of the analyzer.
  • AnalyzeNXCProfile.py is the main program of the analyzer (written in Python).
  • testit.bat will generate a HTML version of the sample files in that directory (same with testit2.bat).

Below you can see two example outputs from the current version (December 12th, 2009). You can distinguish profiled sections from non-profiled ones. At the bottom there is a secion with code that never ran (I tricked the Analyzer by faking some lines inside a block-comment which is not yet supported). The "time" column shows calls that took at least 1ms added up (that's why it's only a lower boundary for execution time). If there were calls where the firmware didn't tick (i.e. calls that definitely took less than 1ms), it's indicated here as percentage.

The 3rd column shows time per call. Again, it's a lower boundary. The bigger this time, the more accurate it should be. If the profiler should've encountered sections which took less than 1ms to execute, but not all the times, it's shown here with frequencies in percent.

Look below for 2 examples. The first one is a real-world case. As you can see, the Ultrasonic sensor never found a target in my sample run — that's valuable debug information. The 2nd example is from my old benchmark and much more artificial — but without looking at the LCD screen, you can see that "shifting" operations are quite expensive, for example.

Currently all of this is proof-of-concept and work in progress. Anyway, enjoy!
Linus Atorf

Profile results of sample2.nxc
File summary
Source file name:sample2.nxc
Profile results file:sample2.prf
__FIRMWARE_VERSION:120
__ENHANCED_FIRMWARE:no
Runtime summary
Total program runtime (until STOP): 5.58 seconds
Profiler runtime (between START and STOP): 5.55 seconds
Sections runtime (sum of all sections > 1ms): 5.19 seconds
Profiled source code
Calls Time Time / Call Code
Not profiled//#!C
/*
%
% Another example to demonstrate the NXC-Profiler!
%
%   see http://www.mindstorms.rwth-aachen.de/trac/wiki/NXCProfiler
%   and http://forums.nxtasy.org/index.php?showtopic=4496
%
% Signature
%   Author: Linus Atorf (see AUTHORS)
%   Date: 2009/12/12
%   License: GPLv3
%
%
% ***********************************************************************************************
% *  This file is part of the NXC Profiler.                                                     *
% *                                                                                             *
% *  The NXC Profiler is free software: you can redistribute it and/or modify                   *
% *  it under the terms of the GNU General Public License as published by the Free Software     *
% *  Foundation, either version 3 of the License, or (at your option) any later version.        *
% *                                                                                             *
% *  The NXC Profiler is distributed in the hope that it will be useful,                        *
% *  but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS  *
% *  FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details.             *
% *                                                                                             *
% *  You should have received a copy of the GNU General Public License along with the           *
% *  NXC Profiler. If not, see <http://www.gnu.org/licenses/>.                                  *
% ***********************************************************************************************
*/

// SET UP THE PROFILER
// comment this out to silently disable profiling without any side effects!
#define PROFILER_ENABLE
// how many times did we use PROFILER_BEGINSECTION (and ENDSECTION)
#define PROFILER_MAXSECTIONS 7
// name of the binary results file we later analyze
#define PROFILER_RESULTSFILE "sample2.prf"
// this does all the magic :-)
#include "Profiler01.nxc"


#define USPORT S1

task main () {

    int distance;
    SetSensorLowspeed(USPORT);

    PROFILER_START();

    // main loop
    while (!ButtonPressed(BTNCENTER, false)) {

173> 5.190 s (94%)> 30.0 ms        PROFILER_BEGINSECTION(0);
        distance = SensorUS(USPORT);
        PROFILER_ENDSECTION(0);
Not profiled
173 
 
> 0.003 s (0%)

by 1% of the calls		 
 
> 1.0 ms (in  1%)

< 1.0 ms (in 98%)		        PROFILER_BEGINSECTION(3);
        // empty...
        PROFILER_ENDSECTION(3);
Not profiled
        if (distance < 100) {
Never executed            PROFILER_BEGINSECTION(1);
            PlayTone(1000, 100);
            PROFILER_ENDSECTION(1);
Not profiled        } else {
173 
 
> 0.000 s (0%)

by 0% of the calls		< 1 ms             PROFILER_BEGINSECTION(2);
            PlayTone(200, 100);
            PROFILER_ENDSECTION(2);
Not profiled        }//end if

    }//end while

    PROFILER_STOP();
}// end task

Generated by Linus' NXC Profiler version 0.1


Profile results of sample.nxc
File summary
Source file name:sample.nxc
Profile results file:sample.prf
__FIRMWARE_VERSION:120
__ENHANCED_FIRMWARE:no
Runtime summary
Total program runtime (until STOP): 17.29 seconds
Profiler runtime (between START and STOP): 17.28 seconds
Sections runtime (sum of all sections > 1ms): 9.11 seconds
Profiled source code
Calls Time Time / Call Code
Not profiled//#!C
/*
%
% Example to demonstrate the NXC-Profiler!
%
%   see http://forums.nxtasy.org/index.php?showtopic=4496
%
%
% Signature
%   Author: Linus Atorf (see AUTHORS)
%   Date: 2009/12/07
%   License: GPLv3
%
%
% ***********************************************************************************************
% *  This file is part of the NXC Profiler.                                                     *
% *                                                                                             *
% *  The NXC Profiler is free software: you can redistribute it and/or modify                   *
% *  it under the terms of the GNU General Public License as published by the Free Software     *
% *  Foundation, either version 3 of the License, or (at your option) any later version.        *
% *                                                                                             *
% *  The NXC Profiler is distributed in the hope that it will be useful,                        *
% *  but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS  *
% *  FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details.             *
% *                                                                                             *
% *  You should have received a copy of the GNU General Public License along with the           *
% *  NXC Profiler. If not, see <http://www.gnu.org/licenses/>.                                  *
% ***********************************************************************************************
*/


// SET UP THE PROFILER

// comment this out to silently disable profiling without any side effects!
#define PROFILER_ENABLE

// how many times did we use PROFILER_BEGINSECTION (and ENDSECTION)
#define PROFILER_MAXSECTIONS 7
// name of the binary results file we later analyze
#define PROFILER_RESULTSFILE "sample.prf"
// this does all the magic :-)
#include "Profiler01.nxc"




// smaller value for quicker testing
// greater value for more accurate results
#define TESTITERATIONS 2000

// constants
#define OPSPERTESTLOOP 5
#define ARRAYSIZE 200





task main () {

    PROFILER_START();

    long longI;
    long longA = 234;
    long longB = -243534554;
    long longC;
    long longD;
    long long1 = 1;

    long longArray[ARRAYSIZE];


    int intI;
    int intA = 23;
    int intB = -2345;
    int intC;
    int intD;
    int int1 = 1;

    long StartTick;

    long OpsPerSec;


    TextOut(0, LCD_LINE1, "testing...", true);


1> 0.760 s (4%)> 760.0 ms    PROFILER_BEGINSECTION(0);
// --- Test INT ADDITIONS
    StartTick = CurrentTick();
    for (intI = 0; intI < TESTITERATIONS; intI++) {
        intC = intA + intB;
        intA = intC - intB;
        intC = intA + intB;
        intA = intC - intB;
        intC = intA + intB;
    }//end for
    PROFILER_ENDSECTION(0);
Not profiled
    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "int +-", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    until (ButtonPressed(BTNCENTER, false));
    TextOut(0, LCD_LINE1, "testing...", true);


1> 0.658 s (4%)> 658.0 ms    PROFILER_BEGINSECTION(1);
// --- Test LONG ADDITIONS
    StartTick = CurrentTick();
    for (longI = 0; longI < TESTITERATIONS; longI++) {
        longC = longA + longB;
        longA = longC - longB;
        longC = longA + longB;
        longA = longC - longB;
        longC = longA + longB;
    }//end for
    PROFILER_ENDSECTION(1);
Not profiled
    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "long +-", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    until (ButtonPressed(BTNCENTER, false));
    TextOut(0, LCD_LINE1, "testing...", true);



// --- Test LONG MULTIPLICATIONS
1> 0.684 s (4%)> 684.0 ms    PROFILER_BEGINSECTION(2);
    StartTick = CurrentTick();
    for (longI = 0; longI < TESTITERATIONS; longI++) {
        longC = longA * longB;
        longD = longA * 2;
        longC = longD * 5;
        longD = longB * (-35);
        longC = longB * longA;
    }//end for
    PROFILER_ENDSECTION(2);
Not profiled
    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "long *", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    until (ButtonPressed(BTNCENTER, false));
    TextOut(0, LCD_LINE1, "testing...", true);



// --- Test INT SHIFTS
1> 2.715 s (16%)> 2715.0 ms    PROFILER_BEGINSECTION(3);
    StartTick = CurrentTick();
    for (intI = 0; intI < TESTITERATIONS; intI++) {
        intC = intA << 2;
        intD = intB >> 1;
        intC = intB << 8;
        intD = intA >> 4;
        intC = intA << int1;
    }//end while
    PROFILER_ENDSECTION(3);
Not profiled
    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "int <<", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    until (ButtonPressed(BTNCENTER, false));
    TextOut(0, LCD_LINE1, "testing...", true);

// --- Test LONG SHIFTS
1> 2.650 s (15%)> 2650.0 ms    PROFILER_BEGINSECTION(4);
    StartTick = CurrentTick();
    for (longI = 0; longI < TESTITERATIONS; longI++) {
        longC = longA << 2;
        longD = longB >> 1;
        longC = longB << 8;
        longD = longA >> 4;
        longC = longA << long1;
    }//end while
    PROFILER_ENDSECTION(4);
Not profiled
    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "long <<", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    until (ButtonPressed(BTNCENTER, false));
    TextOut(0, LCD_LINE1, "testing...", true);




// --- Test VARIOUS CALLS
    StartTick = CurrentTick();
    for (longI = 0; longI < (TESTITERATIONS * 3); longI++) {
6000 
 
> 1.640 s (9%)

by 27% of the calls		 
 
> 1.0 ms (in 27%)

< 1.0 ms (in 72%)		        PROFILER_BEGINSECTION(5);
        longD = MotorTachoCount(OUT_A);
        longD = CurrentTick();
        longC = MotorTachoCount(OUT_B);
        longC = CurrentTick();
        longD = MotorTachoCount(OUT_C);
        PROFILER_ENDSECTION(5);
Not profiled    }//end while

    OpsPerSec = (TESTITERATIONS * 1000 * OPSPERTESTLOOP * 3)  / (CurrentTick() - StartTick);

    TextOut(0, LCD_LINE1, "tick/tachocount calls", true);
    NumOut (0, LCD_LINE3, OpsPerSec);

    PROFILER_STOP();

    until (ButtonPressed(BTNCENTER, false));


// --- Done

    /* DIRTY DIRTY HACK TEST
       this code was not profiled
       this is a quick hack... bad bad...
Never executed       PROFILER_BEGINSECTION(6);
       // something
       // something
       // this should never ever be executed
       // different color highlighting?
       PROFILER_ENDSECTION(6);
Not profiled    */

}//end task






Generated by Linus' NXC Profiler version 0.1