root/trunk/blade/Performance/Perform.d

/**
 * Performance tests
 * Author: Don Clugston. Portions by Agner Fog.
 * License: Modified BSD, (but note that it uses GPL-licensed modules).
 *
 * Determine the performance of a section of code, using the built-in
 * performance counters of Pentium processors.
 * The performance counters are set using a device driver obtained from Agner 
 * Fog's website (www.agner.org); his code is licenced under the GPL.
 * Since, in most cases, only two performance counters can be used at once,
 * the code is run multiple times with different performance counters enabled.
 *
 * REPEATABILITY
 * It is popular to raise the priority of thread to real-time priority, to avoid
 * interrupts, but this does not seem to be beneficial (Windows time slices are
 * typically 20ms, even for low-priority threads). It seems better to attempt to
 * detect corrupted measurements, and discard them. The technique used here is 
 * not infallible (fails once in every few thousand runs).
 *
 * TODO: Might be better to include OS time as well (just in case task switch occurs?)
 */
module Blade.Performance.Perform;
import Blade.Performance.MSRDriver;
import std.stdio;
//import std.cpuid;
import win32.core;
import std.string;

scope class PerformanceTester
{
private:
    CMSRDriver driver;
public:    
    this() {
        driver = new CMSRDriver;
        driver.LoadDriver();
        lockToSingleCPU();
        //regsToMeasure = regsToMeasurePM;
    }
    ~this() {
        driver.UnloadDriver();
    }
    struct AllPerfMeasurements
    {
        long timestamp;
        int[38] perfCounter;
    }

private:
    
 AllPerfMeasurements all;

 // The results of reading the timestamp clock and the performance counters
 struct PerfCounterMeasurement {
    ulong timestamp;
    uint[2] perfCounter;
 };

// Serialize, then read time stamp clock and performance counters 0 and 1
static void readCounters(PerfCounterMeasurement *dest) {
   asm {
       naked;
      // ENTRY: dest is in EAX (D calling convention).
      // NOTE: The rdpmc instruction corrupts EAX,ECX and EDX.
      // cpuid corrupts EAX,EBX, ECX, EDX
      // rdtsc corrupts EAX, EDX.
      push EBX;
      push EAX;
      xor EAX, EAX;
      cpuid; // Serialize. Corrupts EAX, EBX, ECX, EDX
      rdtsc;
      pop EBX;   // EBX = dest
      mov [EBX+0], EAX;  // time low
      mov [EBX+4], EDX;  // time high
      mov ECX, 0;
      rdpmc;
      mov [EBX+8], EAX;  // performance counter 0
      mov ECX, 1;
      rdpmc;
      mov [EBX+12], EAX; // performance counter 1
      xor EAX, EAX;
      cpuid; // serialize again
      pop EBX;
      ret;
   }
 }
 // low 16 bits is event number, bits 24..17 are unit mask.
 const uint[] regsToMeasure = [0xC0, 0xD0, 0xC2, 0x03,
                            0xA2, 0x04, 0xD2, 0x05, 
                            0x43, 0x46, 0x47, 0x48,
                            0x86, 0x81, 0x87, 0x85,
                            0xF28, 0xF2E, 0xF29, 0xF2A,
                            0xF0,
                            0x24, 0x26,
                            0xC4, 0xC9, 0xC5, 0xCA, 0xE2, 0xE6,
                            0xC8, 0x06,
                            0x93, 0x90, 0xDA, 0xA0 // PM only
                            , 0x79, 0x58, 0x1F29
                            ];
 const char [][] shortDesc = [
    "Instrct", "InDecod", "Uops(F)", "LdBlks",
    "ResStll", "Drains",  "PartRAT", "Misalgn", 
    "DataRef", "DtLnsIn", "DtLnOut", "DtMis",
    "IFtStal", "IFtcMis", "ILdStal", "ITlbMis",
    "L2IFtch", "L2Req",   "L2Ld",    "L2St",
    "PrefUp",
    "L2In",    "L2Out",
    "Brnches", "BrTaken", "BrMisp",  "BrTkMis", "BTBMiss", "BAClrs",
    "HwIntru", "SegRegL",
    "CallMis", "RetMisp", "FusdUop", "UopsUF",
    "Unhaltd", "SpdStep", "L2LdHw" // hardware prefetch
    ];
        
    // Notes:
    // 0xA0 is "unfused microoperations submitted to execution units (Undocumented counter!)"(Agner Fog).
    // SbDrains gives time lost to CPUID, interrupts, etc
    
//    uint[] regsToMeasure;
public:
 void DoPerformanceTest(void delegate() testfunc, void delegate() initfunc, void delegate() nulltestfunc=null)
 {
    void nulltest() { }
    if (nulltestfunc is null) nulltestfunc = &nulltest;
   
    SMSRInOut[4] startcmd;
    SMSRInOut[4] stopcmd;    
    
    const int PerfEvtSel0 = 0x186;
    const int PerfEvtSel1 = 0x187;
    const int PerfCtr0 = 0xC1;
    const int PerfCtr1 = 0xC2;

    startcmd[0] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfEvtSel0, 0);
    startcmd[1] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfCtr0, 0L);
    startcmd[2] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfEvtSel1, 0);
    startcmd[3] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfCtr1, 0L);
    
    stopcmd[0] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfEvtSel0, 0L);
    stopcmd[1] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfCtr0, 0L);
    stopcmd[2] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfEvtSel1, 0L);
    stopcmd[3] = SMSRInOut(EMSR_COMMAND.MSR_WRITE, PerfCtr1, 0L);
    
    PerfCounterMeasurement[4][10] results;    
    int standard_time_stamp = int.max;
    int standard_null_time_stamp = int.max;

    for (int countersetnum=0; countersetnum<regsToMeasure.length; countersetnum+=2) {
        // Bit 22 on PervEvtSel0 = enable counters.
        // Bit 16 = count non-OS events. Bit 17 = count OS events. 
        // bit 18 = edge detect. Bit 24-31 = counter mask (only count multiple events per cycle).
        startcmd[0].value = regsToMeasure[countersetnum]   | 0x0041_0000;
        startcmd[2].value = regsToMeasure[countersetnum+1] | 0x0001_0000;

        PerfCounterMeasurement minMeas; // smallest value for the test code
        PerfCounterMeasurement secondMeas; // candiate for minMeas
        PerfCounterMeasurement minNullMeas; // smallest value for the null code
        PerfCounterMeasurement secondNullMeas; // candiate for minNullMeas
        // The lowest value is usually, but not always, the best.
        // Occasionally, a measurement gives a spuriously low value. We guard against
        // this by choosing the smallest measurement which occurs more than once.
        int countMinTime = 0; // The number of measurements which have achieved the min time.
        int secondMinTime = 0;
        int countNullTime = 0;
        int secondNullTime = 0;
    
        do {
            driver.AccessRegisters(startcmd);    
            for (int i=0; i<8;++i) {
                initfunc();
                readCounters(&results[i][0]);
                testfunc();
                readCounters(&results[i][1]);
                initfunc();
                readCounters(&results[i][2]);
                nulltestfunc();
                readCounters(&results[i][3]);
            }
            driver.AccessRegisters(stopcmd);        
            minMeas.timestamp = uint.max;
            minNullMeas.timestamp = uint.max;
            countMinTime = 0;
            countNullTime = 0;
            secondMinTime = 0;
            secondNullTime = 0;
            for (int j=0; j<2;++j) {
                minMeas.perfCounter[j]=uint.max;
                secondMeas.perfCounter[j]=uint.max;
                minNullMeas.perfCounter[j]=uint.max;
                secondNullMeas.perfCounter[j]=uint.max;
            }
            // Start from end, since final measurements are usually most reliable.
            for (int i=7; i>=0; --i) {
                uint u = (results[i][1].timestamp-results[i][0].timestamp);
                if (u==minMeas.timestamp) ++countMinTime;
                if (u==secondMeas.timestamp) ++secondMinTime;
                else if (u < minMeas.timestamp) {
                    if (countMinTime>0) {
                        secondMinTime = countMinTime;
                        secondMeas  = minMeas;
                    }
                    minMeas.timestamp=u;
                    countMinTime=1;
                } else if (u < secondMeas.timestamp) {
                    secondMeas.timestamp = u; secondMinTime=1;
                }
                u = (results[i][3].timestamp-results[i][2].timestamp);              
                if (u==minNullMeas.timestamp) ++countNullTime;
                if (u==secondNullMeas.timestamp) ++secondNullTime;
                if (u < minNullMeas.timestamp) {
                    if (countNullTime>0) {
                        secondNullTime = countNullTime;
                        secondNullMeas = minNullMeas;
                    }
                    minNullMeas.timestamp=u;
                    countNullTime = 1;
                } else if (u<secondNullMeas.timestamp) {
                    secondNullMeas.timestamp = u; secondNullTime=1;
                }
                for (int j=0; j<2; ++j) {
                    u = results[i][1].perfCounter[j]-results[i][0].perfCounter[j];
                    if (u<minMeas.perfCounter[j]) minMeas.perfCounter[j]=u;
                    u = results[i][3].perfCounter[j]-results[i][2].perfCounter[j];
                    if (u<minNullMeas.perfCounter[j]) minNullMeas.perfCounter[j]=u;
                }
            }
         //if (countMinTime==0 && secondMinTime==0), we have a totally random result
         
         // The mintime must have occured at least twice, and there must not be two candidates.
        } while ((countMinTime<3 && secondMinTime<3) || (countMinTime>2 && secondMinTime>2) ||(countNullTime<3 && secondNullTime<3));
        
        if (countMinTime<3 && secondMinTime>=3) {
            minMeas = secondMeas;
        }
        if (countNullTime<3 && secondNullTime>=3) {
            minNullMeas = secondNullMeas;
        }
        bool unusual = false;
    
        if (standard_time_stamp==int.max) {
            standard_time_stamp = minMeas.timestamp;
            standard_null_time_stamp = minNullMeas.timestamp;
            writefln("Standard=(%d, %d)",standard_time_stamp, standard_null_time_stamp);
        } else {
            if (standard_time_stamp != minMeas.timestamp || standard_null_time_stamp !=minNullMeas.timestamp) {
                writefln("Standard=(%d,%d), this=(%d,%d) second=(%d %d)", standard_time_stamp, standard_null_time_stamp, minMeas.timestamp,minNullMeas.timestamp, secondMeas.timestamp,secondNullMeas.timestamp);
                unusual = true;
            }
        }
        all.timestamp = standard_time_stamp-standard_null_time_stamp; //minMeas.timestamp - minNullMeas.timestamp;
        all.perfCounter[countersetnum] = minMeas.perfCounter[0]-minNullMeas.perfCounter[0];
        all.perfCounter[countersetnum+1] = minMeas.perfCounter[1]-minNullMeas.perfCounter[1];
    
        if (unusual) {       
            writefln("Different timestamp: %s %s %d %d ####################", shortDesc[countersetnum*2], shortDesc[countersetnum], all.timestamp, minMeas.timestamp - minNullMeas.timestamp);
            for (int i=0; i<8; ++i) {
                    writefln("%d --> %d,%d", i, results[i][1].timestamp-results[i][0].timestamp, results[i][3].timestamp-results[i][2].timestamp);
            }
        }   
    }
 }

 void describe()
 {
    writefln("ALL RESULTS");
    char [] heading = "Ticks" ~ \t;
    char [] vals = std.string.toString(all.timestamp) ~ \t;
    int kol=1;
    for(int i=0; i<shortDesc.length; ++i) {
        heading ~= shortDesc[i]~ \t;
        vals ~= std.string.toString(all.perfCounter[i])~\t;
        ++kol;
        if (kol==8 || i==shortDesc.length-1) {
            writefln(heading); writefln(vals); heading=""; vals=""; kol=0;
        }
    }
 }
}