Profiling Scripts

If your script seems to be slow on execution, it is possible to profile the run-time behavior during the execution.

The following simple script example shows how to profile it.

#include "include/dmutil.h"

/* A 'useless' time sink for profiling */
function_1()
{
    for(i=0;i<5;i=i+1;){
        function_2();
    }
    return(0);
}

/* A 'useless' time sink for profiling */
function_2()
{
    for (i = 0; i < 100000; i = i + 1;) {
        rec = DM_INIT_TAGREC();
        DM_SET_TAGVAL(rec, "foo", "foo");
        DM_SET_TAGVAL(rec, "bar", "bar");
        DM_SET_TAGVAL(rec, "baz", "baz");
        DM_SET_TAGVAL(rec, "quux", "quux");
        function_3(rec);
        DM_FREE_TAGREC(rec);
    }
    return(0);
}

/* A 'useless' time sink for profiling */
function_3(rec)
{
    foo = DM_GET_TAGVAL(rec, "foo");
    return(0);
}

/*  Select the file to write the profiling info */
choose_log_path()
{
    filters = "Text Files (*.txt)";
    flags = U_GFN_SAVE;
    filter_index = 1;
    log_path = U_GET_FILENAME("Select log file", "./", "profile.txt", filters, flags, 
filter_index);
    
    /* In the current version (2023-01) the profile file must not exist when the profil-ing starts */
    if(F_EXIST(log_path))F_DELETE_FILE(log_path);
    return log_path;
}

main()
{
    log_path = choose_log_path();
    if(ISINT(log_path))return(-1);
        
    st = DM_START_SCRIPT_PROFILING(log_path);
    function_1();
    st = DM_END_SCRIPT_PROFILING();
    
    U_FILE_BROWSER ( "Script Profiling Results", log_path );
    
    U_MESSAGEBOX("Script complete", U_MB_INFO, U_MB_OK, 0);
}

The script above does not do anything useful except demonstrates profiling. The profiled part of the code is between the DM_START_SCRIPT_PROFILING and DM_END_SCRIPT_PROFILING extern calls.

When the script is executed profiling info is extracted to the selected file (log_path).

The result looks like this:

Profiling started at: Wed Jan 11 15:41:46 2023

Profiling ended at: Wed Jan 11 15:41:50 2023

Elapsed total time: 3s

Most time-consuming scripts

Most time-consuming externs

The info consists of:

• Total execution time

• Most time consuming user defined script functions

• Most time consuming extern functions

• For each function:

  • Amount of calls

  • Total duration (of all calls together)

  • Longest duration (of a single call)

  • Average duration (of a single call)

  • Shortest duration (of a single call)

You should remove the externs DM_START_SCRIPT_PROFILING and DM_END_SCRIPT_PROFILING from the code, prior to releasing your script to the users.

The example script code can be found in %PMS_HOME%\dm\macro\Examples\Scriptprofiling.mac

Note: The profile log file needs to be explicitly removed before it can be reused for profiling.