diff --git a/docs/topics/commands.rst b/docs/topics/commands.rst index 8d1351eb9..59dd40109 100644 --- a/docs/topics/commands.rst +++ b/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 ======================= diff --git a/docs/topics/debug.rst b/docs/topics/debug.rst index 988e37bbd..eb3f7ab63 100644 --- a/docs/topics/debug.rst +++ b/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 `_, pass a filename: + +.. code-block:: shell + + scrapy crawl myspider --profile=myspider.prof diff --git a/scrapy/cmdline.py b/scrapy/cmdline.py index 6c306afdb..11090d67a 100644 --- a/scrapy/cmdline.py +++ b/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__": diff --git a/scrapy/commands/__init__.py b/scrapy/commands/__init__.py index 19b6f6681..18959b38a 100644 --- a/scrapy/commands/__init__.py +++ b/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( diff --git a/tests/test_cmdline/__init__.py b/tests/test_cmdline/__init__.py index 98a85bc17..6aeafc4c5 100644 --- a/tests/test_cmdline/__init__.py +++ b/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}