Finding slow spots in a loop - can AI help?

For a few of my clients I manually cache complex data. HTML graphs that need to be displayed on every student's screen, based on calculations of calculations of their graduation track, credits earned, etc. (~100 steps per cache update)
I run these in a loop overnight, and users can trigger them manually. When they trigger them manually it performs it on the server and takes a 2-5 seconds, depending on the client. Not an issue for one or two students, but when recomputing a few hundred or a few thousand students it can take anywhere from 30m to a couple of hours. I want to drill down and figure out which parts of this process take the most time and see if I can optimize them. Some of these caches are simply taking a calc field and writing it to a matching _cache, others involve a SQL command that gets written to the cache.
My historical process to find the slowdowns has been:

  1. create a loop script that has the server go through x students (10 or 20) and records how long it takes to update cache on all of them.
  2. run and record that time
  3. Make a duplicate update cache script
  4. Comment out 80% of the items and run it again...
  5. Find the sections with the highest times and keep refining until I find the biggest single line and work on that...
  6. Repeat

It's VERY VERY time consuming. Running it through Claude could help me narrow down the potentially slow ones, which could help... but I'm wondering if there's some way to wire up Claude to perform this on its own. Basically run the script, comment out code and give me a line-by-line report of which lines cause the biggest slowdowns.

Has anyone tried anything like this?

Here's the way to do this. I'll post a couple custom functions in the example file that can help avoid the manual tedium of this. I'll show code both with and without custom functions.

Example File

benchmark.fmp12 (232 KB)

With CFs

# -------------------------------------------------
Set Variable [ $section ; "Section 1" ]
# -------------------------------------------------
Set Variable [ $! ; RuntimeStart ( $section ) ]
# do stuff
Set Variable [ $! ; RuntimeEnd ( $section ) ]


# -------------------------------------------------
Set Variable [ $section ; "Section 2" ]
# -------------------------------------------------
Set Variable [ $! ; RuntimeStart ( $section ) ]
# do stuff
Set Variable [ $! ; RuntimeEnd ( $section ) ]


# -------------------------------------------------
# Log Results
# -------------------------------------------------
Perform Script [ From File: "Log" ; Script: "Create Log Entry" ; Parameter: RuntimesGet() ]

Without CFs (more tedious)

Option 1

log each section time as you go. This is good if your script has multiple possible exit points and you want to log as much as you can before it exits early.

Set Variable [ $section ; "Section 1" ]
Set Variable [ $start ; Get ( CurrentTimeUTCMilliseconds ) ]
# do stuff
Set Variable [ $runtime ; Get ( CurrentTimeUTCMilliseconds ) - $start ]
Perform Script [ From File: "Log" ; Script: "Create Log Entry" ; Parameter: $section & " runtime: " & $runtime ]

Set Variable [ $section ; "Section 2" ]
Set Variable [ $start ; Get ( CurrentTimeUTCMilliseconds ) ]
# do stuff
Set Variable [ $runtime ; Get ( CurrentTimeUTCMilliseconds ) - $start ]
Perform Script [ From File: "Log" ; Script: "Create Log Entry" ; Parameter: $section & " runtime: " & $runtime ]

Option 2

calculate but don't log runtimes for each section, then log them all at the end. This is good if you script has a single exit point at the end, so you can aggregate runtimes into a single log entry

Set Variable [ $section ; "Section 1" ]
Set Variable [ $start ; Get ( CurrentTimeUTCMilliseconds ) ]
# do stuff
Set Variable [ $runtime ; Get ( CurrentTimeUTCMilliseconds ) - $start ]
Set Variable [ $runtimeList ; List ( $runtimeList ; $section & ": " & $runtime ) ]

Set Variable [ $section ; "Section 2" ]
Set Variable [ $start ; Get ( CurrentTimeUTCMilliseconds ) ]
# do stuff
Set Variable [ $runtime ; Get ( CurrentTimeUTCMilliseconds ) - $start ]
Set Variable [ $runtimeList ; List ( $runtimeList ; $section & ": " & $runtime ) ]

