FMS19.6.3 poor performance on M1 mini / Ventura

Questions
1

I'm in the process of upgrading several servers from 2012 Mac Minis (Intel Core i5 or i7) to M1 (or M2) Mac Minis. The old servers were running macOS 10.13 and FileMaker Server 18.x, new ones are running latest ventura (13.2) and FMS (19.6.3)

While general UI operation feels quite a bit faster, some things are notably slower:

I have a large table which gets updated once a month, with dozens of triggered, stored, indexed autoenter calculations. It's updated via a "Replace Field Contents [TriggerField=1]" script step.

Here's what I see:

  • FMS 18 on Intel mac Mini: FileMaker Pro runs at 100% CPU, FileMaker Server runs at 100% CPU, total script time : 11 minutes for about 11000 records (e.g. 1000 records per minute).
  • FMS 19 on M1 mac Mini: FileMaker Pro runs at about 20% CPU, FileMaker Server runs at about 20% CPU, total script time : 33 minutes.

To eliminate variables, I also tried running the script in PSOS mode:

  • FMS 19 on M1 mac Mini (script running in PSOS): fmaesd process runs at about 20% CPU, FileMaker Server runs at about 20% CPU, total script time : 30 minutes.

Based on prior tests with a M1, I was expecting about a 3x-4x speedup. Instead, I am seeing a 3x slowdown, so overall it's about 10x slower than it should be.

During these tests on the M1, the fact that FMS, FMP, and FMAESD processes are all slouching along at under 30% CPU usage seems like a red flag to me.

Any ideas for debugging this?

2

Checking TopCallStats, I see this message repeating over and over:

Operation Target Network Bytes In Network Bytes Out Elapsed Time Wait Time I/O Time Client name
Query DB::table(131)::field definitions(3) 210 29 39428 39115 0 MyScript - user 8 (FileMaker Script)
Query DB::table(131)::field definitions(3) 210 29 39355 39205 0 MyScript - user 8 (FileMaker Script)
Query DB::table(131)::field definitions(3) 210 29 39329 39178 0 MyScript - user 8 (FileMaker Script)
Query DB::table(131)::field definitions(3) 210 29 39215 39067 0 MyScript - user 8 (FileMaker Script)
3

They would be all of the auto enter calculations which are being triggered.

Batching can be used to improve performance. There is an under-the-hood episode that discusses this and shows stats. FileMaker Server is happiest doing a short sprint. It will do a lot of short sprints. All of the short sprints will run faster than one long marathon.

1 Like
4

It’s possible. But I feel like if FileMaker server 19 was 10 times slower across-the-board, I think other people would be complaining.

My suspicion, is that I’m looking for one specific auto enter-Calc field or relationship that is misbehaving in filemaker 19.

5

Have you checked table ID 131, field ID 3 ?

6

This is my first time using TopCallStats, so bear with me.

As I understand it, the culprit is this:

Operation Target Network Bytes In Network Bytes Out Elapsed Time Wait Time I/O Time Client name
Query DB::table(131)::field definitions(3) 210 29 39428 39115 0 MyScript - user 8 (FileMaker Script)
  • the script name matches the script I'm running.
  • the Wait Time is 39000 microseconds, or 30 milliseconds. That seems like a lot of waiting! I'm not clear if that is 30 msec per record, per field, or per what.
  • The Operation is "Query" which sounds like pulling data across a relationship.
  • The target is Table 131, Field Definitions(3).
finding TableID and FieldID

To get Table IDs you have to use FileMaker Pro, advanced tools, and do a Database Design report, (in XML format not HTML). Open the txt file and search for <BaseTable id="131

To get Field IDs, search the file the same way for <Field id="3"

