Calling function does nothing but takes huge amount of time vs called function

General FreeBASIC programming questions.
cbruce
Posts: 166
Joined: Sep 12, 2007 19:13
Location: Dallas, Texas

Calling function does nothing but takes huge amount of time vs called function

Post by cbruce »

My head-banging-against-the-wall issue is:

Although EXTRACT_STAGE_01() actually does nothing more than call EXTRACT_STAGE_02() twice... EXTRACT_STAGE_01() is showing a runtime of approximately 8 seconds per 5 million calls... while EXTRACT_STAGE_02() is showing a runtime of less than 1 second for the 10 million times that it is called from EXTRACT_STAGE_01()!

Windows 10 64-bit, i7, 32G ram ... I've tried with 1.07, 1.08, and 1.09 GCC 64-bit FB compiler versions.

I'm profiling with my own macros, (in the code below), and they work fine in all of my other programs.

Please help me find my stupid!

This is the stripped down test code:

Code: Select all

' =======================================================================
' EXAMPLE COMMAND LINE: for running 1 million test() with 5 extract() per 
' test() that are each extracting 7 significant digits from each double; 
' for a total of 14 significant digits per extract(). 
' 
' X:\>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5 > dump__00__test_extract.txt
' =======================================================================
' EXAMPLE OUTPUT: 
' 
/'
Performance PROFILING is ON

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      8.917946      8.917946      8.917946     1  __FB_MAINPROC__
     1000000      8.860727         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     5000000      7.787557         < 1.0         < 1.0     5  EXTRACT_STAGE_01
    10000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000      7.976083         < 1.0         < 1.0     1  __extract_decimals

Time = 8.918786599999294
'/
' =======================================================================
'
'  ===================================================================
type BEH_Program_Info__TYPE
  as const string Title    = "00__test_extract"
  as const string Version  = "0.4 (2022-01-29_2233)"
  as const string Author   = "Bruce E. Huber"
  '
  as const string SRC_File = "00__test_extract.bas"
end type
'
dim shared gBEH_Program_Info as BEH_Program_Info__TYPE
'  ===================================================================
'
'
' =======================================================================
' Includes: 
#include once "string.bi"    'For Format().
#include once "vbcompat.bi"  'For datetime serial functions.
' beh.pad() functions...
' ------------------------------------------------------------
namespace beh
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters: 
            ' // --------------------------------------------------
    declare function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
    declare function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
    declare function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters ...
            ' // --------------------------------------------------
            '
    function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
        dim result_str as string
        dim fill as string = string( fmt_width, asc(fill_char))
        pad_output_LR = ucase( pad_output_LR)
        if pad_output_LR = "L" then
                    'L' = Pad the LEFT side of the string. (default)
            if len( pad_this_str) <= fmt_width then
                result_str = right( fill + pad_this_str, fmt_width)
            else
                result_str = pad_this_str
            END IF
        else
                    'R' = Pad the RIGHT side of the string.
            if len( pad_this_str) <= fmt_width then
                result_str = left( pad_this_str + fill, fmt_width)
            else
                result_str = pad_this_str
            END IF
        endif
        return result_str
    END function  'PRIVATE__pad_output'
            '
    function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str( num_to_pad))
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function    'pad(double)'
            '
    function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str_to_pad)
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function  'pad(string)'
            '
            ' // --------------------------------------------------
            ' //   ... FUNC - Pad Strings with Fill Characters.
            ' // --------------------------------------------------
            '
end namespace  'beh'
' =======================================================================
'
'
' =======================================================================
    ' 
    ' ?Performance Profile mode?
    #define  def_BEH_PROFILE  true
    '...
    #if (def_BEH_PROFILE = TRUE)
      ' Enable blocks of performance profiling code:
      #define ifpro    #if 1
    #else
      ' Disable blocks of performance profiling code:
      #define ifpro    #if 0
    #endif
    #define elsepro  #else
    #define endpro   #endif
    '
    ifpro
      ' {PROFILE} 
      ' Global variables for performance profiling:
      '
      enum _pro__Func_enum Explicit
        ' Function names as numeric constants.
        _pro__FUNC_FIRST_ENUM = 0
            __FB_MAINPROC__
            my_MAIN
            get_cmdline
            set_options
            extract_stage_01
            extract_stage_02
        _pro__FUNC_LAST_ENUM
      end enum
      '
      type _pro__Func_typ
        dim as zstring*100   FnName = ""
        dim as integer       FnNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Func_typ gProFN(_pro__Func_enum._pro__FUNC_LAST_ENUM)
      '
      enum _pro__Action_enum Explicit
        ' Repeatable-Action names as numeric constants.
        _pro__ACTION_FIRST_ENUM = 0
            __extract_decimals
        _pro__ACTION_LAST_ENUM
      end enum
      '
      type _pro__Action_typ
        dim as zstring*100   ActName = ""
        dim as integer       ActNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Action_typ gProACT(_pro__Action_enum._pro__ACTION_LAST_ENUM)
    endpro
    '
    ifpro
      ' {PROFILE} 
      ' Macros for performance profiling of separate Functions: 
      #macro _pro__Func_ENTRY_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime = timer
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = false then
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnName = __FUNCTION__
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnNum = _pro__Func_enum.__FUNCTION_NQ__
        end if
      #endmacro
      '
      #macro _pro__Func_EXIT_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime = timer
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime - gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true then
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime < gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime > gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
        else
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        end if
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).TotTime += gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallCount += 1
      #endmacro
      '
      ' Macros for performance profiling of other repeatable Actions: 
      #macro _pro__Action_ENTRY_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).StartTime = timer
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = false then
          gProACT(_pro__Action_enum.m_Enum).ActName = #m_Enum
          gProACT(_pro__Action_enum.m_Enum).ActNum = _pro__Action_enum.m_Enum
        end if
      #endmacro
      '
      #macro _pro__Action_EXIT_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).EndTime = timer
        gProACT(_pro__Action_enum.m_Enum).CallTime = gProACT(_pro__Action_enum.m_Enum).EndTime - gProACT(_pro__Action_enum.m_Enum).StartTime
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = true then
          if gProACT(_pro__Action_enum.m_Enum).CallTime < gProACT(_pro__Action_enum.m_Enum).MinTime then
              gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
          if gProACT(_pro__Action_enum.m_Enum).CallTime > gProACT(_pro__Action_enum.m_Enum).MaxTime then
              gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
        else
          gProACT(_pro__Action_enum.m_Enum).isInitialized = true
          gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
        end if
        gProACT(_pro__Action_enum.m_Enum).TotTime += gProACT(_pro__Action_enum.m_Enum).CallTime
        gProACT(_pro__Action_enum.m_Enum).CallCount += 1
      #endmacro
    endpro
    '
' =======================================================================
'
type myVars__typ
  dim as double  prv_ss_r
  dim as double  prv_ss_i
  dim as zstring*50 prv_ss_str
end type
'
type TEST_overrides_typ
  ' To override options from command line - get_cmdline(). 
  ' To check for overrides - set_options(). 
  '
  ' Bit-flags that show if command line overrides are active. 
  ' Using a ULONG for the bit-field - 32 bits available. 
  dim as ulong NUM_SIG_DIGITS         : 1  = 0
  dim as ulong NUM_EXTRACT_INSTANCES  : 1  = 0
end type
'
type TEST_options_typ
  ' To programatically set values - set_options(). 
  ' To dynamically override from command line - get_cmdline(). 
  '
  ' Nested type with bit-flags that show if command line overrides are active: 
  dim as TEST_overrides_typ overrides
  ' Options - and default values:
  dim as integer NUM_SIG_DIGITS         = 7
  dim as integer NUM_EXTRACT_INSTANCES  = 5
