Best Practices (Papyrus)

Post » Mon Nov 19, 2012 4:44 am

With the advent of Papyrus and the implementation of multithreading (read more http://www.creationkit.com/Threading_Notes_(Papyrus) and http://www.creationkit.com/Differences_from_Previous_Scripting#Functionality_Changes), scripting in Skyrim involves unique challenges that were not encountered in previous games. Perhaps the biggest concern is that scripting has become a zero sum game. In previous games, each iteration of a script would be forced to run within a single frame. Whereas this meant that extremely heavy scripting could affect framerate, it also meant you could know for absolute certain that your script would run each iteration within a single frame. Timing was taken care of, and scripts were essentially independent.

In Skyrim, however, things are different. Scripts are no longer forced to run within a single frame, but are instead allotted certain amounts of processing time, of which there is a limited supply. What this means for scripters is that instead of scripts affecting framerate and relying on it for timing, scripts now affect the speed of other scripts and rely on them for timing. As I said before, scripting has become a zero sum game.

This means that optimisation and awareness of efficiency have become much more important than ever before. While the increase in efficiency made by making a single change to a more efficient way of doing the same thing may be miniscule, it all adds up in the end. After seeing the effects of trying to run script-heavy mods written with little or no awareness of these issues, I think it would be prudent to start a discussion on some "Best Practice" standards for Papyrus scripting.

Eventually, I want this discussion (which I hope will be ongoing) to result in a "Papyrus Best Practices" page on the Creation Kit wiki. However, the wiki isn't the best place for discussion, so I wanted to start talking about it here instead of going ahead and starting to write such standards on my own. After all, I don't think that's how they should be developed - they should be a result of community discussion and, hopefully, eventual agreement. I hope to have some constructive discussion of efficiency, optimisation, and what should and shouldn't become "Best Practice" standards before the information gets put on the wiki for all to see.



First and foremost, I think this generic "rule of thumb" should be the most important thing to consider when scripting in Skyrim:

Run as much code as necessary as often as necessary, and no more.



With the recent http://www.gamesas.com/topic/1409880-relz-wipz-code-comparer-papyrus/ of JustinOther's and my http://skyrim.nexusmods.com/mods/23782 utility, it's become much easier to compare similar snippets of code in order to determine which of them is objectively faster.

For example, it can be used to compare various methods of accessing the player as an Actor:

Game.GetForm(0x14)
Game.GetFormFromFile(0x14, "Skyrim.esm")
Game.GetPlayer()
Actor Property PlayerRef Auto ; Auto-filled in Creation Kit

By comparing these snippets, which should all be functionally identical to one another, it is possible to determine which is the best to use. In this case, the property wins by a very clear margin.

Spoiler
[09/03/2012 - 12:13:39AM] Code Comparer log opened (PC)[09/03/2012 - 12:13:39AM] Code Comparer Version: 1.000000[09/03/2012 - 12:13:39AM] Skyrim Version: 1.7.7.0[09/03/2012 - 12:13:39AM] SKSE Version: 1.051100[09/03/2012 - 12:13:51AM] Calibration Complete for 10^4 iterations: 0.041440 for each empty test[09/03/2012 - 12:13:51AM] === 'GetForm' ===[09/03/2012 - 12:13:51AM] Started 'GetForm' at: 34.956001 | Iterations to complete: 10000[09/03/2012 - 12:13:51AM] Finished 'GetForm' at: 35.067562 | Iterations completed: 10000[09/03/2012 - 12:13:51AM] Time elapsed (Raw) for 'GetForm': 0.153000[09/03/2012 - 12:13:51AM] Time elapsed (Calibrated) for 'GetForm': 0.111560[09/03/2012 - 12:13:51AM] Approximate time for each iteration (Raw): 0.000015[09/03/2012 - 12:13:51AM] Approximate time for each iteration (Calibrated): 0.000011[09/03/2012 - 12:14:01AM] Calibration Complete for 10^4 iterations: 0.041820 for each empty test[09/03/2012 - 12:14:01AM] === 'GetFormFromFile' ===[09/03/2012 - 12:14:01AM] Started 'GetFormFromFile' at: 45.202000 | Iterations to complete: 10000[09/03/2012 - 12:14:01AM] Finished 'GetFormFromFile' at: 45.315178 | Iterations completed: 10000[09/03/2012 - 12:14:01AM] Time elapsed (Raw) for 'GetFormFromFile': 0.154999[09/03/2012 - 12:14:01AM] Time elapsed (Calibrated) for 'GetFormFromFile': 0.113179[09/03/2012 - 12:14:01AM] Approximate time for each iteration (Raw): 0.000015[09/03/2012 - 12:14:01AM] Approximate time for each iteration (Calibrated): 0.000011[09/03/2012 - 12:14:15AM] Calibration Complete for 10^4 iterations: 0.041470 for each empty test[09/03/2012 - 12:15:57AM] === 'getplayer' ===[09/03/2012 - 12:15:57AM] Started 'getplayer' at: 59.305000 | Iterations to complete: 10000[09/03/2012 - 12:15:57AM] Finished 'getplayer' at: 161.638519 | Iterations completed: 10000[09/03/2012 - 12:15:57AM] Time elapsed (Raw) for 'getplayer': 102.374992[09/03/2012 - 12:15:57AM] Time elapsed (Calibrated) for 'getplayer': 102.333519[09/03/2012 - 12:15:57AM] Approximate time for each iteration (Raw): 0.010237[09/03/2012 - 12:15:57AM] Approximate time for each iteration (Calibrated): 0.010233[09/03/2012 - 12:16:07AM] Calibration Complete for 10^4 iterations: 0.041450 for each empty test[09/03/2012 - 12:16:08AM] === 'PlayerRef' ===[09/03/2012 - 12:16:08AM] Started 'PlayerRef' at: 171.867996 | Iterations to complete: 10000[09/03/2012 - 12:16:08AM] Finished 'PlayerRef' at: 171.868561 | Iterations completed: 10000[09/03/2012 - 12:16:08AM] Time elapsed (Raw) for 'PlayerRef': 0.042007[09/03/2012 - 12:16:08AM] Time elapsed (Calibrated) for 'PlayerRef': 0.000558[09/03/2012 - 12:16:08AM] Approximate time for each iteration (Raw): 0.000004[09/03/2012 - 12:16:08AM] Approximate time for each iteration (Calibrated): 0.000000[09/03/2012 - 12:16:19AM] Log closed

From this result, I would say that it should be considered best practice to access the player object via an Actor property that has been assigned a value in the Creation Kit. Whereas directly pointing object properties at specific objects via the Creation Kit does cause them to remain permanently persistent, this is not a concern when applied to the player.



Another, less important general rule that I try to apply where possible is this:

All else being equal, a native solution is better.

Doing something manually via Papyrus that can be done natively is going to both be slower and have a bigger effect on the Papyrus engine and therefore other scripts. If it's possible to implement a native solution, it's generally the better option.

There are caveats, though, hence the "All else being equal..." part of that rule. Take, for example, the Math.floor() function. It's a native global function, accessible via the Math script, that truncates a floating point value and returns it as an integer. The following two code snippets are functionally equivalent, but which should be used?
Int Foo = 3.14159265359 as Int
Int Foo = TestLib.QuickFloor(3.14159265359); Using this in TestLib.pscInt Function QuickFloor(Float afValue) Global	Return afValue as IntEndFunction
Int Foo = Math.Floor(3.14159265359)

Spoiler
[08/29/2012 - 07:44:54PM] Code Comparer log opened (PC)[08/29/2012 - 07:44:54PM] Skyrim Version: 1.7.7.0[08/29/2012 - 07:44:54PM] SKSE Version: 1.051100[08/29/2012 - 07:44:54PM] =========================[08/29/2012 - 07:44:59PM] Int Foo = 3.14159265359 as Int[08/29/2012 - 07:44:59PM] Started test 0 at: 34.506001 | Iterations to complete: 10000[08/29/2012 - 07:44:59PM] Finished test 0 at: 34.596001 | Iterations completed: 10000[08/29/2012 - 07:44:59PM] Time elapsed for test 0: 0.090000[08/29/2012 - 07:44:59PM] Approximate time for each iteration: 0.000009[08/29/2012 - 07:44:59PM] =========================[08/29/2012 - 07:45:01PM] Int Foo = TestLib.QuickFloor(3.14159265359)[08/29/2012 - 07:45:01PM] Started test 1 at: 36.476002 | Iterations to complete: 10000[08/29/2012 - 07:45:01PM] Finished test 1 at: 37.084999 | Iterations completed: 10000[08/29/2012 - 07:45:01PM] Time elapsed for test 1: 0.608997[08/29/2012 - 07:45:01PM] Approximate time for each iteration: 0.000061[08/29/2012 - 07:45:01PM] =========================[08/29/2012 - 07:45:04PM] Int Foo = Math.Floor(3.14159265359)[08/29/2012 - 07:45:04PM] Started test 2 at: 40.035000 | Iterations to complete: 10000[08/29/2012 - 07:45:04PM] Finished test 2 at: 40.174999 | Iterations completed: 10000[08/29/2012 - 07:45:04PM] Time elapsed for test 2: 0.139999[08/29/2012 - 07:45:04PM] Approximate time for each iteration: 0.000014[08/29/2012 - 07:45:04PM] =========================[08/29/2012 - 07:45:11PM] Log closed

In this case, Math.floor() is more efficient than casting a Float to an Int, but only with all else being equal. In this case, that means when a global function is called as part of the code. However, since Math.floor() requires calling a global function but casting a Float to an Int doesn't, the inline casting method is actually more efficient and, I'd argue, should be considered best practice.

In fact, comparing global functions, local functions, and inline code, you can see that there's generally an even greater overhead associated with calling local functions. Here are some result from the code comparer comparing a global function, local function, and inline code snippet all essentially using the following code:
Float Foo = 3.14; ...Foo as Int
The Math.Floor() native global function was added as an extra test too. The profiling logs showed no queueing, so these results should be able to be taken as-is:

Spoiler
[09/02/2012 - 04:20:59PM] Code Comparer log opened (PC)[09/02/2012 - 04:20:59PM] Skyrim Version: 1.7.7.0[09/02/2012 - 04:20:59PM] SKSE Version: 1.051100[09/02/2012 - 04:21:12PM] Calibration Complete: 0.022330 for 10000 iterations.[09/02/2012 - 04:21:12PM] === 'Math's Floor' ===[09/02/2012 - 04:21:12PM] Started 'Math's Floor' at: 36.118999 | Iterations to complete: 10000[09/02/2012 - 04:21:12PM] Finished 'Math's Floor' at: 36.224670 | Iterations completed: 10000[09/02/2012 - 04:21:12PM] Time elapsed for 'Math's Floor': 0.105672[09/02/2012 - 04:21:12PM] Approximate time for each iteration: 0.000011[09/02/2012 - 04:21:12PM] === 'As Int' ===[09/02/2012 - 04:21:12PM] Started 'As Int' at: 36.263000 | Iterations to complete: 10000[09/02/2012 - 04:21:12PM] Finished 'As Int' at: 36.269669 | Iterations completed: 10000[09/02/2012 - 04:21:12PM] Time elapsed for 'As Int': 0.006670[09/02/2012 - 04:21:12PM] Approximate time for each iteration: 0.000001[09/02/2012 - 04:21:12PM] === 'GlobalFloor' ===[09/02/2012 - 04:21:12PM] Started 'GlobalFloor' at: 36.304001 | Iterations to complete: 10000[09/02/2012 - 04:21:12PM] Finished 'GlobalFloor' at: 36.442669 | Iterations completed: 10000[09/02/2012 - 04:21:12PM] Time elapsed for 'GlobalFloor': 0.138669[09/02/2012 - 04:21:12PM] Approximate time for each iteration: 0.000014[09/02/2012 - 04:21:13PM] === 'LocalFloor' ===[09/02/2012 - 04:21:13PM] Started 'LocalFloor' at: 36.490002 | Iterations to complete: 10000[09/02/2012 - 04:21:13PM] Finished 'LocalFloor' at: 36.769669 | Iterations completed: 10000[09/02/2012 - 04:21:13PM] Time elapsed for 'LocalFloor': 0.279668[09/02/2012 - 04:21:13PM] Approximate time for each iteration: 0.000028[09/02/2012 - 04:21:33PM] Log closed
Another test done in reverse order:
[09/02/2012 - 04:33:25PM] Code Comparer log opened (PC)[09/02/2012 - 04:33:25PM] Skyrim Version: 1.7.7.0[09/02/2012 - 04:33:25PM] SKSE Version: 1.051100[09/02/2012 - 04:33:39PM] Calibration Complete: 0.041860 for 10000 iterations.[09/02/2012 - 04:33:39PM] === 'LocalFloor' ===[09/02/2012 - 04:33:39PM] Started 'LocalFloor' at: 42.231998 | Iterations to complete: 10000[09/02/2012 - 04:33:39PM] Finished 'LocalFloor' at: 42.489140 | Iterations completed: 10000[09/02/2012 - 04:33:39PM] Time elapsed for 'LocalFloor': 0.257140[09/02/2012 - 04:33:39PM] Approximate time for each iteration: 0.000026[09/02/2012 - 04:33:39PM] === 'GlobalFloor' ===[09/02/2012 - 04:33:39PM] Started 'GlobalFloor' at: 42.592999 | Iterations to complete: 10000[09/02/2012 - 04:33:39PM] Finished 'GlobalFloor' at: 42.706142 | Iterations completed: 10000[09/02/2012 - 04:33:39PM] Time elapsed for 'GlobalFloor': 0.113143[09/02/2012 - 04:33:39PM] Approximate time for each iteration: 0.000011[09/02/2012 - 04:33:39PM] === 'As Int' ===[09/02/2012 - 04:33:39PM] Started 'As Int' at: 42.789001 | Iterations to complete: 10000[09/02/2012 - 04:33:39PM] Finished 'As Int' at: 42.799141 | Iterations completed: 10000[09/02/2012 - 04:33:39PM] Time elapsed for 'As Int': 0.010138[09/02/2012 - 04:33:39PM] Approximate time for each iteration: 0.000001[09/02/2012 - 04:33:39PM] === 'Math's Floor' ===[09/02/2012 - 04:33:39PM] Started 'Math's Floor' at: 42.862000 | Iterations to complete: 10000[09/02/2012 - 04:33:39PM] Finished 'Math's Floor' at: 42.944141 | Iterations completed: 10000[09/02/2012 - 04:33:39PM] Time elapsed for 'Math's Floor': 0.082141[09/02/2012 - 04:33:39PM] Approximate time for each iteration: 0.000008[09/02/2012 - 04:33:56PM] Log closed

Both of these results rank the different methods in the same order:
  • Inline code
  • Native global function
  • Global function
  • Local function
I expect this is due to the fact that, unlike global functions, local functions need to wait for a specific object to be ready before they can run, which adds a bit more overhead. Inline code, of course, should involve no extra overhead, or at least could be considered to involve a baseline level of overhead.

As a result of these tests, I'd also like to propose this as a best practice:

All functions that could be global* should be global, and all others should not.
* i.e. all functions that don't need to know anything about the object to which their script is attached

The reason why I'm not recommending that all functions should be global (after all, they do have less overhead) is that this would mean they're not thread safe. See http://www.creationkit.com/Threading_Notes_(Papyrus) for more information.



Just in case anyone starts to wonder why I've started a thread and then not replied to anything in it for quite a while, I'm out of town for the weekend and will have very little internet access. I'm actually posting this via my phone, and basically I likely won't be able to take part in any discussion myself for a couple of days.

Cipscis



EDIT 10th September 2012:

Values that will not change should only be requested once.

Values such as the player and the base object of a scripted ObjectReference will not change, so it is safe to only request them once. Repeatedly calling functions such as http://www.creationkit.com/GetPlayer_-_Game or http://www.creationkit.com/GetBaseObject_-_ObjectReference is therefore unnecessary and, what's more, will result in a slower, less efficient script.

For values that will be the same in any one instance of a script but may vary between instances, such as the http://www.creationkit.com/GetBaseObject_-_ObjectReference of a scripted ObjectReference, the best approach is probably to store its value in a variable or auto property that is set within an http://www.creationkit.com/OnInit event. It would be possibly to use auto properties that have their values set via the Creation Kit, but such cases couldn't make use of its "Auto-Fill Properties" feature and would therefore require that properties be manually assigned each time the script is attached to an object, so this is unlikely to be a more useful approach most of the time.

For values that will be the same for any instance of a script, such as the player, it is usually best to set them in the Creation Kit. Auto properties that are given the editorID of the object to which they point as their name can make use of the Creation Kit's "Auto-Fill Properties" feature. It's worth noting that this feature works for auto properties with the name "PlayerRef".

Important Note:
Pointing a property at a particular object in the Creation Kit has drawbacks when that object is an ObjectReference (including Actors), as it will force them to remain always http://www.creationkit.com/Persistence_(Papyrus). This is usually not desired, so be careful not to use the Creation Kit to point properties at ObjectReferences or Actors that shouldn't always remain persistent, and once you're done with an ObjectReference or Actor any variables or properties that were pointing at it should be set to None so that it is not forced to remain persistent.

Cipscis



Edit 11th September 2012

When registering for events, wherever possible only register for a single event.

Many registration events come in two flavours - one registers for continual events and another registers for just a single event. To use the most common example, http://www.creationkit.com/RegisterForUpdate_-_Form registers for continual http://www.creationkit.com/OnUpdate_-_Form events, whereas http://www.creationkit.com/RegisterForSingleUpdate_-_Form registers for a single OnUpdate event.

It's important to use the "register for a single event" flavour wherever possible for two reasons:
  • When a mod is uninstalled, scripts that have been previously added to objects will not be removed, but the file containing the compiled script itself will likely have be removed with the rest of the mod. When this happens, the object stays registered to receive all events for which it was already registered, and the game will continue to send these events to the object even though the code that handled the events no longer exists.

    Continuing to receive these events will put extra stress on the scripting system, as well as filling up the Papyrus error log with a new error every time the registered event is passed to the removed script.

  • When registering to continually receive events, especially OnUpdate events, it's possible that the next event will be sent to the script before the previous one has finished. If this happens, it will cause extra stress on the scripting system and will also cause save bloat (i.e. an increase in file size for saved games) as more events are queued on the stack and saved with the game.

    The save bloat behaviour caused by registering for continual updates in this way was, to my knowledge, first diagnosed http://www.gamesas.com/topic/1349327-scripting-savegame-bloating/
This behaviour can be avoided by using a "chain" of registrations for single events. For OnUpdate events, that might look something like this:
Spoiler
Float Property UpdateInterval = 5.0 AutoEvent OnInit	RegisterForSingleUpdate(UpdateInterval)EndEventEvent OnUpdate	; Do stuff	RegisterForSingleUpdate(UpdateInterval)EndEvent



Always use the correct type of literal.

When passing http://www.creationkit.com/Literals_Reference, it is always best to use the correct type. Some types can automatically be http://www.creationkit.com/Cast_Reference to other types, but this should never be possible when dealing with literals.

For example, when passing arguments to functions, the correct type should always be used. This means that if a function argument is of type float, a literal of type int should not be passed. For example:
RegisterForSingleUpdate(1) ; Is less efficient than...RegisterForSingleUpdate(1.0)
The reason for this difference is that, in addition to the function call that is happening regardless, a cast operation is also required that takes slightly more time and is wholly unnecessary in cases like this.

To pass a whole number as a float just add ".0" at the end. For example, 1 is an int but 1.0 is a float.

Because all types can be automatically cast to bool, code like this is still valid:
Enable(1)
However, because http://www.creationkit.com/Enable_-_ObjectReference takes a single parameter of type bool, this is a more efficient way of doing exactly the same thing:
Enable(true)

When passing non-literal values, such as those stored in variables, it is entirely alright to rely on auto-casting. In cases like that, a cast will happen whether you do it manually (e.g. "MyActorVar as bool") or you allow the compiler to handle it.

Cipscis
User avatar
Marie Maillos
 
Posts: 3403
Joined: Wed Mar 21, 2007 4:39 pm

Post » Mon Nov 19, 2012 4:08 am

Some interesting and valuable points. One general comment I'd make regarding choosing the fastest executing code - always make your choice with due regard to readability and necessity. There's no point jumping through hoops to make a piece of code that runs once during initialisation run as fast as possible - readability and a coherent logical structure will always be better in those cases. Focus optimisation attention on code that runs very frequently, and before trying to make the code run faster always ask "Does this need to run repeatedly at all, or as often?"

An example: in my flying machine, I have three scripts. One runs on the main lifter, and essentially calculates and applies the physics impulse. This runs often (RegisterForSingleUpdate 0.1), but has very little code. The second script runs on the rudder, testing the keyboard for left/right turns and applying the appropriate physics impulse. Again this uses a 0.1 SingleUpdate frequency.

The third script is the big, complicated one. This is the state machine, holding all the logic regarding whether the flying machine is landed, launching, landing etc. It only runs every 2 seconds or less often.

I'd suggest, as a general rule, if you have a large script running frequently, even if much of it is hidden away with conditional statements, then you probably need to take a step back and think about redesigning your whole setup. Get as much code as possible including conditional statements out of your frequently running scripts and into rarely running scripts.
User avatar
Ellie English
 
Posts: 3457
Joined: Tue Jul 11, 2006 4:47 pm

Post » Sun Nov 18, 2012 7:23 pm

If I may, I would like to ask if you have any insights on these two functions
- Utility.RandomFloat
- Utility.RandomInt

I have not used your testing utility, but I have used a much simpler test script of my own to conclude, that these two functions seem to take an amazing amount of time to complete: around 12-13 ms per single function call. However, then I realized, that the result is approximately the inverse of my 75 FPS refresh rate, and changes in accordance to it, so apparently those functions may be called only once per frame, and calling them sequentially is likely to involve a lot of passive waiting.

That would make it a bit difficult to determine the most efficient way to deal with a situation requiring several random numbers. One may apparently either wait over several frames to get them all through sequential function calls, or first generate one high-resolution random number and then mathematically extract several low-resolution ones from it as may be required or feasible. The latter approach is certainly faster but could in a complex case potentially lead to higher processor loading overall, perhaps.

On a side issue: It seems to me, that also the value which GetCurrentRealTime() returns might be updated only once per frame. If so, and if one has a refresh rate of 60 FPS, that would potentially introduce a timing error of up to 33 ms for each test run that contains two calls to that function. I have not bothered to fully verify this, but to eliminate it as a potential source of error, I prefer to use a larger and varied number of iterations in my own tests, especially when calibrating, to push the run time to several seconds even for empty tests.
User avatar
City Swagga
 
Posts: 3498
Joined: Sat May 12, 2007 1:04 am

Post » Mon Nov 19, 2012 8:45 am

RandomInt vs. RandomFloat

Code Comparer.log:
Spoiler
  • 10^0 Iterations
    Spoiler

    • RandomInt
      [09/08/2012 - 01:47:17PM] === 'RandomInt' ===[09/08/2012 - 01:47:17PM] Time elapsed (calibration offset) for an empty test: 0.012001[09/08/2012 - 01:47:17PM] Started 'RandomInt' at: 82.037003 | Iterations to complete: 1[09/08/2012 - 01:47:17PM] Finished 'RandomInt' at: 82.056999 | Iterations completed: 1[09/08/2012 - 01:47:17PM] Time elapsed (Raw) for 'RandomInt': 0.019997[09/08/2012 - 01:47:17PM] Time elapsed (Calibrated) for 'RandomInt: 0.007996'[09/08/2012 - 01:47:17PM] Approximate time for each iteration (Raw): 0.019997[09/08/2012 - 01:47:17PM] Approximate time for each iteration (Calibrated): 0.007996
    • RandomFloat
      [09/08/2012 - 01:47:17PM] === 'RandomFloat' ===[09/08/2012 - 01:47:17PM] Time elapsed (calibration offset) for an empty test: 0.010002[09/08/2012 - 01:47:17PM] Started 'RandomFloat' at: 82.098000 | Iterations to complete: 1[09/08/2012 - 01:47:17PM] Finished 'RandomFloat' at: 82.119003 | Iterations completed: 1[09/08/2012 - 01:47:17PM] Time elapsed (Raw) for 'RandomFloat': 0.021004[09/08/2012 - 01:47:17PM] Time elapsed (Calibrated) for 'RandomFloat: 0.011002'[09/08/2012 - 01:47:17PM] Approximate time for each iteration (Raw): 0.021004[09/08/2012 - 01:47:17PM] Approximate time for each iteration (Calibrated): 0.011002
  • 10^1 Iterations
    Spoiler

    • RandomInt
      [09/08/2012 - 01:47:36PM] === 'RandomInt' ===[09/08/2012 - 01:47:36PM] Time elapsed (calibration offset) for an empty test: 0.011002[09/08/2012 - 01:47:36PM] Started 'RandomInt' at: 100.718002 | Iterations to complete: 10[09/08/2012 - 01:47:36PM] Finished 'RandomInt' at: 100.833000 | Iterations completed: 10[09/08/2012 - 01:47:36PM] Time elapsed (Raw) for 'RandomInt': 0.114998[09/08/2012 - 01:47:36PM] Time elapsed (Calibrated) for 'RandomInt: 0.103996'[09/08/2012 - 01:47:36PM] Approximate time for each iteration (Raw): 0.011500[09/08/2012 - 01:47:36PM] Approximate time for each iteration (Calibrated): 0.010400
    • RandomFloat
      [09/08/2012 - 01:47:36PM] === 'RandomFloat' ===[09/08/2012 - 01:47:36PM] Time elapsed (calibration offset) for an empty test: 0.011002[09/08/2012 - 01:47:36PM] Started 'RandomFloat' at: 100.875000 | Iterations to complete: 10[09/08/2012 - 01:47:36PM] Finished 'RandomFloat' at: 100.990997 | Iterations completed: 10[09/08/2012 - 01:47:36PM] Time elapsed (Raw) for 'RandomFloat': 0.115997[09/08/2012 - 01:47:36PM] Time elapsed (Calibrated) for 'RandomFloat: 0.104996'[09/08/2012 - 01:47:36PM] Approximate time for each iteration (Raw): 0.011600[09/08/2012 - 01:47:36PM] Approximate time for each iteration (Calibrated): 0.010500
  • 10^2 Iterations
    Spoiler

    • RandomInt
      [09/08/2012 - 01:05:19PM] === 'RandomInt' ===[09/08/2012 - 01:05:19PM] Time elapsed (calibration offset) for an empty test: 0.011993[09/08/2012 - 01:05:19PM] Started 'RandomInt' at: 94.803001 | Iterations to complete: 100[09/08/2012 - 01:05:19PM] Finished 'RandomInt' at: 95.811996 | Iterations completed: 100[09/08/2012 - 01:05:19PM] Time elapsed (Raw) for 'RandomInt': 1.008995[09/08/2012 - 01:05:19PM] Time elapsed (Calibrated) for 'RandomInt: 0.997002'[09/08/2012 - 01:05:19PM] Approximate time for each iteration (Raw): 0.010090[09/08/2012 - 01:05:19PM] Approximate time for each iteration (Calibrated): 0.009970
    • RandomFloat
      [09/08/2012 - 01:05:20PM] === 'RandomFloat' ===[09/08/2012 - 01:05:20PM] Time elapsed (calibration offset) for an empty test: 0.010002[09/08/2012 - 01:05:20PM] Started 'RandomFloat' at: 95.852997 | Iterations to complete: 100[09/08/2012 - 01:05:20PM] Finished 'RandomFloat' at: 96.891998 | Iterations completed: 100[09/08/2012 - 01:05:20PM] Time elapsed (Raw) for 'RandomFloat': 1.039001[09/08/2012 - 01:05:20PM] Time elapsed (Calibrated) for 'RandomFloat: 1.028999'[09/08/2012 - 01:05:20PM] Approximate time for each iteration (Raw): 0.010390[09/08/2012 - 01:05:20PM] Approximate time for each iteration (Calibrated): 0.010290
  • 10^3 Iterations
    Spoiler

    • RandomInt
      [09/08/2012 - 01:05:50PM] === 'RandomInt' ===[09/08/2012 - 01:05:50PM] Time elapsed (calibration offset) for an empty test: 0.011002[09/08/2012 - 01:05:50PM] Started 'RandomInt' at: 116.257004 | Iterations to complete: 1000[09/08/2012 - 01:05:50PM] Finished 'RandomInt' at: 126.487000 | Iterations completed: 1000[09/08/2012 - 01:05:50PM] Time elapsed (Raw) for 'RandomInt': 10.229996[09/08/2012 - 01:05:50PM] Time elapsed (Calibrated) for 'RandomInt: 10.218994'[09/08/2012 - 01:05:50PM] Approximate time for each iteration (Raw): 0.010230[09/08/2012 - 01:05:50PM] Approximate time for each iteration (Calibrated): 0.010219
    • RandomFloat
      [09/08/2012 - 01:06:00PM] === 'RandomFloat' ===[09/08/2012 - 01:06:00PM] Time elapsed (calibration offset) for an empty test: 0.010002[09/08/2012 - 01:06:00PM] Started 'RandomFloat' at: 126.528000 | Iterations to complete: 1000[09/08/2012 - 01:06:00PM] Finished 'RandomFloat' at: 136.759003 | Iterations completed: 1000[09/08/2012 - 01:06:00PM] Time elapsed (Raw) for 'RandomFloat': 10.231003[09/08/2012 - 01:06:00PM] Time elapsed (Calibrated) for 'RandomFloat: 10.221001'[09/08/2012 - 01:06:00PM] Approximate time for each iteration (Raw): 0.010231[09/08/2012 - 01:06:00PM] Approximate time for each iteration (Calibrated): 0.010221
  • 10^4 Iterations
    Spoiler

    • RandomInt
      [09/08/2012 - 01:08:03PM] === 'RandomInt' ===[09/08/2012 - 01:08:03PM] Time elapsed (calibration offset) for an empty test: 0.042999[09/08/2012 - 01:08:03PM] Started 'RandomInt' at: 157.772995 | Iterations to complete: 10000[09/08/2012 - 01:08:03PM] Finished 'RandomInt' at: 259.862000 | Iterations completed: 10000[09/08/2012 - 01:08:03PM] Time elapsed (Raw) for 'RandomInt': 102.089005[09/08/2012 - 01:08:03PM] Time elapsed (Calibrated) for 'RandomInt: 102.046005'[09/08/2012 - 01:08:03PM] Approximate time for each iteration (Raw): 0.010209[09/08/2012 - 01:08:03PM] Approximate time for each iteration (Calibrated): 0.010205
    • RandomFloat
      [09/08/2012 - 01:09:45PM] === 'RandomFloat' ===[09/08/2012 - 01:09:45PM] Time elapsed (calibration offset) for an empty test: 0.041992[09/08/2012 - 01:09:45PM] Started 'RandomFloat' at: 259.933990 | Iterations to complete: 10000[09/08/2012 - 01:09:45PM] Finished 'RandomFloat' at: 362.187988 | Iterations completed: 10000[09/08/2012 - 01:09:45PM] Time elapsed (Raw) for 'RandomFloat': 102.253998[09/08/2012 - 01:09:45PM] Time elapsed (Calibrated) for 'RandomFloat: 102.212006'[09/08/2012 - 01:09:45PM] Approximate time for each iteration (Raw): 0.010225[09/08/2012 - 01:09:45PM] Approximate time for each iteration (Calibrated): 0.010221

RandomInt is consistently faster than RandomFloat, but by a narrow margin. Both, as you've surmised, do have queuing going on between iterations if called multiple times consecutively.

Profiling Logs:
Spoiler
  • RandomInt
    Spoiler
    Stack_1157 log opened (PC)88308:START:115788308:POP:1157:7:None:Debug..StartStackProfiling88308:PUSH:1157:7:CodeComparerQUST (02000800):Form..StartObjectProfiling88309:POP:1157:7:CodeComparerQUST (02000800):Form..StartObjectProfiling88309:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..Track88309:PUSH:1157:6:CodeComparerQUST (02000800):Form..GotoState88309:PUSH:1157:7:CodeComparerQUST (02000800):Form..onEndState88309:POP:1157:7:CodeComparerQUST (02000800):Form..onEndState88309:PUSH:1157:7:CodeComparerQUST (02000800):Form..onBeginState88309:POP:1157:7:CodeComparerQUST (02000800):Form..onBeginState88309:POP:1157:6:CodeComparerQUST (02000800):Form..GotoState88309:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..test88309:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88317:PUSH:1157:7:None:utility..GetCurrentRealTime88317:POP:1157:7:None:utility..GetCurrentRealTime88317:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88327:PUSH:1157:7:None:utility..GetCurrentRealTime88327:POP:1157:7:None:utility..GetCurrentRealTime88327:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..test88327:PUSH:1157:6:CodeComparerQUST (02000800):Form..GotoState88327:PUSH:1157:7:CodeComparerQUST (02000800):Form..onEndState88327:POP:1157:7:CodeComparerQUST (02000800):Form..onEndState88327:PUSH:1157:7:CodeComparerQUST (02000800):Form..onBeginState88327:POP:1157:7:CodeComparerQUST (02000800):Form..onBeginState88327:POP:1157:6:CodeComparerQUST (02000800):Form..GotoState88327:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript.test1.test88327:QUEUE_PUSH:1157:7:None:Debug.??.Notification88337:PUSH:1157:7:None:Debug..Notification88337:POP:1157:7:None:Debug..Notification88337:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88348:PUSH:1157:7:None:utility..GetCurrentRealTime88348:POP:1157:7:None:utility..GetCurrentRealTime88348:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88358:PUSH:1157:7:None:utility..RandomInt88358:POP:1157:7:None:utility..RandomInt88358:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88368:PUSH:1157:7:None:utility..RandomInt88368:POP:1157:7:None:utility..RandomInt88370:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88378:PUSH:1157:7:None:utility..RandomInt88378:POP:1157:7:None:utility..RandomInt88378:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88389:PUSH:1157:7:None:utility..RandomInt88389:POP:1157:7:None:utility..RandomInt88389:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88399:PUSH:1157:7:None:utility..RandomInt88399:POP:1157:7:None:utility..RandomInt88399:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88410:PUSH:1157:7:None:utility..RandomInt88410:POP:1157:7:None:utility..RandomInt88410:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88420:PUSH:1157:7:None:utility..RandomInt88420:POP:1157:7:None:utility..RandomInt88420:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88431:PUSH:1157:7:None:utility..RandomInt88431:POP:1157:7:None:utility..RandomInt88431:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88443:PUSH:1157:7:None:utility..RandomInt88443:POP:1157:7:None:utility..RandomInt88443:QUEUE_PUSH:1157:7:None:utility.??.RandomInt88452:PUSH:1157:7:None:utility..RandomInt88452:POP:1157:7:None:utility..RandomInt88452:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88463:PUSH:1157:7:None:utility..GetCurrentRealTime88463:POP:1157:7:None:utility..GetCurrentRealTime88463:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript.test1.test88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:None:Debug..TraceUser88463:POP:1157:6:None:Debug..TraceUser88463:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..Track88463:PUSH:1157:7:None:Debug..StopScriptProfiling88464:POP:1157:7:None:Debug..StopScriptProfiling88464:PUSH:1157:7:None:Debug..StopStackProfiling88464:DONE:1157Log closed
  • RandomFloat
    Spoiler
    Stack_1157 log opened (PC)88466:START:115788466:POP:1157:7:None:Debug..StartStackProfiling88466:PUSH:1157:7:CodeComparerQUST (02000800):Form..StartObjectProfiling88467:POP:1157:7:CodeComparerQUST (02000800):Form..StartObjectProfiling88467:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..Track88467:PUSH:1157:6:CodeComparerQUST (02000800):Form..GotoState88467:PUSH:1157:7:CodeComparerQUST (02000800):Form..onEndState88467:POP:1157:7:CodeComparerQUST (02000800):Form..onEndState88467:PUSH:1157:7:CodeComparerQUST (02000800):Form..onBeginState88467:POP:1157:7:CodeComparerQUST (02000800):Form..onBeginState88467:POP:1157:6:CodeComparerQUST (02000800):Form..GotoState88467:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..test88467:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88473:PUSH:1157:7:None:utility..GetCurrentRealTime88473:POP:1157:7:None:utility..GetCurrentRealTime88473:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88484:PUSH:1157:7:None:utility..GetCurrentRealTime88484:POP:1157:7:None:utility..GetCurrentRealTime88484:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..test88484:PUSH:1157:6:CodeComparerQUST (02000800):Form..GotoState88484:PUSH:1157:7:CodeComparerQUST (02000800):Form..onEndState88484:POP:1157:7:CodeComparerQUST (02000800):Form..onEndState88484:PUSH:1157:7:CodeComparerQUST (02000800):Form..onBeginState88484:POP:1157:7:CodeComparerQUST (02000800):Form..onBeginState88484:POP:1157:6:CodeComparerQUST (02000800):Form..GotoState88484:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript.test0.test88484:QUEUE_PUSH:1157:7:None:Debug.??.Notification88494:PUSH:1157:7:None:Debug..Notification88494:POP:1157:7:None:Debug..Notification88494:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88504:PUSH:1157:7:None:utility..GetCurrentRealTime88504:POP:1157:7:None:utility..GetCurrentRealTime88505:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88515:PUSH:1157:7:None:utility..RandomFloat88515:POP:1157:7:None:utility..RandomFloat88515:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88526:PUSH:1157:7:None:utility..RandomFloat88526:POP:1157:7:None:utility..RandomFloat88526:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88536:PUSH:1157:7:None:utility..RandomFloat88536:POP:1157:7:None:utility..RandomFloat88536:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88546:PUSH:1157:7:None:utility..RandomFloat88546:POP:1157:7:None:utility..RandomFloat88546:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88557:PUSH:1157:7:None:utility..RandomFloat88557:POP:1157:7:None:utility..RandomFloat88558:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88567:PUSH:1157:7:None:utility..RandomFloat88567:POP:1157:7:None:utility..RandomFloat88567:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88579:PUSH:1157:7:None:utility..RandomFloat88579:POP:1157:7:None:utility..RandomFloat88579:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88588:PUSH:1157:7:None:utility..RandomFloat88588:POP:1157:7:None:utility..RandomFloat88588:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88600:PUSH:1157:7:None:utility..RandomFloat88600:POP:1157:7:None:utility..RandomFloat88600:QUEUE_PUSH:1157:7:None:utility.??.RandomFloat88610:PUSH:1157:7:None:utility..RandomFloat88610:POP:1157:7:None:utility..RandomFloat88610:QUEUE_PUSH:1157:7:None:utility.??.GetCurrentRealTime88621:PUSH:1157:7:None:utility..GetCurrentRealTime88621:POP:1157:7:None:utility..GetCurrentRealTime88621:POP:1157:6:CodeComparerQUST (02000800):codecomparerquestscript.test0.test88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:None:Debug..TraceUser88621:POP:1157:6:None:Debug..TraceUser88621:PUSH:1157:6:CodeComparerQUST (02000800):codecomparerquestscript..Track88621:PUSH:1157:7:None:Debug..StopScriptProfiling88623:POP:1157:7:None:Debug..StopScriptProfiling88623:PUSH:1157:7:None:Debug..StopStackProfiling88623:DONE:1157Log closed
User avatar
BEl J
 
Posts: 3397
Joined: Tue Feb 13, 2007 8:12 am

Post » Mon Nov 19, 2012 5:54 am

RandomInt vs. RandomFloat

[snip]

RandomInt is consistently faster than RandomFloat, but by a narrow margin. Both, as you've surmised, do have queuing going on between iterations if called multiple times consecutively.

[snip]
The difference is so tiny, is it ever going to be relevant in a real-world situation? How many random floats is any mod ever going to need? I'd suggest that if a mod needs enough RandomFloats to make it worth using RandomInt instead, then that mod is in very serious need of a total re-think.

Don't misunderstand me, I'm not for one second criticising the attempt to get hard numbers on the speed of different operations. But if we're starting to debate the correct method of getting absolutely perfect measurements of utterly insignificant differences, then we're wasting our time.
User avatar
Ricky Rayner
 
Posts: 3339
Joined: Fri Jul 13, 2007 2:13 am

Post » Mon Nov 19, 2012 2:26 am

Wasn't suggesting favoring one or the other, just presenting the data which shows their performance is comparable and, as the question was posed regarding the waiting/queuing of those functions when called multiple times consecutively, conducting the tests provided the profiling logs showing the queuing. In the case of RandomInt vs. RandomFloat, it's nice to know one can use whichever fits the context without considering 'cost' unlike GetValueInt() vs. GetValue() As Int where the latter is substantially slower/more 'expensive'. :shrug:
User avatar
Kat Ives
 
Posts: 3408
Joined: Tue Aug 28, 2007 2:11 pm

Post » Mon Nov 19, 2012 5:48 am

Wasn't suggesting favoring one or the other, just presenting the data which shows their performance is comparable and, as the question was posed regarding the waiting/queuing of those functions when called multiple times consecutively, conducting the tests provided the profiling logs showing the queuing. In the case of RandomInt vs. RandomFloat, it's nice to know one can use whichever fits the context without considering 'cost' unlike GetValueInt() vs. GetValue() As Int where the latter is substantially slower/more 'expensive'. :shrug:
Ok, my misunderstanding - sorry about that :).