# Then at the end:
Perform Script [ From File: "Log" ; Script: "Create Log Entry" ; Parameter: $runtimeList ]

Turn on Top Call stats on your server. It will tell you exactly which process is taking time, CPU, network, etc.

It can be a little hard to read at first but it will give you the information you want.

I love what @jwilling has posted, and have made use of a similar approach many times, always with success. I prefer having some CFs to help tidy the process. I developed this idea pretty far, and never regretted any of the effort that I invested -- I always felt that it returned well.

Additional note on personal lessons learned:

  1. When I first started doing this sort of thing, I would lay down a huge number of granular metric captures. As I became more seasoned with this sort of thing, I felt that it was more efficient to start with wider brush strokes, i.e. capture metrics for larger chunks of code, and then after some iterations decide which chunks I should attack with greater granularity of metric capturing.

  2. It's especially good to keep the mechanics of the metrics-grabbing simple and efficient. This, of course, is always true with code, but especially so when one starts injecting a pattern many times throughout the code base. It's easy to overlook that elaborate logging adds its own overhead. For me, it was a very humbling moment when I realized how much one of my more sophisticated approaches for logging the metrics was contributing to slowness. After that lesson, I simplified and developed means for the logging to record a sense of its own added overhead, so as to keep my code in check.

As far as using AI to find slow points:

I am not in a position to make great solid claims to assess what AI could do for you if you fed it your code base and asked for answers.

I would imagine just that asking either AI (or a seasoned group of developers) what sort of things to look out for (without supplying your code) would yield a good checklist, which might prove as effective as, or more effective than, asking for analysis of code.

Categories of runtime overhead:

When I used to work with devs to help them identify and understand bottlenecks, there were some common categories/themes that would frequently come up:

  1. Not realizing that certain operations can take as long as they do (especially at scale with full production data). Definitely ExecuteSQL can fall into this category, but it's not the only one. Anything that involves disk io or network io can fall into this category, and this (disk io) implicates operations which necessarily must grab a lot of record data to fulfill a relationship or aggregation operation.

  2. Underestimating how a moderate-cost operation, when repeated many times, can blow up the cost of the bigger-picture parent operation.

  3. Scripting (or calculations) which needlessly repeat an operation within a loop which could have instead been performed only once outside of the loop, and cached. This one sounds like a "newbie" sort of mistake, but it happens to all levels of devs, sometimes because we are so busy focusing on business logic that we forget or neglect to apply our "efficiency and best practice chops" to the code we are staring at. A lot of times I think it happens because what started as a quick dirty prototype for a task turned into production code without one or two passes taken to review it.

  4. Not understanding some of the cost/efficiency/inefficiency of platform features, and how to best work with them so as to emphasize efficiencies, and not exacerbate inefficiencies. These are topics such as: Operations involving large text, operations involving large JSON, looped operations w.r.t. caching, the cost of a record commits, etc..

I second all the additional points above.

I'll also add my own experience about @steve_ssh 's point

Not understanding some of the cost/efficiency/inefficiency of platform features

I am often surprised by what turns out to be the slow part of my code, despite thinking I have a pretty darn solid understanding of the cost/(in)efficiency of various platform features. That's taught me that there really is no substitute for measuring/benchmarking our code! It's hard or impossible to reason our way to the culprit in some cases.

J

Heck, i've seen discussions about theoretical efficiency go on for much longer than it takes to add code instrumentation and just get the real answer.

Thanks everyone. This gives me HUGE confidence in my approach.

@Malcolm it doesn't seem like top calls has that level of granularity to find what specific lines in a single script cause the biggest slowdowns.
@steve_ssh yeah I tend to do the same breakdown of grouping my speed tests... but (see below)
@jwilling I agree 100% about testing, and like your ideas of streamlining. In the past I've literally spent hours trying to get SQL statements out of my scripts to "speed things up" only to find out that when I made relationships and did it natively through Filemaker some operations become even slower. So now I sort of feel "SQL is slower, 80% of the time, test to confirm" :slight_smile:

Here's what my current working plan is:

  1. I made a duplicate of the update cache script
  2. I asked Claude to go in and put timestamps before and after, along with simple to search comments
  3. I wrote a script that aggregates the counters for each step and writes it to a CSV

I've trained Claude to give me all code in XML snippets so I can easily paste them into script editor with Base Elements.

It worked well. It ran 20 iterations and returned the results I needed. The code is still my own and I understand it, but the laborious debugging code just showed up after 20 minutes (with a little back and forth) in a very human readable way:

And returns a CSV that looks like this (after I add percents and some color coding)

Comment Name,Avg Time
#1 $HolidayList,.00396
#2 Last_Tracker_Credit_Date_Cache,.00157
#3 Last_Tracker_Credit_Weeks_Since_Cache,.00002
#4 $LastTrackerSubmissionDate,.00253
#5 Last_Tracker_Submission_Date_Cache,.00008
#6 Last_Tracker_Submission_Weeks_Since_Cache,.00004
#7 Credits_To_Date_Cache,.00051

If it's helpful to anyone here's my stub script. You'll need to set the subscript it runs and build a launcher that runs it on server if you want server numbers and get(scriptresult):

<?xml version="1.0" encoding="UTF-8"?>

<fmxmlsnippet type="FMObjectList">

  <Step enable="True" id="89" name="# (comment)">

    <Text>--- PROFILER INIT : reset JSON store, force DeepCache ---</Text>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA["{}"]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$$Prof</Name>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[0]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$$IterCount</Name>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[1]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$$DeepCache</Name>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[If ( Get(ScriptParameter) = "" ; 20 ; GetAsNumber ( Get(ScriptParameter) ) )]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$target</Name>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[0]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$thecounter</Name>

  </Step>

  <Step enable="True" id="6" name="Go to Layout">

    <LayoutDestination value="SelectedLayout"/>

    <Layout id="318" name="Student_UtilityForScripts"/>

  </Step>

  <Step enable="True" id="28" name="Perform Find">

    <Restore state="True"/>

    <Query>

      <RequestRow operation="Include">

        <Criteria>

          <Field table="🧑‍🎓Student" id="32" name="Status"/>

          <Text>Current</Text>

        </Criteria>

      </RequestRow>

    </Query>

  </Step>

  <Step enable="True" id="39" name="Sort Records">

    <NoInteract state="True"/>

    <Restore state="True"/>

    <SortList Maintain="True" value="True">

      <Sort type="Ascending">

        <PrimaryField>

          <Field table="🧑‍🎓Student" id="9" name="Name_Full_c"/>

        </PrimaryField>

      </Sort>

    </SortList>

  </Step>

  <Step enable="True" id="89" name="# (comment)">

    <Text>start ~100 from the end so we sample real students</Text>

  </Step>

  <Step enable="True" id="16" name="Go to Record/Request/Page">

    <NoInteract state="True"/>

    <RowPageLocation value="First"/>

    <Calculation><![CDATA[Get(FoundCount) - 100]]></Calculation>

  </Step>

  <Step enable="True" id="71" name="Loop">

    <Restore state="False"/>

    <FlushType value="Always"/>

  </Step>

  <Step enable="False" id="80" name="Refresh Window">

    <Option state="False"/>

    <FlushSQLData state="False"/>

  </Step>

  <Step enable="True" id="1" name="Perform Script">

    <Calculation><![CDATA["All"]]></Calculation>

    <Script id="824" name="⏱️SpeedTest_UpdateSINGLEStudent_Cache"/>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[$thecounter + 1]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$thecounter</Name>

  </Step>

  <Step enable="True" id="72" name="Exit Loop If">

    <Calculation><![CDATA[$thecounter > $target]]></Calculation>

  </Step>

  <Step enable="True" id="16" name="Go to Record/Request/Page">

    <NoInteract state="False"/>

    <Exit state="False"/>

    <RowPageLocation value="Next"/>

  </Step>

  <Step enable="True" id="73" name="End Loop"/>

  <Step enable="True" id="89" name="# (comment)">

    <Text>--- COMPILE CSV from $$Prof : read t1..n1, t2..n2, ... by index ---</Text>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA["Comment Name,Avg Time"]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$csv</Name>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[1]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$i</Name>

  </Step>

  <Step enable="True" id="71" name="Loop">

    <Restore state="False"/>

    <FlushType value="Defer"/>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[JSONGetElement ( $$Prof ; "n" & $i )]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$name</Name>

  </Step>

  <Step enable="True" id="68" name="If">

    <Restore state="False"/>

    <Calculation><![CDATA[$name <> "" and $name <> "?"]]></Calculation>

  </Step>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[$csv & ¶ & $name & "," & Round ( GetAsNumber ( JSONGetElement ( $$Prof ; "t" & $i ) ) / Max ( $$IterCount ; 1 ) / 1000 ; 5 )]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$csv</Name>

  </Step>

  <Step enable="True" id="70" name="End If"/>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[$i + 1]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$i</Name>

  </Step>

  <Step enable="True" id="72" name="Exit Loop If">

    <Calculation><![CDATA[$i > 300]]></Calculation>

  </Step>

  <Step enable="True" id="73" name="End Loop"/>

  <Step enable="True" id="141" name="Set Variable">

    <Value>

      <Calculation><![CDATA[""]]></Calculation>

    </Value>

    <Repetition>

      <Calculation><![CDATA[1]]></Calculation>

    </Repetition>

    <Name>$$DeepCache</Name>

  </Step>

  <Step enable="True" id="103" name="Exit Script">

    <Calculation><![CDATA[$csv]]></Calculation>

  </Step>

