[pantsd] Build graph caching via v2 engine integration.

Review Request #3798 - Created April 30, 2016 and submitted

Information
Kris Wilson
pants
3227, 3307
3800
Reviewers
pants-reviews
benjyw, jsirois, peiyu, stuhood

This implements the initial round of build graph caching in pailgun-based runs via integration of the v2 engine.

A sibling review will follow to land in lockstep with this RB to move all dependent objects across the pants.engine.exp boundary and excise any exp-aligned naming.

  • Migrate the v2 engine setup guts of commands.py into goal_runner.py bundled as EngineInitializer to bootstrap PantsDaemonLauncher and the setup of SchedulerService without forming a graph dependency cycle. Integrate this in the current commands.py and tests for coverage.
  • Plumb a path for BuildGraph reuse in pailgun runs (requires --enable-pantsd).
  • Add syncronous, scheduler-backed BuildGraph construction in-daemon (pre-fork) with fallback to legacy graph usage on exception.
  • Factor out a global state scrubber util for use in the pantsd startup and pailgun runs to resolve TODO.
  • Inline the import of LocalPantsRunner in the mainline runner path for a ~100ms speedup in the thin client case.
  • Add .pantsd.startup to .gitignore since the new interprocess lock does not clean up lockfiles.
  • Misc cleanups and optimizations.

https://travis-ci.org/pantsbuild/pants/builds/126936108

+ considerable local testing:

[window B] setup tail:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ tail -F .pants.d/pantsd/pantsd.log

[window A] env var export + throwaway run to launch pantsd:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ export PANTS_ENABLE_PANTSD=true
[illuminati pants (kwlzn/engine/closed_loop_runner)]$ export PANTS_PANTSD_FS_EVENT_DETECTION=true
[illuminati pants (kwlzn/engine/closed_loop_runner)]$ ./pants -ldebug help-advanced > /dev/null
DEBUG] acquiring lock: <pants.process.lock.OwnerPrintingInterProcessFileLock object at 0x10af64c10>
DEBUG] launching pantsd
DEBUG] Selected watchman binary bootstrapped to: /Users/kwilson/.cache/pants/bin/watchman/mac/10.11/4.5.0/watchman
DEBUG] launching watchman
DEBUG] watchman cmd is: /Users/kwilson/.cache/pants/bin/watchman/mac/10.11/4.5.0/watchman get-pid --no-save-state --statefile=/Users/kwilson/dev/pants/.pants.d/watchman/watchman.state --sockname=/Users/kwilson/dev/pants/.pants.d/watchman/watchman.sock --logfile=/Users/kwilson/dev/pants/.pants.d/watchman/watchman.log --log-level 2
DEBUG] ensuring creation of directory: /Users/kwilson/dev/pants/.pants.d/watchman
DEBUG] watchman is running, pid=71075 socket=/Users/kwilson/dev/pants/.pants.d/watchman/watchman.sock
DEBUG] purging metadata directory: /Users/kwilson/dev/pants/.pids/pantsd
DEBUG] forking <pants.pantsd.pants_daemon.PantsDaemon object at 0x10af64c90>
DEBUG] released lock: <pants.process.lock.OwnerPrintingInterProcessFileLock object at 0x10af64c10>
DEBUG] pantsd is running at pid 71081
[illuminati pants (kwlzn/engine/closed_loop_runner)]$

[window B] output:

D0430 14:51:10.843097 71081 pants_daemon.py:120] logging initialized
I0430 14:51:10.843727 71081 pants_daemon.py:163] pantsd starting, log level is DEBUG
I0430 14:51:10.845850 71081 pants_daemon.py:124] setting up service <pants.pantsd.service.fs_event_service.FSEventService object at 0x10aeb9d50>
I0430 14:51:10.846252 71081 pants_daemon.py:124] setting up service <pants.pantsd.service.scheduler_service.SchedulerService object at 0x10aeeb2d0>
I0430 14:51:10.846585 71081 pants_daemon.py:124] setting up service <pants.pantsd.service.pailgun_service.PailgunService object at 0x410b360290>
I0430 14:51:10.846873 71081 pants_daemon.py:137] starting service <pants.pantsd.service.pailgun_service.PailgunService object at 0x410b360290>
I0430 14:51:10.847280 71081 pailgun_service.py:64] starting pailgun server on port 53442
I0430 14:51:10.847786 71081 pants_daemon.py:137] starting service <pants.pantsd.service.fs_event_service.FSEventService object at 0x10aeb9d50>
I0430 14:51:10.848162 71081 pants_daemon.py:137] starting service <pants.pantsd.service.scheduler_service.SchedulerService object at 0x10aeeb2d0>
D0430 14:51:11.041810 71081 watchman.py:147] watchman command_list is: [[u'subscribe', '/Users/kwilson/dev/pants', u'all_files', {'fields': [u'name'], 'expression': [u'allof', [u'anyof', [u'type', u'f'], [u'type', u'l']], [u'not', [u'dirname', u'dist', [u'depth', u'eq', 0]]], [u'not', [u'pcre', u'^\\..*', u'wholename']], [u'not', [u'match', u'*.pyc']]]}]]
I0430 14:51:11.047462 71081 watchman.py:153] confirmed watchman subscription: {'subscribe': 'all_files', 'version': '4.5.0', 'clock': 'c:1462053065:71075:1:4'}
I0430 14:51:11.049132 71081 scheduler_service.py:54] enqueuing 4552 changes for subscription all_files
D0430 14:51:11.069974 71081 scheduler_service.py:81] processing 4552 files for subscription all_files (first_event=True)
D0430 14:51:16.052555 71081 fs_event_service.py:146] callback ID 1 for all_files succeeded

[window A] initial cold run to prime the resident scheduler:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ time ./pants list 3rdparty:: > /dev/null

real  0m1.927s
user  0m0.129s
sys 0m0.067s

[window B] pantsd log output:

I0430 14:53:04.627880 71081 pailgun_server.py:72] handling pailgun request: `./pants list 3rdparty::`
D0430 14:53:04.628139 71081 pailgun_server.py:73] pailgun request environment: ...
D0430 14:53:04.628923 71081 pailgun_service.py:51] requesting BuildGraph from <pants.pantsd.service.scheduler_service.SchedulerService object at 0x10aeeb2d0>
D0430 14:53:04.629442 71081 scheduler_service.py:92] execution commandline: [u'./pants', 'list', '3rdparty::']
D0430 14:53:04.676603 71081 scheduler_service.py:94] parsed spec_roots: [DescendantAddresses(directory='3rdparty')]
D0430 14:53:04.677037 71081 graph.py:193] Injecting to <pants.engine.exp.legacy.graph.ExpGraph object at 0x1090639d0>: [DescendantAddresses(directory='3rdparty')]
D0430 14:53:06.114860 71081 scheduler.py:614] visited 1219 nodes in 344 scheduling iterations. there have been 4022 total steps for 1987 total nodes.
D0430 14:53:06.123577 71081 scheduler_service.py:97] engine cache stats: hits=0, misses=3976, total=3976
D0430 14:53:06.123779 71081 scheduler_service.py:98] build_graph is: <pants.engine.exp.legacy.graph.ExpGraph object at 0x1090639d0>
D0430 14:53:06.124270 71081 process_manager.py:178] purging metadata directory: /Users/kwilson/dev/pants/.pids/pantsd-run-2016-04-30T14_53_06_124079
D0430 14:53:06.124444 71081 process_manager.py:402] forking <pants.bin.daemon_pants_runner.DaemonPantsRunner object at 0x410b360450>

[window A] warm run:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ time ./pants list 3rdparty:: > /dev/null

real  0m0.609s
user  0m0.130s
sys 0m0.066s

[window B] pantsd log output:

I0430 14:53:40.948565 71081 pailgun_server.py:72] handling pailgun request: `./pants list 3rdparty::`
D0430 14:53:40.949038 71081 pailgun_server.py:73] pailgun request environment: ...
D0430 14:53:40.949594 71081 pailgun_service.py:51] requesting BuildGraph from <pants.pantsd.service.scheduler_service.SchedulerService object at 0x10aeeb2d0>
D0430 14:53:40.950035 71081 scheduler_service.py:92] execution commandline: [u'./pants', 'list', '3rdparty::']
D0430 14:53:40.992217 71081 scheduler_service.py:94] parsed spec_roots: [DescendantAddresses(directory='3rdparty')]
D0430 14:53:41.005194 71081 graph.py:193] Injecting to <pants.engine.exp.legacy.graph.ExpGraph object at 0x410b6d41d0>: [DescendantAddresses(directory='3rdparty')]
D0430 14:53:41.015544 71081 scheduler.py:614] visited 1219 nodes in 0 scheduling iterations. there have been 4022 total steps for 1987 total nodes.
D0430 14:53:41.022319 71081 scheduler_service.py:97] engine cache stats: hits=0, misses=3976, total=3976
D0430 14:53:41.022509 71081 scheduler_service.py:98] build_graph is: <pants.engine.exp.legacy.graph.ExpGraph object at 0x410b6d41d0>
D0430 14:53:41.022916 71081 process_manager.py:178] purging metadata directory: /Users/kwilson/dev/pants/.pids/pantsd-run-2016-04-30T14_53_41_022726
D0430 14:53:41.023076 71081 process_manager.py:402] forking <pants.bin.daemon_pants_runner.DaemonPantsRunner object at 0x10af3d210>

[window A] testing invalidation:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ find 3rdparty -name BUILD -exec touch {} \;
[illuminati pants (kwlzn/engine/closed_loop_runner)]$

[window B] pantsd log output:

...
I0430 14:57:12.536189 71081 scheduler.py:180] invalidated 901 of 1086 nodes
...

[window A] post-invalidation re-run:

[illuminati pants (kwlzn/engine/closed_loop_runner)]$ time ./pants list 3rdparty:: > /dev/null

real  0m1.138s
user  0m0.128s
sys 0m0.066s

[window B] pantsd log output:

I0430 14:59:42.952877 71081 pailgun_server.py:72] handling pailgun request: `./pants list 3rdparty::`
D0430 14:59:42.953142 71081 pailgun_server.py:73] pailgun request environment: ...
D0430 14:59:42.953516 71081 pailgun_service.py:51] requesting BuildGraph from <pants.pantsd.service.scheduler_service.SchedulerService object at 0x10aeeb2d0>
D0430 14:59:42.953715 71081 scheduler_service.py:92] execution commandline: [u'./pants', 'list', '3rdparty::']
D0430 14:59:42.998142 71081 scheduler_service.py:94] parsed spec_roots: [DescendantAddresses(directory='3rdparty')]
D0430 14:59:43.001378 71081 graph.py:193] Injecting to <pants.engine.exp.legacy.graph.ExpGraph object at 0x410b4ff490>: [DescendantAddresses(directory='3rdparty')]
D0430 14:59:43.551987 71081 scheduler.py:614] visited 1219 nodes in 172 scheduling iterations. there have been 6172 total steps for 1987 total nodes.
D0430 14:59:43.562912 71081 scheduler_service.py:97] engine cache stats: hits=2127, misses=3976, total=6103
D0430 14:59:43.563154 71081 scheduler_service.py:98] build_graph is: <pants.engine.exp.legacy.graph.ExpGraph object at 0x410b4ff490>
D0430 14:59:43.563565 71081 process_manager.py:178] purging metadata directory: /Users/kwilson/dev/pants/.pids/pantsd-run-2016-04-30T14_59_43_563377
D0430 14:59:43.563733 71081 process_manager.py:402] forking <pants.bin.daemon_pants_runner.DaemonPantsRunner object at 0x10a7bf650>

Issues

  • 0
  • 5
  • 4
  • 9
Description From Last Updated
Kris Wilson
Kris Wilson
Stu Hood
John Sirois
Peiyu Wang
Stu Hood
Kris Wilson
Kris Wilson
Patrick Lawson
Kris Wilson
Benjy Weinberger
John Sirois
Kris Wilson
Stu Hood
Kris Wilson
Review request changed

Status: Closed (submitted)

Change Summary:

thanks folks! this is submitted @ e6c510fd3110d4c00004481d06e70e956d1415cf

Loading...