Anvil server serialization/transit very slow?

[erik]

I’ve noticed that many of my Forms seem exceedingly slow while loading despite using the usual performance tricks such as grouping multiple server calls into a single server call, Timers etc. So I implemented the timing logging utils from anvil_extras.utils and anvil_extras.logging.TimerLogger to try to get some clues.

To start with, I have a simple “loading” form that handles user login (through Google) and collects some metadata from a server side function to route the user to the appropriate form for them.

Instrumenting this form as well as the server side function shows that most of the time spent is waiting on the data to be returned from an already completed function call.

2022-04-27 16:35:32: __init__(<Reporting.Loading.Loading ob...) called
16:35:32 | timing loading init: ( 0.000 secs) | start
16:35:32 | timing loading init: ( 0.001 secs) | init_components (restart)
16:35:33 | timing loading init: ( 1.260 secs) | login_with_form (restart)               <===== 1.2 seconds for already authenticated user!
2022-04-27 23:35:39: get_loading_screen_data() called
2022-04-27 23:35:39: get_loading_screen_data() completed(0.12s)                     <============
16:35:39 | timing loading init: ( 5.814 secs) | get_loading_screen_data (restart)   <============
16:35:39 | timing loading init: ( 0.002 secs) | update self.item (restart)
16:35:39 | timing loading init: ( 0.001 secs) | refresh_bindings (restart)
16:35:39 | timing loading init: ( 0.000 secs) | end

As you can see, the get_loading_screen_data() completes in 0.12s – but on the form side, the anvil.server.call('get_loading_screen_data') takes 5.8s (!!!) to complete. Additionally the 1.2 seconds for anvil.users.login_with_form() seem excessive (I’m already authenticated).

Any suggestions on improving this? Seems like it is an issue with Anvil itself.

Thanks!
Erik

[stucork]

Unrelated to the question, but it’s great to see the TimerLogger in the wild!

[hugetim]

It’s hard to know without seeing your code, but I’m not convinced you’re interpreting those timings correctly. I’m reading the 5.8 as the total round-trip time for the server function, which also could include time importing your server modules. Still, though…

[erik]

Here are some specifics with the profiling code in place.

The “Loading” form:

from ._anvil_designer import LoadingTemplate
from anvil import *
import anvil.server
import anvil.google.auth, anvil.google.drive
from anvil.google.drive import app_files
import anvil.users
import anvil.tables as tables
import anvil.tables.query as q
from anvil.tables import app_tables
from anvil_extras.utils import timed
from anvil_extras.logging import TimerLogger

class Loading(LoadingTemplate):
  @timed
  def __init__(self, **properties):
    # Set Form properties and Data Bindings.
    with TimerLogger("timing loading init") as T:
      self.init_components(**properties)
      T.check("init_components", restart=True)

      # Any code you write here will run when the form opens.
      self.user = anvil.users.login_with_form()
      T.check("login_with_form", restart=True)
      data = anvil.server.call('get_loading_screen_data')
      T.check("get_loading_screen_data", restart=True)
      self.item.update(data)
      T.check("update self.item", restart=True)
      self.refresh_data_bindings()
      T.check("refresh_bindings", restart=True)
    
  @timed
  def dev_redirect(self):
    if not self.user['is_dev']:
      return
    form, kwargs = anvil.server.call('get_dev_redirect')
    print("dev_redirect", form, kwargs)
    open_form(form, **kwargs)

  @timed
  def form_show(self, **event_args):
    """This method is called when the column panel is shown on the screen""" 
    if self.user['is_dev']:
      self.dev_redirect()
    else:
      open_form(self.item['home_form'])

The server functions:

@anvil.server.callable
def get_accounts_for_user(user):
  logged_in_as = anvil.users.get_user()
  if logged_in_as != user:
    print("Users don't match.", user, logged_in_as)
    return []
  return app_tables.accounts.search(report_users=[user])