</fmxmlsnippet>

It looks like your problem is resolved and you have great insights into the process.

I have to pick you up on your comment about Top Call Stats because it is designed to identify long running processes. It polls every single line of code as it is performed. To save you the effort of building your own analytic tool, there are several pre-built FMP Top Call Stats visualisers floating around in the community.

Awesome. Thanks that’s good to know. I showed the logs to Claude and it lied and told me it wasn’t granular enough for that. :slight_smile:

The thread focused on measuring performance bottlenecks. It might be more useful to understand what it is about the data that is taking so long to assemble, which may be data / data structure related, and as a result, code performance may be the treatment of the symptoms, not the root cause?

Alternatively, would this be a good candidate for javascript graphs in a webviewer? Or is the performance in the assembly of data required?

Yes, step 2 will be figuring out what the bottleneck is, but step 1 was to find the 8 lines that took up 80% of the time to focus on them since many of the lines of code took only a couple of milliseconds and I wanted to pick the best places to optimize.

I'm just thinking about the many times I've seen performance impacts that were not code based, but data structure based, with complex code work-arounds to compensate.

Took one inherited script that was taking an average of 6 min 47 seconds to run, restructured the data model explicitly around what was needed to get the required set of data, resulting in .31 second - 1/3rd of a single second - run time. Same data, same logic (with context changes for the new TOG),

but step 1 was to find the 8 lines that took up 80% of the time

A+ this is the way.

Let me add one consideration here, which may or may not apply. If the 8 lines happen to involve a Find or ExecuteSQL, it's possible optimizing those lines can lead later ExecuteSQL or Finds to run slower, because the first query may be doing some caching that is utilized in later queries.

A while back I worked on a script where that happened, and i optimized each query, one at a time from the top, and watched each next query get suddenly slow.

ha... that sounds like fun! But good tip.

I wonder if you swapped the order what would happen, or ran other scripts in between.

In this case 60% of the time it took were obscure things that probably only have to be generated overnight. Meeting with client tomorrow, but right now if they run the update it will just do the basic update in 40% of the time, so it's a solid start just knowing what the problem is without any real optimization.