As a matter of interest, I seem to recall there have been a few discussions about timing of instructions before; have the results of the investigations ever been pulled together? If not, I'll see if I can find time to comb through old threads and summarise the findings here.
User avatar
Benito Martinez
 
Posts: 3470
Joined: Thu Aug 30, 2007 6:33 am

Post » Sun Nov 18, 2012 9:59 pm

No worries. :) There have been a number of speed tests run across multiple threads. I'd just assume rerun the tests though as there are now calibrated results and profiling logs to provide more info. The second post in http://www.gamesas.com/topic/1409880-relz-wipz-code-comparer-papyrus/ is pretty much dedicated to results of tests/contests. I'd imagine a test output list would be better there leaving this thread for anolysis of the results and drawing conclusions as to what qualifies as "best practice"? Post test requests or your own results in Code Comparer's thread, for instance, then I can add the results to a list in the second post for easy referencing.

If there seems a better way to organize stuff, I'm all ears, but that would seem the way to go as this thread will invariably delve into subjects Code Comparer can't measure and there's really not too much to talk about in the Code Comparer thread save results/updates.
User avatar
Dawn Farrell
 
Posts: 3522
Joined: Thu Aug 23, 2007 9:02 am

Post » Mon Nov 19, 2012 6:42 am

Interesting stuff, gonna go rewrite some stuff in my own code after this.
Also good to know about Randomint, but then again u should always use Int unless u need to use float anyway.

