rapid-bird-79300
03/23/2021, 12:23 AM2 minutes and 5 seconds
)
• container without cache (>12 minutes
)
• host with cache (1 minute and 11 seconds
)
• container with cache (2 minute and 17 seconds
)
◦ mounted via -v $HOME/.cache/pants:/build/.cache/pants
It feels like it's related to IO performance of the container but not 100% sure. Any ideas why running fresh in a container with no cache takes so long? Or do others have experience they can share when running pants with docker?witty-crayon-22786
03/23/2021, 12:34 AMrapid-bird-79300
03/23/2021, 12:35 AMwitty-crayon-22786
03/23/2021, 12:35 AMfast-nail-55400
03/23/2021, 12:36 AM-ldebug
)rapid-bird-79300
03/23/2021, 12:38 AMfast-nail-55400
03/23/2021, 12:39 AMpip
cache into the container as wellwitty-crayon-22786
03/23/2021, 12:40 AM~/.cache/pants/named_caches
?fast-nail-55400
03/23/2021, 12:40 AM$HOME/Library/Caches/pip/wheels
on macOS)./pants
bootstraps its venvwitty-crayon-22786
03/23/2021, 12:41 AMfast-nail-55400
03/23/2021, 12:42 AMrapid-bird-79300
03/23/2021, 12:44 AM00:42:26.75 [DEBUG] Starting: local_cache_read
00:42:26.75 [DEBUG] Starting: local_cache_read
00:42:26.75 [DEBUG] Starting: (Waiting) Determine Python imports for <redacted>
fast-nail-55400
03/23/2021, 12:48 AM--no-dynamic-ui
, this should enable the “straggler logging” which logs tasks that take longer than 60 seconds (checking every 30 seconds).rapid-bird-79300
03/23/2021, 12:49 AMdynamic_ui = false
set in my pants.toml. That's the same right?fast-nail-55400
03/23/2021, 12:49 AMrapid-bird-79300
03/23/2021, 12:50 AMfast-nail-55400
03/23/2021, 12:50 AMrapid-bird-79300
03/23/2021, 12:52 AMfast-nail-55400
03/23/2021, 12:54 AMrapid-bird-79300
03/23/2021, 12:55 AMfast-nail-55400
03/23/2021, 12:58 AMrapid-bird-79300
03/23/2021, 1:05 AM2.3.0
fast-nail-55400
03/23/2021, 1:09 AMrapid-bird-79300
03/23/2021, 1:10 AMFROM python:3.7.10-slim
WORKDIR /build
RUN apt-get update -y && apt-get install curl build-essential git unzip -y
ADD app app
COPY pants.ci.toml pants.toml
COPY pants .
RUN ./pants --version
ENTRYPOINT ["./pants"]
01:12:46.80 [DEBUG] Running Determine Python imports for <redacted> under semaphore with concurrency id: 2
01:12:46.80 [DEBUG] Starting: Determine Python imports for <redacted>
fast-nail-55400
03/23/2021, 1:17 AMrapid-bird-79300
03/23/2021, 1:20 AM01:12:45.88 [DEBUG] Completed: Find interpreter for constraints: CPython>=3.6
01:12:45.88 [DEBUG] Completed: (Waiting) Find interpreter for constraints: CPython>=3.6
01:12:45.88 [DEBUG] Completed: local_cache_read
01:12:45.88 [DEBUG] Completed: Find Python interpreter for constraints - Selected /usr/local/bin/python3.7 to run PEXes with.
01:12:46.18 [DEBUG] Starting: local_cache_read
01:12:46.76 [DEBUG] Starting: local_cache_read
01:12:46.76 [DEBUG] Starting: local_cache_read
01:12:46.76 [DEBUG] Starting: local_cache_read
01:12:46.76 [DEBUG] Starting: local_cache_read
01:12:46.76 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.77 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.78 [DEBUG] Starting: (Waiting) Determine Python imports for <redacted>
01:12:46.78 [DEBUG] Running Determine Python imports for <redacted> under semaphore with concurrency id: 1
01:12:46.78 [DEBUG] Starting: Determine Python imports for <redacted>
01:12:46.78 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.79 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: local_cache_read
01:12:46.80 [DEBUG] Starting: (Waiting) Determine Python imports for <redacted>
01:12:46.80 [DEBUG] Running Determine Python imports for <redacted> under semaphore with concurrency id: 2
01:12:46.80 [DEBUG] Starting: Determine Python imports for <redacted>
fast-nail-55400
03/23/2021, 1:22 AMwitty-crayon-22786
03/23/2021, 1:24 AMrapid-bird-79300
03/23/2021, 1:25 AMfast-nail-55400
03/23/2021, 1:27 AMrapid-bird-79300
03/23/2021, 1:29 AMfast-nail-55400
03/23/2021, 1:29 AMrapid-bird-79300
03/23/2021, 1:30 AM01:12:46.80 [DEBUG] Starting: Determine Python imports for <redacted>
fast-nail-55400
03/23/2021, 1:31 AM--pex-verbosity=9
-ldebug
as well)witty-crayon-22786
03/23/2021, 1:32 AMDetermine Python imports for
line, then it might … actually be hung, unfortunately.rapid-bird-79300
03/23/2021, 1:33 AMwitty-crayon-22786
03/23/2021, 1:34 AM-ldebug
might be triggering a race condition of some sort in your environment. if you have time to investigate that i can help look at it tomorrow… but with regard to your benchmarking, dropping back to just -linfo
(the default) should still get you a pretty good amount of log info.rapid-bird-79300
03/23/2021, 1:36 AMwitty-crayon-22786
03/23/2021, 1:37 AMrapid-bird-79300
03/23/2021, 1:39 AM--pex-verbosity=9
and -ldebug
):-linfo
as @witty-crayon-22786 mentioned...
188.41s Inferring Python dependencies by analyzing imports
188.41s Inferring Python dependencies by analyzing imports
188.49s Inferring Python dependencies by analyzing imports
188.51s Inferring Python dependencies by analyzing imports
188.55s Inferring Python dependencies by analyzing imports
188.55s Inferring Python dependencies by analyzing imports
188.59s Inferring Python dependencies by analyzing imports
188.66s Inferring Python dependencies by analyzing imports
188.66s Inferring Python dependencies by analyzing imports
188.69s Inferring Python dependencies by analyzing imports
188.69s Inferring Python dependencies by analyzing imports
188.74s Inferring Python dependencies by analyzing imports
188.76s Inferring Python dependencies by analyzing imports
188.79s Inferring Python dependencies by analyzing imports
188.80s Inferring Python dependencies by analyzing imports
188.83s Inferring Python dependencies by analyzing imports
188.88s Inferring Python dependencies by analyzing imports
188.89s Inferring Python dependencies by analyzing imports
188.98s Inferring Python dependencies by analyzing imports
189.03s Inferring Python dependencies by analyzing imports
189.03s Inferring Python dependencies by analyzing imports
189.64s Inferring Python dependencies by analyzing imports
189.94s Inferring Python dependencies by analyzing imports
189.97s Inferring Python dependencies by analyzing imports
189.98s Inferring Python dependencies by analyzing imports
190.01s Inferring Python dependencies by analyzing imports
190.03s Inferring Python dependencies by analyzing imports
190.03s Inferring Python dependencies by analyzing imports
190.08s Inferring Python dependencies by analyzing imports
190.08s Inferring Python dependencies by analyzing imports
190.11s Inferring Python dependencies by analyzing imports
190.11s Inferring Python dependencies by analyzing imports
197.40s Inferring Python dependencies by analyzing imports
203.41s Inferring Python dependencies by analyzing imports
221.78s Inferring Python dependencies by analyzing imports
221.86s Inferring Python dependencies by analyzing imports
221.94s Inferring Python dependencies by analyzing imports
224.65s Inferring Python dependencies by analyzing imports
229.38s Inferring Python dependencies by analyzing imports
230.39s Inferring Python dependencies by analyzing imports
230.47s Inferring Python dependencies by analyzing imports
231.37s Inferring Python dependencies by analyzing imports
231.40s Inferring Python dependencies by analyzing imports
232.53s Inferring Python dependencies by analyzing imports
232.55s Inferring Python dependencies by analyzing imports
232.55s Inferring Python dependencies by analyzing imports
232.56s Inferring Python dependencies by analyzing imports
232.57s Inferring Python dependencies by analyzing imports
232.59s Inferring Python dependencies by analyzing imports
232.62s Inferring Python dependencies by analyzing imports
232.62s Inferring Python dependencies by analyzing imports
232.70s Inferring Python dependencies by analyzing imports
witty-crayon-22786
03/23/2021, 1:45 AMhundreds-father-404
03/23/2021, 1:45 AMwitty-crayon-22786
03/23/2021, 1:46 AM./pants help-advanced global | grep -A6 'local-parallelism='
report?rapid-bird-79300
03/23/2021, 1:49 AM$ ./pants help-advanced global | grep -A6 'local-parallelism='
18:48:37.63 [INFO] initializing pantsd...
18:48:37.94 [INFO] pantsd initialized.
--process-execution-local-parallelism=<int>
PANTS_PROCESS_EXECUTION_LOCAL_PARALLELISM
process_execution_local_parallelism
default: 12
current value: 12 (from pants.ci.toml)
Number of concurrent processes that may be executed locally.
I have set process_execution_local_parallelism
to the default value when testing.fast-nail-55400
03/23/2021, 3:31 AMNo entry point specified, dropping into interpreter
witty-crayon-22786
03/23/2021, 3:36 AMenough-analyst-54434
03/23/2021, 3:40 AM$ pex -v -- -c 'print("no entrypoint being used here")'
pex: Building pex: 0.8ms
pex: Resolving distributions ([]): 0.2ms
pex: Resolving requirements.: 0.1ms
Running PEX file at /tmp/tmptk7v2hk4 with args ['-c', 'print("no entrypoint being used here")']
pex: PEX.run invoking /home/jsirois/.venv/pex/bin/python3 /tmp/tmptk7v2hk4 -c print("no entrypoint being used here")
pex: Re-executing: cmdline='/usr/bin/python3.9 /tmp/tmptk7v2hk4 -c print("no entrypoint being used here")', sys.executable='/home/jsirois/.venv/pex/bin/python3', PEX_PYTHON=None, PEX_PYTHON_PATH=None, interpreter_constraints=[]
pex: Found site-library: /usr/lib/python3.9/site-packages
pex: Tainted path element: /usr/lib/python3.9/site-packages
pex: Scrubbing from user site: /home/jsirois/.local/lib/python3.9/site-packages
pex: Scrubbing from site-packages: /usr/lib/python3.9/site-packages
pex: New sys.path: ['/tmp/tmptk7v2hk4/.bootstrap', '/tmp/tmptk7v2hk4', '/usr/lib/python39.zip', '/usr/lib/python3.9', '/usr/lib/python3.9/lib-dynload']
pex: Activating PEX virtual environment from /tmp/tmptk7v2hk4: 0.1ms
pex: No entry point specified, dropping into interpreter
pex: Bootstrap complete, performing final sys.path modifications...
pex: PYTHONPATH contains:
pex: /tmp/tmptk7v2hk4
pex: * /usr/lib/python39.zip
pex: /usr/lib/python3.9
pex: /usr/lib/python3.9/lib-dynload
pex: /tmp/tmptk7v2hk4/.bootstrap
pex: * - paths that do not exist or will be imported via zipimport
no entrypoint being used here
pex: PEX.run invoking /usr/local/bin/python3.7 /tmp/process-executionA0Ms6e/.tmp/tmpo6joc6ld -c import hashlib, os, sys
python = os.path.realpath(sys.executable)
print(python)
hasher = hashlib.sha256()
with open(python, "rb") as fp:
for chunk in iter(lambda: fp.read(8192), b""):
hasher.update(chunk)
print(hasher.hexdigest())
IE: We're doing interpreter selection: https://github.com/pantsbuild/pants/blob/48f9ed14d5e5e487e007225aa4ef0b4ba985387b/src/python/pants/backend/python/util_rules/pex.py#L440-L478witty-crayon-22786
03/23/2021, 3:52 AMacceptable-guitar-79854
03/23/2021, 3:04 PMDetermine Python imports ...
but it did complete and then it worked just as fast as usualrapid-bird-79300
03/23/2021, 3:26 PMthen it worked just as fast as usualI'm assuming this is when the cache kicked in
acceptable-guitar-79854
03/23/2021, 3:32 PMrapid-bird-79300
03/25/2021, 2:57 AMFrom python3.7
-> FROM ubuntu:latest
(20.04
) result in wayyy faster runs. To the point where I think it's reasonable to run in CI.
Here's a thread where I was debugging different Ubuntu versions https://pantsbuild.slack.com/archives/C0105PY6BM5/p1616551044003200
Thank you to everyone who helped out with this issue! Looking forward to wearing my new favorite pants in production!hundreds-father-404
03/25/2021, 6:47 AM