Implement profiling page for Panel

doc/user_guide/index.rst

@@ -65,6 +65,10 @@ when needed.
 
 `Authentication <Authentication.html>`_
  Learn how to add an authentication component in front of your application.
+
+`Profiling and Debugging <Performance_and_Debugging.html>`_
+ Learn how to speed up your application and find issues.
+
 
 Supplementary guides
 --------------------
@@ -93,4 +97,5 @@ Supplementary guides
     Building Custom Components <Custom_Components>
     Asynchronous and Concurrent Process <Async_and_Concurrency>
     Authentication <Authentication>
+    Performance and Debugging <Performance_and_Debugging>
     Django Apps <Django_Apps>

examples/user_guide/Performance_and_Debugging.ipynb

@@ -0,0 +1,224 @@
+{
+ "cells": [
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "import panel as pn\n",
+    "pn.extension('terminal')"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "When developing applications that are to be used by multiple users and which may process a lot of data it is important to ensure the application is well optimized. Additionally complex applications may have very complex callbacks which are difficult to trace and debug. In this user guide section we will walk you some of the best practices to debug your applications and profile your application to maximize performance."
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "## Caching\n",
+    "\n",
+    "The Panel architecture ensures that multiple user sessions can run in the same process and therefore have access to the same global state. This means that we can cache data in Panel's global `state` object, either by directly assigning to the `pn.state.cache` dictionary object or by using the `pn.state.as_cached` helper function.\n",
+    "\n",
+    "To assign to the cache manually, simply put the data load or expensive calculation in an `if`/`else` block which checks whether the custom key is already present: \n",
+    "\n",
+    "```python\n",
+    "if 'data' in pn.state.cache:\n",
+    "    data = pn.state.cache['data']\n",
+    "else:\n",
+    "    pn.state.cache['data'] = data = ... # Load some data or perform an expensive computation\n",
+    "```\n",
+    "\n",
+    "The `as_cached` helper function on the other hand allows providing a custom key and a function and automatically caching the return value. If provided the `args` and `kwargs` will also be hashed making it easy to cache (or memoize) on the arguments to the function: \n",
+    "\n",
+    "```python\n",
+    "def load_data(*args, **kwargs):\n",
+    "    return  ... # Load some data\n",
+    "\n",
+    "data = pn.state.as_cached('data', load_data, *args, **kwargs)\n",
+    "```\n",
+    "\n",
+    "The first time the app is loaded the data will be cached and subsequent sessions will simply look up the data in the cache, speeding up the process of rendering. If you want to warm up the cache before the first user visits the application you can also provide the `--warm` argument to the `panel serve` command, which will ensure the application is initialized once on launch."
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "## Admin Panel\n",
+    "\n",
+    "The `/admin` panel provides an overview of the current application and provides tools for debugging and profiling. It can be enabled by passing the ``--admin`` argument to the `panel serve` command."
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "### Overview\n",
+    "\n",
+    "The overview page provides some details about currently active sessions, running versions and resource usage (if `psutil` is installed).\n",
+    "\n",
+    "<img src=\"../assets/admin_overview.png\" width=\"70%\"></img>"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "### Launch Profiler\n",
+    "\n",
+    "The launch profiler profiles the execution time of the initialization of a particular application. It can be enabled by setting a profiler using the commandline ``--profiler`` option. Available profilers include:\n",
+    "\n",
+    "- [`pyinstrument`](https://pyinstrument.readthedocs.io): A statistical profiler with nice visual output\n",
+    "- [`snakeviz`](https://jiffyclub.github.io/snakeviz/): SnakeViz is a browser based graphical viewer for the output of Python’s cProfile module and an alternative to using the standard library pstats module.\n",
+    "\n",
+    "Once enabled the launch profiler will profile each application separately and provide the profiler output generated by the selected profiling engine.\n",
+    "\n",
+    "<img src=\"../assets/launch_profiler.png\" width=\"80%\"></img>"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "### User profiling\n",
+    "\n",
+    "In addition to profiling the launch step of an application it is often also important to get insight into the interactive performance of an application. For that reason Panel also provides the `pn.io.profile` decorator that can be added to any callback and will report the profiling results in the `/admin` panel. The `profile` helper takes to arguments, the name to record the profiling results under and the profiling `engine` to use.\n",
+    "\n",
+    "```python\n",
+    "@pn.io.profile('clustering', engine='snakeviz')\n",
+    "def get_clustering(event):\n",
+    "    # some expensive calculation\n",
+    "    ...\n",
+    "    \n",
+    "widget.param.watch(my_callback, 'value')\n",
+    "```\n",
+    "\n",
+    "<img src=\"../assets/user_profiling.png\" width=\"80%\"></img>"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "The user profiling may also be used in an interactive session, e.g. we might decorate a simple callback with the `profile` decorator:"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "import time\n",
+    "\n",
+    "slider = pn.widgets.FloatSlider(name='Test')\n",
+    "\n",
+    "@pn.depends(slider)\n",
+    "@pn.io.profile('formatting')\n",
+    "def format_value(value):\n",
+    "    time.sleep(1)\n",
+    "    return f'Value: {value+1}'\n",
+    "\n",
+    "pn.Row(slider, format_value)"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "Then we can request the named profile 'formatting' using the `pn.state.get_profile` function:"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "pn.state.get_profile('formatting')"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "### Logs\n",
+    "\n",
+    "The Logs page provides a detailed breakdown of the user interaction with the application. Additionally users may also log to this logger using the `pn.state.log` function, e.g. in this example we log the arguments to the clustering function:\n",
+    "\n",
+    "```python\n",
+    "def get_clusters(x, y, n_clusters):\n",
+    "    pn.state.log(f'clustering {x!r} vs {y!r} into {n_clusters} clusters.')\n",
+    "    ...\n",
+    "    return ...\n",
+    "```\n",
+    "\n",
+    "\n",
+    "\n",
+    "<img src=\"../assets/admin_logs.png\" width=\"80%\"></img>\n",
+    "\n"
+   ]
+  },
+  {
+   "cell_type": "markdown",
+   "metadata": {},
+   "source": [
+    "The logging terminal may also be used interactively, however you have to ensure that the 'terminal' extension is loaded with `pn.extension('terminal')`. If the extension is initialized it can be rendered by accessing it on `pn.state.log_terminal`:"
+   ]
+  },
+  {
+   "cell_type": "code",
+   "execution_count": null,
+   "metadata": {},
+   "outputs": [],
+   "source": [
+    "slider = pn.widgets.FloatSlider(name='Test')\n",
+    "\n",
+    "@pn.depends(slider)\n",
+    "def format_value(value):\n",
+    "    pn.state.log(f'formatting value {value}')\n",
+    "    return f'Value: {value+1}'\n",
+    "\n",
+    "pn.Column(\n",
+    "    pn.Row(slider, format_value),\n",
+    "    pn.state.log_terminal,\n",
+    "    sizing_mode='stretch_both'\n",
+    ")\n"
+   ]
+  }
+ ],
+ "metadata": {
+  "kernelspec": {
+   "display_name": "Python 3",
+   "language": "python",
+   "name": "python3"
+  },
+  "language_info": {
+   "codemirror_mode": {
+    "name": "ipython",
+    "version": 3
+   },
+   "file_extension": ".py",
+   "mimetype": "text/x-python",
+   "name": "python",
+   "nbconvert_exporter": "python",
+   "pygments_lexer": "ipython3",
+   "version": "3.8.8"
+  },
+  "widgets": {
+   "application/vnd.jupyter.widget-state+json": {
+    "state": {},
+    "version_major": 2,
+    "version_minor": 0
+   }
+  }
+ },
+ "nbformat": 4,
+ "nbformat_minor": 4
+}

