https://pantsbuild.org/ logo
#general
Title
# general
r

rapid-bird-79300

03/23/2021, 12:23 AM
Hey Pants team! - I'm testing pants in a docker container for portability. I'm currently investigating an issue where pants takes significantly longer in the docker container than when running on host. Here are some stats I've observed: • host without cache (
2 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?
w

witty-crayon-22786

03/23/2021, 12:34 AM
hey Nick!
👋 1
is this Linux on Linux, or Linux on macOS ?
r

rapid-bird-79300

03/23/2021, 12:35 AM
Hey Stu! I'm testing locally on macOS. Also have been testing on linux via jenkins CI and experienced the same issues.
w

witty-crayon-22786

03/23/2021, 12:35 AM
mm. yea, Docker running Linux atop macOS is dramatically slower in my experience, although i haven’t tracked down why.
👍 1
using a VM via vagrant or virtualbox doesn’t experience the difference
f

fast-nail-55400

03/23/2021, 12:36 AM
do you have debug logs available? (via
-ldebug
)
I’m curious to know if the Pants run is rebuilding its venv or something else that would take a while without the cache.
r

rapid-bird-79300

03/23/2021, 12:38 AM
@fast-nail-55400 hmm let me try that and see what it produces
f

fast-nail-55400

03/23/2021, 12:39 AM
also I’d try mounting the
pip
cache into the container as well
👍 1
w

witty-crayon-22786

03/23/2021, 12:40 AM
@fast-nail-55400: by pip cache, do you mean
~/.cache/pants/named_caches
?
f

fast-nail-55400

03/23/2021, 12:40 AM
(
$HOME/Library/Caches/pip/wheels
on macOS)
@witty-crayon-22786: No the pip cache for when
./pants
bootstraps its venv
w

witty-crayon-22786

03/23/2021, 12:41 AM
hm. that should only affect startup time, right?
f

fast-nail-55400

03/23/2021, 12:42 AM
well if the container has to download every wheel to bootstrap, wouldn’t that take forever with a slow network connection?
that’s also why I’d like to see a log. it would help narrow down whether the slowness is in Pants bootstrap or whether it occurs once Pants is running
👍 2
r

rapid-bird-79300

03/23/2021, 12:44 AM
now running with debug mode in container now and taking some time on this line:
Copy code
00: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>
I haven't seen debug logs on my host yet so not sure if this is the start of the slowness or not.
f

fast-nail-55400

03/23/2021, 12:48 AM
also try disabling the dynamic UI with
--no-dynamic-ui
, this should enable the “straggler logging” which logs tasks that take longer than 60 seconds (checking every 30 seconds).
👍 2
r

rapid-bird-79300

03/23/2021, 12:49 AM
I have
dynamic_ui = false
set in my pants.toml. That's the same right?
f

fast-nail-55400

03/23/2021, 12:49 AM
yes, that is the same
r

rapid-bird-79300

03/23/2021, 12:50 AM
cool and it hasn't produced any logs after that last line I sent above
f

fast-nail-55400

03/23/2021, 12:50 AM
going by the log you pasted above, the Python imports step is just blocked. The local_cache_read tasks should not be taking that long.
essentially they are just reads from the filesystem (using the LMDB library)
have you tried making an empty docker volume and mounting that as the cache? that would be “without cache” but would change which filesystem Pants was reading/writing into
r

rapid-bird-79300

03/23/2021, 12:52 AM
yeah still hanging on that python import step. Here's what the container usage looks like
hmm haven't tried that yet. Let me give it a shot
f

fast-nail-55400

03/23/2021, 12:54 AM
the Python import step said “Waiting” which means it was blocked doing nothing until other tasks completed
just searching the web for “macOS docker storage slowness” turns up a bunch of blogs on the subject
seems to be a macOS/Docker issue
r

rapid-bird-79300

03/23/2021, 12:55 AM
yeah I just to note I experience the same issue on our jenkins CI pipeline
so perhaps a docker issue
f

fast-nail-55400

03/23/2021, 12:58 AM
do you get similar logs from the Jenkins CI pipeline?
👀 1
also what version of Pants are you using?
r

rapid-bird-79300

03/23/2021, 1:05 AM
I'm using the latest version
2.3.0
mounting an empty volume (or none at all) has no impact. Still take > 12 mins. Checking on jenkins now.
so if it isn't using a bind mount and still takes that long not sure if it's related to the IO.
f

fast-nail-55400

03/23/2021, 1:09 AM
I’m running on macOS myself. I can try replicating the result.
👍 1
r

rapid-bird-79300

03/23/2021, 1:10 AM
cool let me know how that goes. Here's my simple dockerfile I'm testing with
Copy code
FROM 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"]
noticing long runs on jenkins CI:
Copy code
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>
so looks to be the same
f

fast-nail-55400

03/23/2021, 1:17 AM
are you able to share more of the log?
also, trying to replicate locally, hit some permissions problems in the container I’m trying, so Pants won’t bootstrap its venv, I have some stuff to figure out there
👍 1
r

