Skyrim

Profiling is a form of software analysis that measures data related to the execution of your code as it executes. Profiling is often used to measure the time it takes your code to run. Papyrus profiling logs include the timings for functions as they are called, which helps to illustrate the overall performance of your scripts. If code execution is a race and your script is the sprinter, you are the coach and your profiling is the many arms jutting out of your torso, operating stopwatches to independently track the movements of different parts of the sprinter’s body.
 
Why Profile?
There are a few major reasons to profile your Papyrus scripts. First of all, the performance of software can be unintuitive. Developers guess the performance of code about as well as 10-year-olds play the violin. Generally, not very well. This is especially true in Papyrus given that we are working with a scripting language and engine that we don’t know much about the internals of. Only by profiling your scripts can you get hard evidence of how well they are performing. This data gives you the information you need to learn how to improve your scripts.

Depending on the script you are writing, the time it takes to execute can be incredibly important. Imagine the frustration of a dodge mod with a second of latency every time you try to roll, or a heal-on-low-health spell that only triggers after you’ve died. Slow scripts kill. Profiling can show what functions are causing that.

Some mods don’t need precise timing though. Even in those cases, your script’s performance matters. Papyrus is multithreaded, but one of its crucial architectural decisions is that only one thread can operate on a script at a time. This cuts down on race conditions, but it also means that popular functions can take progressively longer to access as more scripts try to call them and enter a queue. The worst performing parts of your scripts will often be these popular functions, and by accessing them you are contributing to making them slower. Combine this with the CPU time you are hogging and you have a recipe for script lag, not just for your scripts but for every other mod’s scripts too. You aren’t the only modder calling these functions. Be a good neighbor. Profile your scripts.

How Do You Profile?
First things first, you have to enable profiling. Navigate to ‘Documents\My Games\Skyrim’ and crack open Skyrim.ini. Navigate to the [Papyrus] section. Add the line ‘bEnableProfiling=1’ if it doesn’t already exist. If it does exist, make sure bEnableProfiling is set to 1. This setting allows the game to create profiling logs, though it won’t do so automatically. There are a few ways to tell the game to profile, but to my knowledge only two allow you to be specific about the scripts you’d like to track. They are both functions that need to be called in a script and they both have different uses. These are Debug.StartScriptProfiling and Debug.StartStackProfiling.

Debug.StartScriptProfiling takes a script name as a parameter. When called, it logs when each function or event inside the script passed in as a parameter starts and finishes executing into a single file. Note that this function is called in a separate script than the one that is being profiled. It’s useful for getting a broad picture of how well the different functions in the script perform and is a great way to detect areas that need addressing. However, logs produced this way don’t give any indication as to why functions perform the way they do. There is no data for how the internals of the function are performing. That’s where stack profiling comes in.

Debug.StartStackProfiling takes no parameters. Instead, you place it into the function you want to profile, just before the code you’d like to track the performance of. You can call Debug.StopStackProfiling after the last line you’d like to profile within the same function if you only want to profile a part of the function. Otherwise, the stack profiling log will finish when the parent function finishes. Unlike script profiling logs, stack profiling logs only track for a single instance of a function or event. Rather than just showing when that function started and finished, stack profiling logs track the timings of all the function calls made within that parent function call. External function calls are generally what makes a function slow in Papyrus, so stack logs give you a breakdown of exactly what is making the function you are profiling perform the way it does. With this knowledge in hand, you can make changes to make the function faster.

Regardless of the function you are using to profile, logs are placed in ‘Documents\My Games\Skyrim\Logs\Script\Profiling’ as .log files. I recommended you do something with the old log files in this folder before you go on to profile another section of your scripts. You don’t want to mix up data from different functions here. With that in mind, make sure to remove the ‘Start Profiling’ calls from any scripts you distribute. You don’t want to fill someone else’s log folder with your profiling data.

Alright, I’ve Profiled. What the Hell Is this Data?
It’s perhaps not the clearest format in the world. It’s also a bit difficult to work with without tools, hence why I developed the Papyrus Profiling Parser. Still, even with tools it helps to know what you’re looking at.

Most lines in a Papyrus profiling log have 6 components, each split by a colon delimeter (‘:’). The last component indicates the function the line is about. The first component is a time stamp in milliseconds. The second component indicates the function’s execution state. Together these three bits of information tell us what we are looking at. Most lines in a profiling log tell us the exact time in milliseconds when a given function reached a certain execution state. There are four possible execution states: QUEUE_PUSH, PUSH, QUEUE_POP, and POP. PUSH indicates that the function has started executing and POP indicates that it has finished. The queue states exist because only one thread is permitted to act on a script at a time or because some functions must wait for the next frame to execute. Function calls in the queue states are either waiting to begin or waiting to end. If we know the exact timings for each of these states, we can subtract them from one another to determine the elapsed time between states, which tells us how long they took.

For example, POP - PUSH gives us the time it took the function to execute once it started. PUSH - QUEUE_PUSH tells us how much time was spent waiting for the function to begin executing. POP - QUEUE_PUSH shows us exactly how long the function took from start to finish. With this information in hand, you can now determine which sections of your scripts are too slow and what functions are making them that way. I found grouping the data in profiling log files manually for this purpose to be far too cumbersome, hence why I developed the Papyrus Profiling Parser.

There are a few more data components in the log files, but the only other one I found useful was the third component. This is the stack ID associated with the parent function of the function being profiled. In a single stack log, every line will share the same value for this, which makes sense considering they are all under the same parent function.

