Document and improve --profile

docs/topics/commands.rst

@@ -620,6 +620,66 @@ In this case you should set the :setting:`FORCE_CRAWLER_PROCESS` setting to
 ``True`` (at the project level or via the command line) so that Scrapy uses
 :class:`~scrapy.crawler.CrawlerProcess` which supports all reactors.
 
+.. _cli-global-options:
+
+Global options
+==============
+
+The following options are available for all Scrapy commands:
+
+.. option:: --profile [FILE]
+
+    Run the command under :mod:`cProfile`. Profile statistics are printed to
+    the log after the command finishes. If ``FILE`` is given, binary cProfile
+    stats are also written to that file for later analysis with tools like
+    :mod:`pstats`.
+
+    Example (log only):
+
+    .. code-block:: none
+
+        scrapy crawl myspider --profile
+
+    Example (log + binary dump):
+
+    .. code-block:: none
+
+        scrapy crawl myspider --profile=myspider.prof
+
+    See also :option:`--profile-sort` and :option:`--profile-limit`.
+
+.. option:: --profile-sort COLUMN
+
+    Sort the profile stats output by ``COLUMN``. Accepts any column name
+    supported by :meth:`pstats.Stats.sort_stats`, such as ``cumulative``
+    (default), ``tottime``, ``calls``, ``name``, etc.
+
+.. option:: --profile-limit N
+
+    Limit the profile stats output to the top ``N`` rows. Default: ``30``.
+
+.. option:: --logfile FILE
+
+    Redirect the log output to ``FILE`` instead of stderr.
+
+.. option:: -L, --loglevel LEVEL
+
+    Override the :setting:`LOG_LEVEL` setting. Valid levels are ``CRITICAL``,
+    ``ERROR``, ``WARNING``, ``INFO``, and ``DEBUG``.
+
+.. option:: --nolog
+
+    Disable logging entirely. Equivalent to setting :setting:`LOG_ENABLED` to
+    ``False``.
+
+.. option:: --pidfile FILE
+
+    Write the process ID to ``FILE``.
+
+.. option:: -s NAME=VALUE, --set NAME=VALUE
+
+    Override a Scrapy setting. May be repeated.
+
 Custom project commands
 =======================
 

docs/topics/debug.rst

@@ -182,3 +182,24 @@ To debug spiders with Visual Studio Code you can use the following ``launch.json
 
 Also, make sure you enable "User Uncaught Exceptions", to catch exceptions in
 your Scrapy spider.
+
+Profiling
+=========
+
+To measure where your spider spends time, run any Scrapy command under
+:mod:`cProfile` using the :option:`--profile` option:
+
+.. code-block:: shell
+
+    scrapy crawl myspider --profile
+
+Profile statistics are printed to the log after the command finishes. Use
+:option:`--profile-sort` to change the sort column and
+:option:`--profile-limit` to cap the number of rows shown.
+
+To also save binary stats for later analysis with :mod:`pstats` or tools like
+`SnakeViz <https://jiffyclub.github.io/snakeviz/>`_, pass a filename:
+
+.. code-block:: shell
+
+    scrapy crawl myspider --profile=myspider.prof

scrapy/cmdline.py

@@ -3,7 +3,10 @@ from __future__ import annotations
 import argparse
 import cProfile
 import inspect
+import io
+import logging
 import os
+import pstats
 import sys
 from importlib.metadata import entry_points
 from typing import TYPE_CHECKING, ParamSpec
@@ -24,6 +27,8 @@ if TYPE_CHECKING:
 
 _P = ParamSpec("_P")
 