rapid-bird-79300

03/23/2021, 1:20 AM
here's more of the jenkins log (let me know if you need additional info)
Copy code
01: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>
in this case I'm not mounting any volumes to the container
f

fast-nail-55400

03/23/2021, 1:22 AM
do you have access to the kernel logs for the Jenkins worker machine? specifically, any I/O errors?
w

witty-crayon-22786

03/23/2021, 1:24 AM
just to confirm: when you say “long runs”, do you mean that it hangs there? or does it eventually make progress?
r

rapid-bird-79300

03/23/2021, 1:25 AM
here some more logs that occur that may be useful
@witty-crayon-22786 it seems to just hang there. I know from previous runs it will complete the goal as expected
@fast-nail-55400 I don't believe I have access to the kernel logs atm but can escalate later if needed.
f

fast-nail-55400

03/23/2021, 1:27 AM
do your containers have CPU limits?
I’m basically just coming up with possible ideas to check, no specific theory formulated
r

rapid-bird-79300

03/23/2021, 1:29 AM
I don't believe so and was thinking the same. I have allocated 8 CPUs for my local machine and I don't have any limits set.
f

fast-nail-55400

03/23/2021, 1:29 AM
the last line log suggests it is resolving python constraints
the cache reads all complete so, at least for Jenkins on Linux, slow storage is probably not the issue
r

rapid-bird-79300

03/23/2021, 1:30 AM
yeah those are logs outputed before it gets stuck at
01:12:46.80 [DEBUG] Starting: Determine Python imports for <redacted>
f

fast-nail-55400

03/23/2021, 1:31 AM
try
--pex-verbosity=9
(with
-ldebug
as well)
let that run, and let’s see what it says
👍 1
that will increase the logging for the pex run doing the resolution
w

witty-crayon-22786

03/23/2021, 1:32 AM
to be clear, if it seems to just hang for a while on a
Determine Python imports for
line, then it might … actually be hung, unfortunately.
that will invoke a process that usually takes on the order of 30 ms to run.
r

rapid-bird-79300

03/23/2021, 1:33 AM
yeah in this case it is 🙁 been running for over 20mins now
w

witty-crayon-22786

03/23/2021, 1:34 AM
i expect that
-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.
👍 1
r

rapid-bird-79300

03/23/2021, 1:36 AM
yeah that would make sense because it's the only difference from the previous runs, I'll stick to that. I definitely have time tomorrow to continue the investigation with you. Thank you for all your help today!
w

witty-crayon-22786

03/23/2021, 1:37 AM
sorry for the trouble with that flag. getting test coverage for logging is … challenging
r

rapid-bird-79300

03/23/2021, 1:39 AM
@fast-nail-55400 here's log output with the flags you suggested (
--pex-verbosity=9
and
-ldebug
):
now it seems to be hanging like before. Most likely will have to use
-linfo
as @witty-crayon-22786 mentioned
also testing the same command locally I see:
Copy code
...  
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
👀 2
w

witty-crayon-22786

03/23/2021, 1:45 AM
er
oh.
h

hundreds-father-404

03/23/2021, 1:45 AM
I think @acceptable-guitar-79854 has seen this on Windows WSL once?
w

witty-crayon-22786

03/23/2021, 1:46 AM
what does
Copy code
./pants help-advanced global | grep -A6 'local-parallelism='
report?
r

rapid-bird-79300

03/23/2021, 1:49 AM
Copy code
$ ./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.
f

fast-nail-55400

03/23/2021, 3:31 AM
the log has this in it:
No entry point specified, dropping into interpreter
cc @enough-analyst-54434 ^^
w

witty-crayon-22786

03/23/2021, 3:36 AM
…!
e

enough-analyst-54434

03/23/2021, 3:40 AM
Yeah - that's expected. If you notice in those logs the Pex command includes -c '...', just like a Python interpreter:
Copy code
$ 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
In particular the log is:
Copy code
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-L478
There are a few other items on my debug stack and lots of folks are already paged into this and looking at it so I'll step back unless pulled in,
👍 2
w

witty-crayon-22786

03/23/2021, 3:52 AM
same here. Mondays… sheesh
a

acceptable-guitar-79854

03/23/2021, 3:04 PM
@hundreds-father-404 that's right, on a fresh installation of pants on WSL it took a v long time (8 minutes) to
Determine Python imports ...
but it did complete and then it worked just as fast as usual
👀 1
r

rapid-bird-79300

03/23/2021, 3:26 PM
@acceptable-guitar-79854 interesting to see similar results.
then it worked just as fast as usual
I'm assuming this is when the cache kicked in
a

acceptable-guitar-79854

03/23/2021, 3:32 PM
yes
👍 1
r

rapid-bird-79300

03/25/2021, 2:57 AM
Okay finally have some resolution here! It turns out it came down to the OS. Changing my base image from
From 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!
👀 1
h

hundreds-father-404

03/25/2021, 6:47 AM
Thanks for the follow up Nick!
👍 1
6 Views