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:
LogFilenameInformation Show for Each Collection Interval
Usage StatisticsStats.logOne entry which summarizes information about all of the remote calls, across all files and clients.
Client StatisticsClientStats.logOne entry for every client which summarizes information about the remote calls to and from that client *
Top Call StatisticsTopCallStats.logUp 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.

Enable top call statistics log in the admin console
Figure 1. Enable top call statistics in the admin console under Database Server > Logging

The top call statistics log can also be enabled or disabled using the command line as shown in Figure 2:

se the command line to enable/disable top call statistics in FileMaker Server
Figure 2. Use the command line to enable/disable top call statistics
  • 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.

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).

Figure 3. First Row Option
Figure 3. First Row Option
Converted file displaying the top call stats in FileMaker Server
Figure 4. Converted file displaying the top call stats

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).

Remote calls diagram FileMaker Server
Figure 5. Remote calls diagram.

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 CallsClient 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:
OperationTarget
UnlockMyFile
Commit Records (Commit)MyFile::table(138)
Query (Find)MyFile::table(138)::field definitions(1)
LockMyFile::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

13 thoughts on “FileMaker Server Top Call Statistics Logging”

  1. Pingback: FileMaker Cloud, FM Server Top Call, Environment's Effect on Achievement - FileMakerProGurus

  2. You kept using the word expensive in your article, but I think the word you actually meant to use instead is extensive. “…which tracks up to 25 of the most expensive remote calls that occur…” These remote calls cost the most amount of money (expensive)? Or don’t you mean that these are the most comprehensive (extensive)?

    1. Hi Kim,

      I did mean to use the word “expensive”, although I can understand how that could be confusing, so thank you for pointing that out to me. I’ve updated the beginning of the blog post so that this is hopefully more clear now.

      In this context, saying that a remote call is expensive means that its Total Elapsed time is longer than that of other remote calls. Calls that take a long time to complete (i.e. high Total Elapsed time) end up using more processing power. These calls can become a bottleneck, and so in that way, they are considered “expensive”.

  3. Is there a reference anywhere to what the various operations actually are? For instance, I’m seeing a lot of time being spent on “Compare Modification Counts”. I have no idea what this is, and it doesn’t seem to be documented anywhere. This leaves me with no idea what I need to tweak in my database.

    1. Hi Mike, it sure would be nice to have, but unfortunately I am not aware of a good reference for this.

      My guess is that “Compare Modification Counts” is used as part of the file open routine (when the file is being opened by a client) when the client needs to determine how much of its persistent cache it needs to discard.

      If large sets of records are being modified fairly frequently, then it would make sense that this cache invalidation routine will take a longer time to run, and so you might see the “Compare Modification Counts” and “Download List” calls listed in the top call stats.

    1. Chris, thanks for letting us know. I updated the YouTube link. I don’t know what the new link should be for the session slides, so I’m leaving that as is, even though it is at the moment broken.

  4. In your blog, you mentioned- “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.”

    Where can I get the client log?

    1. Hi James,

      Back when I originally wrote this blog, enabling the client statistics log was done a bit differently, but these days here’s how you do it:

      From the machine where FileMaker Server is installed, open a terminal, command prompt, or PowerShell window, and type this: fmsadmin enable clientstats. You’ll be asked to provide your admin console credentials. While you’re at it, I recommend enabling server stats as well: fmsadmin enable serverstats.

      Now check the Logs folder which is located inside the FileMaker Server installation folder. You’ll have to wait for the next collection interval to roll around – this is typically set to 30 seconds – but once that happens, you should see a ClientStats.log file appear in the Logs folder. (The log file that corresponds to the server stats is called Stats.log.)

      Hope that helps,
      Mislav

  5. Thank you for your article, very helpful. I am looking at the stats and I see very high elapsed times for operation ‘Download thumbnail’ with target ‘(filename)::file status’. Any idea what that action is?

    1. Hi Jeroen,

      I’m not sure. I looked at a sample TopCallStats log file I had laying around and found two “Download Thumbnail” entries:
      * Download Thumbnail >> {filename}::file status
      * Download Thumbnail >> table{tableId}::containers

      The second of those (containers) seems straightforward, but the first one (file status) is puzzling. I’ll ask around about this and will post here if I find out anything.

    2. Hi @Jeroen Aarts, did you ever solve this?

      This entry (Download Thumbnail >> {filename}::file status) seems to be responsible for bringing down my server completely. It never finishes the call even after 60 minutes!

      Has happened 3 times in the last month on FMS 19.4.2 on Linux. I also had this problem on another server (totally different app) back in July 2021 when it was running something older than 19.3.2 on Linux, but the problem never recurred after upgrading to 19.3.2 and now 19.4.2…

Leave a Comment

Your email address will not be published. Required fields are marked *

Are You Using FileMaker to Its Full Potential?

Claris FileMaker 2023 logo
Scroll to Top