+logger = logging.getLogger(__name__)
+
 
 class ScrapyArgumentParser(argparse.ArgumentParser):
     def _parse_optional(
@@ -216,7 +221,7 @@ def execute(argv: list[str] | None = None, settings: Settings | None = None) ->
 
 
 def _run_command(cmd: ScrapyCommand, args: list[str], opts: argparse.Namespace) -> None:
-    if opts.profile:
+    if opts.profile is not None:
         _run_command_profiled(cmd, args, opts)
     else:
         cmd.run(args, opts)
@@ -232,6 +237,15 @@ def _run_command_profiled(
     p.runctx("cmd.run(args, opts)", globals(), loc)
     if opts.profile:
         p.dump_stats(opts.profile)
+    stream = io.StringIO()
+    stats = pstats.Stats(p, stream=stream)
+    stats.sort_stats(opts.profile_sort)
+    stats.print_stats(opts.profile_limit)
+    stats_output = stream.getvalue()
+    if logging.root.handlers:
+        logger.info("Profile stats:\n%s", stats_output)
+    else:
+        sys.stderr.write(f"Profile stats:\n{stats_output}")
 
 
 if __name__ == "__main__":

scrapy/commands/__init__.py

@@ -96,8 +96,30 @@ class ScrapyCommand(ABC):
         group.add_argument(
             "--profile",
             metavar="FILE",
+            nargs="?",
+            const="",
             default=None,
-            help="write python cProfile stats to FILE",
+            help=(
+                "Run under cProfile, printing stats to the log after the "
+                "command finishes (use --profile=FILE to also write binary "
+                "cProfile stats to FILE)"
+            ),
+        )
+        group.add_argument(
+            "--profile-sort",
+            metavar="COLUMN",
+            default="cumulative",
+            help=(
+                "Sort profile stats by COLUMN, e.g. 'cumulative', 'tottime', "
+                "'calls' (default: cumulative)"
+            ),
+        )
+        group.add_argument(
+            "--profile-limit",
+            metavar="N",
+            type=int,
+            default=30,
+            help="Limit profile stats output to N rows (default: 30)",
         )
         group.add_argument("--pidfile", metavar="FILE", help="write process ID to FILE")
         group.add_argument(

tests/test_cmdline/__init__.py

@@ -25,6 +25,13 @@ class TestCmdline:
         comm = proc.communicate()[0].strip()
         return comm.decode(encoding)
 
+    def _execute_with_stderr(self, *new_args, **kwargs):
+        encoding = sys.stdout.encoding or "utf-8"
+        args = (sys.executable, "-m", "scrapy.cmdline", *new_args)
+        proc = Popen(args, stdout=PIPE, stderr=PIPE, env=self.env, **kwargs)
+        stdout, stderr = proc.communicate()
+        return stdout.strip().decode(encoding), stderr.decode(encoding)
+
     def test_default_settings(self):
         assert self._execute("settings", "--get", "TEST1") == "default"
 
@@ -38,18 +45,39 @@ class TestCmdline:
         path = Path(tempfile.mkdtemp())
         filename = path / "res.prof"
         try:
-            self._execute("version", "--profile", str(filename))
+            _, stderr = self._execute_with_stderr("version", "--profile", str(filename))
             assert filename.exists()
             out = StringIO()
             stats = pstats.Stats(str(filename), stream=out)
             stats.print_stats()
             out.seek(0)
-            stats = out.read()
-            assert str(Path("scrapy", "commands", "version.py")) in stats
-            assert "tottime" in stats
+            stats_text = out.read()
+            assert str(Path("scrapy", "commands", "version.py")) in stats_text
+            assert "tottime" in stats_text
+            assert "Profile stats:" in stderr
+            assert str(Path("scrapy", "commands", "version.py")) in stderr
         finally:
             shutil.rmtree(path)
 
+    def test_profiling_no_file(self):
+        _, stderr = self._execute_with_stderr("version", "--profile")
+        assert "Profile stats:" in stderr
+        assert str(Path("scrapy", "commands", "version.py")) in stderr
+
+    def test_profiling_sort(self):
+        _, stderr = self._execute_with_stderr(
+            "version", "--profile", "--profile-sort", "tottime"
+        )
+        assert "Profile stats:" in stderr
+        assert "tottime" in stderr
+
+    def test_profiling_limit(self):
+        _, full_stderr = self._execute_with_stderr("version", "--profile")
+        _, limited_stderr = self._execute_with_stderr(
+            "version", "--profile", "--profile-limit", "1"
+        )
+        assert limited_stderr.count("\n") < full_stderr.count("\n")
+
     def test_override_dict_settings(self):
         EXT_PATH = "tests.test_cmdline.extensions.DummyExtension"
         EXTENSIONS = {EXT_PATH: 200}