panel/auth.py

@@ -125,7 +125,7 @@ async def get_authenticated_user(self, redirect_uri, client_id, state,
             params['scope'] = self._SCOPE
         if 'scope' in config.oauth_extra_params:
             params['scope'] = config.oauth_extra_params['scope']
-        log.debug("%s making authorize request" % type(self).__name__)
+        log.debug("%s making authorize request", type(self).__name__)
         self.authorize_redirect(**params)
 
     async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret):
@@ -149,7 +149,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if not client_secret:
             raise ValueError('The client secret is undefined.')
 
-        log.debug("%s making access token request." % type(self).__name__)
+        log.debug("%s making access token request.", type(self).__name__)
 
         params = {
             'code':          code,
@@ -196,7 +196,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if not user:
             return
 
-        log.debug("%s received user information." % type(self).__name__)
+        log.debug("%s received user information.", type(self).__name__)
         return self._on_auth(user, body['access_token'])
 
     def get_state_cookie(self):
@@ -214,7 +214,7 @@ def set_state_cookie(self, state):
         self.set_secure_cookie(STATE_COOKIE_NAME, state, expires_days=1, httponly=True)
 
     async def get(self):
-        log.debug("%s received login request" % type(self).__name__)
+        log.debug("%s received login request", type(self).__name__)
         if config.oauth_redirect_uri:
             redirect_uri = config.oauth_redirect_uri
         else:
@@ -249,7 +249,7 @@ async def get(self):
             user = await self.get_authenticated_user(**params)
             if user is None:
                 raise HTTPError(403)
-            log.debug("%s authorized user, redirecting to app." % type(self).__name__)
+            log.debug("%s authorized user, redirecting to app.", type(self).__name__)
             self.redirect('/')
         else:
             # Redirect for user authentication
@@ -407,7 +407,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if not client_secret:
             raise ValueError('The client secret is undefined.')
 
-        log.debug("%s making access token request." % type(self).__name__)
+        log.debug("%s making access token request.", type(self).__name__)
 
         http = self.get_auth_http_client()
 
@@ -441,7 +441,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if 'access_token' not in body:
             return self._on_error(response, body)
 
-        log.debug("%s granted access_token." % type(self).__name__)
+        log.debug("%s granted access_token.", type(self).__name__)
 
         headers = dict(self._API_BASE_HEADERS, **{
             "Authorization": "Bearer {}".format(body['access_token']),
@@ -458,7 +458,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if not user:
             return
 
-        log.debug("%s received user information." % type(self).__name__)
+        log.debug("%s received user information.", type(self).__name__)
 
         return self._on_auth(user, body['access_token'])
 
@@ -496,7 +496,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if not client_secret:
             raise ValueError('The client secret are undefined.')
 
-        log.debug("%s making access token request." % type(self).__name__)
+        log.debug("%s making access token request.", type(self).__name__)
 
         http = self.get_auth_http_client()
 
@@ -529,7 +529,7 @@ async def _fetch_access_token(self, code, redirect_uri, client_id, client_secret
         if 'access_token' not in body:
             return self._on_error(response, body)
 
-        log.debug("%s granted access_token." % type(self).__name__)
+        log.debug("%s granted access_token.", type(self).__name__)
 
         access_token = body['access_token']
         id_token = body['id_token']
@@ -541,8 +541,8 @@ def _on_auth(self, id_token, access_token):
         if user_key in decoded:
             user = decoded[user_key]
         else:
-            log.error("%s token payload did not contain expected '%s'." %
-                      (type(self).__name__, user_key))
+            log.error("%s token payload did not contain expected %r.",
+                      type(self).__name__, user_key)
             raise HTTPError(400, "OAuth token payload missing user information")
         self.set_secure_cookie('user', user)
         if state.encryption: