Repository: jupyterhub/jupyterhub
Pull request: make init_spawners check O(running servers) not O(total users)
by making the query on Server objects instead of User objects, which is logically equivalent because we were already filtering on `if spawner.server is not None`

avoids lots of ORM work on startup since there are typically a small number of running servers relative to the total number of users

this also means that the users dict is not fully populated at startup, which is a big change. I don't know that that's safe at this point and need to dig into that assumption in a few places.

In my tests, this brings startup with 30k users with only a few running down from 45 seconds to ~1 second.

closes #2928



Problem statement:
Extremely slow hub start up with large numbers of users
**Describe the bug**

We have an instance of JupyterHub with over 50,000 users in it, connected to a custom authenticator. When starting the hub pod it takes over 15 minutes to get to the ready state, where it is accepting requests. During this period of time the Hub is effectively offline for users and they can not start notebooks. This appears to be linear related to users based on the delays we were seeing at 30,000.

**To Reproduce**

1. Create 50k+ users
2. Boot hub, see how long until pod goes to ready state

**Expected behavior**

Ideally this would take a lot less time. 

**Compute Information**
 - Kubernetes 1.15
 - JupyterHub Version - jupyterhub/k8s-hub:0.9.0-beta.3

Hints from issue discussion:
After some investigation in the code, I'm curious if this block is the culprit: https://github.com/jupyterhub/jupyterhub/blob/bc7bb5076ff2deabc7702c75dce208166d14568e/jupyterhub/app.py#L1668-L1702

Iterating through all 50k + users on boot definitely has a cost, even if only a few ms per user, that adds up. Would it be possible to make this scan skippable? Or moved out of the boot critical path.
I can confirm it also happens when running JupyterHub via `jupyterhub` command and not only via Kubernetes
 #2525 may be relevant.
I don't think it's really related to #2525. In adding some debug code there are 2 big iteration loops over every user (which grows linearly over time). 

The first one is adding every user to the authenticator, linked above. This seems like it's something that ideally the authenticator would have an interface to say whether or not this was needed, so an authenticator could skip that step.

The second one is the init_spawners. This one is more confusing to me, because the code seems to specify an init_spawners timeout, after which point it will do this async in the background. However, testing locally that doesn't work. I set it to 2 seconds, and it still has to process every row in the db, the timeout is never triggered. I wonder if because the db loop is not async friendly that this timeout is not working as expected. 

With a local checkout can basically drop our startup time from 15 minutes to a couple of seconds by doing an early return in init_users and not runnning the full add_user loop, and always doing the init_spawners in async mode. 

Proposed solution (which I can iterate on if people are interested) 

1. Either make the authenticator have an interface for whether add_user is useful for it (for external auth it is not), or make a config value to skip it.
2. Add an init_spawners_async config value to only do init_spawners in the async mode. Default to False for current behavior, but True would skip it. 
Thanks for the debugging and suggestions. @minrk has done a lot of work and thinking on the fast/slow startup and I think implemented most of the init spawners timeout (or at least he was involved). This means it would be good to get his input, especially on historical parts.
Profiling startup is important, that's where we've found big wins in the past, and probably where we should start here as well, now that we seem to have recurring issues. Iterating over 50k entries in Python doesn't generally take a huge amount of time unless there's a nontrivial action taken on each. The default add_user is a call adding a string to a set, so we're talking less than a millisecond per user (a quick test on my laptop has this stage taking about one second with 50k users with GitHubOAuthenticator, or 20 microseconds per user). So skipping `add_user` isn't likely to save a lot of time, and would introduce a new problem by requiring a new solution for what the base add_user does, reconciling whitelists.

A quick profile of startup with several thousand users suggests that the time is still ~all in `init_spawners`, even with no spawners running. There's probably something unnecessary going on here, and the Authenticator is unlikely to be a big help.

The main task of Hub startup is to ensure consistency of the database state. It's hard to do this in anything less than O(N) time, but it shouldn't have to be a big number times N, at least for the typically large majority of users who aren't running.

Importantly, almost nothing of what is done with idle users is async, so the async init_spawners is unlikely to help. That only helps the slow startup for lots of *running* users, whereas for very large user counts, it's likely ~all blocking database calls. I see this taking 45 seconds with 30k users on my laptop, which is too long!
What database are you using in profiling this? We're using postgresql in production. The concern isn't actually the add_user call per say. I suspect there is enough overhead of the ORM reflection creation (this is also based on previous experience on this overhead in OpenStack). For out 50,000 user case to get to 15 minutes, it only means we need to be spending 9ms per user in each of these loops. 

Running with --log-level=DEBUG definitely shows these 2 iteration loops as being where we're loosing most of the time when talking to a postgresql database.
Having diagnosed the main issue of instantiating the higher-level User wrapper (O(N users) queries for Spawners, then O(N spawners > N users) queries for running servers), I now have a draft where startup for 30k users with only 10 running is down from 45 seconds to 1.2 seconds. I just have to check if that breaks anything!
Great! Would love to give that a shot and test with our data. Let me know when a branch exists with it. 
I'm profiling with sqlite, but the database implementation shouldn't be relevant to the calls to add_user, which makes no database calls.

If indeed it were 9 milliseconds, but the add_user loop is closer to microseconds in my measurements, so you'd need more like a million users for that to happen.

Unfortunately, you do have to be careful with debug-level logging for performance, since there are extra queries to produce the debug logs see all of what's going on.

Commit message: spawner test assumed app.users is populated

Patch to review:
diff --git a/jupyterhub/app.py b/jupyterhub/app.py
index 0bd57de746..b0cc694a7d 100644
--- a/jupyterhub/app.py
+++ b/jupyterhub/app.py
@@ -1670,9 +1670,12 @@ async def init_users(self):
         # This lets whitelist be used to set up initial list,
         # but changes to the whitelist can occur in the database,
         # and persist across sessions.
+        total_users = 0
         for user in db.query(orm.User):
             try:
-                await maybe_future(self.authenticator.add_user(user))
+                f = self.authenticator.add_user(user)
+                if f:
+                    await maybe_future()
             except Exception:
                 self.log.exception("Error adding user %s already in db", user.name)
                 if self.authenticator.delete_invalid_users:
@@ -1694,6 +1697,7 @@ async def init_users(self):
                         )
                     )
             else:
+                total_users += 1
                 # handle database upgrades where user.created is undefined.
                 # we don't want to allow user.created to be undefined,
                 # so initialize it to last_activity (if defined) or now.
@@ -1705,6 +1709,8 @@ async def init_users(self):
         # From this point on, any user changes should be done simultaneously
         # to the whitelist set and user db, unless the whitelist is empty (all users allowed).
 
+        TOTAL_USERS.set(total_users)
+
     async def init_groups(self):
         """Load predefined groups into the database"""
         db = self.db
@@ -2005,21 +2011,24 @@ async def check_spawner(user, name, spawner):
             spawner._check_pending = False
 
         # parallelize checks for running Spawners
+        # run query on extant Server objects
+        # so this is O(running servers) not O(total users)
         check_futures = []
-        for orm_user in db.query(orm.User):
-            user = self.users[orm_user]
-            self.log.debug("Loading state for %s from db", user.name)
-            for name, orm_spawner in user.orm_spawners.items():
-                if orm_spawner.server is not None:
-                    # spawner should be running
-                    # instantiate Spawner wrapper and check if it's still alive
-                    spawner = user.spawners[name]
-                    # signal that check is pending to avoid race conditions
-                    spawner._check_pending = True
-                    f = asyncio.ensure_future(check_spawner(user, name, spawner))
-                    check_futures.append(f)
-
-        TOTAL_USERS.set(len(self.users))
+        for orm_server in db.query(orm.Server):
+            orm_spawners = orm_server.spawner
+            if not orm_spawners:
+                continue
+            orm_spawner = orm_spawners[0]
+            orm_user = orm_spawner.user
+            # instantiate Spawner wrapper and check if it's still alive
+            # spawner should be running
+            user = self.users[orm_spawner.user]
+            spawner = user.spawners[orm_spawner.name]
+            self.log.debug("Loading state for %s from db", spawner._log_name)
+            # signal that check is pending to avoid race conditions
+            spawner._check_pending = True
+            f = asyncio.ensure_future(check_spawner(user, spawner.name, spawner))
+            check_futures.append(f)
 
         # it's important that we get here before the first await
         # so that we know all spawners are instantiated and in the check-pending state
diff --git a/jupyterhub/orm.py b/jupyterhub/orm.py
index 3198a046db..4e15109208 100644
--- a/jupyterhub/orm.py
+++ b/jupyterhub/orm.py
@@ -230,7 +230,7 @@ class Spawner(Base):
     user_id = Column(Integer, ForeignKey('users.id', ondelete='CASCADE'))
 
     server_id = Column(Integer, ForeignKey('servers.id', ondelete='SET NULL'))
-    server = relationship(Server, cascade="all")
+    server = relationship(Server, backref='spawner', cascade="all")
 
     state = Column(JSONDict)
     name = Column(Unicode(255))
@@ -282,7 +282,7 @@ class Service(Base):
 
     # service-specific interface
     _server_id = Column(Integer, ForeignKey('servers.id', ondelete='SET NULL'))
-    server = relationship(Server, cascade='all')
+    server = relationship(Server, backref='service', cascade='all')
     pid = Column(Integer)
 
     def new_api_token(self, token=None, **kwargs):
diff --git a/jupyterhub/tests/test_spawner.py b/jupyterhub/tests/test_spawner.py
index 177c1da053..fa0cbeab51 100644
--- a/jupyterhub/tests/test_spawner.py
+++ b/jupyterhub/tests/test_spawner.py
@@ -103,7 +103,8 @@ def wait():
 
 
 async def test_single_user_spawner(app, request):
-    user = next(iter(app.users.values()), None)
+    orm_user = app.db.query(orm.User).first()
+    user = app.users[orm_user]
     spawner = user.spawner
     spawner.cmd = ['jupyterhub-singleuser']
     await user.spawn()


Code review comments:
diff_hunk: @@ -1670,9 +1670,12 @@ def init_hub(self):
         # This lets whitelist be used to set up initial list,
         # but changes to the whitelist can occur in the database,
         # and persist across sessions.
+        total_users = 0
         for user in db.query(orm.User):
             try:
-                await maybe_future(self.authenticator.add_user(user))
+                f = self.authenticator.add_user(user)
+                if f:
+                    await maybe_future()
path: jupyterhub/app.py
text: @user1:
for my education: why doesn't the `f` go in the `maybe_future`? Right now it seems like it is a future that isn't awaited, which is a bug??

Or is it because we don't need to/care to wait for the future to resolve. Feels like there should be a way to make that explicit (or a comment?). The `await maybe_future()` is then just a way of saying "I yield, in case someone else wants to do something"?

@author:
>  why doesn't the f go in the maybe_future

Because I forgot to put it there. It definitely needs to be there!