The top call stats log was introduced in FileMaker 15 and when we first heard about it we were excited about the possibilities of using it to track down where the bottlenecks might be in our solutions and where to go prospecting for performance optimization opportunities.
Over time that excitement has been tempered by the fact that the information in the top call stats log is not that easy to interpret. In this blog post, I’ve attempted to summarize the history of our experience with top call stats and tools that have helped us interpret those stats.
Before diving too deeply into top call stats, I’d like to complement Claris on the overall excellence of FileMaker Server. I think it says a lot that we so rarely have to even look at the top call stats log because FileMaker Server generally ‘just works’ and responds gracefully to some of the heaviest loads we place on it.
The downside of the above is that we don’t have very many real world cases where we have to rely on the top call stats log and it makes it harder to become proficient with interpreting it.
FileMaker Server Docs
You can start with the FileMaker Server documentation for a basic overview. The FMS docs provide a good starting point on how to enable the top call stats log in the FileMaker Server Admin Console and what each of the data points in the log represents.
The holy grail, how to interpret the information in the log, is not to be found here however, so on we proceed.
2016 Devcon session
If you can find a link to it, Jon Thatcher of FileMaker did a server performance session at the FileMaker Devcon in 2016 where he talked about using the top call stats log for tracking down performance issues.
Unfortunately, I can no longer find the 2016 video. The video of the same session in 2017 is available on YouTube and refers you to the 2016 video for top call stats logging info, however the 2016 video no longer appears to be available.
Jon’s session outlined a basic methodology for using the top call stats log that involved using the client stats log to identify the source of an issue and then utilizing the top call stats log to attempt to identify the specific operational bottleneck.
Following on this session, we spent some time in our weekly dev meetings with the top call stats log attempting to analyze the data in this way. Unfortunately, tracing a performance issue from a user’s complaint, through the client stats log and then into the top call stats log is fairly challenging
A step beyond the FileMaker docs
This Soliant blog post written in 2017 is an essential supplement to the FileMaker Server documentation. It covers the same material as the FMS documentation and builds on it to give much more detail about what each specific element in the log file represents and what all of the possible values are.
For help with interpreting the log file though, this post points you to the above video by Jon Thatcher, so we still don’t have a lot of help on interpreting the top call stats log.
Top Call Stats, viewed graphically
Earlier this year, Joe Martin of 360Works, published this excellent video demonstrating a helper file that he put together for analyzing the top call stats log.
Joe does a good job of explaining how the FileMaker log file stores data in logging intervals that can be used to directly relate data between the separate log files.
Building on this, Joe created a FileMaker helper file (available for download at the above link) that allows you to import the top call stats log, client stats log, and server stats log. It then builds a reference between the files.
The result is a javascript graph that lets you see graphically during any given log interval what the top calls were and which clients they were related to. You can sort the server stats by one of the stats, like elapsed time per call, then examine the slower log intervals to see what was happening during that time.
Unfortunately, you can still only see table and field numbers, not real table and field names, and it can be hard to figure out what is going on when the log entry was made. It is often not that helpful to know simply that the ‘Perform Script on Server’ script step was used with no other context.
FM Perception
Starting last year, we did a new evaluation of DDR tools and decided to switch to FM Perception. We’ve been quite happy with it and it turns out to have a feature we weren’t aware of originally – parsing the top calls log along with the DDR.
With FM Perception and the demo file from the 360Works blog post, we have the tools that let us look at the top calls log in a graphical way and search for issues from the perspective of the client experiencing slow performance, and then track down that logging interval in the log file in FM Perception and easily see exactly which table and field the log file is referencing.
In addition, since we’re already in a DDR cross referencing tool, we can easily dig further and figure out more contextual information than the log file provides.
In the screen capture from the 360Works demo file, we’re able to see a log interval where a perform script on server script step ran and then a Find operation ran on table 131, field 39.
Jumping from there to the FM Perception screen capture, we can see that the field in question is from the Events table and is called ‘deleted’.
A quick search of all instances of the use of the ‘Perform Script on Server’ script step quickly reveals where we used that in context with a find on the ‘deleted’ field.
So now we can look at the exact script that was running when the top call event was logged, which is what we really want.
I imagine that over time we’ll see additional tools and methods for working with the top call stats log, but for now these last two tools give us a pretty good approach to top call log analysis.
Have you spent some time working with top call stats? We’d love to hear your comments below about your experiences with top call stats.
Please contact us if we can assist with bottlenecks in your Claris FileMaker solutions!
~John Newhoff
