Now more than ever we’re relying on Perform Script on Server (PSoS) to maximize FileMaker performance, so naturally a need arose for a way to proactively monitor how many concurrent scripts are being triggered. This type of logging helps us see if we’re reaching our maximum limit, or have a rogue script eating up processing power.
Our first attempt has been to put the logging of PSoS into a table in the same file. The basic idea is that when a script is executed on FileMaker Server, the first thing it does is create a record in the PSoS log table with an ID that it can later find and update. A duration isn’t the only thing that’s captured. Take a look at the fields in the table below:
DURATION – calculation [If ( IsEmpty ( END ); “”; Round ( ( END – START ); 3 ) )]DURATION – calculation [If ( IsEmpty ( END ); “”; Round ( ( END – START ); 3 ) )]
Some of these are obvious as to what information they capture, and some of them less obvious.
‘Token’ is the unique identifier and as such we could probably even do away with the first 2 fields ( ID and Separator ). Then comes ‘Sequence_Number’: Todd Geist posted a few months ago about how Get ( UserName ) doesn’t just return the user name when run on the server, but a concatenated set of the following values:
The sequence number is a sequential number of PSoS scripts that have been performed on server for any file on that server since the last time the server was restarted.
You can get the start and end and the duration using…
GetAsTime ( Get ( CurrentTimeUTCMilliseconds ) / 1000 )
The more you rely on PSoS the more you’ll have a need to monitor how close which files, scripts or users are getting close to that limit. A log will also let you monitor scripts that are not exiting; for example, if you have a start number that isn’t going back to 1, you’ll know there’s a script that’s stuck in an endless loop consuming valuable CPU power.
The actual script that you will reference in your PSoS script only takes 1 parameter. All you need to worry about is whether you’re calling it at the Start or at the End. Here are the basic components of that script itself, with the red box around the step that actually does all the work. It uses the XML API to run a script in the PSoS_Log_CWP file and sends along all the necessary information.
What’s great is its simplicity, and that it works on your server logging PSoS activity for all of your hosted files:
The beauty of this approach is using ‘Insert from URL’ to send an XML request to trigger a script in the PSoS_Log_CWP file, which will then perform the necessary actions to record the information sent to it from the scripts parameters.
Here are the steps you’ll need to add this functionality to your hosted solutions.
The PSoS_Log_CWP file is pretty much ready to use, all you’ll need to do is host the file on your server and follow these steps to integrate functionality:
1 – Copy all the custom functions that are in the PSoS_Log_Client file
2 – Copy the FOCUS table
3 – Create a new layout called PSOS_LOG and copy the fields that are on that layout over.
4 – Copy all the scripts over. Mostly you only need “log psos ( LogPsosParameter )”
This takes less than a minute to integrate into a starter file, and then you are ready to start using it.
Once you have it wired up, you’ll be able to:
1 – See how long each of your PSoS scripts is taking to run
2 – See how many overlapping PSoS scripts you have running at any point in time
3 – Because we also capture the script parameter that is sent up to the server, you can inspect it to troubleshoot your PSoS scripts.
This technique has been indispensable since I’ve started using it. I would love to hear your thoughts or comments on this approach!
A big thank you to Steve Senft-Herrera who helped make this incredibly simple to implement, and to make it possible to document pretty much all the solutions you have from any server.
One thought on “FileMaker Log Files: Episode VII – PSoS Awakens”