byte-physics / igortest

Igor Pro Universal Testing Framework
https://docs.byte-physics.de/igor-unit-testing-framework/
BSD 3-Clause "New" or "Revised" License
7 stars 2 forks source link

Tracing Analytics: Optimize GetTotals #458

Closed Garados007 closed 1 year ago

Garados007 commented 1 year ago

Optimize the runtime of GetTotals() and ShowTopFunctions. The old function profiling result showed this:

Total time: 36.1456, Time in Function code: 36.1456 (100%)
Top function percentages:
Function igortest-tracing-analytics.ipf GetTotals: 100%

Annotated Top Functions:

*******************************************************************************************
Function: igortest-tracing-analytics.ipf igortest-tracing-analytics.ipf#GetTotals; Percent total 100%
*******************************************************************************************
[00]            |static Function/WAVE GetTotals()
[00]            |   variable i, numWaves
[00]            |
[00]*           |   TUFXOP_GetStorage/N="IUTF_TestRun" storage
[00]            |   numWaves = DimSize(storage, UTF_ROW)
[00]            |   WAVE/ZZ totals
[00]*           |   for(i = 0; i < numWaves; i++)
[00]*           |       WAVE/WAVE/Z entryOuter = storage[i]
[00]*           |       if(!WaveExists(entryOuter))
[00]*           |           continue
[00]            |       endif
[00]*           |       WAVE entry = entryOuter[0]
[00]*           |       if(WaveExists(totals))
[100]********** |           totals += entry
[00]            |       else
[00]*           |           Duplicate/FREE=1 entry, totals
[00]            |       endif
[00]            |   endfor
[00]            |
[00]            |   if(!WaveExists(totals))
[00]            |       Make/N=0/FREE=1 totals
[00]            |   endif
[00]            |
[00]            |   return totals
[00]            |End

The new function profiling result shows this:

Total time: 0.920468, Time in Function code: 0.916994 (99.6%)
Top function percentages:
Function igortest-tracing-analytics.ipf GetTotals: 93%

Annotated Top Functions:

*******************************************************************************************
Function: igortest-tracing-analytics.ipf igortest-tracing-analytics.ipf#GetTotals; Percent total 93%
*******************************************************************************************
[00]            |static Function/WAVE GetTotals()
[00]            |   variable i, numWaves
[00]            |
[00]            |   TUFXOP_GetStorage/N="IUTF_TestRun" storage
[00]            |   numWaves = DimSize(storage, UTF_ROW)
[00]            |   WAVE/ZZ totals
[01]*           |   for(i = 0; i < numWaves; i++)
[00]*           |       WAVE/WAVE/Z entryOuter = storage[i]
[00]*           |       if(!WaveExists(entryOuter))
[00]            |           continue
[00]            |       endif
[00]*           |       WAVE entry = entryOuter[0]
[00]*           |       if(WaveExists(totals))
[91]*********   |           FastOp totals += entry
[00]            |       else
[01]*           |           Duplicate/FREE=1 entry, totals
[00]            |       endif
[00]            |   endfor
[00]            |
[00]            |   if(!WaveExists(totals))
[00]            |       Make/N=0/FREE=1 totals
[00]            |   endif
[00]            |
[00]            |   return totals
[00]            |End

This small fix makes ShowTopFunctions about 39 times faster!

Close: #456

Garados007 commented 1 year ago

I have done the function profiling if I call ShowTopFunctions with 5000 instead of 50.

Total time: 1.21085, Time in Function code: 1.20737 (99.7%)
Top function percentages:
Function igortest-tracing-analytics.ipf GetTotals: 61%
Function igortest-utils.ipf NicifyTableText: 17%
Function igortest-tracing-analytics.ipf SearchHighestWithMeta: 10%

Annotated Top Functions:

*******************************************************************************************
Function: igortest-tracing-analytics.ipf igortest-tracing-analytics.ipf#GetTotals; Percent total 61%
*******************************************************************************************
[00]            |static Function/WAVE GetTotals()
[00]            |   variable i, numWaves
[00]            |
[00]*           |   TUFXOP_GetStorage/N="IUTF_TestRun" storage
[00]            |   numWaves = DimSize(storage, UTF_ROW)
[00]            |   WAVE/ZZ totals
[00]*           |   for(i = 0; i < numWaves; i++)
[00]*           |       WAVE/WAVE/Z entryOuter = storage[i]
[00]*           |       if(!WaveExists(entryOuter))
[00]            |           continue
[00]            |       endif
[00]*           |       WAVE entry = entryOuter[0]
[00]*           |       if(WaveExists(totals))
[60]******      |           FastOp totals += entry
[00]            |       else
[01]*           |           Duplicate/FREE=1 entry, totals
[00]            |       endif
[00]*           |   endfor
[00]            |
[00]            |   if(!WaveExists(totals))
[00]            |       Make/N=0/FREE=1 totals
[00]            |   endif
[00]            |
[00]            |   return totals
[00]            |End