Now What?
At this point you know everything you need to know. Subtract the times of each execution state to get the elapsed time between them (in milliseconds). Use this information to determine how long functions are taking, and if they are taking too long try to come up with an alternate approach. 

You can determine the grouping of the data manually, but this is usually pretty tedious if you are working with more than just a single sequential stack profiling log. Use my tool to handle the grouping for you, pull data from a bunch of stack profiling logs together, or if you want the data in an Excel-ready format. 

Best of luck!

Article information

Added on

Written by

JakeAlaimo

5 comments

  1. niston
    niston
    • premium
    • 315 kudos
    Looking at a FO4 Stack Profiling Log, wondering about the unit of measurement.
    Start: 92049311, Done: 92146026, Difference: 96715

    Spoiler:  
    Show


    Stack_9389320 log opened (PC-64)
    92049311:START:9389320
    92049410:POP:9389320:6:None:debug..StartStackProfiling
    92049463:PUSH:9389320:6: (FF068046):NetLink:LinkLayer..CheckFrameTypeValid
    92049487:POP:9389320:6: (FF068046):NetLink:LinkLayer..CheckFrameTypeValid
    92049518:PUSH:9389320:6: (FF068046):NetLink:LinkLayer..NETLINK_PROTOCOL_VERSION
    92049551:POP:9389320:6: (FF068046):NetLink:LinkLayer..NETLINK_PROTOCOL_VERSION
    92049602:PUSH:9389320:6: (FF068046):NetLink:LinkLayer.started._L1TX
    92049639:PUSH:9389320:7: (FF068046):NetLink:LinkLayer.started._L1EnumStations
    92049651:QUEUE_PUSH:9389320:8:None:SUP_F4SE.??.GetPowerGridForObject
    92065658:PUSH:9389320:8:None:SUP_F4SE..GetPowerGridForObject
    92065707:POP:9389320:8:None:SUP_F4SE..GetPowerGridForObject
    92068372:QUEUE_PUSH:9389320:8:None:SUP_F4SE.??.GetPowerGridElements
    92085399:PUSH:9389320:8:None:SUP_F4SE..GetPowerGridElements
    92086977:POP:9389320:8:None:SUP_F4SE..GetPowerGridElements
    92089391:QUEUE_PUSH:9389320:8:None:SUP_F4SE.??.FilterObjectRefArrayByRefs
    92104697:PUSH:9389320:8:None:SUP_F4SE..FilterObjectRefArrayByRefs
    92104934:POP:9389320:8:None:SUP_F4SE..FilterObjectRefArrayByRefs
    92107497:PUSH:9389320:8: (FF068046):netlink:api:linklayerbase..OK_NOERROR
    92107508:POP:9389320:8: (FF068046):netlink:api:linklayerbase..OK_NOERROR
    92107548:POP:9389320:7: (FF068046):NetLink:LinkLayer.started._L1EnumStations
    92107565:PUSH:9389320:7: (FF068046):netlink:api:linklayerbase..OK_NOERROR
    92107577:POP:9389320:7: (FF068046):netlink:api:linklayerbase..OK_NOERROR
    92107599:QUEUE_PUSH:9389320:7:None:SUP_F4SE.??.FilterObjectRefArrayByRefs
    92124052:PUSH:9389320:7:None:SUP_F4SE..FilterObjectRefArrayByRefs
    92124245:POP:9389320:7:None:SUP_F4SE..FilterObjectRefArrayByRefs
    92126062:QUEUE_PUSH:9389320:7:None:SUP_F4SE.??.NotifyReferenceScripts
    92143252:PUSH:9389320:7:None:SUP_F4SE..NotifyReferenceScripts
    92143463:POP:9389320:7:None:SUP_F4SE..NotifyReferenceScripts
    92145987:PUSH:9389320:7:None:debug..Trace
    92146004:POP:9389320:7:None:debug..Trace
    92146013:POP:9389320:6: (FF068046):NetLink:LinkLayer.started._L1TX
    92146022:PUSH:9389320:6:None:debug..StopStackProfiling
    92146026:DONE:9389320
    Log closed



    If these numbers were Milliseconds, my function would take almost 97 seconds to complete  - When, in reality, it's completed within the blink of an eye and therefore the unit cannot possibly be Milliseconds. So what is it instead? Microseconds? Ticks?
    1. niston
      niston
      • premium
      • 315 kudos
      Answering my own question for future reference, the unit of measurement in FO4 profiling logs is microseconds.
      Found by repeatedly profiling Utility.Wait(10).
  2. x13v3
    x13v3
    • supporter
    • 0 kudos
    I added support for Papyrus profiles to the flamegraph-like visualizer speedscope, you can upload your profiles and inspect them in your browser.
  3. Firefinger
    Firefinger
    • premium
    • 1 kudos
    Where can you insert the profiling commands at to get a good look at the global activity?
    Can this profiling just be enabled and disabled globally from the console?
    1. PistachioRaptor
      PistachioRaptor
      • premium
      • 289 kudos
      Depends what kind of data you need, and what you mean by “global” activity. I wrote this to help others improve their own scripts, but if you’re looking for overall papyrus performance data across all scripts you have a few options.

      You can use StartObjectProfiling to profile all the scripts firing off a specific form. The StartPapyrusFormProfile console command does the same. If you’re on Fallout 4, you have access to the TogglePapyrusGlobalProfiler console command, which should provide profiling data for all scripts. Unfortunately, that’s not available for Skyrim as it isn’t useful in most cases. You can use the DumpPapyrusStacks console command to get a sense for the scripts that are running at any given moment, or you can try a latency tester someone has developed if all you really want to know is how well your setup is working.