-Exo
User avatar
Katy Hogben
 
Posts: 3457
Joined: Mon Oct 30, 2006 12:20 am

Post » Mon Nov 19, 2012 3:30 am

Looking at the profiling logs for the RandomInt vs. RandomFloat tests, it looks like pretty much all the time taken is between the QUEUE_PUSH and PUSH, whereas PUSH and POP happen during the same millisecond. While there seems to be some incredibly slight difference between the two functions, it seems pretty negligible to me. Unfortunately, if the vast majority of the time taken for each of these functions is just due to the overhead involved in calling a Global function (which is how I've interpreted the profiling logs) then it's unlikely that, for example, a faster alternative could be implemented by SKSE. In that case, it's probably best not to worry about using one over the other, especially with the difference being so small.

Cipscis
User avatar
Multi Multi
 
Posts: 3382
Joined: Mon Sep 18, 2006 4:07 pm

Post » Mon Nov 19, 2012 4:37 am

One thing JustinOther noticed while we were developing the Code Comparer is that some of the "convenience functions" added in by Bethesda involve more function calls (and therefore more overhead) than effectively calling them inline. Take the http://www.creationkit.com/GlobalVariable_Script for example:
Spoiler
Scriptname GlobalVariable extends Form Hidden; Obtains the global's current valuefloat Function GetValue() native; Sets the global's current valueFunction SetValue(float afNewValue) native; convenience functions for intsint Function GetValueInt()	return GetValue() as intendFunction; Sets the global's current valueFunction SetValueInt(int aiNewValue)	SetValue(aiNewValue as float)endFunction; Easy access to the global's valuefloat Property Value Hidden  float Function get()    return GetValue()  EndFunction  Function set(float afValue)    SetValue(afValue)  EndFunctionEndProperty; the threadsafe way to modify a global variablefloat Function Mod(float afHowMuch)                Value += afHowMuch                Return ValueEndFunction

As you can see, calling the convenience function http://www.creationkit.com/GetValueInt_-_GlobalVariable is functionally exactly the same as this:
(GlobalVariableProp.GetValue() as Int)
While this is functionally identical, it also contains one extra function call and will therefore be slightly slower.

Of course, this is going to be true of any convenience function, and sometimes functions simply are convenient enough to ignore this cost of speed. For single line functions like this, though, I think it's best to avoid them and call them inline instead.

A more obvious example is the http://www.creationkit.com/GetActorRef_-_ReferenceAlias function from the http://www.creationkit.com/ReferenceAlias_Script:
Spoiler
; Get the object reference this alias refers toObjectReference Function GetReference() native; ...; Autocast to Actor is applicableActor Function GetActorReference()	return GetReference() as ActorendFunction; ...; Convenience fucntionActor Function GetActorRef()	return GetActorReference()endFunction
As you can see, calling GetActorRef or http://www.creationkit.com/GetActorReference_-_ReferenceAlias is functionally equivalent to this:
(ReferenceAliasProp.GetReference() as Actor)
The only real difference is that, for GetActorReference, an extra function call is involved, and for GetActorRef, two extra function calls are involved.

Aliases like GetActorRef add nothing to the code, not even as much as convenience functions like GetActorReference, but they do impact the efficiency of code very slightly and, I think, should therefore be avoided entirely.



One thing I've contemplated to get around this problem is to implement a precompiler and an "Inline" keyword for function definitions. It's just an idea at the moment, but it's something I can see myself taking on as a project in the future. Basically it would allow for code like this:
Actor Function GetActorRef() Inline	return GetActorReference()EndFunction
When run through the precompiler, the following might happen (to maintain function scope I've wrapped it in the less expensive "If True"):
foo = GetActorRef(); is turned into...If True	foo = GetActorReference()EndIf
Just an idea I thought I might put out there, to see what other scripters might think.

Cipscis

EDIT:

Presumably, in that example, if GetActorReference were also declared with the keyword Inline then the precompiler would turn it into something like this:
If True	If True		foo = GetReference() as Actor	EndIfEndIf
Remember, the "If True" is to retain function block, so any arguments or local variables still work.

If I were to also intercept the code at the assembly stage (something I've been looking at doing recently) then presumably the slight slowdown caused by "If True" could be removed while maintaining the advantages of block scope.

There are another couple of small speed advantages that could be gained by intercepting the code between the compiler and the assembler, as the compiler has a few inefficiencies that should be easy to detect, but I probably shouldn't get too far ahead of myself just yet.

Cipscis
User avatar
Devin Sluis
 
Posts: 3389
Joined: Wed Oct 24, 2007 4:22 am

Post » Sun Nov 18, 2012 9:53 pm

I have rather assumed that the 'use properties rather than functions' rule for the player applies to everything when persistence is not an issue. So for example I have stopped using GetOwningQuest() in dialogue scripts. Does that seem sensible?

Lately, I have also been using dialogue scripts whenever possible, since one can apparently delete TIFs without causing errors about missing properties. But I used to put as little as possible in TIFs, because they are so horribly named - instead I'd put a function in the quest script and call that. And I wondered whether we have any real data about the speed of different scripts, because I have the completely unscientific impression that using the quest script sometimes made things noticeably slower. If I'm not imagining things, it seems unlikely that I'd have noticed just th e overhead of a couple of function calls, but I wondered whether quest scripts might be slower because they are longer, or Conditional, or already running, or something. Does this sound at all plausible?
User avatar
John N
 
Posts: 3458
Joined: Sun Aug 26, 2007 5:11 pm

Post » Mon Nov 19, 2012 12:20 am

As far as I know, when a property's value is assigned in the Creation Kit that property's value is set whenever the object to which it is attached is initialised (including after it is http://www.creationkit.com/Reset_-_ObjectReference), just before its http://www.creationkit.com/OnInit event runs.

I'm not sure how the speed of this compares with setting the values of properties via functions like http://www.creationkit.com/GetBaseObject_-_ObjectReference in an OnInit event, but either way it is definitely better (for values that won't change) to record them once instead of calling the function again multiple times - accessing the value of a local variable or auto property is very much faster than calling any function.

If you look at the assembly generated by the compiler (you can view the assembly file, which has an extension of .pas, by running the compiler with the -keepasm or -asmonly argument) you'll see that a bunch of temporary local variables are generated behind the scenes to store the results of functions like these, so creating new local variables to store those values shouldn't be a concern.

The compiler actually seems to be pretty poorly optimised in this respect, actually. Take this short script, for example:
Spoiler
ScriptName TestFileActor playerFunction SetPlayer()	player = Game.GetPlayer()EndFunction
The generated assembly for its SetPlayer function looks like this:
Spoiler
.function SetPlayer   .userFlags 0  .docString ""  .return NONE  .paramTable  .endParamTable  .localTable    .local ::temp0 actor  .endLocalTable  .code    CALLSTATIC game GetPlayer ::temp0  ;@line 6    ASSIGN player ::temp0 ;@line 6  .endCode.endFunction
As you can see, even though it shouldn't be necessary, an extra local variable is used as an intermediary between Game.GetPlayer and the local "player" variable.

It's actually possible to modify the assembly by hand, removing this local variable and adjusting the function to pass "player" as the location in which the return value of Game.GetPlayer() should be stored, then run the modified assembly through the Papyrus Assembler to create a slightly more streamlined script, but doing so is obviously risky.

Whether or not there is a significant difference in speed between setting the value of an auto property via the Creation Kit and setting it once in an OnInit block doesn't seem that important to me - the difference would be so minor as to be inconsequential, since it happens so rarely. I think it should definitely be considered best practice, though, to use one of those two methods to store values that won't change instead of calling a function again and again.

For the sake of convenience, values that will be the same for any instance of the script (like "PlayerRef") should probably use properties set in the CK and make use of the "Auto-Fill Properties" feature (this does work with "PlayerRef", in case you're wondering), whereas values that may be different for different instances of the script (like, in some cases, the return value of GetBaseObject) should probably be set in an OnInit block so as to keep the required setup for a script at a convenient level, instead of requiring manual selection of properties for each instance of the script.

Cipscis
User avatar
Shelby McDonald
 
Posts: 3497
Joined: Sat Jan 13, 2007 2:29 pm

Post » Mon Nov 19, 2012 8:36 am

I've edited the OP to include this point: Values that will not change should only be requested once.

Cipscis
User avatar
ijohnnny
 
Posts: 3412
Joined: Sun Oct 22, 2006 12:15 am

Post » Mon Nov 19, 2012 4:14 am

I've noticed that MoveTo/SetPosition are pretty fast on their own, but very, very slow if called in any sort of a loop. The execution time increases almost exponentially with the number of iterations in the loop. Can you explain to me like I'm five years old how queuing works here, and possibly how to avoid this problem?
User avatar
kiss my weasel
 
Posts: 3221
Joined: Tue Feb 20, 2007 9:08 am

Post » Mon Nov 19, 2012 4:08 am

I've noticed that MoveTo/SetPosition are pretty fast on their own, but very, very slow if called in any sort of a loop. The execution time increases almost exponentially with the number of iterations in the loop. Can you explain to me like I'm five years old how queuing works here, and possibly how to avoid this problem?
Can you post the code you're using? There could very well be other factors than the speed of either of those functions at play.
User avatar
Darian Ennels
 
Posts: 3406
Joined: Mon Aug 20, 2007 2:00 pm

Post » Mon Nov 19, 2012 1:06 am

Possibly it would worth including in the OP some general best-practice advice - "Never use RegisterFor if RegisterForSingle is available."

So, I think that would be "Never use RegisterForUpdate, RegisterForUpdateGameTime or RegisterForLOS."

The reasoning behind this is that

1) Using these features can easily lead to ever-increasing CPU load if the update time is set even fractionally less than the time required to process each update.

2) Uninstalling and updating mods becomes even harder.

Any other features that Papyrus makes available but which really should be avoided (except in dire need, with great care)?
User avatar
Tyrel
 
Posts: 3304
Joined: Tue Oct 30, 2007 4:52 am

Post » Mon Nov 19, 2012 12:51 am

Can you post the code you're using? There could very well be other factors than the speed of either of those functions at play.

It's in this thread, along with some related discoveries:
http://www.gamesas.com/topic/1387493-faster-way-to-moveto
User avatar
Hella Beast
 
Posts: 3434
Joined: Mon Jul 16, 2007 2:50 am

Post » Mon Nov 19, 2012 6:12 am

@andyw:
I completely agree with you there, andyw. I'll add it to the OP a bit later, once I've written it up to my satisfaction.

For those registrations that can't be specified beforehand as "one time only" events, would code like this do the trick?
RegisterForSleep(); ...Event OnSleepStart(float afSleepStartTime, float afDesiredSleepEndTime)	UnregisterForSleep()	; Do stuff	RegisterForSleep()EndEvent
Or would the script be removed when the mod is uninstalled and that unregistration wouldn't run because the event body no longer exists? I'm afraid I don't entirely remember how those things work.

@Verteiron:
The wiki has a decent explanation of how threading works http://www.creationkit.com/Threading_Notes_(Papyrus). Remember that http://www.creationkit.com/MoveTo_-_ObjectReference and http://www.creationkit.com/SetPosition_-_ObjectReference are both http://www.creationkit.com/Category:Latent_Functions.

If I understand things correctly, here's how it should work: When a script calls an external or latent function, one of two things can happen:
  • If the object on which the function is being called is currently locked (i.e. another thread is busy doing something with it), then your function is queued to be pushed to the stack (QUEUE_PUSH) and your thread is made to wait until your function can be called.
  • If/once the object on which the function is being called is available, then your function is pushed to the stack (PUSH) and the external or latent function starts to run. While this function is running, your script becomes unlocked, allowing another thread to enter it if need be.
Once the external or latent function is finished and ready to return, again one of two things can happen:
  • If another thread has entered your script while it was unlocked, it will have become locked and the function you've called will be queued to be popped from the stack (QUEUE_POP), and the original thread will have to sit and wait for the current thread to leave and your script to become unlocked before it can continue.
  • If/once your script is unlocked again, your function is popped from the stack (POP), and the original thread will return to your script and continue as normal from the next line.
I don't know if MoveTo or SetPosition are actually slow or if this slowness is due to your thread spending a lot of time queued while other threads are busy with either your original script or the objects you're trying to manipulate.

Try calling http://www.creationkit.com/StartStackProfiling_-_Debug before you run through your loop and take a look at the profiling logs - it should show each QUEUE_PUSH, PUSH, QUEUE_POP, and POP alongside a time marker (in ms since the game was started, I think). The readme of JustinOther's and my http://skyrim.nexusmods.com/mods/23782 utility has a bit more information on interpreting profiling logs.

If it turns out that the delay is due to a lot of queueing, then there might be something we could do to minimise it and speed up your script.

Cipscis
User avatar
^_^
 
Posts: 3394
Joined: Thu May 31, 2007 12:01 am

Post » Mon Nov 19, 2012 10:24 am

Can anyone confirm for me that this description of what happens when a mod that registered an object to receive continual events is uninstalled is accurate?
When a mod is uninstalled, scripts that have been previously added to objects will not be removed, but the file containing the compiled script itself will likely have be removed with the rest of the mod. When this happens, the object stays registered to receive all events for which it was already registered, and the game will continue to send these events to the object even though the code that handled the events no longer exists.

Continuing to receive these events will put extra stress on the scripting system, as well as filling up the Papyrus error log with a new error every time the registered event is passed to the removed script.
I don't have access to Skyrim at the moment, so I can't test it myself and probably won't be able to for another 30 hours or so.

Cipscis
User avatar
Joanne Crump
 
Posts: 3457
Joined: Sat Jul 22, 2006 9:44 am

Post » Mon Nov 19, 2012 8:29 am

I've updated the OP again to add 2 new rules:
When registering for events, wherever possible only register for a single event.
Always use the correct type of literal.

I think the description I've given for what happens after uninstalling a mod is accurate, but if you have any suggestions to improve its accuracy or clarity please let me know. Like I said earlier, eventually this will be going on the wiki for anyone to edit, so don't hold back on suggestions now just because it's a forum post I've made.

Cipscis
User avatar
megan gleeson
 
Posts: 3493
Joined: Wed Feb 07, 2007 2:01 pm

Post » Mon Nov 19, 2012 5:24 am

When a mod is uninstalled, scripts that have been previously added to objects will not be removed, but the file containing the compiled script itself will likely have be removed with the rest of the mod. When this happens, the object stays registered to receive all events for which it was already registered, and the game will continue to send these events to the object even though the code that handled the events no longer exists.

Continuing to receive these events will put extra stress on the scripting system, as well as filling up the Papyrus error log with a new error every time the registered event is passed to the removed script.
Sounds right from all I've seen. It's best to script preexisting references with a script extending ReferenceAlias rather than ObjectReference or Actor as the script will sever itself from an alias cleanly in the event the quest stops or ceases to exist. Others have more experience with this than I, but I did experiment with a scripted Skyrim.ESM table and in the plugin's absence, the script still ran. Outright deleting the script resulted in log errors.
User avatar
JUan Martinez
 
Posts: 3552
Joined: Tue Oct 16, 2007 7:12 am

Post » Sun Nov 18, 2012 8:05 pm

I'll poke my head in and say hi ... I don't have a specific comment as yet, but I do want to backup something andyw posted, up the page.

For the average modder on here there is a big advantage (for the community) if they take onboard some of this advice. But, I think a lot more of this advice is going to bog them down in detail they don't understand (which never helps anyone).

It would be good to see a Best-Practice Guide that (at least) started with "the most bang for your buck" stuff: So Justin's oft trailed method of getting a reference to the player (rather than game.getplayer()). And, on a wider but similar front, Cipis' suggestion to get a variable whose value will not change "only once". That sort of stuff is useful, pretty easy to understand, done widely and done often. So there's a big bang if you implement those tricks.

A function v Function anolysis for stuff only called once or twice in a mod ... not so much use.

Just don't get lost in the very, very small details; or many people are going to ignore the good-stuff (wood for the trees and all that?) ...

:)


(just a post to give a bit of confidence back to the newer modders who might wander in here, really, I guess ...)
User avatar
Roberta Obrien
 
Posts: 3499
Joined: Tue Oct 23, 2007 1:43 pm

Post » Mon Nov 19, 2012 1:14 am

Yeah, I hear you. Best practices will do no good unless they're made accessible, though, you're absolutely right there. At the moment the order of the points made in the OP is just based on the order in which they were thought of/brought up.

I guess the most important things to do when it comes to making this accessible are to...
  • ...make the information available in the appropriate places (e.g. the http://www.creationkit.com/GetPlayer_-_Game documentation should have a note linking to the best practice on only getting this value once per script).
  • ...provide solutions. So, for example, the best practices documentation should not only note that Game.GetPlayer() shouldn't be used repeatedly but it should also show how a script can be changed to use the standard best practice instead.
Listing the best practices in approximate order of important also comes to mind, since some are obviously more important than others (e.g. avoiding Game.GetPlayer() will have a much bigger impact than remembering to use literals of the correct type).

I think it's probably best to keep them all on the same page on the wiki, but I can also see how putting each standard on its own page and creating a "Best Practices" category might also be a useful approach - does anyone else have any thoughts on this?

I feel like this is getting pretty close to the point where it'll be useful to have on the wiki, so it might go up soon. Is there anything else I've forgotten about that'll be important for making these standards accessible? I admit that I sometimes find it difficult to imagine things from the perspective of an inexperienced scripter.

Cipscis
User avatar
Sarah Knight
 
Posts: 3416
Joined: Mon Jun 19, 2006 5:02 am

Post » Mon Nov 19, 2012 9:40 am

Another "best practice" that I think is worth considering, although it's obviously less important than some of the others already discussed:

Avoid small convenience functions.

Some of the convenience functions added by Bethesda add very little (or sometimes nothing) to a script while also adding the extra overhead of another function call.

For example, the http://www.creationkit.com/GetActorReference_-_ReferenceAlias function from the http://www.creationkit.com/ReferenceAlias_Script:
; Autocast to Actor is applicableActor Function GetActorReference()	return GetReference() as ActorendFunction
Both following two snippets of code from scripts extending ReferenceAlias are functionally identical, but the second is slightly more efficient:
MyRef = GetActorReference()
MyRef = GetReference() as Actor

For a more obvious example of why some of these functions should be avoided, let's look at http://www.creationkit.com/GetActorRef_-_ReferenceAlias, which the wiki lists as an alias of GetActorReference:
; Convenience fucntionActor Function GetActorRef()	return GetActorReference()endFunction
The only advantage of using GetActorRef over GetActorReference is that it allows you to save 6 keypresses, but it also adds the extra overhead of calling a non-global function.

I think it should be considered best practice to avoid these functions where they add very little to the script, although I'm not quite sure where to draw the line. I would say "functions that take no arguments", but I can still see the use of convenience functions that take no arguments but shorten code considerably.

For now, the best appropriate wording I can think of is "avoid small convenience functions".

Cipscis
User avatar
Jennifer Munroe
 
Posts: 3411
Joined: Sun Aug 26, 2007 12:57 am

Next

Return to V - Skyrim