The new FileMaker Server 15 “Top Call Stats” feature helps us identify potential bottlenecks. It shows the most expensive user activity, broken down by user and type of action being taken.
Video Transcript:
Hello, my name is Mislav Kos.
FileMaker server 15 adds a new feature called Top Call Stats Logging. This logs up to the 25 most expensive remote calls made during a collection interval.
So, what is a remote call? It’s any operation that you take in FileMaker. For example, navigating a layout, creating a new record, committing a record, performing a find, and so on. Each of these operations triggers one or more remote calls to happen on the server.
If we take a look in the admin console where this is configured, in the “Database Server” section, under the “Logging” tab, at the bottom, there are two new checkboxes. The “Client Statistics” checkbox is something that we had before. But in FileMaker server 14, it used to appear in the “Statistics” section, in the “Clients” tab in the upper right. In 15, we take a look at “Statistics,” then the “Clients” tab, and it’s no longer there. It has been moved to the “Logging” tab.
It also works a little bit differently. Back in 14, if you checked the “Log client statistics” box and then move away from this tab, even if you were just to go to the server and then come back, it would get unchecked. In 15, we can move away from this tab. We can even go to a different section and close the admin console, and it will stay checked.
Do note that if we were to stop the database server, and I’ll do that here right now, and then we start it back up again, those boxes will be unchecked. We can see that they are unchecked here at the bottom of the screen. We can see they are unchecked here and we could check them off. But let’s take this opportunity to show you a different way that we can enable these logs.
Here, I have a couple of batch files that I have created, enable topcallstats and disable topcallstats. You can enable top calls with the first command, and you can disable second with the second command. Note that you do have to provide your admin console credentials. In my batch file, I have a pause at the end. That is just so I can get a visual confirmation that the command was run successfully.
If I double-click on this batch file, I can see that result says, “UseTopCallsLog = true”. I can now hit any key and that goes away. Note that the refresh box does not refresh right away. Even if I go to another tab and come back, it still does not refresh. But if I navigate to another section and come back, now we can see that it is enabled.
The client stats and the top call stats are collected in intervals. The duration of the interval is set up here, under statistics. I have it set to one. The default is 30 seconds, one is almost certainly too short of a time, especially if you are dealing with a stressed server; when you do have the logging of these statistics enabled, it does create additional work for the server to do. And so, there is potential that the performance of the server will be degraded.
So, you don’t want to set the collection interval too low. I set it to one just for my own testing and also because there is no one else accessing this particular server. The other thing to point out in this section is that the size of the log file is set right here, in the “Log Size (MB)” field. 40 MB is the default size. Both of these two settings, the collection interval time and the default log size apply not only to client stats in the top call stats logs, but also to the access and usage stats and also to the event logs which isn’t shown here. It is a log that the FileMaker server always maintains, and so it cannot be turned off.
Let’s take a look at where these log files are kept. All of the FileMaker server logs are kept in this “Logs” folder here. We can see the Top Call Stats Log file here, as well as the Client Stats Log. Once a log file exceeds the specified size, and again for us that was set to 40 MB, the FileMaker server will rename it “TopCallStats-old” and it will start a new “TopCallStats.Log” file. If there was a “-old” file previously, that one will be deleted when that happens. So, take care to collect these files frequently enough so that you don’t lose any data that you want to make sure to keep.
Let’s take a look at the log file itself. If we double-click on it, we can see the log entries. The latest operation will be at the bottom. We can see that the time that this entry was collected was 3:45:19. I’m going to open up a file that I have hosted on the server.
Let’s take a look at what happened to the log file. We scroll to the bottom and can see that there are several new entries now. The one that was there before is further up top. If we look at the log file directory, we can see the other log files which are being kept by FileMaker server. For some of these, there is the viewer that is built into the admin console
For server events, server access, and web publishing core, we can see these log files here in the “Logs” folder: access, event, and wpe. You can view these files in the admin console. For stats and client stats, that corresponds with the server stats and the client stats. You can also view these, though only up to a point. It only shows the current and recent data, maybe an hour or so worth of data.
For the top call stats log, however, there is no viewer provided. If you want to look at the data, you can do so in a text editor. The log file is tab delimited, so you can also open it up with any application that can view tab-delimited data like excel. Or, you could simply drag it out to the FileMaker Pro icon and it will import it into a brand-new file. You can then view the data that way.
So, how do we make sense of what is shown in the log file? Well, it might be helpful to know that in the admin console help documentation, you can go to monitoring FileMaker server, scroll down a bit here, click “Viewing Log File Entries,” and there is a section for “Top Call Statistics Log.” This can serve as a useful reference and each of the columns has an explanation.
The first column shows a timestamp value. The first thing to note here is that this timestamp is going to be the same for all the remote calls that got logged in the same collection interval. We can see that the values in the first two entries are the same. Then we can see the timestamp from the next collection interval here, in this portion of the timestamp, and so on. Note that the timestamp uses millisecond precision. We can see the seconds here, but then we also get the fractional value. And, the time zone will be the same as that of the server.
The next column shows the start time for the remote call that corresponds to this particular entry. This is also a timestamp, but it’s different from how you might usually think of a timestamp. This column show the number of seconds since the database server process was started. In this case, “185” means that the database server was restarted a little more than three minutes ago.
The values shown after are essentially microseconds, but they have been converted to seconds so we see a fractional value. But, there is a high level of precision that is being shown. The end time also shows the number of seconds since the database server process was last started. Note that if the remote call is still in progress when this entry is logged, the “end time” value will be empty.
The total elapsed time shows the number of microseconds elapsed for the remote calls so far. Note that these are microseconds which are different from the start and end times which were showing their values in seconds. There is a statistic later on here for the elapsed time. The values in these two columns will typically be the same. But the values will be different if the remote call began in a collection interval prior to the one that we are looking at here.
A diagram of this might be useful. If we can imagine time flowing from left to right, we have Remote Call A on top, that began and finished in the first collection interval. Then, below, we have Remote Call B that started in the first collection interval, but it did not finish at that time. It finished during the second collection interval.
The second collection interval would have an entry for Remote Call B, provided that it was one of the top 25 most expensive calls. Its elapsed time shown for that interval would be 18, but its total elapsed time would be 33 seconds. We can see an example of that here where the elapsed time and the total elapsed time are not the same, which tells us that this remote call began in a prior collection interval. The total elapsed time is the metric that is used to determine which calls make it into this log.
Remember, it is not all remote calls that are being logged. It is the top 25 most expensive calls. Most expensive is determined by looking at the total elapsed time.
Another way that the total elapsed number is used here is that the remote calls that are shown here are ordered by the total elapsed time in descending order. If we set our found set to include only entries from this collection interval, we can see that this list is ordered by descending order based on the total elapsed value.
The next column is operation and it contained two different pieces of data. The first is the name of the remote call. And the second piece is the client task. That is shown in parentheses. The client task is not always shown. It is only show if it is relevant.
We can see here, under the View Index, that sometimes we have client tasks that are being shown, and other times it’s just a remote call that’s being shown. For some entries, the client task will also show the percent completed. We don’t see any examples of that here. But the way it would look, for example, if the find operation was still in process at the time that this log entry was collected, it would say something like “finding”, and 10 percent or 50 percent to indicate how far along it’s gotten in completing the operation.
Over time, you will collect different kinds of operations. If you’re wondering what the full list of those remote calls and client tasks is, here it is. Here we have the remote calls being shown on the left. Then the information that is shown in the parenthesis – that is the client task, that is shown over here on the right. These are all the different possible values that you might see in that list.
The next column tells us the solution element that is being targeted by the remote call operation. The first value is always going to be the name of the hosted file that a client has opened. Then, following it after the double colon, there will be additional information if it is available.
For example here, we can tell that the operation is committing records and that this is happening against a table whose ID is 138. So, where does this ID value come from? Well, it’s not the internal ID that you can look up using the table IDs function or if you queried to FileMaker underscore tables virtual table using execute sequel. This ID in the target column corresponds to the ID that is shown in the XML DDR, the database design report. Note that is does not show up in the HTML DDR, only the XML DDR.
In this example here, all the remote calls are targeting the table with the ID 138. If we look at some of the other examples that we have, we can see that at other times a layout is being targeted, or a script, and so on. Here is the list of all possible values that might appear in the target column.
The next several columns are the same stats that we can see in the server statistics area of the admin console. If we take a look there quickly, we have network kilobytes per second in and out. We have elapsed time, wait time, disk i/o time. These are the same stats that are shown in our log file. These two show us the number of bytes received from and sent to the client. These values are for this particular remote call and for this collection interval only. So, this remote call might actually send out additional bytes if it were to span multiple collection intervals.
The elapsed time shows the number of microseconds elapsed for this remote call during this collection interval. Again, this number will typically be the same as the total elapsed time so long as the remote call started and ended during the same collection interval.
The wait times shows us the number of microseconds that the remote call spent waiting in this collection interval. An example of why this might occur is maybe there were no processor cores available at the time. Or, maybe some other remote call had locked the table which this remote call here needed access to.
Disk I/O time is also in microseconds and it shows how much time the remote call spent during this collection interval, reading from and writing to disk.
The last value shows the client name. It’s either going to be a name or an identifier along with an IP address. If the client is a web direct client, that will be made apparent here. Also, if the client is actually a server-side script, that script’s name will be shown here. If we take a look at all the values we have here in this log so far, we can tell service scripts had run.
So, how might we use the top call stats log? The basic idea is that if FileMaker server is performing slowly, and if the problem is with FileMaker server, or with a database file that is being hosted, the top call stats log will give you a better show at narrowing down what the contributing factors are.
For example, if you have a single table everyone is writing to or searching against, you would expect to see a lot of calls related to managing the locking of that table or the index. Another example might be if you receive reports of FileMaker server being slow for everyone. Then you look at this log file and you may spot a single client appearing at the top calls stats much more so than other clients. This would direct your investigation to take a look at what that user is doing different from other users.
Well, I hope you find this information useful. Please check out our other videos at Soliant TV, and thank you for watching!
Pingback: FileMaker 15: FileMaker Server Top Call Stats Logging – FileMaker Connect