When I look up the TableID and FieldID, I learn they are not the table I'm doing the update in, but a related table. The field name is the primary key that links the two tables. It's a One to Many relationship, related on an indexed number field, and I'm doing the update on the Many side, so it shouldn't be slow. (e.g. it's not a multi-predicate join, it's not sorted, it's not using text fields...)

7

The two tables I'm using are Worker (one record per person) and WorkerDate (one record per person per month). I was wrong in staying that the relationship is not sorted, it is sorted but it's reverse sorted on the WorkerDate side by date E.g. when accessing WorkerDate from Worker, you always get the most recent record. But when accessing Worker from WorkerDate, there is no sort.

I have seen a lot of info from Claris about server-side sorting in FMS 19 to increase performance, and I'm wondering if one of these changes actually caused a performance regression?

8

The top call stats are atomic, so those are going to be recording interaction with that field.

Yes, Query is going to be a find. Perhaps not a scripted find. It could be related data coming in.

I believe the wait time is incorporated into elapsed time. So wait for 39115, run for 313, elapsed time is 39428.

2 Likes
9

Doing more testing to narrow down where the problem is by running the same 1000 record update script in various settings:

  • FMP 18, local file, Intel i9, Ventura 13.2: 10 seconds
  • FMP 19, local file, Intel i9, Ventura 13.2: 10 seconds
  • FMP 19, local file, M1, Monterey 12.6.2: 7 seconds
  • FMP 19 (Intel i9) <--> FMS19 (M1). Ventura 13.2: 60 seconds
  • FMS 19 (PSOS), M1 Ventura 13.2: 50 seconds
  • FMS 19 (Server Script), M1 Ventura 13.2: 50 seconds

Conclusions:

  • FMP is fine and there's no change between FMP18 and FMP19 when using a local file.
  • The problem only manifests when running on FMS 19
  • it happens when using PSOS, so the problem is not due to networking issues.

Further tests will use PSOS since that seems to eliminate extraneous variables:

  • De-indexing then reindexing the Key field for both tables: no change
  • Remove the Sort criteria in the relationship joining the two tables: no change.
  • FMS set cache size from 512 to 2048 MB (the database is about 1800MB in size): no change

During all these tests, the CPU usage on FMSERVERD and FMSAESD remains anemic:

image

So now I'm thinking: perhaps FMS19 is optimizing for multiple users? What if I ran multiple instances of the PSOS script in parallel, each using its own 1000 record batch?

Things get even worse: Server CPU drops to under 10%!

image
image704×170 25.8 KB

One PSOS script takes 50 seconds. Running 4 at once takes 500 seconds (should be closer to 200).

I'm feeling like there is a serious performance regression in FMS19.

10

More tests:

  • I stopped the server, restarted it, and repeated the PSOS test: no change.

  • I stopped the server, used the ReleaseDebugOn.txt file to disable as many of the new FMS features I could find:

/Library/FileMaker Server/Database Server/bin/ReleaseDebugOn.txt

DisableServerSideSummary
DisableSharingLockOnServer
DisableServerSideSorting
DisableMemoryKeyCmpIndexing
RemoteCalls
ForceOutput

Repeated the PSOS test: no change.

11

Using Activity Monitor, I recorded a Sample of the FMSASED process. It looks to me like the thread is spending a long time waiting for the RCTransaction to complete:

image
image1280×1038 162 KB

I wonder if this could be related to the new Transaction features introduced in FMS 19.6 ?

  • Surrounding the Replace Field Contents Script step with Open Transaction / Commit Transaction: no change.
1 Like
12

It's a big new change, so it's fairly likely that it has some side effects.

I'm not sure if we have Claris engineers watching here, so it's worth repeating over on the community site

With regard to CPU, I'm not sure you can make a direct comparison with M1 and Intel chips. I suspect that there are hardware differences that mean the CPU stats aren't telling the full story.

1 Like
13

I did a quick test using another M1 mini running FMS 19.5 on macOS Monterey 12.6.2 with the same results. This rules out either Ventura or the most recent FM19.6.3 updates, or the new Transaction feature as being the issue.

3 Likes
14

Good point, I don't generally post over there.

I think my next step is to see if I can reproduce this in a smaller sample database. If so, I'll definitely try to submit a bug report.

1 Like
15

A number of issues were resolved in the most recent FM release / MacOS in the last couple days, including the 300 line script workspace limitation

General RFC points (but as you say, it was working with earlier releases, so YMMV):
There are some issues relative to particular usages of RFC;
IF you are doing a relational RFC from the context of a parent into a child data set, each record re-executes the FIND across the relationship - performance killer
RFC does NOT commit the changed records as it runs. As a result, if any of your other batch updates are dependent on these changes, your results may not be as expected
RFC skips any locked records, with no error generated.
You should always conditionally validate that a RFC target found set will exist, prior to executing the RFC; if not, and no target found set exists, RFC continues forward, which, based on the script, can have disastrous results on data.
It is almost always better - and equally performant - to do a FIND > Loop > set field cycle vs. RFC, as it also affords the opportunity to capture update errors that RFC ignores.

1 Like
16

Hi Kirk, I'm confused - I'm on 19.6.3 which is the latest, but has been out for over a week now, and still has that crashing bug. Are you using an unreleased beta version perhaps?

Good points about RFC, and I do see some issues noted in the FMS release notes, for example

  • The Replace Field Contents script step was much slower in version 19.5.1 than in previous versions. (19.5.2 FMP release notes)

However:

  • I'm using 19.6.3
  • I tried replaicng RFC with a Find/Loop script, and performance is identical.
17

The "number of issues resolved" thread I was reading, was about the latest version of MacOS, in conjunction with the latest FM release, resolving a number of issues.... a frequent crash and the 300 line script ceiling were 2 identified. Performance was not discussed in the thread, except for the really slow cut and paste in layout mode.

I use your same technique on about 30 fields in a DB of a few thousand records, and the update time is < 3 seconds on a server side script - FMS 18 on a 2018 6 core i7 mini. I have an M1 mini at another data center running the latest FMS; if I get some time, I'll copy this over there any check on performance.....

This likely has nothing to do with your performance issue, but is relevant to the method:
Not absolutely confident on this one, but I read something about it recently from the head guy at Soliant: I might suggest instead, setting the LET trigger calc in the auto-enter to something like a timestamp. That is because with a trigger field = 1, if the trigger is already 1, it would not cause the auto-enter to evaluate. You'd have to check to see the current value and toggle it - more code/time. IF you use a timestamp (or a UUID) you can be assured that the value will be different, and confident that the field triggers.

1 Like
18

Thanks, that would be interesting. In my case, it's two tables, each with 100+ fields, and 10000 records in one table and over 1 million in the other table, but I can show the slowdown even when using a small batch of 1000 records.

I'm 99% sure this is not the case, and that setting a triggerField to the same value will cause recalculations, but thanks for the idea, as if this were a new behavior, it certainly could cause trouble!

19

I recently upgraded this server from Ventura 13.2 to 13.5 and have re-run the test.

  • FMS 19.6.3 (Server Script), M1 Ventura 13.2: 50 seconds
  • FMS 19.6.3 (Server Script), M1 Ventura 13.5: 51 seconds

So the OS change seems to have done nothing.

I'm still seeing the same pathological behavior, where both the FileMaker Server process and the FileMaker Scripting process both are using 10% to 20% of the CPU.

20

I posted this on the Claris Discussions as well: https://community.claris.com/en/s/question/0D53w00006CqTwBCAV/fms-1963-poor-performance-compared-to-fms-18