FileMaker Server Top Call Statistics Logging

With the release of version 15 in May 2016, FileMaker Server 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 is enabled in the admin console in the Database Server > Logging area as shown in Figure 1. Once enabled, it will continue to capture information even if the admin console is closed. However, if the Database Server is stopped, the top call statistics log will not automatically re-enable once the Database Server is started up again.

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

The log file data is stored in a tab-delimited text file with the name TopCallStats.log. For Windows, the default path for all log files is C:Program FilesFileMakerFileMaker ServerLogs. The path for Mac servers is /Library/FileMaker Server/Logs/. Unlike with a Mac, the Logs path can be changed on Windows by installing FileMaker Server to a non-default location.

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.

• Timestamp
• Start/End Time
• Total Elapsed
• Operation
• Target
• 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
Adjust Reference Count Build Index Commit Records Compare Modification Counts Create Record Download Download File Download List Download Temporary Download Thumbnail Download With Lock Get Container URL Get DSN List Get File List Get File Size Get Guest Count Get Host Timestamp Lock Lock Finished Login Logout	Notify Notify Conflicts ODBC Command ODBC Connect ODBC Query Open Perform Script On Server Query Remove All Locks Request Notification Serialize Transfer Container Unlock Update Table Upgrade Lock Upload Upload Binary Data Upload List Upload With Lock Verify Container	Abort Aggregate Build Dependencies Commit Compress File Compute Statistics Consistency Check Copy File Copy Record Count Delete Record Set Delete Records Disk Cache Write Disk Full Disk I/O Export Records	Find Find Remote Index Lock Conflict Optimize File Perform Script On Server Process Record List Purge Temporary Files Remove Free Blocks Replace Records Search Skip Index Sort Update Schema URL Data Transfer Verify

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:

Operation	Target
Unlock	MyFile
Commit Records (Commit)	MyFile::table(138)
Query (Find)	MyFile::table(138)::field definitions(1)
Lock	MyFile::table(138)::records

List of all possible targets:

Target
base directory containers custom menu custom menu set field definitions field index file reference file status font global function globals	layout library master record list records relationship script table table occurrence theme value list

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:

1. First identify the problem resource (CPU, RAM, disk, or network) using the FileMaker 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.
2. 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.
3. Finally, use Top Call Statistics to identify the problem operation(s).

References

• 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