@anvil.server.callable
@timed
def get_loading_screen_data():
  user = anvil.users.get_user()
  number_of_accounts = len(get_accounts_for_user(user))
  home_form = 'ClientReport.AdPerformance'
  if number_of_accounts > 1:
    home_form = 'ClientReport.AccountList'
  if user['is_staff']:
     home_form = 'Admin.AccountList'  
  return {
    "home_form": home_form,
    "number_of_accounts": number_of_accounts,
  }

[hugetim]

Yeah, I don’t see anything in this code that could account for that slow timing. Are you importing anything unusual in your server module, by chance? Imports of certain libraries take a few seconds:

Slow import of googleapiclient

I’m building an app that interacts with Google’s API services. My forms’ interactions with the server module seemed really slow to me. I examined the individual load times for the all of the imports at the top of my server module and it turns out that the following line would take anywhere from 3 to 5 seconds alone: from googleapiclient.discovery import build Has anyone else experienced this type of delay when using googleapiclient.discovery? Is my 3-5 second time to load normal? Any suggestio…

I haven’t noticed any unusual slowdowns in my stuff the past few days, myself.

[erik]

I am importing pandas, numpy, and gspread for use in other functions. Pandas is probably the one that takes the most time, but not something that takes on the order of 5 seconds in my experience. Just to be sure, I added a TimerLogger to the imports for that module. Total time is 1.6 seconds. So, there still seems to be quite a bit of time unaccounted for.

I added some more instrumentation around the function call on the client and it appears that the latency is occurring while waiting for the function to start executing, not after the return. So this could be some kind of cold start or import issue.

I also noticed from my import logging (not included below), that all the modules are being imported on every function call (ie I clicked around and triggered several server calls at in succession, each of which logged the imports). I was under the impression that Anvil was running server code in docker containers, and that containers were being reused to serve multiple requests. Is this not the case?

10:24:18 | timing loading init: ( 0.000 secs) | start
10:24:18 | timing loading init: ( 0.000 secs) | init_components (restart)
10:24:19 | timing loading init: ( 0.796 secs) | login_with_form (restart)
10:24:19 | timing loading init: ( 0.000 secs) | get_loading_screen_data start   <==== Right before anvil.server.call()
17:24:23 | client_dashboard imports: ( 0.000 secs) | starting imports
17:24:23 | client_dashboard imports: ( 0.002 secs) | import models
17:24:25 | client_dashboard imports: ( 1.668 secs) | done importing models
17:24:25 | client_dashboard imports: ( 1.668 secs) | Finished imports
2022-05-02 17:24:25: get_loading_screen_data() called
2022-05-02 17:24:25: get_loading_screen_data() completed(0.13s)
10:24:25 | timing loading init: ( 6.170 secs) | get_loading_screen_data completed (restart)  <=== Right after anvil.server.call().
10:24:25 | timing loading init: ( 0.001 secs) | update self.item (restart)
10:24:25 | timing loading init: ( 0.000 secs) | refresh_bindings (restart)
10:24:25 | timing loading init: ( 0.000 secs) | end

[jshaffstall]

@erik

I also noticed from my import logging (not included below), that all the modules are being imported on every function call

If you have a business plan or above, you can mark your servers as persistent, which would get the behavior you expect. Below that, the server environment is spun up for every server call.

[hugetim]

See the last item here:

[Wiki] Performance optimization

This page addresses performance optimization. The list in this page is far from being complete, there may be some incorrect information and it’s likely to become stale and obsolete over time. Feel free to fix content, language or format, anything you don’t like and add anything missing. If there is something that you don’t understand, please create a new post and ask for clarification. Then, once the topic is clear, you can edit this page and improve it. Some points are inspired by forum post…

Depending on how you’re doing the import logging, you might not be capturing the time it takes to do all those imports.

Hypothetically, suppose the server function you’re looking at is in ServerModule2. Anvil may first load ServerModule1, which imports pandas, let’s say. Then it loads ServerModule2, which imports pandas, numpy, and gspread. If you only time the imports in ServerModule2, that would only tell you the time it takes to import numpy and gspread because pandas was already imported during the loading of ServerModule1.