end type
' Holds the current instances of options.
dim shared as TEST_options_typ  gOptUsing
' Holds the original options specified on the command line. 
dim shared as TEST_options_typ  gOptCmd
' Holds the original options specified in set_options(). 
dim shared as TEST_options_typ  gOptSet
'
' Used when comparing and ranging decimal characters. 
CONST as ubyte ASC_PLUS  = &h2B
CONST as ubyte ASC_MINUS = &h2D
CONST as ubyte ASC_DOT   = &h2E
CONST as ubyte ASC_ZERO  = &h30
CONST as ubyte ASC_ONE   = &h31
CONST as ubyte ASC_NINE  = &h39
CONST as ubyte ASC_LC_e  = &h65
CONST as ubyte ASC_UC_E  = &h45
' Used to bit-or with a letter character so we only have to compare for the uppercase character. 
CONST as ubyte ASC_UCASE2LCASE = &h20
'
' =======================================================================
'
declare Sub      my_MAIN()
declare Function get_cmdline() as integer
declare Sub      set_options()
declare Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
declare Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
'
' ============================================================
      ' Start Time. 
      dim as double t_start
      dim shared as integer gTestNum
      dim shared as integer gMaxTestNum
          '
          ifpro
            ' {PROFILE} 
            print
            print "Performance PROFILING is ON"
          elsepro
            print
            print "Performance PROFILING is OFF"
          endpro
          '
      t_start = timer
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_ENTRY_macro
          endpro
          '
      ' ----------------------------------------------------
      ' Run the individual tests from this loop. 
      ' ----------------------------------------------------
      gTestNum = 1
      gMaxTestNum = 1   'Set final size during first loop in myMain(). 
      do while gTestNum <= gMaxTestNum
        '
        my_MAIN()
        gTestNum += 1
        ' 
      loop
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_EXIT_macro
          endpro
          '
          ifpro
            ' {PROFILE} 
            print
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("F#", 4); "  "; 
            print "FuncName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "--------"
            '
            for i as integer = 0 to _pro__Func_enum._pro__FUNC_LAST_ENUM
              if gProFN(i).FnNum > -1 then
                print beh.pad(gProFN(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProFN(i).TotTime < 1.0, "< 1.0", format(gProFN(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MinTime < 1.0, "< 1.0", format(gProFN(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MaxTime < 1.0, "< 1.0", format(gProFN(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProFN(i).FnNum, 4); "  "; 
                print gProFN(i).FnName
              end if
            next
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("A#", 4); "  "; 
            print "ActionName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "---------"
            '
            for i as integer = 0 to _pro__Action_enum._pro__ACTION_LAST_ENUM
              if gProACT(i).ActNum > -1 then
                print beh.pad(gProACT(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProACT(i).TotTime < 1.0, "< 1.0", format(gProACT(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MinTime < 1.0, "< 1.0", format(gProACT(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MaxTime < 1.0, "< 1.0", format(gProACT(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProACT(i).ActNum, 4); "  "; 
                print gProACT(i).ActName
              end if
            next
            print
          endpro
          '
      print
      print "Time = "; str(timer - t_start)
      print "---------------------------------------------------------"
      print
      print
      '
    END
' ============================================================


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub my_MAIN()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim result as integer
  '
  RANDOMIZE , 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a random seed value.
  'RANDOMIZE 3.76543, 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a fixed value for repeatable results during testing.
  '
  if gTestNum = 1 then
      get_cmdline()
      set_options()
  end if
  '
  ' Reset original options for the next test.  
  gOptUsing = gOptSet
  '
  redim as myVars__typ myVars(1 to gOptUsing.NUM_EXTRACT_INSTANCES)
  '
  'START LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
  for extraction_num as integer = 1 to gOptSet.NUM_EXTRACT_INSTANCES
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_ENTRY_macro(__extract_decimals)
        endpro
        '
    '------
    result = extract_stage_01(myVars(extraction_num), gOptUsing.NUM_SIG_DIGITS)
    '------
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_EXIT_macro(__extract_decimals)
        endpro
        '
  next
  'END   LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
END Sub  ''my_MAIN()


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim as zstring*50  ThisDblStr
  dim as integer     ThisDblStrLen
  dim as integer     digit_ct(1 to 2)  ' Significant Digit counter.
  '
  ' I replaced everything else I was doing in here with just two straight calls to
  ' this functions helper function that actually does all of the work to extract 
  ' significant digits from a double. 
  '
  ' BUT this function still takes a magnitude greater amount of time (via profiling) 
  ' to run then the helper function that it is calling twice per instance !!!
  for ij as integer = 1 to 2
    if ij = 1 then
      ' Process the first double. 
      ThisDblStr = str(rnd)
      digit_ct(1) = extract_stage_02(ThisDblStr, num_digits)
    else
      ' Process the second double. 
      ThisDblStr = str(rnd)
      digit_ct(2) = extract_stage_02(ThisDblStr, num_digits)
    end if
  next ij
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN (digit_ct(1) + digit_ct(2))
  '
end Function  ''extract_stage_01 OVERLOAD (myVars as myVars__typ, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  '------
  ' Find "."
  ' If asc_zero < previous_char <= asc_nine then first digit
  ' Gather N significant digits
  ' Find "Ee"
  ' If "Ee" then skip next_char (asc_sign) and gather digits to end-of-string
  '------
  dim as integer digit_ct  ' Significant Digit counter.
  dim as integer first_pos ' First Significant Digit position. 
  dim as integer last_pos  ' Last Significant Digit position. 
  dim as integer dot_pos   ' Decimal point "." byte position.
  dim as integer exp_pos   ' "E" or "e" byte position.
  dim as integer iout      ' Output byte position.
  dim as ubyte   byt
  dim as zstring*50 outStr
  '------
  digit_ct = 0
  first_pos = -1
  last_pos = -1
  dot_pos = -1
  exp_pos = -1
  iout = 0
  ' Find the decimal point "." and any exponent "E" or "e" character. 
  for ik as integer = 0 to (len(dblStr) - 1)
    if dblStr[ik] = ASC_DOT then
      ' Found the decimal point "." character. 
      dot_pos = ik
      continue for
    end if
    if ((dblStr[ik] or ASC_UCASE2LCASE) = ASC_LC_e) then 
      ' Found an exponent "E" or "e" character. 
      exp_pos = ik
      exit for
    end if
  next
  '
  ' Check to see if the digit preceding the decimal point is significant. 
  if dblStr[dot_pos - 1] > ASC_ZERO then
    ' Yes - this is our first significant digit. 
    first_pos = dot_pos - 1
    outStr[iout] = dblStr[first_pos]
    iout += 1
    digit_ct += 1
  end if
  '
  ' Do we have the first significant digit yet? 
  if first_pos >= 0 then
    ' Yes - go get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (dot_pos + num_digits - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  else
    ' No - go find the first significant digit after the decimal point and 
    ' then get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (len(dblStr) - 1)
      if (first_pos < 0) and (dblStr[ik] = ASC_ZERO) then
        ' Still looking for the first significant digit. 
        continue for
      end if
      ' Found the first significant digit past the decimal point. 
      first_pos = ik
      exit for
    next
    ' Now go get the rest of the significant digits. 
    for kk as integer = (first_pos) to (first_pos + num_digits - 1)
      outStr[iout] = dblStr[kk]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Now get any exponent digits that might be available. 
  if exp_pos >= 0 then
    ' Skip the "E/e" and "+/-" characters and just grab the digits. 
    for ik as integer = (exp_pos + 2) to (len(dblStr) - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Return the string of significant decimals extracted from this. 
  dblStr = outStr
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  ' Return the count of significant decimals extracted from this. 
  RETURN digit_ct
  '
end Function   ''extract_stage_02(dblStr as zstring, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function get_cmdline() as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  ' Parse command line arguments and override any previously set  
  ' options, as necessary. 
  ' 
  ' If there are any invalid parameter values, they will be 
  ' ignored and the default/set option values will be used. 
  '
  Dim As Integer cmd_parm_i
  Dim As String  arg 
  Dim as String  srch
  Dim As integer itmp 
  Dim As double  dtmp 
  Dim As String  stmp 
  '
  cmd_parm_i = 1
  Do
    arg = ucase(Command(cmd_parm_i))
    If Len(arg) = 0 Then
      Exit Do
    End If
    '
    srch = "TOT_TESTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gMaxTestNum = itmp
      end if
    end if
    '
    srch = "NUM_EXTRACTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 1
        gOptCmd.NUM_EXTRACT_INSTANCES = itmp
      end if
    end if
    '
    srch = "NUM_DIGITS="  ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 and itmp <= 18 then
        gOptCmd.overrides.NUM_SIG_DIGITS = 1
        gOptCmd.NUM_SIG_DIGITS = itmp
      end if
    end if
   '
    cmd_parm_i += 1
  Loop
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN 0
  '
end Function  ''get_cmdline()


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub set_options()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  if gOptCmd.overrides.NUM_SIG_DIGITS = 0 then
    gOptSet.NUM_SIG_DIGITS = 7
  else
    gOptSet.NUM_SIG_DIGITS = gOptCmd.NUM_SIG_DIGITS 
  end if
  '
  '
  if gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 0 then
    gOptSet.NUM_EXTRACT_INSTANCES  = 5 
  else
    gOptSet.NUM_EXTRACT_INSTANCES = gOptCmd.NUM_EXTRACT_INSTANCES 
  end if
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
end Sub  ''set_options()

Last edited by cbruce on Feb 10, 2022 1:22, edited 1 time in total.
jj2007
Posts: 2326
Joined: Oct 23, 2016 15:28
Location: Roma, Italia
Contact:

Re: Calling function does nothing but takes huge amount of time vs called function

Post by jj2007 »

FB64

Code: Select all

Performance PROFILING is ON


   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1         < 1.0         < 1.0         < 1.0     1  __FB_MAINPROC__
           1         < 1.0         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
           5         < 1.0         < 1.0         < 1.0     5  EXTRACT_STAGE_01
          10         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
           5         < 1.0         < 1.0         < 1.0     1  __extract_decimals

Time = 0.001337899477221072
---------------------------------------------------------
Gas

Code: Select all

Performance PROFILING is ON


   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1         < 1.0         < 1.0         < 1.0     1  __FB_MAINPROC__
           1         < 1.0         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
           5         < 1.0         < 1.0         < 1.0     5  EXTRACT_STAGE_01
          10         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
           5         < 1.0         < 1.0         < 1.0     1  __extract_decimals

Time = 0.05324585329489651

Code: Select all

Performance PROFILING is ON


   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1         < 1.0         < 1.0         < 1.0     1  __FB_MAINPROC__
           1         < 1.0         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
           5         < 1.0         < 1.0         < 1.0     5  EXTRACT_STAGE_01
          10         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
           5         < 1.0         < 1.0         < 1.0     1  __extract_decimals


Gcc Time = 0.05176673337462034
cbruce
Posts: 166
Joined: Sep 12, 2007 19:13
Location: Dallas, Texas

Re: Calling function does nothing but takes huge amount of time vs called function

Post by cbruce »

Hi jj2007! Thanks, but you didn't run it with the command line parameters as shown at the top of the code... so it only ran *one* test with *five* extracts by default... you need one million tests (like the example command line) in order to see the magnitude of differences.

Thanks!
CBruce
adeyblue
Posts: 300
Joined: Nov 07, 2019 20:08

Re: Calling function does nothing but takes huge amount of time vs called function

Post by adeyblue »

There's nothing wrong with it (well, the macro verbosity could be tamed by declaring a byref variable in the entry macros and using that instead of constant array accesses, but that's style rather than correctness).

See, I can make it 400x slower without changing either function.

Code: Select all

Performance PROFILING is ON


   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1    399.075054    399.075054    399.075054     1  __FB_MAINPROC__
     1000000    398.565283         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     5000000    396.287014         < 1.0         < 1.0     5  EXTRACT_STAGE_01
    10000000      1.416487         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000    396.582224         < 1.0         < 1.0     1  __extract_decimals


Time = 399.0757295483097
---------------------------------------------------------
Your anomaly is that you're not just timing your code, you're timing rnd too. And mersenne twister is probably the slowest of the RNGs (apart from 5, the crypto one, which is shown above).

This is perhaps the one problem with manual instrumentation, if you call things you can't/haven't instrumented then you can still have a large search area to figure out your performance problems. If only FB had a way to get call stacks, someone could write/FB code would then be usable in sampling profilers which would let you zero in a bit further.
cbruce
Posts: 166
Joined: Sep 12, 2007 19:13
Location: Dallas, Texas

Re: Calling function does nothing but takes huge amount of time vs called function

Post by cbruce »

Hi adeyblue! Thanks, but I just modified the code and moved the RND() calls outside all the performance counters for the two extract() functions. As you can see, that made a very minimal impact on the time that extract_stage_01() is profiling.

But also let me make clear.... How long extract_stage_01() takes to run is not the question - this is not directly about performance.

If the only thing that extract_stage_01() does is call extract_stage_02() twice... how can extract_stage_01() take 8 seconds to run, when extract_stage_02() (which is doing all of the work) runs in sub-seconds???

What is taking extract_stage_01() so long???

Or else, If extract_stage_01() is taking the time it should, then why does extract_stage_02() profile show sub-second time instead???

Here is the updated code, with the RND() calls removed from the area in question:

Code: Select all

' =======================================================================
' EXAMPLE COMMAND LINE: for running 1 million test() with 5 extract() per 
' test() that are each extracting 7 significant digits from each double; 
' for a total of 14 significant digits per extract(). 
' 
' X:\>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5 > dump__00__test_extract.txt
' =======================================================================
' EXAMPLE OUTPUT: 
' 
/'
Performance PROFILING is ON

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      8.956318      8.956318      8.956318     1  __FB_MAINPROC__
     1000000      8.906589         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     5000000      7.032985         < 1.0         < 1.0     5  EXTRACT_STAGE_01
    10000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000      7.221917         < 1.0         < 1.0     1  __extract_decimals

Time = 8.957249599974603
'/
' =======================================================================
'
'  ===================================================================
type BEH_Program_Info__TYPE
  as const string Title    = "00__test_extract"
  as const string Version  = "0.4 (2022-01-29_2233)"
  as const string Author   = "Bruce E. Huber"
  '
  as const string SRC_File = "00__test_extract.bas"
end type
'
dim shared gBEH_Program_Info as BEH_Program_Info__TYPE
'  ===================================================================
'
'
' =======================================================================
' Includes: 
#include once "string.bi"    'For Format().
#include once "vbcompat.bi"  'For datetime serial functions.
' beh.pad() functions...
' ------------------------------------------------------------
namespace beh
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters: 
            ' // --------------------------------------------------
    declare function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
    declare function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
    declare function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters ...
            ' // --------------------------------------------------
            '
    function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
        dim result_str as string
        dim fill as string = string( fmt_width, asc(fill_char))
        pad_output_LR = ucase( pad_output_LR)
        if pad_output_LR = "L" then
                    'L' = Pad the LEFT side of the string. (default)
            if len( pad_this_str) <= fmt_width then
                result_str = right( fill + pad_this_str, fmt_width)
            else
                result_str = pad_this_str
            END IF
        else
                    'R' = Pad the RIGHT side of the string.
            if len( pad_this_str) <= fmt_width then
                result_str = left( pad_this_str + fill, fmt_width)
            else
                result_str = pad_this_str
            END IF
        endif
        return result_str
    END function  'PRIVATE__pad_output'
            '
    function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str( num_to_pad))
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function    'pad(double)'
            '
    function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str_to_pad)
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function  'pad(string)'
            '
            ' // --------------------------------------------------
            ' //   ... FUNC - Pad Strings with Fill Characters.
            ' // --------------------------------------------------
            '
end namespace  'beh'
' =======================================================================
'
'
' =======================================================================
    ' 
    ' ?Performance Profile mode?
    #define  def_BEH_PROFILE  true
    '...
    #if (def_BEH_PROFILE = TRUE)
      ' Enable blocks of performance profiling code:
      #define ifpro    #if 1
    #else
      ' Disable blocks of performance profiling code:
      #define ifpro    #if 0
    #endif
    #define elsepro  #else
    #define endpro   #endif
    '
    ifpro
      ' {PROFILE} 
      ' Global variables for performance profiling:
      '
      enum _pro__Func_enum Explicit
        ' Function names as numeric constants.
        _pro__FUNC_FIRST_ENUM = 0
            __FB_MAINPROC__
            my_MAIN
            get_cmdline
            set_options
            extract_stage_01
            extract_stage_02
        _pro__FUNC_LAST_ENUM
      end enum
      '
      type _pro__Func_typ
        dim as zstring*100   FnName = ""
        dim as integer       FnNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Func_typ gProFN(_pro__Func_enum._pro__FUNC_LAST_ENUM)
      '
      enum _pro__Action_enum Explicit
        ' Repeatable-Action names as numeric constants.
        _pro__ACTION_FIRST_ENUM = 0
            __extract_decimals
        _pro__ACTION_LAST_ENUM
      end enum
      '
      type _pro__Action_typ
        dim as zstring*100   ActName = ""
        dim as integer       ActNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Action_typ gProACT(_pro__Action_enum._pro__ACTION_LAST_ENUM)
    endpro
    '
    ifpro
      ' {PROFILE} 
      ' Macros for performance profiling of separate Functions: 
      #macro _pro__Func_ENTRY_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime = timer
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = false then
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnName = __FUNCTION__
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnNum = _pro__Func_enum.__FUNCTION_NQ__
        end if
      #endmacro
      '
      #macro _pro__Func_EXIT_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime = timer
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime - gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true then
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime < gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime > gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
        else
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        end if
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).TotTime += gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallCount += 1
      #endmacro
      '
      ' Macros for performance profiling of other repeatable Actions: 
      #macro _pro__Action_ENTRY_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).StartTime = timer
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = false then
          gProACT(_pro__Action_enum.m_Enum).ActName = #m_Enum
          gProACT(_pro__Action_enum.m_Enum).ActNum = _pro__Action_enum.m_Enum
        end if
      #endmacro
      '
      #macro _pro__Action_EXIT_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).EndTime = timer
        gProACT(_pro__Action_enum.m_Enum).CallTime = gProACT(_pro__Action_enum.m_Enum).EndTime - gProACT(_pro__Action_enum.m_Enum).StartTime
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = true then
          if gProACT(_pro__Action_enum.m_Enum).CallTime < gProACT(_pro__Action_enum.m_Enum).MinTime then
              gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
          if gProACT(_pro__Action_enum.m_Enum).CallTime > gProACT(_pro__Action_enum.m_Enum).MaxTime then
              gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
        else
          gProACT(_pro__Action_enum.m_Enum).isInitialized = true
          gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
        end if
        gProACT(_pro__Action_enum.m_Enum).TotTime += gProACT(_pro__Action_enum.m_Enum).CallTime
        gProACT(_pro__Action_enum.m_Enum).CallCount += 1
      #endmacro
    endpro
    '
' =======================================================================
'
type myVars__typ
  dim as double  aDbl
  dim as double  bDbl
  dim as zstring*50 abDblStr
end type
'
type TEST_overrides_typ
  ' To override options from command line - get_cmdline(). 
  ' To check for overrides - set_options(). 
  '
  ' Bit-flags that show if command line overrides are active. 
  ' Using a ULONG for the bit-field - 32 bits available. 
  dim as ulong NUM_SIG_DIGITS         : 1  = 0
  dim as ulong NUM_EXTRACT_INSTANCES  : 1  = 0
end type
'
type TEST_options_typ
  ' To programatically set values - set_options(). 
  ' To dynamically override from command line - get_cmdline(). 
  '
  ' Nested type with bit-flags that show if command line overrides are active: 
  dim as TEST_overrides_typ overrides
  ' Options - and default values:
  dim as integer NUM_SIG_DIGITS         = 7
  dim as integer NUM_EXTRACT_INSTANCES  = 5
end type
' Holds the current instances of options.
dim shared as TEST_options_typ  gOptUsing
' Holds the original options specified on the command line. 
dim shared as TEST_options_typ  gOptCmd
' Holds the original options specified in set_options(). 
dim shared as TEST_options_typ  gOptSet
'
' Used when comparing and ranging decimal characters. 
CONST as ubyte ASC_PLUS  = &h2B
CONST as ubyte ASC_MINUS = &h2D
CONST as ubyte ASC_DOT   = &h2E
CONST as ubyte ASC_ZERO  = &h30
CONST as ubyte ASC_ONE   = &h31
CONST as ubyte ASC_NINE  = &h39
CONST as ubyte ASC_LC_e  = &h65
CONST as ubyte ASC_UC_E  = &h45
' Used to bit-or with a letter character so we only have to compare for the uppercase character. 
CONST as ubyte ASC_UCASE2LCASE = &h20
'
' =======================================================================
'
declare Sub      my_MAIN()
declare Function get_cmdline() as integer
declare Sub      set_options()
declare Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
declare Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
'
' ============================================================
      ' Start Time. 
      dim as double t_start
      dim shared as integer gTestNum
      dim shared as integer gMaxTestNum
          '
          ifpro
            ' {PROFILE} 
            print
            print "Performance PROFILING is ON"
          elsepro
            print
            print "Performance PROFILING is OFF"
          endpro
          '
      t_start = timer
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_ENTRY_macro
          endpro
          '
      ' ----------------------------------------------------
      ' Run the individual tests from this loop. 
      ' ----------------------------------------------------
      gTestNum = 1
      gMaxTestNum = 1   'Set final size during first loop in myMain(). 
      do while gTestNum <= gMaxTestNum
        '
        my_MAIN()
        gTestNum += 1
        ' 
      loop
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_EXIT_macro
          endpro
          '
          ifpro
            ' {PROFILE} 
            print
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("F#", 4); "  "; 
            print "FuncName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "--------"
            '
            for i as integer = 0 to _pro__Func_enum._pro__FUNC_LAST_ENUM
              if gProFN(i).FnNum > -1 then
                print beh.pad(gProFN(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProFN(i).TotTime < 1.0, "< 1.0", format(gProFN(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MinTime < 1.0, "< 1.0", format(gProFN(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MaxTime < 1.0, "< 1.0", format(gProFN(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProFN(i).FnNum, 4); "  "; 
                print gProFN(i).FnName
              end if
            next
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("A#", 4); "  "; 
            print "ActionName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "---------"
            '
            for i as integer = 0 to _pro__Action_enum._pro__ACTION_LAST_ENUM
              if gProACT(i).ActNum > -1 then
                print beh.pad(gProACT(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProACT(i).TotTime < 1.0, "< 1.0", format(gProACT(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MinTime < 1.0, "< 1.0", format(gProACT(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MaxTime < 1.0, "< 1.0", format(gProACT(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProACT(i).ActNum, 4); "  "; 
                print gProACT(i).ActName
              end if
            next
            print
          endpro
          '
      print
      print "Time = "; str(timer - t_start)
      print "---------------------------------------------------------"
      print
      print
      '
    END
' ============================================================


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub my_MAIN()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim result as integer
  '
  RANDOMIZE , 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a random seed value.
  'RANDOMIZE 3.76543, 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a fixed value for repeatable results during testing.
  '
  if gTestNum = 1 then
      get_cmdline()
      set_options()
  end if
  '
  ' Reset original options for the next test.  
  gOptUsing = gOptSet
  '
  redim as myVars__typ myVars(1 to gOptUsing.NUM_EXTRACT_INSTANCES)
  '
  'START LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
  for extraction_num as integer = 1 to gOptSet.NUM_EXTRACT_INSTANCES
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' Note: Outside the action profile - so will not affect that timing.
    myVars(extraction_num).aDbl = rnd
    myVars(extraction_num).bDbl = rnd
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' 
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_ENTRY_macro(__extract_decimals)
        endpro
        '
    '------
    result = extract_stage_01(myVars(extraction_num), gOptUsing.NUM_SIG_DIGITS)
    '------
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_EXIT_macro(__extract_decimals)
        endpro
        '
  next
  'END   LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
END Sub  ''my_MAIN()


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim as zstring*50  ThisDblStr
  dim as integer     ThisDblStrLen
  dim as integer     digit_ct(1 to 2)  ' Significant Digit counter.
  '
  ' I replaced everything else I was doing in here with just two straight calls to
  ' this functions helper function that actually does all of the work to extract 
  ' significant digits from a double. 
  '
  ' BUT this function still takes a magnitude greater amount of time (via profiling) 
  ' to run then the helper function that it is calling twice per instance !!!
  for ij as integer = 1 to 2
    if ij = 1 then
      ' Process the first double. 
      ThisDblStr = str(myVars.aDbl)
      digit_ct(1) = extract_stage_02(ThisDblStr, num_digits)
    else
      ' Process the second double. 
      ThisDblStr = str(myVars.bDbl)
      digit_ct(2) = extract_stage_02(ThisDblStr, num_digits)
    end if
  next ij
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN (digit_ct(1) + digit_ct(2))
  '
end Function  ''extract_stage_01 OVERLOAD (myVars as myVars__typ, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  '------
  ' Find "."
  ' If asc_zero < previous_char <= asc_nine then first digit
  ' Gather N significant digits
  ' Find "Ee"
  ' If "Ee" then skip next_char (asc_sign) and gather digits to end-of-string
  '------
  dim as integer digit_ct  ' Significant Digit counter.
  dim as integer first_pos ' First Significant Digit position. 
  dim as integer last_pos  ' Last Significant Digit position. 
  dim as integer dot_pos   ' Decimal point "." byte position.
  dim as integer exp_pos   ' "E" or "e" byte position.
  dim as integer iout      ' Output byte position.
  dim as ubyte   byt
  dim as zstring*50 outStr
  '------
  digit_ct = 0
  first_pos = -1
  last_pos = -1
  dot_pos = -1
  exp_pos = -1
  iout = 0
  ' Find the decimal point "." and any exponent "E" or "e" character. 
  for ik as integer = 0 to (len(dblStr) - 1)
    if dblStr[ik] = ASC_DOT then
      ' Found the decimal point "." character. 
      dot_pos = ik
      continue for
    end if
    if ((dblStr[ik] or ASC_UCASE2LCASE) = ASC_LC_e) then 
      ' Found an exponent "E" or "e" character. 
      exp_pos = ik
      exit for
    end if
  next
  '
  ' Check to see if the digit preceding the decimal point is significant. 
  if dblStr[dot_pos - 1] > ASC_ZERO then
    ' Yes - this is our first significant digit. 
    first_pos = dot_pos - 1
    outStr[iout] = dblStr[first_pos]
    iout += 1
    digit_ct += 1
  end if
  '
  ' Do we have the first significant digit yet? 
  if first_pos >= 0 then
    ' Yes - go get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (dot_pos + num_digits - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  else
    ' No - go find the first significant digit after the decimal point and 
    ' then get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (len(dblStr) - 1)
      if (first_pos < 0) and (dblStr[ik] = ASC_ZERO) then
        ' Still looking for the first significant digit. 
        continue for
      end if
      ' Found the first significant digit past the decimal point. 
      first_pos = ik
      exit for
    next
    ' Now go get the rest of the significant digits. 
    for kk as integer = (first_pos) to (first_pos + num_digits - 1)
      outStr[iout] = dblStr[kk]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Now get any exponent digits that might be available. 
  if exp_pos >= 0 then
    ' Skip the "E/e" and "+/-" characters and just grab the digits. 
    for ik as integer = (exp_pos + 2) to (len(dblStr) - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Return the string of significant decimals extracted from this. 
  dblStr = outStr
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  ' Return the count of significant decimals extracted from this. 
  RETURN digit_ct
  '
end Function   ''extract_stage_02(dblStr as zstring, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function get_cmdline() as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  ' Parse command line arguments and override any previously set  
  ' options, as necessary. 
  ' 
  ' If there are any invalid parameter values, they will be 
  ' ignored and the default/set option values will be used. 
  '
  Dim As Integer cmd_parm_i
  Dim As String  arg 
  Dim as String  srch
  Dim As integer itmp 
  Dim As double  dtmp 
  Dim As String  stmp 
  '
  cmd_parm_i = 1
  Do
    arg = ucase(Command(cmd_parm_i))
    If Len(arg) = 0 Then
      Exit Do
    End If
    '
    srch = "TOT_TESTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gMaxTestNum = itmp
      end if
    end if
    '
    srch = "NUM_EXTRACTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 1
        gOptCmd.NUM_EXTRACT_INSTANCES = itmp
      end if
    end if
    '
    srch = "NUM_DIGITS="  ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 and itmp <= 18 then
        gOptCmd.overrides.NUM_SIG_DIGITS = 1
        gOptCmd.NUM_SIG_DIGITS = itmp
      end if
    end if
   '
    cmd_parm_i += 1
  Loop
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN 0
  '
end Function  ''get_cmdline()


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub set_options()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  if gOptCmd.overrides.NUM_SIG_DIGITS = 0 then
    gOptSet.NUM_SIG_DIGITS = 7
  else
    gOptSet.NUM_SIG_DIGITS = gOptCmd.NUM_SIG_DIGITS 
  end if
  '
  '
  if gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 0 then
    gOptSet.NUM_EXTRACT_INSTANCES  = 5 
  else
    gOptSet.NUM_EXTRACT_INSTANCES = gOptCmd.NUM_EXTRACT_INSTANCES 
  end if
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
end Sub  ''set_options()
fxm
Moderator
Posts: 12110
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Calling function does nothing but takes huge amount of time vs called function

Post by fxm »

Everything after this first line and up to the last line (end of extract_stage_02) does not count towards the runtime of extract_stage_02, but does count towards the runtime of extract_stage_01:

Code: Select all

 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).EndTime =timer
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime =gProFN(_pro__Func_enum. EXTRACT_STAGE_02).EndTime -gProFN(_pro__Func_enum. EXTRACT_STAGE_02).StartTime
 if gProFN(_pro__Func_enum. EXTRACT_STAGE_02).isInitialized =true then
 if gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime <gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MinTime then
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MinTime =gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime
 end if
 if gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime >gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MaxTime then
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MaxTime =gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime
 end if
 else
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).isInitialized =true
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MinTime =gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).MaxTime =gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime
 end if
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).TotTime +=gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallTime
 gProFN(_pro__Func_enum. EXTRACT_STAGE_02).CallCount +=1
 RETURN digit_ct
But this only counts for 0.25 second on the execution time of extract_stage_02.

Otherwise, this extra time for extract_stage_01 of 8 seconds minus 2*1 seconds (equal to 6 seconds) is the call time of 2*1000000 functions, so 3 microseconds per call + especially the context (keywords consuming time: TIMER and RND).
dodicat
Posts: 7983
Joined: Jan 10, 2006 20:30
Location: Scotland

Re: Calling function does nothing but takes huge amount of time vs called function

Post by dodicat »

...
mistake
...
I'll try again.
Last edited by dodicat on Feb 10, 2022 13:00, edited 1 time in total.
jj2007
Posts: 2326
Joined: Oct 23, 2016 15:28
Location: Roma, Italia
Contact:

Re: Calling function does nothing but takes huge amount of time vs called function

Post by jj2007 »

cbruce wrote: Feb 10, 2022 1:47Here is the updated code, with the RND() calls removed from the area in question
The result is PI:

Code: Select all

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      3.127624      3.127624      3.127624     1  __FB_MAINPROC__
      200000      3.097910         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     1000000      2.364588         < 1.0         < 1.0     5  EXTRACT_STAGE_01
     2000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     1000000      2.411479         < 1.0         < 1.0     1  __extract_decimals


Time = 3.145483327000193
Munair
Posts: 1286
Joined: Oct 19, 2017 15:00
Location: Netherlands
Contact:

Re: Calling function does nothing but takes huge amount of time vs called function

Post by Munair »

jj2007 wrote: Feb 10, 2022 12:21 [The result is PI
Off by 0,00389067341 :|
jj2007
Posts: 2326
Joined: Oct 23, 2016 15:28
Location: Roma, Italia
Contact:

Re: Calling function does nothing but takes huge amount of time vs called function

Post by jj2007 »

Munair wrote: Feb 10, 2022 15:08
jj2007 wrote: Feb 10, 2022 12:21 [The result is PI
Off by 0,00389067341 :|
Sorry, must be a rounding error 8)
cbruce
Posts: 166
Joined: Sep 12, 2007 19:13
Location: Dallas, Texas

Re: Calling function does nothing but takes huge amount of time vs called function

Post by cbruce »

There is a define that allows you to include/exclude the performance profiling code:
. #define def_BEH_PROFILE true
Just change that define to false and *ALL* profile code is *EXCLUDED* when compiling.

As you can see, excluding the profiling code does very little to reduce the overall time of a run:

Code: Select all

X:>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5

Performance PROFILING is ON

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      8.944856      8.944856      8.944856     1  __FB_MAINPROC__
     1000000      8.895521         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     5000000      7.019118         < 1.0         < 1.0     5  EXTRACT_STAGE_01
    10000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000      7.208149         < 1.0         < 1.0     1  __extract_decimals

Time = 8.97422789997654
---------------------------------------------------------


X:>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5

Performance PROFILING is OFF

Time = 8.309963700012304
---------------------------------------------------------
0.67 seconds difference in time for the two runs means that EXTRACT_STAGE_01() has magnitudes of overhead compared to the subroutine EXTRACT_STAGE_02() that it calls twice per instance ... and it is *NOT* the profiling code - and the RND()s are *outside* these calls.

So, my question still is... Where is all of the time in EXTRACT_STAGE_01() coming from?

Thanks!
CBruce

Note: If you run the stub with the parameters as given in the *examples* - then we'll be comparing apples-to-apples instead of trying to eat PI.
dodicat
Posts: 7983
Joined: Jan 10, 2006 20:30
Location: Scotland

Re: Calling function does nothing but takes huge amount of time vs called function

Post by dodicat »

The time spent in extract_stage_01 actually equals the time spent in extract_stage_01+the time spent in extract_stage_02(twice)
(you get your timings at the beginning and end of each function)
I can simulate, and adjusting parameters I can get quite a difference, as you have:

Code: Select all



#cmdline "-gen gcc -Wc -O2"
declare Function extract_stage_02(m as long) as integer
dim shared as double timein01,timein02

Function extract_stage_01(m as long) as integer
      var t=timer
      
     for n as long=1 to m
           rnd
           next
      
     extract_stage_02(1)
     extract_stage_02(1)
      var t2=timer
      timein01+=t2-t
      return 1
end function

Function extract_stage_02(m as long) as integer
      var t=timer
     for n as long=1 to m
           rnd
           next
      var t2=timer
      timein02+=t2-t
      return 1
end function

for n as long=1 to 9000000
    extract_stage_01(25)  
next 
print timein01,timein02
sleep


 
jj2007
Posts: 2326
Joined: Oct 23, 2016 15:28
Location: Roma, Italia
Contact:

Re: Calling function does nothing but takes huge amount of time vs called function

Post by jj2007 »

cbruce wrote: Feb 10, 2022 21:55Where is all of the time in EXTRACT_STAGE_01() coming from?
It's one procedure that is being called many times. So it takes a while, that's normal.
fxm
Moderator
Posts: 12110
Joined: Apr 22, 2009 12:46
Location: Paris suburbs, FRANCE

Re: Calling function does nothing but takes huge amount of time vs called function

Post by fxm »

cbruce wrote: Feb 10, 2022 1:47 Hi adeyblue! Thanks, but I just modified the code and moved the RND() calls outside all the performance counters for the two extract() functions. As you can see, that made a very minimal impact on the time that extract_stage_01() is profiling.
Most of the execution time of extract_stage_01 is due to the two STR() keywords.
If you move the two STR() calls outside as done for the two RND(), the execution time becomes small:

Code: Select all

' =======================================================================
' EXAMPLE COMMAND LINE: for running 1 million test() with 5 extract() per 
' test() that are each extracting 7 significant digits from each double; 
' for a total of 14 significant digits per extract(). 
' 
' X:\>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5 > dump__00__test_extract.txt
' =======================================================================
' EXAMPLE OUTPUT: 
' 
/'
Performance PROFILING is ON

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      8.956318      8.956318      8.956318     1  __FB_MAINPROC__
     1000000      8.906589         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
     5000000      7.032985         < 1.0         < 1.0     5  EXTRACT_STAGE_01
    10000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000      7.221917         < 1.0         < 1.0     1  __extract_decimals

Time = 8.957249599974603
'/
' =======================================================================
'
'  ===================================================================
type BEH_Program_Info__TYPE
  as const string Title    = "00__test_extract"
  as const string Version  = "0.4 (2022-01-29_2233)"
  as const string Author   = "Bruce E. Huber"
  '
  as const string SRC_File = "00__test_extract.bas"
end type
'
dim shared gBEH_Program_Info as BEH_Program_Info__TYPE
'  ===================================================================
'
'
' =======================================================================
' Includes: 
#include once "string.bi"    'For Format().
#include once "vbcompat.bi"  'For datetime serial functions.
' beh.pad() functions...
' ------------------------------------------------------------
namespace beh
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters: 
            ' // --------------------------------------------------
    declare function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
    declare function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
    declare function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters ...
            ' // --------------------------------------------------
            '
    function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
        dim result_str as string
        dim fill as string = string( fmt_width, asc(fill_char))
        pad_output_LR = ucase( pad_output_LR)
        if pad_output_LR = "L" then
                    'L' = Pad the LEFT side of the string. (default)
            if len( pad_this_str) <= fmt_width then
                result_str = right( fill + pad_this_str, fmt_width)
            else
                result_str = pad_this_str
            END IF
        else
                    'R' = Pad the RIGHT side of the string.
            if len( pad_this_str) <= fmt_width then
                result_str = left( pad_this_str + fill, fmt_width)
            else
                result_str = pad_this_str
            END IF
        endif
        return result_str
    END function  'PRIVATE__pad_output'
            '
    function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str( num_to_pad))
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function    'pad(double)'
            '
    function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str_to_pad)
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function  'pad(string)'
            '
            ' // --------------------------------------------------
            ' //   ... FUNC - Pad Strings with Fill Characters.
            ' // --------------------------------------------------
            '
end namespace  'beh'
' =======================================================================
'
'
' =======================================================================
    ' 
    ' ?Performance Profile mode?
    #define  def_BEH_PROFILE  true
    '...
    #if (def_BEH_PROFILE = TRUE)
      ' Enable blocks of performance profiling code:
      #define ifpro    #if 1
    #else
      ' Disable blocks of performance profiling code:
      #define ifpro    #if 0
    #endif
    #define elsepro  #else
    #define endpro   #endif
    '
    ifpro
      ' {PROFILE} 
      ' Global variables for performance profiling:
      '
      enum _pro__Func_enum Explicit
        ' Function names as numeric constants.
        _pro__FUNC_FIRST_ENUM = 0
            __FB_MAINPROC__
            my_MAIN
            get_cmdline
            set_options
            extract_stage_01
            extract_stage_02
        _pro__FUNC_LAST_ENUM
      end enum
      '
      type _pro__Func_typ
        dim as zstring*100   FnName = ""
        dim as integer       FnNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Func_typ gProFN(_pro__Func_enum._pro__FUNC_LAST_ENUM)
      '
      enum _pro__Action_enum Explicit
        ' Repeatable-Action names as numeric constants.
        _pro__ACTION_FIRST_ENUM = 0
            __extract_decimals
        _pro__ACTION_LAST_ENUM
      end enum
      '
      type _pro__Action_typ
        dim as zstring*100   ActName = ""
        dim as integer       ActNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Action_typ gProACT(_pro__Action_enum._pro__ACTION_LAST_ENUM)
    endpro
    '
    ifpro
      ' {PROFILE} 
      ' Macros for performance profiling of separate Functions: 
      #macro _pro__Func_ENTRY_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime = timer
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = false then
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnName = __FUNCTION__
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnNum = _pro__Func_enum.__FUNCTION_NQ__
        end if
      #endmacro
      '
      #macro _pro__Func_EXIT_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime = timer
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime - gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true then
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime < gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime > gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
        else
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        end if
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).TotTime += gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallCount += 1
      #endmacro
      '
      ' Macros for performance profiling of other repeatable Actions: 
      #macro _pro__Action_ENTRY_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).StartTime = timer
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = false then
          gProACT(_pro__Action_enum.m_Enum).ActName = #m_Enum
          gProACT(_pro__Action_enum.m_Enum).ActNum = _pro__Action_enum.m_Enum
        end if
      #endmacro
      '
      #macro _pro__Action_EXIT_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).EndTime = timer
        gProACT(_pro__Action_enum.m_Enum).CallTime = gProACT(_pro__Action_enum.m_Enum).EndTime - gProACT(_pro__Action_enum.m_Enum).StartTime
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = true then
          if gProACT(_pro__Action_enum.m_Enum).CallTime < gProACT(_pro__Action_enum.m_Enum).MinTime then
              gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
          if gProACT(_pro__Action_enum.m_Enum).CallTime > gProACT(_pro__Action_enum.m_Enum).MaxTime then
              gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
        else
          gProACT(_pro__Action_enum.m_Enum).isInitialized = true
          gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
        end if
        gProACT(_pro__Action_enum.m_Enum).TotTime += gProACT(_pro__Action_enum.m_Enum).CallTime
        gProACT(_pro__Action_enum.m_Enum).CallCount += 1
      #endmacro
    endpro
    '
' =======================================================================
'
type myVars__typ
  dim as zstring*50 zsaDbl
  dim as zstring*50 zsbDbl
end type
'
type TEST_overrides_typ
  ' To override options from command line - get_cmdline(). 
  ' To check for overrides - set_options(). 
  '
  ' Bit-flags that show if command line overrides are active. 
  ' Using a ULONG for the bit-field - 32 bits available. 
  dim as ulong NUM_SIG_DIGITS         : 1  = 0
  dim as ulong NUM_EXTRACT_INSTANCES  : 1  = 0
end type
'
type TEST_options_typ
  ' To programatically set values - set_options(). 
  ' To dynamically override from command line - get_cmdline(). 
  '
  ' Nested type with bit-flags that show if command line overrides are active: 
  dim as TEST_overrides_typ overrides
  ' Options - and default values:
  dim as integer NUM_SIG_DIGITS         = 7
  dim as integer NUM_EXTRACT_INSTANCES  = 5
end type
' Holds the current instances of options.
dim shared as TEST_options_typ  gOptUsing
' Holds the original options specified on the command line. 
dim shared as TEST_options_typ  gOptCmd
' Holds the original options specified in set_options(). 
dim shared as TEST_options_typ  gOptSet
'
' Used when comparing and ranging decimal characters. 
CONST as ubyte ASC_PLUS  = &h2B
CONST as ubyte ASC_MINUS = &h2D
CONST as ubyte ASC_DOT   = &h2E
CONST as ubyte ASC_ZERO  = &h30
CONST as ubyte ASC_ONE   = &h31
CONST as ubyte ASC_NINE  = &h39
CONST as ubyte ASC_LC_e  = &h65
CONST as ubyte ASC_UC_E  = &h45
' Used to bit-or with a letter character so we only have to compare for the uppercase character. 
CONST as ubyte ASC_UCASE2LCASE = &h20
'
' =======================================================================
'
declare Sub      my_MAIN()
declare Function get_cmdline() as integer
declare Sub      set_options()
declare Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
declare Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
'
' ============================================================
      ' Start Time. 
      dim as double t_start
      dim shared as integer gTestNum
      dim shared as integer gMaxTestNum
          '
          ifpro
            ' {PROFILE} 
            print
            print "Performance PROFILING is ON"
          elsepro
            print
            print "Performance PROFILING is OFF"
          endpro
          '
      t_start = timer
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_ENTRY_macro
          endpro
          '
      ' ----------------------------------------------------
      ' Run the individual tests from this loop. 
      ' ----------------------------------------------------
      gTestNum = 1
      gMaxTestNum = 1   'Set final size during first loop in myMain(). 
      do while gTestNum <= gMaxTestNum
        '
        my_MAIN()
        gTestNum += 1
        ' 
      loop
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_EXIT_macro
          endpro
          '
          ifpro
            ' {PROFILE} 
            print
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("F#", 4); "  "; 
            print "FuncName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "--------"
            '
            for i as integer = 0 to _pro__Func_enum._pro__FUNC_LAST_ENUM
              if gProFN(i).FnNum > -1 then
                print beh.pad(gProFN(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProFN(i).TotTime < 1.0, "< 1.0", format(gProFN(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MinTime < 1.0, "< 1.0", format(gProFN(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MaxTime < 1.0, "< 1.0", format(gProFN(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProFN(i).FnNum, 4); "  "; 
                print gProFN(i).FnName
              end if
            next
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("A#", 4); "  "; 
            print "ActionName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "---------"
            '
            for i as integer = 0 to _pro__Action_enum._pro__ACTION_LAST_ENUM
              if gProACT(i).ActNum > -1 then
                print beh.pad(gProACT(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProACT(i).TotTime < 1.0, "< 1.0", format(gProACT(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MinTime < 1.0, "< 1.0", format(gProACT(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MaxTime < 1.0, "< 1.0", format(gProACT(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProACT(i).ActNum, 4); "  "; 
                print gProACT(i).ActName
              end if
            next
            print
          endpro
          '
      print
      print "Time = "; str(timer - t_start)
      print "---------------------------------------------------------"
      print
      print
      '
    END
' ============================================================


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub my_MAIN()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim result as integer
  '
  RANDOMIZE , 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a random seed value.
  'RANDOMIZE 3.76543, 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a fixed value for repeatable results during testing.
  '
  if gTestNum = 1 then
      get_cmdline()
      set_options()
  end if
  '
  ' Reset original options for the next test.  
  gOptUsing = gOptSet
  '
  redim as myVars__typ myVars(1 to gOptUsing.NUM_EXTRACT_INSTANCES)
  '
  'START LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
  for extraction_num as integer = 1 to gOptSet.NUM_EXTRACT_INSTANCES
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' Note: Outside the action profile - so will not affect that timing.
    myVars(extraction_num).zsaDbl = str(rnd)
    myVars(extraction_num).zsbDbl = str(rnd)
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' 
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_ENTRY_macro(__extract_decimals)
        endpro
        '
    '------
    result = extract_stage_01(myVars(extraction_num), gOptUsing.NUM_SIG_DIGITS)
    '------
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_EXIT_macro(__extract_decimals)
        endpro
        '
  next
  'END   LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
END Sub  ''my_MAIN()


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim as zstring*50  ThisDblStr
  dim as integer     ThisDblStrLen
  dim as integer     digit_ct(1 to 2)  ' Significant Digit counter.
  '
  ' I replaced everything else I was doing in here with just two straight calls to
  ' this functions helper function that actually does all of the work to extract 
  ' significant digits from a double. 
  '
  ' BUT this function still takes a magnitude greater amount of time (via profiling) 
  ' to run then the helper function that it is calling twice per instance !!!
  for ij as integer = 1 to 2
    if ij = 1 then
      ' Process the first double. 
      ThisDblStr = myVars.zsaDbl
      digit_ct(1) = extract_stage_02(ThisDblStr, num_digits)
    else
      ' Process the second double. 
      ThisDblStr = myVars.zsbDbl
      digit_ct(2) = extract_stage_02(ThisDblStr, num_digits)
    end if
  next ij
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN (digit_ct(1) + digit_ct(2))
  '
end Function  ''extract_stage_01 OVERLOAD (myVars as myVars__typ, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  '------
  ' Find "."
  ' If asc_zero < previous_char <= asc_nine then first digit
  ' Gather N significant digits
  ' Find "Ee"
  ' If "Ee" then skip next_char (asc_sign) and gather digits to end-of-string
  '------
  dim as integer digit_ct  ' Significant Digit counter.
  dim as integer first_pos ' First Significant Digit position. 
  dim as integer last_pos  ' Last Significant Digit position. 
  dim as integer dot_pos   ' Decimal point "." byte position.
  dim as integer exp_pos   ' "E" or "e" byte position.
  dim as integer iout      ' Output byte position.
  dim as ubyte   byt
  dim as zstring*50 outStr
  '------
  digit_ct = 0
  first_pos = -1
  last_pos = -1
  dot_pos = -1
  exp_pos = -1
  iout = 0
  ' Find the decimal point "." and any exponent "E" or "e" character. 
  for ik as integer = 0 to (len(dblStr) - 1)
    if dblStr[ik] = ASC_DOT then
      ' Found the decimal point "." character. 
      dot_pos = ik
      continue for
    end if
    if ((dblStr[ik] or ASC_UCASE2LCASE) = ASC_LC_e) then 
      ' Found an exponent "E" or "e" character. 
      exp_pos = ik
      exit for
    end if
  next
  '
  ' Check to see if the digit preceding the decimal point is significant. 
  if dblStr[dot_pos - 1] > ASC_ZERO then
    ' Yes - this is our first significant digit. 
    first_pos = dot_pos - 1
    outStr[iout] = dblStr[first_pos]
    iout += 1
    digit_ct += 1
  end if
  '
  ' Do we have the first significant digit yet? 
  if first_pos >= 0 then
    ' Yes - go get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (dot_pos + num_digits - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  else
    ' No - go find the first significant digit after the decimal point and 
    ' then get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (len(dblStr) - 1)
      if (first_pos < 0) and (dblStr[ik] = ASC_ZERO) then
        ' Still looking for the first significant digit. 
        continue for
      end if
      ' Found the first significant digit past the decimal point. 
      first_pos = ik
      exit for
    next
    ' Now go get the rest of the significant digits. 
    for kk as integer = (first_pos) to (first_pos + num_digits - 1)
      outStr[iout] = dblStr[kk]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Now get any exponent digits that might be available. 
  if exp_pos >= 0 then
    ' Skip the "E/e" and "+/-" characters and just grab the digits. 
    for ik as integer = (exp_pos + 2) to (len(dblStr) - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Return the string of significant decimals extracted from this. 
  dblStr = outStr
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  ' Return the count of significant decimals extracted from this. 
  RETURN digit_ct
  '
end Function   ''extract_stage_02(dblStr as zstring, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function get_cmdline() as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  ' Parse command line arguments and override any previously set  
  ' options, as necessary. 
  ' 
  ' If there are any invalid parameter values, they will be 
  ' ignored and the default/set option values will be used. 
  '
  Dim As Integer cmd_parm_i
  Dim As String  arg 
  Dim as String  srch
  Dim As integer itmp 
  Dim As double  dtmp 
  Dim As String  stmp 
  '
  cmd_parm_i = 1
  Do
    arg = ucase(Command(cmd_parm_i))
    If Len(arg) = 0 Then
      Exit Do
    End If
    '
    srch = "TOT_TESTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gMaxTestNum = itmp
      end if
    end if
    '
    srch = "NUM_EXTRACTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 1
        gOptCmd.NUM_EXTRACT_INSTANCES = itmp
      end if
    end if
    '
    srch = "NUM_DIGITS="  ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 and itmp <= 18 then
        gOptCmd.overrides.NUM_SIG_DIGITS = 1
        gOptCmd.NUM_SIG_DIGITS = itmp
      end if
    end if
   '
    cmd_parm_i += 1
  Loop
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN 0
  '
end Function  ''get_cmdline()


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub set_options()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  if gOptCmd.overrides.NUM_SIG_DIGITS = 0 then
    gOptSet.NUM_SIG_DIGITS = 7
  else
    gOptSet.NUM_SIG_DIGITS = gOptCmd.NUM_SIG_DIGITS 
  end if
  '
  '
  if gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 0 then
    gOptSet.NUM_EXTRACT_INSTANCES  = 5 
  else
    gOptSet.NUM_EXTRACT_INSTANCES = gOptCmd.NUM_EXTRACT_INSTANCES 
  end if
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
end Sub  ''set_options()
cbruce
Posts: 166
Joined: Sep 12, 2007 19:13
Location: Dallas, Texas

Re: Calling function does nothing but takes huge amount of time vs called function

Post by cbruce »

Ok, I *CANNOT* do this with my real code, because there is too much other stuff going on in EXTRACT_STAGE_01().

But, with this test stub we are working with... I commented out EXTRACT_STAGE_01() and inlined the two calls to EXTRACT_STAGE_02() in the MAIN() itself.

The ACTION profiling in the test stub normally wrapped the call to EXTRACT_STAGE_01()... which also saw FUNCTION profiling from inside the function itself. That meant that the ACTION profiling was always a little greater than the FUNCTION profiling; as you could see in the outputs.

Now, the ACTION profiling is just wrapping the two setups and calls of EXTRACT_STAGE_02().

The *ONLY* difference is that we no longer have the overhead of calling EXTRACT_STAGE_01().
-- @fxm, please note: The STR() calls, etc. still exist there in the inlined code and are still included in the ACTION profiling.

Please note the *MASSIVE* difference in run time (whether profiling is on/off) with the inlined calls to EXTRACT_STAGE_02() compared to making those same calls from EXTRACT_STAGE_01().
-- (see the example results at the top of the following *NEW* code and compare them to the example results in previous posts)

The "__extract_decimals" ACTION profile shows 1.721487 seconds for the inlined code (here) vs 7.208149 seconds for the same code when run from EXTRACT_STAGE_01() (as seen in previous posts).

How does running the same code from the EXTRACT_STAGE_01() function vs that code inlined in MAIN() cause a *4 TIMES* increase in runtime?

Code: Select all

' =======================================================================
' EXAMPLE COMMAND LINE: for running 1 million test() with 5 extract() per 
' test() that are each extracting 7 significant digits from each double; 
' for a total of 14 significant digits per extract(). 
' 
' X:\>00__test_extract.exe  num_digits=7 tot_tests=1000000 num_extracts=5 > dump__00__test_extract.txt
' =======================================================================
' EXAMPLE OUTPUT: 
' 
/'
---------------------------------------------------------
Performance PROFILING is ON

Testing with: EXTRACT_STAGE_01() REMOVED and its CODE NOW INLINED in MAIN()

   CallCount       TotTime       MinTime       MaxTime    F#  FuncName
   ---------       -------       -------       -------   ---  --------
           1      3.480434      3.480434      3.480434     1  __FB_MAINPROC__
     1000000      3.400812         < 1.0         < 1.0     2  MY_MAIN
           1         < 1.0         < 1.0         < 1.0     3  GET_CMDLINE
           1         < 1.0         < 1.0         < 1.0     4  SET_OPTIONS
    10000000         < 1.0         < 1.0         < 1.0     6  EXTRACT_STAGE_02

   CallCount       TotTime       MinTime       MaxTime    A#  ActionName
   ---------       -------       -------       -------   ---  ---------
     5000000      1.721487         < 1.0         < 1.0     1  __extract_decimals


Time = 3.508637699997053
---------------------------------------------------------


---------------------------------------------------------
Performance PROFILING is OFF

Testing with: EXTRACT_STAGE_01() REMOVED and its CODE NOW INLINED in MAIN()

Time = 2.937173100013752
---------------------------------------------------------
'/
' =======================================================================
'
'  ===================================================================
type BEH_Program_Info__TYPE
  as const string Title    = "00__test_extract"
  as const string Version  = "0.4 (2022-01-29_2233)"
  as const string Author   = "Bruce E. Huber"
  '
  as const string SRC_File = "00__test_extract.bas"
end type
'
dim shared gBEH_Program_Info as BEH_Program_Info__TYPE
'  ===================================================================
'
'
' =======================================================================
' Includes: 
#include once "string.bi"    'For Format().
#include once "vbcompat.bi"  'For datetime serial functions.
' beh.pad() functions...
' ------------------------------------------------------------
namespace beh
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters: 
            ' // --------------------------------------------------
    declare function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
    declare function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
    declare function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
            ' // --------------------------------------------------
            ' //   FUNC - Pad Strings with Fill Characters ...
            ' // --------------------------------------------------
            '
    function PRIVATE__pad_output( pad_this_str as string, fmt_width as ulong, pad_output_LR as string, fill_char as string = " ") as String
        dim result_str as string
        dim fill as string = string( fmt_width, asc(fill_char))
        pad_output_LR = ucase( pad_output_LR)
        if pad_output_LR = "L" then
                    'L' = Pad the LEFT side of the string. (default)
            if len( pad_this_str) <= fmt_width then
                result_str = right( fill + pad_this_str, fmt_width)
            else
                result_str = pad_this_str
            END IF
        else
                    'R' = Pad the RIGHT side of the string.
            if len( pad_this_str) <= fmt_width then
                result_str = left( pad_this_str + fill, fmt_width)
            else
                result_str = pad_this_str
            END IF
        endif
        return result_str
    END function  'PRIVATE__pad_output'
            '
    function pad overload ( num_to_pad as double, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str( num_to_pad))
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function    'pad(double)'
            '
    function pad overload ( str_to_pad as string, fmt_width as ulong = 0, pad_output_LR as string = "L", fill_char as string = " ") as string
        dim result_str as string
        dim pad_this_str as String = trim( str_to_pad)
        if fmt_width = 0 then
            return pad_this_str
        END IF
                'L' = Pad the LEFT side of the string. (default)
                'R' = Pad the RIGHT side of the string.
        result_str = PRIVATE__pad_output( pad_this_str, fmt_width, pad_output_LR, fill_char)
        return result_str
    END function  'pad(string)'
            '
            ' // --------------------------------------------------
            ' //   ... FUNC - Pad Strings with Fill Characters.
            ' // --------------------------------------------------
            '
end namespace  'beh'
' =======================================================================
'
'
' =======================================================================
    ' 
    ' ?Performance Profile mode?
    #define  def_BEH_PROFILE  true
    '...
    #if (def_BEH_PROFILE = TRUE)
      ' Enable blocks of performance profiling code:
      #define ifpro    #if 1
    #else
      ' Disable blocks of performance profiling code:
      #define ifpro    #if 0
    #endif
    #define elsepro  #else
    #define endpro   #endif
    '
    ifpro
      ' {PROFILE} 
      ' Global variables for performance profiling:
      '
      enum _pro__Func_enum Explicit
        ' Function names as numeric constants.
        _pro__FUNC_FIRST_ENUM = 0
            __FB_MAINPROC__
            my_MAIN
            get_cmdline
            set_options
            extract_stage_01
            extract_stage_02
        _pro__FUNC_LAST_ENUM
      end enum
      '
      type _pro__Func_typ
        dim as zstring*100   FnName = ""
        dim as integer       FnNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Func_typ gProFN(_pro__Func_enum._pro__FUNC_LAST_ENUM)
      '
      enum _pro__Action_enum Explicit
        ' Repeatable-Action names as numeric constants.
        _pro__ACTION_FIRST_ENUM = 0
            __extract_decimals
        _pro__ACTION_LAST_ENUM
      end enum
      '
      type _pro__Action_typ
        dim as zstring*100   ActName = ""
        dim as integer       ActNum = -1
        dim as integer       CallCount = 0
        dim as integer       isInitialized = false
        dim as double        StartTime = 0.0
        dim as double        EndTime = 0.0
        dim as double        CallTime = 0.0
        dim as double        MinTime = 0.0
        dim as double        MaxTime = 0.0
        dim as double        TotTime = 0.0
      end type
      dim shared as _pro__Action_typ gProACT(_pro__Action_enum._pro__ACTION_LAST_ENUM)
    endpro
    '
    ifpro
      ' {PROFILE} 
      ' Macros for performance profiling of separate Functions: 
      #macro _pro__Func_ENTRY_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime = timer
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = false then
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnName = __FUNCTION__
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).FnNum = _pro__Func_enum.__FUNCTION_NQ__
        end if
      #endmacro
      '
      #macro _pro__Func_EXIT_macro
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime = timer
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).EndTime - gProFN(_pro__Func_enum.__FUNCTION_NQ__).StartTime
        if gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true then
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime < gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
          if gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime > gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime then
              gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          end if
        else
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).isInitialized = true
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MinTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
          gProFN(_pro__Func_enum.__FUNCTION_NQ__).MaxTime = gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        end if
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).TotTime += gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallTime
        gProFN(_pro__Func_enum.__FUNCTION_NQ__).CallCount += 1
      #endmacro
      '
      ' Macros for performance profiling of other repeatable Actions: 
      #macro _pro__Action_ENTRY_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).StartTime = timer
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = false then
          gProACT(_pro__Action_enum.m_Enum).ActName = #m_Enum
          gProACT(_pro__Action_enum.m_Enum).ActNum = _pro__Action_enum.m_Enum
        end if
      #endmacro
      '
      #macro _pro__Action_EXIT_macro(m_Enum)
        gProACT(_pro__Action_enum.m_Enum).EndTime = timer
        gProACT(_pro__Action_enum.m_Enum).CallTime = gProACT(_pro__Action_enum.m_Enum).EndTime - gProACT(_pro__Action_enum.m_Enum).StartTime
        if gProACT(_pro__Action_enum.m_Enum).isInitialized = true then
          if gProACT(_pro__Action_enum.m_Enum).CallTime < gProACT(_pro__Action_enum.m_Enum).MinTime then
              gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
          if gProACT(_pro__Action_enum.m_Enum).CallTime > gProACT(_pro__Action_enum.m_Enum).MaxTime then
              gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          end if
        else
          gProACT(_pro__Action_enum.m_Enum).isInitialized = true
          gProACT(_pro__Action_enum.m_Enum).MinTime = gProACT(_pro__Action_enum.m_Enum).CallTime
          gProACT(_pro__Action_enum.m_Enum).MaxTime = gProACT(_pro__Action_enum.m_Enum).CallTime
        end if
        gProACT(_pro__Action_enum.m_Enum).TotTime += gProACT(_pro__Action_enum.m_Enum).CallTime
        gProACT(_pro__Action_enum.m_Enum).CallCount += 1
      #endmacro
    endpro
    '
' =======================================================================
'
type myVars__typ
  dim as double  aDbl
  dim as double  bDbl
  dim as zstring*50 abDblStr
end type
'
type TEST_overrides_typ
  ' To override options from command line - get_cmdline(). 
  ' To check for overrides - set_options(). 
  '
  ' Bit-flags that show if command line overrides are active. 
  ' Using a ULONG for the bit-field - 32 bits available. 
  dim as ulong NUM_SIG_DIGITS         : 1  = 0
  dim as ulong NUM_EXTRACT_INSTANCES  : 1  = 0
end type
'
type TEST_options_typ
  ' To programatically set values - set_options(). 
  ' To dynamically override from command line - get_cmdline(). 
  '
  ' Nested type with bit-flags that show if command line overrides are active: 
  dim as TEST_overrides_typ overrides
  ' Options - and default values:
  dim as integer NUM_SIG_DIGITS         = 7
  dim as integer NUM_EXTRACT_INSTANCES  = 5
end type
' Holds the current instances of options.
dim shared as TEST_options_typ  gOptUsing
' Holds the original options specified on the command line. 
dim shared as TEST_options_typ  gOptCmd
' Holds the original options specified in set_options(). 
dim shared as TEST_options_typ  gOptSet
'
' Used when comparing and ranging decimal characters. 
CONST as ubyte ASC_PLUS  = &h2B
CONST as ubyte ASC_MINUS = &h2D
CONST as ubyte ASC_DOT   = &h2E
CONST as ubyte ASC_ZERO  = &h30
CONST as ubyte ASC_ONE   = &h31
CONST as ubyte ASC_NINE  = &h39
CONST as ubyte ASC_LC_e  = &h65
CONST as ubyte ASC_UC_E  = &h45
' Used to bit-or with a letter character so we only have to compare for the uppercase character. 
CONST as ubyte ASC_UCASE2LCASE = &h20
'
' =======================================================================
'
declare Sub      my_MAIN()
declare Function get_cmdline() as integer
declare Sub      set_options()
declare Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
declare Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
'
' ============================================================
      ' Start Time. 
      dim as double t_start
      dim shared as integer gTestNum
      dim shared as integer gMaxTestNum
          '
          ifpro
            ' {PROFILE} 
            print
            print "Performance PROFILING is ON"
          elsepro
            print
            print "Performance PROFILING is OFF"
          endpro
          '
      t_start = timer
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_ENTRY_macro
          endpro
          '
      ' ----------------------------------------------------
      ' Run the individual tests from this loop. 
      ' ----------------------------------------------------
      gTestNum = 1
      gMaxTestNum = 1   'Set final size during first loop in myMain(). 
      do while gTestNum <= gMaxTestNum
        '
        my_MAIN()
        gTestNum += 1
        ' 
      loop
          '
          ifpro
            ' {PROFILE} 
            _pro__Func_EXIT_macro
          endpro
          '
          ifpro
            ' {PROFILE} 
            print
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("F#", 4); "  "; 
            print "FuncName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "--------"
            '
            for i as integer = 0 to _pro__Func_enum._pro__FUNC_LAST_ENUM
              if gProFN(i).FnNum > -1 then
                print beh.pad(gProFN(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProFN(i).TotTime < 1.0, "< 1.0", format(gProFN(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MinTime < 1.0, "< 1.0", format(gProFN(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProFN(i).MaxTime < 1.0, "< 1.0", format(gProFN(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProFN(i).FnNum, 4); "  "; 
                print gProFN(i).FnName
              end if
            next
            print
            '
            print beh.pad("CallCount", 12); "  "; 
            print beh.pad("TotTime", 12); "  "; 
            print beh.pad("MinTime", 12); "  "; 
            print beh.pad("MaxTime", 12); "  "; 
            print beh.pad("A#", 4); "  "; 
            print "ActionName"
            '
            print beh.pad("---------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("-------", 12); "  "; 
            print beh.pad("---", 4); "  "; 
            print "---------"
            '
            for i as integer = 0 to _pro__Action_enum._pro__ACTION_LAST_ENUM
              if gProACT(i).ActNum > -1 then
                print beh.pad(gProACT(i).CallCount, 12); "  "; 
                print beh.pad(iif(gProACT(i).TotTime < 1.0, "< 1.0", format(gProACT(i).TotTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MinTime < 1.0, "< 1.0", format(gProACT(i).MinTime,"#0.000000")), 12); "  "; 
                print beh.pad(iif(gProACT(i).MaxTime < 1.0, "< 1.0", format(gProACT(i).MaxTime,"#0.000000")), 12); "  "; 
                print beh.pad(gProACT(i).ActNum, 4); "  "; 
                print gProACT(i).ActName
              end if
            next
            print
          endpro
          '
      print
      print "Time = "; str(timer - t_start)
      print "---------------------------------------------------------"
      print
      print
      '
    END
' ============================================================


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub my_MAIN()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  dim result as integer
  '
  '------
  ' *** MOVED CODE FROM TEST STUB'S EXTRACT_STAGE_01() TO INLINE HERE IN THE MAIN() ***
  dim aDbl as integer
  dim bDbl as integer
  dim as integer     digit_ct1  ' Significant Digit counter.
  dim as integer     digit_ct2  ' Significant Digit counter.
  dim as integer     xxx
  dim as string      nextDbl
  '------
  '
  RANDOMIZE , 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a random seed value.
  'RANDOMIZE 3.76543, 3  ' Choose FreeBASIC Mersienne Twister RND() and seed it with a fixed value for repeatable results during testing.
  '
  if gTestNum = 1 then
      get_cmdline()
      set_options()
  end if
  '
  ' Reset original options for the next test.  
  gOptUsing = gOptSet
  '
  redim as myVars__typ myVars(1 to gOptUsing.NUM_EXTRACT_INSTANCES)
  '
  'START LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
  for extraction_num as integer = 1 to gOptSet.NUM_EXTRACT_INSTANCES
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' Note: Outside the action profile - so will not affect that timing.
    myVars(extraction_num).aDbl = rnd
    myVars(extraction_num).bDbl = rnd
    ' ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    ' 
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_ENTRY_macro(__extract_decimals)
        endpro
        '
    '------
    '''result = extract_stage_01(myVars(extraction_num), gOptUsing.NUM_SIG_DIGITS)
    '
    ' *** MOVED CODE FROM TEST STUB'S EXTRACT_STAGE_01() TO INLINE HERE IN THE MAIN() ***
    '
    ' Process the first double. 
    nextDbl = str(aDbl)
    digit_ct1 = extract_stage_02(nextDbl, gOptUsing.NUM_SIG_DIGITS)
    ' Process the second double. 
    nextDbl = str(bDbl)
    digit_ct2 = extract_stage_02(nextDbl, gOptUsing.NUM_SIG_DIGITS)
    xxx = digit_ct1 + digit_ct2
    '------
        '
        ifpro
          ' {PROFILE} 
          _pro__Action_EXIT_macro(__extract_decimals)
        endpro
        '
  next
  'END   LOOP 004 >>>>>>>>>>>>>>>>>>>>>>
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
END Sub  ''my_MAIN()


'' ------------------------------------------------------------
'' ------------------------------------------------------------
'Function extract_stage_01(myVars as myVars__typ, num_digits as integer) as integer
'      '
'      ifpro
'        ' {PROFILE} 
'        _pro__Func_ENTRY_macro
'      endpro
'      '
'  dim as zstring*50  ThisDblStr
'  dim as integer     ThisDblStrLen
'  dim as integer     digit_ct(1 to 2)  ' Significant Digit counter.
'  '
'  ' I replaced everything else I was doing in here with just two straight calls to
'  ' this functions helper function that actually does all of the work to extract 
'  ' significant digits from a double. 
'  '
'  ' BUT this function still takes a magnitude greater amount of time (via profiling) 
'  ' to run then the helper function that it is calling twice per instance !!!
'  for ij as integer = 1 to 2
'    if ij = 1 then
'      ' Process the first double. 
'      ThisDblStr = str(myVars.aDbl)
'      digit_ct(1) = extract_stage_02(ThisDblStr, num_digits)
'    else
'      ' Process the second double. 
'      ThisDblStr = str(myVars.bDbl)
'      digit_ct(2) = extract_stage_02(ThisDblStr, num_digits)
'    end if
'  next ij
'      '
'      ifpro
'        ' {PROFILE} 
'        _pro__Func_EXIT_macro
'      endpro
'      '
'  RETURN (digit_ct(1) + digit_ct(2))
'  '
'end Function  ''extract_stage_01 OVERLOAD (myVars as myVars__typ, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function extract_stage_02(dblStr as zstring, num_digits as integer) as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  '------
  ' Find "."
  ' If asc_zero < previous_char <= asc_nine then first digit
  ' Gather N significant digits
  ' Find "Ee"
  ' If "Ee" then skip next_char (asc_sign) and gather digits to end-of-string
  '------
  dim as integer digit_ct  ' Significant Digit counter.
  dim as integer first_pos ' First Significant Digit position. 
  dim as integer last_pos  ' Last Significant Digit position. 
  dim as integer dot_pos   ' Decimal point "." byte position.
  dim as integer exp_pos   ' "E" or "e" byte position.
  dim as integer iout      ' Output byte position.
  dim as ubyte   byt
  dim as zstring*50 outStr
  '------
  digit_ct = 0
  first_pos = -1
  last_pos = -1
  dot_pos = -1
  exp_pos = -1
  iout = 0
  ' Find the decimal point "." and any exponent "E" or "e" character. 
  for ik as integer = 0 to (len(dblStr) - 1)
    if dblStr[ik] = ASC_DOT then
      ' Found the decimal point "." character. 
      dot_pos = ik
      continue for
    end if
    if ((dblStr[ik] or ASC_UCASE2LCASE) = ASC_LC_e) then 
      ' Found an exponent "E" or "e" character. 
      exp_pos = ik
      exit for
    end if
  next
  '
  ' Check to see if the digit preceding the decimal point is significant. 
  if dblStr[dot_pos - 1] > ASC_ZERO then
    ' Yes - this is our first significant digit. 
    first_pos = dot_pos - 1
    outStr[iout] = dblStr[first_pos]
    iout += 1
    digit_ct += 1
  end if
  '
  ' Do we have the first significant digit yet? 
  if first_pos >= 0 then
    ' Yes - go get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (dot_pos + num_digits - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  else
    ' No - go find the first significant digit after the decimal point and 
    ' then get the rest of the significant digits. 
    for ik as integer = (dot_pos + 1) to (len(dblStr) - 1)
      if (first_pos < 0) and (dblStr[ik] = ASC_ZERO) then
        ' Still looking for the first significant digit. 
        continue for
      end if
      ' Found the first significant digit past the decimal point. 
      first_pos = ik
      exit for
    next
    ' Now go get the rest of the significant digits. 
    for kk as integer = (first_pos) to (first_pos + num_digits - 1)
      outStr[iout] = dblStr[kk]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Now get any exponent digits that might be available. 
  if exp_pos >= 0 then
    ' Skip the "E/e" and "+/-" characters and just grab the digits. 
    for ik as integer = (exp_pos + 2) to (len(dblStr) - 1)
      outStr[iout] = dblStr[ik]
      iout += 1
      digit_ct += 1
    next
  end if
  '
  ' Return the string of significant decimals extracted from this. 
  dblStr = outStr
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  ' Return the count of significant decimals extracted from this. 
  RETURN digit_ct
  '
end Function   ''extract_stage_02(dblStr as zstring, num_digits as integer) as integer


' ------------------------------------------------------------
' ------------------------------------------------------------
Function get_cmdline() as integer
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  ' Parse command line arguments and override any previously set  
  ' options, as necessary. 
  ' 
  ' If there are any invalid parameter values, they will be 
  ' ignored and the default/set option values will be used. 
  '
  Dim As Integer cmd_parm_i
  Dim As String  arg 
  Dim as String  srch
  Dim As integer itmp 
  Dim As double  dtmp 
  Dim As String  stmp 
  '
  cmd_parm_i = 1
  Do
    arg = ucase(Command(cmd_parm_i))
    If Len(arg) = 0 Then
      Exit Do
    End If
    '
    srch = "TOT_TESTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gMaxTestNum = itmp
      end if
    end if
    '
    srch = "NUM_EXTRACTS="    ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 then
        gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 1
        gOptCmd.NUM_EXTRACT_INSTANCES = itmp
      end if
    end if
    '
    srch = "NUM_DIGITS="  ' number
    if left(arg, len(srch)) = srch then
      itmp = val(mid(arg, len(srch)+1))
      if itmp >= 1 and itmp <= 18 then
        gOptCmd.overrides.NUM_SIG_DIGITS = 1
        gOptCmd.NUM_SIG_DIGITS = itmp
      end if
    end if
   '
    cmd_parm_i += 1
  Loop
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
  RETURN 0
  '
end Function  ''get_cmdline()


' ------------------------------------------------------------
' ------------------------------------------------------------
Sub set_options()
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_ENTRY_macro
      endpro
      '
  if gOptCmd.overrides.NUM_SIG_DIGITS = 0 then
    gOptSet.NUM_SIG_DIGITS = 7
  else
    gOptSet.NUM_SIG_DIGITS = gOptCmd.NUM_SIG_DIGITS 
  end if
  '
  '
  if gOptCmd.overrides.NUM_EXTRACT_INSTANCES = 0 then
    gOptSet.NUM_EXTRACT_INSTANCES  = 5 
  else
    gOptSet.NUM_EXTRACT_INSTANCES = gOptCmd.NUM_EXTRACT_INSTANCES 
  end if
      '
      ifpro
        ' {PROFILE} 
        _pro__Func_EXIT_macro
      endpro
      '
end Sub  ''set_options()
Thanks!
CBruce
Post Reply