Calculating 10 virtual columns faster than 1 as an action

[1minManager]

Another question for the Appsheet Jedi's as this one has me totally stumped. 

Exec Summary: 10 virtual columns takes 25 secs to compute.  But if one of those is run instead as an action in a bot, the Bot takes the equivalent of 5.46 HOURS to complete.

So based on yesterdays question, I'm moving an App away from virtual columns (VC) and over to a Bot which writes the same calculation as the VC.  The App data structure is laid out as:

Customer -> Site -> Job

Customer Table = 3 VC's, 1847 rows,

Site Table = 7 VC, 13464 rows

Job Table = No VC's, 37645 rows

I'm focusing on the Site table as this is the biggest cause of slow syncs.  I need first to get a bot to update all the rows, then I'll change the bot over to recalculate a single rows data when that record is updated.

Process so far:

1. Created 10 new columns in Site table and chose data type, either date or decimal
2. Changed all the current 10 VC's formula's to either "" or 0.  As the templates looking at these columns would all fail if I just deleted them
3. Total Sync time drops from 25ish secs to 7ish secs
4. Created an action to run in the Site table and find the latest [Related Jobs] where [Weight] > 0.  [WeightTS] is the timestamp the user entered the weight.  See formula below.
5. The formula is an EXACT copy of a formula used by the simplest VC.  Which previously took circa 3 secs to run on 13464 rows when a VC
6. Confirmed action works fine by clicking the action button on a Site record in the app
7. Created a slice which reduces the rows from 13464 to about 2000
8. Created a bot to run on a schedule (so I can manually trigger it) that calls this Action.  The Bot works on the slice
9. Ran the bot, gave up after 5mins of waiting
10. Added a filter conditon in the Bot to ignore rows where COUNT([Related Jobs])=0
11. Gave up after 5mins or waiting
12. Tried COUNT([Related Jobs])=0 as the "Only if this condition is true" in the action
13. Gave up after 5mins
14. Changed filter on the bot to only look at [_RowNumber]<=100
15. Bot finally completes after 76 secs having only actually updated 52 rows.  The missing 48 presumably filtered by the Slice or the Bot filter.  

Date(MAX(Select([Related Jobs][WeightTS],AND(
   ISNOTBLANK([Weight]),
   [Weight]>0
))))

Has anyone else come across this before?  Am I missing something fundamental here?  Is the app doing something weird like updating all the [Related...] columns?  I've checked and no other Bots are triggered by this Bot and the Site_FORM doesn't have an "Event Actions - Save Form" specified.  I can't see anything unsual in the Bot monitor dashboard, apart from all the data prior to Bot running successfully has been deleted somehow.

@MultiTech @Steve @WillowMobileSys @dbaum @Aurelien @SkrOYC @Suvrutt_Gurjar @Kirk_Masden 

[1minManager]

Quick update.  So I noticed that the formula for the "Are updates allowed?" rule for the customer table didn't have an option for when ISBLANK(UserEmail()).  I added that and the Bot now runs in 50ish secs.  No idea why this might be as I can't see how this one column in Site could affect the parent table at all.

Also noticed that I'd missed an App formula in Site, which is quite a big one:

Select(Xref[Council],IN(
TEXT(INTERSECT(
Split(
SUBSTITUTE([Address],",","")
," "),
UNIQUE(SPLIT(Select(Xref[Postcode],TRUE),","))
)),
[Postcode]
))

 Taking this bad-boy out got the Bot down to 20secs.  I'm just going to see what happens when I up this to 500 rows.

[1minManager]

Update 2

Set to [_RowNumber]<=500 , which actually updated 400ish rows, took  37 secs

Set to all rows in Slice (2000ish) 1332 rows updated in 230 secs

So better but still doesn't explain the massive difference in duration. 

230 secs for one action vs 25secs to sync the entire app and do 10 x VC's !

Still looking for any help or explaination

[SkrOYC]

---

@1minManager wrote:

230 secs for one action vs 25secs to sync the entire app and do 10 x VC's !

---

Yes, the difference is quite important and interesting.

Can you make sure there is no extra appformulas on any other column of those rows that might be also be recalculated when you touch your desired column? This may be adding to the whole execution time

[1minManager]

I checked all tables again and could find only [Site].[Address] in the Job table as an App formula.  But Im removed that to an InitialValue and the Bot took 259sec, a bit more than before.  But I don't think the bot updates the Job table at all

[SkrOYC]

Understanded.
My only guess is that AppSheet servers are playing with the resources allocation so that most of it goes to the sync process while other stuff gets prioritized based on the pricing tier our apps are.
So Sync might be on the highest priority when it comes to server procesing

[WillowMobileSys]

One of the major issues I find in attempting to analyze these kind of problems is that the server-side is a BIG black box.  We really don't know all the things that happens to prepare and process these Bots. 

I wonder if you have considered breaking out portions of the processing into API calls?  Certain consistent processing can be done much faster this way.  I believe because the processing is done on the rows in "block" form rather than the single row at a time method as happens when using actions. 

[1minManager]

I did consider doing it via the API.  But despite getting it working on one app with help from another Dev, I'm not fully up to speed on JSON API calls.

[1minManager]

"If all else fails RTFM"  So I checked out https://support.google.com/appsheet/answer/11918582?hl=en  and referenced the Peformance Monitor data for the bot.  Heres what I found

So the top bit tells us more or less what I already know.  It took 4:03 (363 secs) and updated 1347 rows.  But after that it give you a breakdown of each row and how long that took.

So what we are seeing here is some rows taking 0.2secs to update [Related Jobs].  Specifically [internal] ComputeVirtualColumnForImage.  Does anyone know what this is for?  Since 0.2 x 1374 rows = 274.8 secs this accounts for all time taken apart from 30secs which was presumably to read all the data and calculate the [Related...] columns.

[1minManager]

A, hopefully, final update to this.  I stopped trying to make this one formula any more efficent and simply updated the action so that it now does 8 calculations for 8 different formulas on 8 different columns.  After some testing with how many rows I could get it to work on, we have another strange twist. 

I can't say exactly, but its doing these 8 at roughly the same speed as it was doing one.  So my hunch is that for each row it updates, roughly 3/4 of the time spent is calculating the [Related...] column with each formula then taking probably less than 0.01 secs

[SkrOYC]

Plot twist, the [Related...] columns were the evil ones the whole time 😂
Just kidding. Hope we get around this