Aller au contenu
  • Annonces

    • Olivier Devriese

      Nouveauté du forum, les blogs !   30/04/2016

      Envie de créer votre blog FileMaker ? Ca ne peut pas être plus simple qu'avec cette nouvelle section du site FM Source qui est désormais plus qu'un simple forum mais un vrai centre de ressource. Vous pouvez aussi facilement l'alimenter en le liant avec le flux RSS d'un autre blog que vous possédez déjà.
  • billets
    101
  • commentaires
    3
  • vues
    2 323

FileMaker Server Top Call Statistics Logging

Soliant Consulting

181 vues

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

Enable top call statistics log in the admin console

Figure 1. Enable top call statistics in the admin console under Database Server > Logging (click image to enlarge).

se the command line to enable/disable top call statistics.

Figure 2. Use the command line to enable/disable top call statistics (click image to enlarge).

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

First Row Option

Figure 3. First Row Option (click image to enlarge).

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 Files\FileMaker\FileMaker Server\Logs. 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).

Converted file displaying the top call stats .

Figure 4. Converted file displaying the top call stats (click image to enlarge).

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

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

The post FileMaker Server Top Call Statistics Logging appeared first on Soliant Consulting.


Afficher la totalité du billet



0 Commentaire


Commentaires recommandés

Il n’y a aucun commentaire à afficher.

Créer un compte ou se connecter pour commenter

Vous devez être membre afin de pouvoir déposer un commentaire

Créer un compte

Créez un compte sur notre communauté. C’est facile !

Créer un nouveau compte

Se connecter

Vous avez déjà un compte ? Connectez-vous ici.

Connectez-vous maintenant

×