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" 
Here's what my current working plan is:
- I made a duplicate of the update cache script
- I asked Claude to go in and put timestamps before and after, along with simple to search comments
- 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>