With the release of version 15 in May 2016, FileMaker introduced a new feature – the Top Call Statistics Log – which tracks up to 25 of the most expensive (i.e. longest elapsed time) remote calls that occur during a collection interval.
I created a video on this topic back in May and am following up now with a written blog. The information here is essentially the same as in the video. My motivation is to create a text-based reference, because I find that to be a more useful reference than a video.
Statistics Log Files
Some of the actions that a user takes when working with a file hosted on FileMaker Server are processed entirely client-side. An example is sorting data that has already been downloaded to the client. But most actions will result in one or more remote calls which are processed by the server. Some examples include navigating to a layout, creating a new record, committing a record, and performing a find.
While the large majority of remote calls are initiated by the client, it is possible for FileMaker Server to initiate a remote call to the client. An example of this is when FileMaker Server asks the client for the values of its global fields.
When we talk about “clients”, it is important to realize that this includes server-side scripts, the web publishing engine, and ODBC/JDBC connections in addition to the Pro, Go, and WebDirect clients.
When a solution’s performance is suboptimal, it could be due to a specific action that a user (or a group of users) is taking. Before FileMaker 15, we had a view into remote call activity only at an aggregate level, through the usage and client statistics log files. With the top call stats log, we now gain an additional tool which allows us to view statistics for individual remote calls – the top 25 most expensive ones collected during a specified time interval. Using this log file, we now have a chance at pinpointing specific operations which may be causing degraded performance.
The information stored in the three statistics log files is gathered during a collection interval whose default value is 30 seconds. Each entry in a statistics log file must be viewed from the context of its collection interval. At the end of every interval, the new information is added to the bottom of the log.
Here are the three statistics log files:
|Log||Filename||Information Show for Each Collection Interval|
|Usage Statistics||Stats.log||One entry which summarizes information about all of the remote calls, across all files and clients.|
|Client Statistics||ClientStats.log||One entry for every client which summarizes information about the remote calls to and from that client *|
|Top Call Statistics||TopCallStats.log||Up to 25 entries showing discrete (not summarized) statistics from the most expensive remote calls.|
* According to my understanding, the Client Statistics log is supposed to have only one entry per client for every collection interval, but in my testing, I have sometimes seen more than one entry for a client.
Configuring Log Settings
The top call statistics log can also be enabled or disabled using the command line as shown in Figure 2:
- fmsadmin enable topcallstats -u admin -p pword
- fmsadmin disable topcallstats -u admin -p pword
In addition to enabling and disabling the log, the admin console Database Server > Logging area is used to specify the duration of the collection interval and the size of the log file. The default values are 30 seconds for the collection interval and 40 MB for the log file.
The log file size setting pertains to all of the log files, but the collection interval duration is only relevant to the three statistics log files: usage, client, and top calls. When the file size is exceeded, the existing log file is renamed by appending “-old” to the file name, and a new log file is created. If a previous “-old” file already existed, it will be deleted.
You can experiment with making the collection interval shorter, but only set it to very short durations (like 1 second) while diagnosing. The client and top call statistics do create additional overhead for the server, so if you are already dealing with a stressed server, there is potential for further performance degradation. And of course the log files will grow in size much more quickly as well. So, this setting should not be kept at very low values indefinitely.
Viewing the Log File
There is no viewer built into the admin console for the top call stats log file, so to view the data, you will need to open it in a text editor or an application such as Excel. You can also drag the file onto the FileMaker Pro icon (for example, on your desktop), which will create a new database file and automatically import the log data into it. If you do so, select the option to interpret the first row as field names (see Figure 3).
Making Sense of the Top Call Stats Log Data
Each line in the log corresponds to a remote call, and each column corresponds to a particular kind of data. Here is the list of all columns followed by a detailed look at each one.
- Start/End Time
- Total Elapsed
- Network Bytes In/Out
- Elapsed Time
- Wait Time
- I/O Time
- Client Name
Timestamp – This is the timestamp for the collection interval, not for the remote call. In other words, all of the entries that were collected during the same interval will show the same timestamp value. The timestamps use millisecond precision, and the time zone shown is the same as the server. Sample value: 2016-04-23 10:55:09.486 -0500.
Start Time – This shows the number of seconds (with microsecond precision) from when the Database Server was started until the time the remote call started. Sample value: 191.235598.
End Time – Same as the Start Time, except that this show when the remote call ended. If the remote call was still in progress when the data was collected, this value will be empty.
Total Elapsed – Number of microseconds elapsed for the remote call so far. This is the metric that determines which 25 remote calls were the most expensive ones for a given collection interval. The 25 remote calls are sorted in the log based on the Total Elapsed value, with the largest time at the top. Sample value: 1871.
Elapsed Time – Number of microseconds elapsed for the remote call for the collection interval being reported on. In the log file, Elapsed Time is shown as a column closer to the end of all of the other columns, but I am elaborating on it now, since it conceptually fits in with the Total Elapsed column. Sample value: 1871.
The Total Elapsed and Elapsed Time values will typically be the same, but they will be different for a remote call that began in a previous collection interval. For example, in the accompanying diagram, the entries for remote call B in the second collection interval (at 60 seconds) would show Total Elapsed as 33 seconds and Elapsed Time as 18 seconds (the values would actually be shown in microseconds instead of seconds).
Operation – This includes the remote call name and, in parenthesis, the client task being performed. The client task is only shown if applicable. For some entries, the client task will also show the percent completed. For example, for a find operation, the value might say “Query (Find)” if the operation completed before the log data was gathered at the end of the collection interval. But if the operation was still in progress, the value might say “Query (Finding 10%)”.
List of all possible remote call names and client tasks:
|Remote Calls||Client Tasks|
Target – This shows the solution element that is being targeted by the remote call operation. See the accompanying tables (below) for some sample values as well as a list of all possible target values. The name of the hosted database file is always shown as the first value; i.e. before the first double colon. The additional information after the first value will be included if it is available. In the example shown, we can see that there is a lock on one or more records in the table whose ID is 138. The ID value is not the internal table ID; it is the BaseTable ID which comes from the XML Database Design Report (DDR). Using a table’s ID instead of its name is done for security reasons. If your table name is “Payroll”, and that name was exposed in the log file, that would leak potentially useful information about your database to a would-be hacker.
Sample values for Operation and Target:
|Commit Records (Commit)||MyFile::table(138)|
|Query (Find)||MyFile::table(138)::field definitions(1)|
List of all possible targets:
Network Bytes In/Out – These two columns show the number of bytes received from and sent to the client. Each entry shows a value that is pertinent to its remote call and for its corresponding collection interval only. Note that if a remote call spans more than one collection interval, it will likely send or receive additional bytes in the subsequent interval(s); i.e. the values will be different in the different collection intervals. Sample value: 57253.
Elapsed Time – The Elapsed Time statistic column is shown following the Network Bytes Out column, but we already covered it a bit earlier in the blog post, so please refer to the detailed explanation there.
Wait Time – Number of microseconds that a remote call spent waiting in the collection interval. An example of why this might happen is that maybe there weren’t any processor cores available at the time or maybe some other remote call had locked the table which this remote call needed access to. Sample value: 1871.
I/O Time – Number of microseconds that a remote call spent in the collection interval reading from and writing to disk. Sample value: 1871.
Client Name – A name or identifier of a client, along with an IP address. If the client is a WebDirect client, it will be made apparent here. If the client is a server side script, the script name will be shown.
Sample client name values:
- John Smith (Smith Work Mac) [192.168.28.137]
- Archive Old Records – Admin 1 (FileMaker Script)
How to use the top call stats log?
The top call stats log will give you a better shot at identifying the factors contributing to slow performance. For example, if you have a single table that everyone is writing to or searching against, then you would expect to see a lot of remote calls having to do with managing the locking of that table or the index. Another example: If you receive reports of FileMaker being slow for everyone, and if you spot a single client appearing in the top call stats log much more so than other clients, then you can investigate with that user to see what he or she is doing that is different from other users.
Jon Thatcher did an excellent session at the 2016 DevCon during which he gave several examples of using Top Call Stats to troubleshoot performance issues (starting at around 34:37). A recording of the session is available here: “Under the Hood: Server Performance”.
Here is Jon’s general overview of how to use the three statistics logs to identify causes of performance issues:
- First identify the problem resource (CPU, RAM, disk, or network) using the Server Statistics log or an OS tool like (OS X) Activity Monitor or (Windows) Task Manager or PerfMon. The server statistics log can show spikes (for example, long elapsed time), but not which client caused them.
- Next, identify the problem client(s), if any, with Client Statistics. This log can show which client caused the spike, but not which operation caused it.
- Finally, use Top Call Statistics to identify the problem operation(s).
- Tracking activity in log files in FileMaker Server – FileMaker Knowledge Base
- Viewing Statistics in FileMaker Server – FileMaker Knowledge Base
- Top Call statistics logging – FileMaker Knowledge Base
- Top Call Stats Logging video – Soliant TV
- “Under the Hood: Server Performance” – John Thatcher’s 2016 DevCon session
- Session slides for John Thatcher’s session – FileMaker Community