Code: Records per Second Tracking

[ascheevel]

I occasionally need to test/monitor throughput of TIs, especially when tuning parallel execution or debugging sluggish TI performance usually traced to one specific cube action. Below is code that I drop in the Prolog, Data, & Epilog tabs for limiting execution to the first N records, optionally writing message to log at checkpoints, and finally writing performance values to the log at completion.

Code: Select all

## Prolog ##
    nCt = 0;
    nMaxRecords = 50000;
    nLogInterval = 10000;
    nLogOut = 1;


## Data ##

    IF(nCt = 0);
        IF(nLogOut = 1);
            LogOutput('WARN', 'starting data tab');
        ENDIF;
        nStart = NOW();

    ## stop execution if nMaxRecords reached
    ELSEIF(nCt >= nMaxRecords);
        ProcessBreak;
    ENDIF;

    IF(nLogInterval > 0);
        IF(MOD(nCt, nLogInterval) = 0);
            IF(nLogOut = 1);
                sCt = NumberToStringEX(nCt, '#,###', '.', ',');
                LogOutput('WARN', EXPAND('at record %sCt%'));
            ENDIF;
        ENDIF;
    ENDIF;

    nCt = nCt + 1;

    ## skip rest of Data tab; usefule for existing TI when just testing max throughput
    ## comment out ItemSkip and rerun to then see impact of Data tab actions on throughput
    ItemSkip;


## Epilog ##

    nDuration = (NOW() - nStart) * 86400;
    nRecSec = nCt \ nDuration;
    sDuration = NumberToStringEX(nDuration, '#,###', '.', ',');
    sRecSec = NumberToStringEX(nRecSec, '#,###', '.', ',');
    sCt = NumberToStringEX(nCt, '#,###', '.', ',');
    LogOutput('WARN', EXPAND('Duration:%sDuration% seconds; Records:%sCt%; RecordsPerSecond:%sRecSec%'));

[Wim Gielis]

Thank you Andrew, it's useful. I reworked a bit to my preferences and delimiters in the numbers.
Also, the choice to go really detailed until milliseconds, or not.

Code: Select all

#######################################
#####  IF NOT USING MILLISECONDS  #####
#######################################


## START of the Prolog tab ##

nLogOut = 1;
nMaxRecords = 50000;
nLogInterval = 10000;
sFormat_Count = '#,##0';
sFormat_Time = '#,##0.0';
nStart = Now;
nCounter = 0;
If( nLogOut = 1 );
   LogOutput( 'WARN', 'Starting the process' );
EndIf;


## END of the Prolog tab) ##

nDuration = ( Now - nStart ) * 86400;
sDuration = NumberToStringEx( nDuration, sFormat_Time, ',', '.' );
LogOutput( 'WARN', Expand( 'Duration of the Prolog tab: %sDuration% seconds' ));


## START of the Metadata or Data tab ##

If( nCounter = 0 );
   If( nLogOut = 1 );
      LogOutput( 'WARN', 'Starting the Data tab' );
   EndIf;
   nStart = Now;

## Stop execution if nMaxRecords is reached
ElseIf( nCounter >= nMaxRecords );
   ProcessBreak;
EndIf;

nCounter = nCounter + 1;

If( nLogInterval > 0 );
   If( Mod( nCounter, nLogInterval ) = 0 );
      If( nLogOut = 1 );
         sCt = NumberToStringEx( nCounter, sFormat_Count, ',', '.' );
         LogOutput( 'WARN', Expand( ' we are at record %sCt%' ));
      EndIf;
   EndIf;
EndIf;

## Skip the rest of Data tab; useful for existing TI when just testing max throughput
## Comment out ItemSkip and rerun to then see impact of Data tab actions on throughput
ItemSkip;


## START of the Epilog tab ##

nDuration = ( Now - nStart ) * 86400;
nRecSec = nCounter \ nDuration;
sDuration = NumberToStringEx( nDuration, sFormat_Time, ',', '.' );
sRecSec = NumberToStringEx( nRecSec, sFormat_Time, ',', '.' );
sCt = NumberToStringEx( nCounter, sFormat_Count, ',', '.' );
LogOutput( 'WARN', Expand( 'Duration: %sDuration% seconds; Records: %sCt%; Records per second: %sRecSec%' ));

Code: Select all

###################################
#####  IF USING MILLISECONDS  #####
###################################

# NOTE: PAW does not recognize the function MilliTime()
# Process can be saved and run but a warning is given when saving the process.


## START of the Prolog tab ##

nLogOut = 1;
nMaxRecords = 50000;
nLogInterval = 10000;
sFormat_Count = '#,##0';
sFormat_Time = '#,##0.0';
nStart = MilliTime;
nCounter = 0;
If( nLogOut = 1 );
   LogOutput( 'WARN', 'Starting the process' );
EndIf;


## END of the Prolog tab ##

nDuration = ( MilliTime - nStart ) / 1000;
sDuration = NumberToStringEx( nDuration, sFormat_Time, ',', '.' );
LogOutput( 'WARN', Expand( 'Duration of the Prolog tab: %sDuration% seconds' ));


## START of the Metadata or Data tab ##

If( nCounter = 0 );
   If( nLogOut = 1 );
      LogOutput( 'WARN', 'Starting the Data tab' );
   EndIf;
   nStart = MilliTime;

## Stop execution if nMaxRecords is reached
ElseIf( nCounter >= nMaxRecords );
   ProcessBreak;
EndIf;

nCounter = nCounter + 1;

If( nLogInterval > 0 );
   If( Mod( nCounter, nLogInterval ) = 0 );
      If( nLogOut = 1 );
         sCt = NumberToStringEx( nCounter, sFormat_Count, ',', '.' );
         LogOutput( 'WARN', Expand( ' we are at record %sCt%' ));
      EndIf;
   EndIf;
EndIf;

## Skip the rest of Data tab; useful for existing TI when just testing max throughput
## Comment out ItemSkip and rerun to then see impact of Data tab actions on throughput
ItemSkip;


## START of the Epilog tab ##

nDuration = ( MilliTime - nStart ) / 1000;
nRecSec = nCounter \ nDuration;
sDuration = NumberToStringEx( nDuration, sFormat_Time, ',', '.' );
sRecSec = NumberToStringEx( nRecSec, sFormat_Time, ',', '.' );
sCt = NumberToStringEx( nCounter, sFormat_Count, ',', '.' );
LogOutput( 'WARN', Expand( 'Duration: %sDuration% seconds; Records: %sCt%; Records per second: %sRecSec%' ));