Post a reply

[RELz WIPz] Code Comparer (Papyrus)

Post » Mon Nov 19, 2012 2:00 am

Code Comparer (Papyrus)
http://skyrim.nexusmods.com/mods/23782
See also: http://www.gamesas.com/topic/1409991-best-practices-papyrus/

  • Name: Code Comparer (Papyrus)
  • By: JustinOther (Isaak Mills) and Cipscis (Mark Hanna)
  • Version: 1.00
    • Changelog:
      Spoiler

      • v1.00 (09-04-2012): Initial release
  • Description: This is a utility designed for testing the efficiency of Papyrus snippets in the time honored tradition of Cipscis' Code Comparers for Fallouts. There's often more than one way to skin a cat, but which way is the most efficient? This tool aims to provide an easy way to measure multiple snippets' speed/efficiency. While the efficiency of any single script or line of code is generally inconsequential, every little bit helps, so cumulatively scripts' efficiency does matter. There are eight empty slots at the top of CodeComparerQuestScript.PSC numbered 0-7. The tests will iterate the inserted code an allotted number of times (default is 10^4 or 10,000 iterations) upon selection from the "Test" submenu, recording the relevant information to %UserName%\Documents\My Games\Skyrim\Logs\User\Code Comparer.log and the associated Profiling logs. If multiple snippets from within the menu before beginning a test, the fastest snippet will be reported.
    • Test function. These are what you want to edit, inserting your test subjects into the numbered slots.
      Spoiler 
      State Test0	Function Test(Int aiTest, Int aiIterations = 0)		sTestName[aiTest] = "[Subject Name Here]" ; <-- You can name your tests here to make the log output more easily readable		Notification("'" + sTestName[aiTest] + "' started. Iterations to complete: " + iIterations)		fStart[aiTest] = GetCurrentRealTime()		While aiIterations < iIterations			aiIterations += 1			;>>>>>>>>>>>>>>>> Test 0 <<<<<<<<<<<<<<<<;			; [Your Code Here]			;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;;		EndWhile		fFinish[aiTest] = GetCurrentRealTime()	EndFunctionEndState
    • Example output testing functionally similar snippets.
      • Game.GetPlayer() vs. PayerREF property. Iterations 10^1
        Spoiler

        • PlayerREF
          Spoiler

          • Code Comparer.log:
            [09/07/2012 - 06:01:20AM] Code Comparer log opened (PC)[09/07/2012 - 06:01:20AM] Code Comparer Version: 0.000000[09/07/2012 - 06:01:20AM] Skyrim Version: 1.7.7.0[09/07/2012 - 06:01:20AM] SKSE Version: 1.051100[09/07/2012 - 06:03:09AM] === 'PlayerRef' ===[09/07/2012 - 06:03:09AM] Time elapsed (calibration offset) for an empty test: 0.010994[09/07/2012 - 06:03:09AM] Started 'PlayerRef' at: 90.971001 | Iterations to complete: 10[09/07/2012 - 06:03:09AM] Finished 'PlayerRef' at: 90.981003 | Iterations completed: 10[09/07/2012 - 06:03:09AM] Time elapsed (Raw) for 'PlayerRef': 0.010002[09/07/2012 - 06:03:09AM] Time elapsed (Calibrated) for 'PlayerRef: 0.000000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Raw): 0.001000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Calibrated): 0.000000[09/07/2012 - 06:03:09AM] === 'GetPlayer' ===[09/07/2012 - 06:03:09AM] Time elapsed (calibration offset) for an empty test: 0.010002[09/07/2012 - 06:03:09AM] Started 'GetPlayer' at: 91.022003 | Iterations to complete: 10[09/07/2012 - 06:03:09AM] Finished 'GetPlayer' at: 91.132004 | Iterations completed: 10[09/07/2012 - 06:03:09AM] Time elapsed (Raw) for 'GetPlayer': 0.110001[09/07/2012 - 06:03:09AM] Time elapsed (Calibrated) for 'GetPlayer: 0.099998[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Raw): 0.011000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Calibrated): 0.010000[09/07/2012 - 01:58:32AM] Log closed
          • Profiling\Obj_CodeComparerQUST__02000800_.log:
            Obj_CodeComparerQUST__02000800_ log opened (PC)119234:POP:1160:10:CodeComparerQUST (02000800):Form..StartObjectProfiling119234:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..Track119234:PUSH:1160:9:CodeComparerQUST (02000800):Form..GotoState119234:PUSH:1160:10:CodeComparerQUST (02000800):Form..onEndState119234:POP:1160:10:CodeComparerQUST (02000800):Form..onEndState119234:PUSH:1160:10:CodeComparerQUST (02000800):Form..onBeginState119234:POP:1160:10:CodeComparerQUST (02000800):Form..onBeginState119234:POP:1160:9:CodeComparerQUST (02000800):Form..GotoState119234:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..test119256:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..test119256:PUSH:1160:9:CodeComparerQUST (02000800):Form..GotoState119256:PUSH:1160:10:CodeComparerQUST (02000800):Form..onEndState119256:POP:1160:10:CodeComparerQUST (02000800):Form..onEndState119256:PUSH:1160:10:CodeComparerQUST (02000800):Form..onBeginState119256:POP:1160:10:CodeComparerQUST (02000800):Form..onBeginState119256:POP:1160:9:CodeComparerQUST (02000800):Form..GotoState119256:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript.test0.test119387:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript.test0.test119387:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..Track119388:PUSH:1160:10:CodeComparerQUST (02000800):Form..StopObjectProfilingLog closed
          • Profiling\Script_codecomparerquestscript.1.log:
            Script_codecomparerquestscript log opened (PC)119234:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..Track119234:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..test119256:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..test119256:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript.test0.test119387:POP:1160:9:CodeComparerQUST (02000800):codecomparerquestscript.test0.test119387:PUSH:1160:9:CodeComparerQUST (02000800):codecomparerquestscript..TrackLog closed
          • Profiling\Stack_1160.log:
            Stack_1160 log opened (PC)125077:START:1160125077:POP:1160:13:None:Debug..StartStackProfiling125077:PUSH:1160:13:CodeComparerQUST (02000800):Form..StartObjectProfiling125078:POP:1160:13:CodeComparerQUST (02000800):Form..StartObjectProfiling125078:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125078:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125078:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125078:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125078:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125078:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125078:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125078:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125078:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125085:PUSH:1160:13:None:utility..GetCurrentRealTime125085:POP:1160:13:None:utility..GetCurrentRealTime125085:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125095:PUSH:1160:13:None:utility..GetCurrentRealTime125095:POP:1160:13:None:utility..GetCurrentRealTime125095:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125095:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125095:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125095:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125095:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125095:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125095:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125095:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125095:QUEUE_PUSH:1160:13:None:Debug.??.Notification125105:PUSH:1160:13:None:Debug..Notification125105:POP:1160:13:None:Debug..Notification125105:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125115:PUSH:1160:13:None:utility..GetCurrentRealTime125115:POP:1160:13:None:utility..GetCurrentRealTime125115:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125125:PUSH:1160:13:None:utility..GetCurrentRealTime125125:POP:1160:13:None:utility..GetCurrentRealTime125125:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:None:Debug..TraceUser125125:POP:1160:12:None:Debug..TraceUser125125:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125125:PUSH:1160:13:None:Debug..StopScriptProfiling125126:POP:1160:13:None:Debug..StopScriptProfiling125126:PUSH:1160:13:None:Debug..StopStackProfiling125126:DONE:1160Log closed
        • Game.GetPlayer()
          Spoiler

          • Code Comparer.log:
            [09/07/2012 - 06:01:20AM] Code Comparer log opened (PC)[09/07/2012 - 06:01:20AM] Code Comparer Version: 0.000000[09/07/2012 - 06:01:20AM] Skyrim Version: 1.7.7.0[09/07/2012 - 06:01:20AM] SKSE Version: 1.051100[09/07/2012 - 06:03:09AM] === 'PlayerRef' ===[09/07/2012 - 06:03:09AM] Time elapsed (calibration offset) for an empty test: 0.010994[09/07/2012 - 06:03:09AM] Started 'PlayerRef' at: 90.971001 | Iterations to complete: 10[09/07/2012 - 06:03:09AM] Finished 'PlayerRef' at: 90.981003 | Iterations completed: 10[09/07/2012 - 06:03:09AM] Time elapsed (Raw) for 'PlayerRef': 0.010002[09/07/2012 - 06:03:09AM] Time elapsed (Calibrated) for 'PlayerRef: 0.000000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Raw): 0.001000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Calibrated): 0.000000[09/07/2012 - 06:03:09AM] === 'GetPlayer' ===[09/07/2012 - 06:03:09AM] Time elapsed (calibration offset) for an empty test: 0.010002[09/07/2012 - 06:03:09AM] Started 'GetPlayer' at: 91.022003 | Iterations to complete: 10[09/07/2012 - 06:03:09AM] Finished 'GetPlayer' at: 91.132004 | Iterations completed: 10[09/07/2012 - 06:03:09AM] Time elapsed (Raw) for 'GetPlayer': 0.110001[09/07/2012 - 06:03:09AM] Time elapsed (Calibrated) for 'GetPlayer: 0.099998[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Raw): 0.011000[09/07/2012 - 06:03:09AM] Approximate time for each iteration (Calibrated): 0.010000[09/07/2012 - 01:58:32AM] Log closed
          • Profiling\Obj_CodeComparerQUST__02000800_.log:
            Obj_CodeComparerQUST__02000800_ log opened (PC)125078:POP:1160:13:CodeComparerQUST (02000800):Form..StartObjectProfiling125078:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125078:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125078:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125078:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125078:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125078:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125078:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125078:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125095:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125095:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125095:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125095:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125095:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125095:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125095:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125095:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125115:QUEUE_PUSH:1162:0:CodeComparerQUST (02000800):codecomparerquestscript.??.OnUpdate125125:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125125:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125126:PUSH:1160:13:CodeComparerQUST (02000800):Form..StopObjectProfilingLog closed
          • Profiling\Script_codecomparerquestscript.log:
            Script_codecomparerquestscript log opened (PC)125078:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125078:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125095:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125095:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125115:QUEUE_PUSH:1162:0:CodeComparerQUST (02000800):codecomparerquestscript.??.OnUpdate125125:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test1.test125125:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..TrackLog closed
          • Profiling\Stack_1160.log:
            Stack_1160 log opened (PC)125128:START:1160125128:POP:1160:13:None:Debug..StartStackProfiling125128:PUSH:1160:13:CodeComparerQUST (02000800):Form..StartObjectProfiling125129:POP:1160:13:CodeComparerQUST (02000800):Form..StartObjectProfiling125129:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125129:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125129:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125129:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125129:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125129:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125129:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125129:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125129:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125135:PUSH:1160:13:None:utility..GetCurrentRealTime125135:POP:1160:13:None:utility..GetCurrentRealTime125135:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125145:PUSH:1160:13:None:utility..GetCurrentRealTime125145:POP:1160:13:None:utility..GetCurrentRealTime125145:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..test125145:PUSH:1160:12:CodeComparerQUST (02000800):Form..GotoState125145:PUSH:1160:13:CodeComparerQUST (02000800):Form..onEndState125145:POP:1160:13:CodeComparerQUST (02000800):Form..onEndState125145:PUSH:1160:13:CodeComparerQUST (02000800):Form..onBeginState125145:POP:1160:13:CodeComparerQUST (02000800):Form..onBeginState125145:POP:1160:12:CodeComparerQUST (02000800):Form..GotoState125145:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test0.test125145:QUEUE_PUSH:1160:13:None:Debug.??.Notification125155:PUSH:1160:13:None:Debug..Notification125155:POP:1160:13:None:Debug..Notification125155:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125165:PUSH:1160:13:None:utility..GetCurrentRealTime125165:POP:1160:13:None:utility..GetCurrentRealTime125165:QUEUE_PUSH:1160:13:None:Game.??.getplayer125175:PUSH:1160:13:None:Game..getplayer125175:POP:1160:13:None:Game..getplayer125175:QUEUE_PUSH:1160:13:None:Game.??.getplayer125185:PUSH:1160:13:None:Game..getplayer125185:POP:1160:13:None:Game..getplayer125185:QUEUE_PUSH:1160:13:None:Game.??.getplayer125195:PUSH:1160:13:None:Game..getplayer125195:POP:1160:13:None:Game..getplayer125195:QUEUE_PUSH:1160:13:None:Game.??.getplayer125205:PUSH:1160:13:None:Game..getplayer125205:POP:1160:13:None:Game..getplayer125205:QUEUE_PUSH:1160:13:None:Game.??.getplayer125215:PUSH:1160:13:None:Game..getplayer125215:POP:1160:13:None:Game..getplayer125215:QUEUE_PUSH:1160:13:None:Game.??.getplayer125225:PUSH:1160:13:None:Game..getplayer125225:POP:1160:13:None:Game..getplayer125225:QUEUE_PUSH:1160:13:None:Game.??.getplayer125235:PUSH:1160:13:None:Game..getplayer125235:POP:1160:13:None:Game..getplayer125235:QUEUE_PUSH:1160:13:None:Game.??.getplayer125244:PUSH:1160:13:None:Game..getplayer125244:POP:1160:13:None:Game..getplayer125244:QUEUE_PUSH:1160:13:None:Game.??.getplayer125255:PUSH:1160:13:None:Game..getplayer125255:POP:1160:13:None:Game..getplayer125255:QUEUE_PUSH:1160:13:None:Game.??.getplayer125264:PUSH:1160:13:None:Game..getplayer125264:POP:1160:13:None:Game..getplayer125264:QUEUE_PUSH:1160:13:None:utility.??.GetCurrentRealTime125275:PUSH:1160:13:None:utility..GetCurrentRealTime125275:POP:1160:13:None:utility..GetCurrentRealTime125275:POP:1160:12:CodeComparerQUST (02000800):codecomparerquestscript.test0.test125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:None:Debug..TraceUser125275:POP:1160:12:None:Debug..TraceUser125275:PUSH:1160:12:CodeComparerQUST (02000800):codecomparerquestscript..Track125275:PUSH:1160:13:None:Debug..StopScriptProfiling125276:POP:1160:13:None:Debug..StopScriptProfiling125276:PUSH:1160:13:None:Debug..StopStackProfiling125276:DONE:1160Log closed
        As is evidenced by the above, a PlayerREF http://www.creationkit.com/Property_Reference is vastly faster/cheaper than using the function, http://www.creationkit.com/GetPlayer_(Papyrus).
      • fTestGLOB.Value As Int vs. fTestGLOB.GetValue() As Int vs. fTestGLOB.GetValueInt() vs. fTestGLOB.GetValue(). Iterations 10^6
        Spoiler

        • fTestGLOB.GetValue()
          [09/07/2012 - 07:07:04AM] === 'GetValue()' ===[09/07/2012 - 07:07:04AM] Time elapsed (calibration offset) for an empty test: 3.217003[09/07/2012 - 07:07:04AM] Started 'GetValue()' at: 67.016998 | Iterations to complete: 1000000[09/07/2012 - 07:07:04AM] Finished 'GetValue()' at: 82.495003 | Iterations completed: 1000000[09/07/2012 - 07:07:04AM] Time elapsed (Raw) for 'GetValue()': 15.478004[09/07/2012 - 07:07:04AM] Time elapsed (Calibrated) for 'GetValue(): 12.261002[09/07/2012 - 07:07:04AM] Approximate time for each iteration (Raw): 0.000015[09/07/2012 - 07:07:04AM] Approximate time for each iteration (Calibrated): 0.000012
        • fTestGLOB.GetValueInt()
          [09/07/2012 - 07:07:37AM] === 'GetValueInt()' ===[09/07/2012 - 07:07:37AM] Time elapsed (calibration offset) for an empty test: 3.212997[09/07/2012 - 07:07:37AM] Started 'GetValueInt()' at: 86.096001 | Iterations to complete: 1000000[09/07/2012 - 07:07:37AM] Finished 'GetValueInt()' at: 116.244003 | Iterations completed: 1000000[09/07/2012 - 07:07:37AM] Time elapsed (Raw) for 'GetValueInt()': 30.148003[09/07/2012 - 07:07:37AM] Time elapsed (Calibrated) for 'GetValueInt(): 26.935005[09/07/2012 - 07:07:37AM] Approximate time for each iteration (Raw): 0.000030[09/07/2012 - 07:07:37AM] Approximate time for each iteration (Calibrated): 0.000027
        • fTestGLOB.GetValue() As Int
          [09/07/2012 - 07:07:57AM] === 'GetValue() As Int' ===[09/07/2012 - 07:07:57AM] Time elapsed (calibration offset) for an empty test: 3.192001[09/07/2012 - 07:07:57AM] Started 'GetValue() As Int' at: 119.946999 | Iterations to complete: 1000000[09/07/2012 - 07:07:57AM] Finished 'GetValue() As Int' at: 135.792999 | Iterations completed: 1000000[09/07/2012 - 07:07:57AM] Time elapsed (Raw) for 'GetValue() As Int': 15.846001[09/07/2012 - 07:07:57AM] Time elapsed (Calibrated) for 'GetValue() As Int: 12.653999[09/07/2012 - 07:07:57AM] Approximate time for each iteration (Raw): 0.000016[09/07/2012 - 07:07:57AM] Approximate time for each iteration (Calibrated): 0.000013
        • fTestGLOB.Value As Int
          [09/07/2012 - 07:08:31AM] === 'Value As Int' ===[09/07/2012 - 07:08:31AM] Time elapsed (calibration offset) for an empty test: 3.233994[09/07/2012 - 07:08:31AM] Started 'Value As Int' at: 139.395004 | Iterations to complete: 1000000[09/07/2012 - 07:08:31AM] Finished 'Value As Int' at: 169.973007 | Iterations completed: 1000000[09/07/2012 - 07:08:31AM] Time elapsed (Raw) for 'Value As Int': 30.578003[09/07/2012 - 07:08:31AM] Time elapsed (Calibrated) for 'Value As Int: 27.344009[09/07/2012 - 07:08:31AM] Approximate time for each iteration (Raw): 0.000031[09/07/2012 - 07:08:31AM] Approximate time for each iteration (Calibrated): 0.000027
      • fVar as Int vs Math.Floor(fVar)
        Spoiler
        Note the third test is the below code to test end ensure that both functions will return the same value. This utility can be used for testing stuff other than efficiency.
        Float fVar = Utility.RandomFloat(0.0, 100.0)If Math.Floor(fVar) != fVar As Int	TraceUser(sLogName, "Values don't match!") ; Note below that this never firedEndIf
        • fVar as Int
          [09/07/2012 - 06:26:35AM] === 'As Int' ===[09/07/2012 - 06:26:35AM] Time elapsed (calibration offset) for an empty test: 0.044003[09/07/2012 - 06:26:35AM] Started 'As Int' at: 42.372002 | Iterations to complete: 10000[09/07/2012 - 06:26:35AM] Finished 'As Int' at: 42.424000 | Iterations completed: 10000[09/07/2012 - 06:26:35AM] Time elapsed (Raw) for 'As Int': 0.051998[09/07/2012 - 06:26:35AM] Time elapsed (Calibrated) for 'As Int: 0.007996[09/07/2012 - 06:26:35AM] Approximate time for each iteration (Raw): 0.000005[09/07/2012 - 06:26:35AM] Approximate time for each iteration (Calibrated): 0.000001
        • Math.Floor(fVar)
          [09/07/2012 - 06:26:35AM] === 'Floor' ===[09/07/2012 - 06:26:35AM] Time elapsed (calibration offset) for an empty test: 0.042004[09/07/2012 - 06:26:35AM] Started 'Floor' at: 42.487000 | Iterations to complete: 10000[09/07/2012 - 06:26:35AM] Finished 'Floor' at: 42.611000 | Iterations completed: 10000[09/07/2012 - 06:26:35AM] Time elapsed (Raw) for 'Floor': 0.124001[09/07/2012 - 06:26:35AM] Time elapsed (Calibrated) for 'Floor: 0.081997[09/07/2012 - 06:26:35AM] Approximate time for each iteration (Raw): 0.000012[09/07/2012 - 06:26:35AM] Approximate time for each iteration (Calibrated): 0.000008
        • Test returned values of Floor vs. 'As Int' to ensure the same values are returned
          [09/07/2012 - 06:27:14AM] === 'Compare values returned by 'As Int' & 'Floor'' ===[09/07/2012 - 06:27:14AM] Time elapsed (calibration offset) for an empty test: 0.012001[09/07/2012 - 06:27:14AM] Started 'Compare values returned by 'As Int' & 'Floor'' at: 70.765999 | Iterations to complete: 1000[09/07/2012 - 06:27:14AM] Finished 'Compare values returned by 'As Int' & 'Floor'' at: 81.156998 | Iterations completed: 1000[09/07/2012 - 06:27:14AM] Time elapsed (Raw) for 'Compare values returned by 'As Int' & 'Floor'': 10.390999[09/07/2012 - 06:27:14AM] Time elapsed (Calibrated) for 'Compare values returned by 'As Int' & 'Floor': 10.378998[09/07/2012 - 06:27:14AM] Approximate time for each iteration (Raw): 0.010391[09/07/2012 - 06:27:14AM] Approximate time for each iteration (Calibrated): 0.010379
        Casting a Float variable or property 'As Int' proves to be substantially faster than using http://www.creationkit.com/Floor_-_Math while they'll verifiably return the same values.
  • Requirements: Skyrim v1.6.0.89 or later.
  • Installation: Unpack the contents of the .7z into Skyrim\Data. Activate Code Comparer.esp when testing.
  • Uninstallation: Deactivate the plugin and/or delete the associated files.
  • Other contents:
    • Code Comparer.ini: This enables the necessary debug features such as logging, profiling, etc.
    • Code Comparer - Purge logs.bat: It's just a quick way to delete all the .log files that accumulate, making it easier to find your test results and/or clean up your Logs directory after testing.
    • Script Logs - Shortcut.lnk: It's just a shortcut to the script log folder for easy access. You can drop the .bat into the shortcut after installation to store it with the .log files it deletes.
  • Use: Insert code into the empty slots found in CodeComparerQuestScript.PSC's Test function s (they're right up top) and compile. Make sure Code Comparer.esp is set to load with the launcher and load a save, preferably a clean save in an area with little going on. To start tests open Code Comparer's menu. Depending upon whether SKSE is installed or not, the menu is accessed differently.
    • If a sufficiently current version of SKSE is installed: Press and briefly hold R-Shift (key is rebindable from within menu)
    • If SKSE is not installed or is an insufficiently current version: You will find an apparel item, [Code Comparer], in your inventory. When equipped, the menu will be prompted.
    Once in the menu, you can choose the "Test" submenu, and select the snippet to test. You'll see a notification about the test starting and completing along with the time elapsed once a test is complete. This information and more is recorded in the aforementioned logs. By default, tests will iterate 10,000 times, but you can adjust the iterations from within the "Options" submenu. Note that the menu will not come back up until the current test is completed and that there's no way to cancel the tests for the sake of isolating the snippets and not adding overhead. Taking larger samples will render more accurate results, but be prepared to wait awhile as some tests may take a long time to finish. Note that Code Comparer, in order to increase the accuracy of the results, calibrates itself to offset the overhead of an empty test. Changing the iterations value will prompt recalibration which might take a moment if using higher values.
  • Profiling:
    The profiling log format is as follows:
    :::::
    With being the standard