*******************************************************************************************
Function: igortest-utils.ipf igortest-utils.ipf#NicifyTableText; Percent total 17%
*******************************************************************************************
[00]            |static Function/S NicifyTableText(table, titleList)
[00]            |   WAVE/T table
[00]            |   string titleList
[00]            |
[00]            |   variable numCols, numRows, i, j, padVal
[00]            |   string str
[00]            |
[00]*           |   InsertPoints/M=(UTF_ROW) 0, 2, table
[00]            |   numCols = min(DimSize(table, UTF_COLUMN), ItemsInList(titleList))
[00]            |   for(i = 0; i < numCols; i += 1)
[00]*           |       table[0][i] = StringFromList(i, titleList)
[00]            |   endfor
[00]            |
[00]            |   numCols = DimSize(table, UTF_COLUMN)
[00]            |   numRows = DimSize(table, UTF_ROW)
[00]*           |   Make/FREE/N=(numRows, numCols)/D strSizes
[00]            |
[00]*           |   strSizes = strlen(table[p][q])
[00]            |
[00]*           |   for(j = 0; j < numRows; j += 1)
[00]*           |       padVal = j == 1 ? 0x2d : 0x20
[02]*           |       for(i = 0; i < numCols; i += 1)
[00]            |#if IgorVersion() >= 7.00
[13]*           |           WaveStats/Q/M=1/RMD=[][i, i] strSizes
[00]            |#else
[00]            |           Make/FREE/N=(DimSize(strSizes, UTF_ROW)) strSizeCol
[00]            |           strSizeCol[] = strSizes[p][i]
[00]            |           WaveStats/Q/M=1 strSizeCol
[00]            |#endif
[01]*           |           table[j][i] = num2char(padVal) + PadString(table[j][i], V_Max, padVal) + num2char(padVal)
[00]*           |       endfor
[00]*           |   endfor
[00]            |
[00]            |   str = ""
[00]*           |   for(j = 0; j < numRows; j += 1)
[00]*           |       for(i = 0; i < numCols; i += 1)
[00]*           |           str += table[j][i] + "|"
[00]*           |       endfor
[00]*           |       str += "\r"
[00]            |   endfor
[00]            |
[00]            |   return str
[00]            |End

*******************************************************************************************
Function: igortest-tracing-analytics.ipf igortest-tracing-analytics.ipf#SearchHighestWithMeta; Percent total 10%
*******************************************************************************************
[00]            |static Function/WAVE SearchHighestWithMeta(WAVE/T procs, STRUCT CollectionResult &collectionResult, variable sorting)
[00]            |   variable i, searchIndex, metaIndex
[00]            |   string msg
[00]            |
[00]*           |   Make/FREE=1/N=(collectionResult.count, 5)/T result
[00]*           |   SetDimLabel UTF_COLUMN, 0, 'Function Calls', result
[00]            |   SetDimLabel UTF_COLUMN, 1, 'Sum of called Lines', result
[00]*           |   SetDimLabel UTF_COLUMN, 2, Procedure, result
[00]            |   SetDimLabel UTF_COLUMN, 3, Function, result
[00]*           |   SetDimLabel UTF_COLUMN, 4, Line, result
[00]            |
[00]            |   if(sorting == UTF_ANALYTICS_CALLS)
[00]            |       WAVE searchWave = collectionResult.calls
[00]            |       searchIndex = 0
[00]            |       WAVE metaWave = collectionResult.sums
[00]            |       metaIndex = 1
[00]            |   elseif(sorting == UTF_ANALYTICS_SUM)
[00]            |       WAVE searchWave = collectionResult.sums
[00]            |       searchIndex = 1
[00]            |       WAVE metaWave = collectionResult.calls
[00]            |       metaIndex = 0
[00]            |   else
[00]            |       sprintf msg, "Bug: Sorting %d is not supported", sorting
[00]            |       IUTF_Reporting#IUTF_PrintStatusMessage(msg)
[00]            |       return result
[00]            |   endif
[00]            |
[00]*           |   for(i = 0; i < collectionResult.count; i++)
[09]*           |       WaveStats/M=1/Q searchWave
[00]*           |       if(V_max <= 0)
[00]*           |           Redimension/N=(i, -1) result
[00]*           |           return result
[00]            |       endif
[00]*           |       result[i][searchIndex] = num2istr(V_max)
[00]*           |       result[i][metaIndex] = num2istr(metaWave[V_maxRowLoc][V_maxColLoc])
[00]*           |       result[i][2] = procs[V_maxRowLoc]
[00]*           |       result[i][3] = collectionResult.functions[V_maxRowLoc][V_maxColLoc]
[00]*           |       result[i][4] = num2istr(collectionResult.lines[V_maxRowLoc][V_maxColLoc])
[00]*           |       searchWave[V_maxRowLoc][V_maxColLoc] = NaN
[00]*           |   endfor
[00]            |
[00]            |   return result
[00]            |End

I think, we can keep the rest of the implementation as it is.

t-b commented 1 year ago

Thanks, a factor of 40 is enough for now I guess.