Skyrim
0 of 0

File information

Last updated

Original upload

Created by

Jake Alaimo

Uploaded by

JakeAlaimo

Virus scan

Safe to use

About this mod

Profiling your scripts is a necessary step to ensure that your mod is responsive and doesn’t contribute to global script lag. This is a tool that processes Papyrus profiling log data into a tabular format for easier visualization and export into Excel for statistical analysis.

Permissions and credits
Donations
Profiling your scripts is a necessary step to ensure that your mod is responsive and doesn’t contribute to global script lag. This is a tool that processes Papyrus profiling log data into a tabular format for easier visualization and export into Excel for statistical analysis. You can access it online at PapyrusProfilingParser.com.


This tool is intended to serve as a resource for Papyrus scripters. If you aren’t working on a scripted mod, you probably don’t need this tool.
 

What is Profiling? How Do You Profile in Papyrus?
Spoiler:  
Show

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!




Details

Inputting Log Files: You can add a file to parse by clicking the input box labeled ‘Choose a file…’. Alternatively, you can drag and drop a file onto that same input box. Multi-file selections are supported with both input methods, which is particularly useful for grouping multiple stack logs together. Your profiling logs are created in the‘Documents\My Games\Skyrim\Logs\Script\Profiling’ folder by default.
 
Parsing the Data: Click the green ‘Parse’ button to process the files you’ve inputted. This will produce a series of tabs each containing their own table. Every file will produce a ‘Stack Timings’ tab, which indicates when each stack started and finished recording data. Every other tab will correspond to a unique function or event called and display only the data related to that function/event.
 
Making Sense of the Data: Every row in a tab’s data table will contain a STACK_ID and some combination of QUEUE_PUSH, PUSH, QUEUE_POP, and POP values. A STACK_ID is a numerical identifier denoting the calling context of the functions and events it’s associated with. Every instance of a function or event gets their own ID and the functions called within them are associated with that ID. Thus, if two rows of data share the same STACK_ID, that means the same parent function called both of them. All of the data in a stack log corresponds to a single STACK_ID.
 
And the Other Data: All of the other columns of data contain the time (in milliseconds) that that stage of function execution occurred at. Thus PUSH - QUEUE_PUSH = the elapsed time between trying to call the function and it starting, POP - PUSH = the time it took the function to execute, and POP - QUEUE_PUSH = the total time the function call took to complete. Queues are used because only one thread may act on a script at a time, and some functions wait for the next frame to complete.
 
Exporting the Data: There are two options for exporting the parsed data from the tool, and both are represented with buttons at the bottom of the display. First, you can export the currently displayed table as a CSV file. The filename will be‘[parsed file name]_[displayed tab].csv’. Alternatively, you can copy the entire table to your clipboard, which is then able to be pasted into Excel or similar programs. Both operations are performed by simply clicking the desired button at the bottom of the display.

 

Requirements and Installation

This is a web app and thus runs in your browser. All modern browsers should be supported, but this isn’t intended for mobile use. Edge doesn’t support freezing the first row of the table, but all other features work as intended. This behavior is corrected with newer versions of Edge.

Given that this is a web app, it doesn’t need to be installed at all. You can access it at PapyrusProfilingParser.com or download an offline copy here. Simply extract the archive anywhere and open the included HTML file with your browser of choice.

 

License

This software is available under the GNU General Public License v3.0. The source code can be found here.