Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

File system performance improvements #1592

Open
yallop opened this issue May 5, 2017 · 348 comments
Open

File system performance improvements #1592

yallop opened this issue May 5, 2017 · 348 comments

Comments

@yallop
Copy link
Contributor

@yallop yallop commented May 5, 2017

Recent Docker versions (17.04 CE Edge onwards) add additional flags to the -v option for docker run that make it possible to specify the consistency requirements for a bind-mounted directory. The flags are

  • consistent: Full consistency. The container runtime and the host maintain an identical view of the mount at all times. This is the default.
  • cached: The host's view of the mount is authoritative. There may be delays before updates made on the host are visible within a container.
  • delegated: The container runtime's view of the mount is authoritative. There may be delays before updates made in a container are visible on the host.

In 17.04 cached is significantly faster than consistent for many workloads. However, delegated currently behaves identically to cached. The Docker for Mac team plans to release an improved implementation of delegated in the future, to speed up write-heavy workloads. We also plan to further improve the performance of cached and consistent.

We will post updates relating to Docker for Mac file sharing performance in comments to this issue. Users interested in news about performance improvements should subscribe here.

To keep the signal-to-noise ratio high we will actively moderate this issue, removing off-topic advertisements, etc. Questions about the implementation, the behaviour, and the design are very welcome, as are realistic benchmarks and real-world use cases.

@joemewes
Copy link

@joemewes joemewes commented May 6, 2017

A rudimentary real-worked example (Drupal 8):

Docker for Mac : Version 17.05.0-ce-rc1-mac8 (16582)
Mac-mini :: MacOS Sierra : 10.12.2 (16C67)

A simple command line curl test (taken average of 10 calls to URL) Drupal 8 clean install frontend:

old UNISON (custom synced container approach) Volume mount : 0.470s
standard Volume mount: 1.401s
new :cached Volume mount: 0.490

v.easy implementation to add to my compose.yaml files and happy with any delay between host/output using cached on host codebase.

@yallop Is there a rough/expected release date for 17.04 (stable) ?

@yallop
Copy link
Contributor Author

@yallop yallop commented May 8, 2017

@yallop Is there a rough/expected release date for 17.04 (stable)

The next stable version will be 17.06, and is likely to be released some time in June. There's been a change to the Docker version numbering scheme recently so that the numbers now indicate the release date, with stable releases every three months (March, June, September, December), and edge releases in the months in between. For example, 17.04 is the Edge release in April 2017 and 17.06 is the stable release in June 2017.

@joemewes
Copy link

@joemewes joemewes commented May 8, 2017

ok, thanks for that. do you expect 17.06 to contain at least the current edge implementation of :cached?

@yallop
Copy link
Contributor Author

@yallop yallop commented May 8, 2017

Yes, that's the plan.

@reinout
Copy link

@reinout reinout commented May 9, 2017

How should this work in a docker-compose.yml file? I tried appending :cached to the existing volume setting:

volumes:
  - .:/srv:cached

... but that got me an error (on OSX):

ERROR: Cannot start service my_service: Mounts denied: 9p: Stack overflow

(Docker version 17.05.0-ce-rc1, build 2878a85)

Note: having a global setting or environment variable to switch my local default to "cached" would also be fine (or rather preferable).

@DanielSchwiperich
Copy link

@DanielSchwiperich DanielSchwiperich commented May 9, 2017

The syntax looks correct @reinout
here's a stripped but working example docker-compose.yml

version: '2'
services:
  php:
    image: php:7.1-fpm
    ports:
      - 9000
    volumes:
      - .:/var/www/project:cached

tested on Docker version 17.05.0-ce-rc1, build 2878a85

@reinout
Copy link

@reinout reinout commented May 9, 2017

Your example works. My own one still not (even after really making sure there were no left-over old mounted volumes). So I rebooted. Afterwards, it worked.

So: a reboot might be needed if you've run a docker-compose before upgrading docker to the latest version. Possibly related: I switched from docker stable to edge.


Is there a possibility of a global setting? I don't really want to add this option to the docker-compose.yml that all my linux colleagues are using.

@DanielSchwiperich
Copy link

@DanielSchwiperich DanielSchwiperich commented May 9, 2017

not as far as I know. When you linux colleagues are running edge the flag should work.

Another workaround would be (that's what we do right now for separating linux and mac volume mounting )
to just put the mount settings for mac in a separate file, like docker-compose-mac.yml and then run docker-compose -f docker-compose.yml -f docker-compose.mac.yml up -d

See https://docs.docker.com/compose/extends/

@carn1x
Copy link

@carn1x carn1x commented May 9, 2017

@reinout You could use an additional compose file to override that of your colleagues? For instance, we have:

docker-compose.yml:

version: '2'

services:

  build_docs:
    image: docs/sphinx
    build: .
    environment:
      - DOCS_NAME='docs'
      - SRC_DIR=src
      - DST_DIR=build
    volumes:
      - "./../../docs/dev:/docs"
    command: /docs/source /docs/build

and volumes-cached.yml:

services:
  build_docs:
    volumes:
      - "./../../docs/dev:/docs:cached"

Which can be run with:

$ docker-compose -f docker-compose.yml -f volumes-cached.yml up
@reinout
Copy link

@reinout reinout commented May 9, 2017

Yes, I could do that. But.... I'd have to do that for each of the 12 docker-compose projects. And I'd have to keep it in sync with changes to the "master" docker-compose.yml.

As an intermediary measure: fine. Long term: no, as it is not very don't-repeat-yourself :-)

If someone wants to enable the "cached" behaviour, that person probably wants to use it for all/most of the dockers. Would it make sense as a config setting in the Docker app itself? In the preferences' "File sharing" tab? (This should probably be its own ticket, I assume?)

@yallop
Copy link
Contributor Author

@yallop yallop commented May 9, 2017

@reinout: :cached is supported across platforms, so there should be no issue in adding it directly to compose files.

@reinout
Copy link

@reinout reinout commented May 9, 2017

Provided that everybody uses the latest edge version, right? And it seems a bit strange to add an option that only has effect on osx to everybody's docker-compose.yml.

Anyway, it works for now. I won't drag the signal/noise ratio further down :-)

@matthewjosephtaylor
Copy link

@matthewjosephtaylor matthewjosephtaylor commented May 10, 2017

mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ time dd if=/dev/zero of=./output bs=8k count=40k; rm ./output
40960+0 records in
40960+0 records out
335544320 bytes transferred in 1.300857 secs (257941007 bytes/sec)

real	0m1.320s
user	0m0.012s
sys	0m0.564s
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ docker run -it --rm -v "$(pwd):/host-disk" ubuntu /bin/bash 
root@4e9c8bc5e5c1:/# cd /host-disk/
root@4e9c8bc5e5c1:/host-disk# time dd if=/dev/zero of=./output bs=8k count=40k; rm ./output
40960+0 records in
40960+0 records out
335544320 bytes (336 MB, 320 MiB) copied, 10.7496 s, 31.2 MB/s

real	0m10.756s
user	0m0.050s
sys	0m1.090s
root@4e9c8bc5e5c1:/host-disk# exit
exit
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ docker run -it --rm -v "$(pwd):/host-disk:cached" ubuntu /bin/bash 
root@597dc640bdeb:/# cd /host-disk/
root@597dc640bdeb:/host-disk# time dd if=/dev/zero of=./output bs=8k count=40k; rm ./output
40960+0 records in
40960+0 records out
335544320 bytes (336 MB, 320 MiB) copied, 11.1683 s, 30.0 MB/s

real	0m11.172s
user	0m0.060s
sys	0m1.080s
root@597dc640bdeb:/host-disk# exit
exit
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ docker run -it --rm -v "$(pwd):/host-disk:delegated" ubuntu /bin/bash 
root@985e4143053b:/# cd /host-disk/
root@985e4143053b:/host-disk# time dd if=/dev/zero of=./output bs=8k count=40k; rm ./output
40960+0 records in
40960+0 records out
335544320 bytes (336 MB, 320 MiB) copied, 12.1589 s, 27.6 MB/s

real	0m12.165s
user	0m0.080s
sys	0m1.000s
root@985e4143053b:/host-disk# exit
exit
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ docker run -it --rm -v "$(pwd):/host-disk:consistent" ubuntu /bin/bash 
root@3377ae356124:/# cd /host-disk/
root@3377ae356124:/host-disk# time dd if=/dev/zero of=./output bs=8k count=40k; rm ./output
40960+0 records in
40960+0 records out
335544320 bytes (336 MB, 320 MiB) copied, 12.5944 s, 26.6 MB/s

real	0m12.601s
user	0m0.060s
sys	0m0.980s
root@3377ae356124:/host-disk# exit
exit
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ docker --version
Docker version 17.05.0-ce, build 89658be
mtaylor(mjt)@mtaylor:~/tmp/docker-disk-perf-test$ 

Perhaps my expectations on how this works are unreasonable, or I'm doing something wrong. Above are some simple disk performance tests and I'm not seeing any differences.

Would be interested in knowing if my expectations, or use of the flag is incorrect.

@barat
Copy link

@barat barat commented May 11, 2017

@matthewjosephtaylor ... :cached won't improve dd tests ... for this, you need to check for :delegated to rollout :)

@ToonSpinISAAC
Copy link

@ToonSpinISAAC ToonSpinISAAC commented May 23, 2017

The issue text says:

delegated: The container runtime's view of the mount is authoritative. There may be delays before updates made in a container are visible on the host.

Does this mean that if I were to use delegated (or cached for that matter) that syncing would strictly be a one-way affair?

In other words, to make my question clearer, let's say I have a codebase in a directory and I mount this directory inside a container using delegated. Does this mean that if I update the codebase on the host, the container will overwrite my changes?

What I understood until now was, that using for instance delegated, would keep syncing "two-way", but make it more efficient from the container to the host, but the text leads me to believe that I may have misunderstood, hence the question.

@geerlingguy
Copy link

@geerlingguy geerlingguy commented May 24, 2017

Just posting another data point:

  • Drupal codebase volume with rw,delegated on Docker Edge (for now, it's only using the cached option though): 37 requests/sec
  • Drupal codebase volume with rw (and no extra options): 2 requests/sec

Drupal 8 is ~18x faster if you're using a Docker volume to share a host codebase into a container, and it's pretty close to native filesystem performance.

With cached, Drupal and Symfony development are no longer insanely painful with Docker. With delegated, that's even more true, as operations like composer update (which results in many writes) will also be orders-of-magnitude faster!

@kostajh
Copy link

@kostajh kostajh commented May 24, 2017

I'm seeing good results for running a set of Behat tests on a Drupal 7 site:

On Mac OS, without :cached:

10:02 $ docker exec clientsite_php bin/behat -c tests/behat.yml --tags=~@failing -f progress
...................................................................... 70
...................................................................... 140
...................................................................... 210
...................................................................... 280
.................................................

69 scenarios (69 passed)
329 steps (329 passed)
11m26.20s (70.82Mb)

With :cached:

09:55 $ docker exec clientsite_php bin/behat -c tests/behat.yml --tags=~@failing -f progress
...................................................................... 70
...................................................................... 140
...................................................................... 210
...................................................................... 280
.................................................

69 scenarios (69 passed)
329 steps (329 passed)
4m33.77s (63.33Mb)

On Travis CI (without :cached):

$ docker exec clientsite_php bin/behat -c tests/behat.yml --tags=~@failing -f progress
...................................................................... 70
...................................................................... 140
...................................................................... 210
...................................................................... 280
.................................................
69 scenarios (69 passed)
329 steps (329 passed)
4m7.07s (55.01Mb)

On Travis CI (with :cached):

247.12s$ docker exec cliensite_php bin/behat -c tests/behat.yml --tags=~@failing -f progress
...................................................................... 70
...................................................................... 140
...................................................................... 210
...................................................................... 280
.................................................
69 scenarios (69 passed)
329 steps (329 passed)
4m6.71s (55.01Mb)

Nice work, Docker team! 👏

@carn1x
Copy link

@carn1x carn1x commented Jun 5, 2017

Is it expected that both :cached and :delegated can be combined or will they be mutually exclusive?

@dsheets
Copy link
Contributor

@dsheets dsheets commented Jun 5, 2017

@ToonSpinISAAC both :cached and (when it lands) :delegated perform two-way "syncing". The text you cite is saying that, with :cached, the container may read stale data if it has changed on the host and the invalidation event hasn't propagated yet. With :cached, the container will write-through and no new write-write conflicts can occur (POSIX still allows multiple writers). Think of :cached as "read caching". With :delegated, if the container writes to a file that write will win even if an intermediate write has occurred on the host. Container writes can be delayed indefinitely but are guaranteed to persist after the container has successfully exited. flush and similar functionality will also guarantee persistence. Think of :delegated as "read-write caching". Even under :delegated, synchronization happens in both directions and updates may occur rapidly (but don't have to). Additionally, you may overlap :cached and :delegated and :cached semantics will override :delegated semantics. See https://docs.docker.com/docker-for-mac/osxfs-caching/#delegated guarantee 5. If you are using :delegated for source code but your container does not write to your code files (this seems unlikely but maybe it auto-formats or something?), there is nothing to worry about. :delegated is currently the same as :cached but will provide write caching in the future.

@carn1x :cached and :delegated (and :default and :consistent) form a partial order (see https://docs.docker.com/docker-for-mac/osxfs-caching/#semantics). They can't be combined but they do degrade to each other. This allows multiple containers with different requirements to share the same bind mount directories safely.

@lmakarov
Copy link

@lmakarov lmakarov commented Jun 6, 2017

From within a container is there a way to tell which flag was applied for a volume?

I'm getting the same output from mount regardless of the flag used. Is there another way to check?

$ mount | grep osxfs
osxfs on /var/www/project type fuse.osxfs (rw,nosuid,nodev,relatime,user_id=0,group_id=0,allow_other,max_read=1048576)
Version 17.06.0-rc1-ce-mac13 (18169)
Channel: edge
2425473dc2
@dsheets
Copy link
Contributor

@dsheets dsheets commented Jun 6, 2017

@lmakarov /Applications/Docker.app/Contents/MacOS/com.docker.osxfs state should show you the host directories that are mounted into containers and their mount options. For instance, after I run docker run --rm -it -v ~:/host:cached alpine ash, I then see:

$ /Applications/Docker.app/Contents/MacOS/com.docker.osxfs state
Exported directories:
 - /Users to /Users (nodes_/Users table size: 62)
 - /Volumes to /Volumes (nodes_/Volumes table size: 0)
 - /tmp to /tmp (nodes_/private/tmp table size: 9)
 - /private to /private (nodes_/private table size: 0)
Container-mounted directories:
 - /Users/dsheets into b8f7765665782501bc1a099f1898911b7eb393b08930be638545a55fd06e420e (state=cached)
@ToonSpinISAAC
Copy link

@ToonSpinISAAC ToonSpinISAAC commented Jun 12, 2017

Thanks for taking the time to clarify and explain @dsheets!

@gondalez
Copy link

@gondalez gondalez commented Jun 13, 2017

Is there any indication from the high sierra dev beta of how this (and docker mac in general) will work under APFS?

Sorry if this is off-topic but it's a question I keep wanting to ask every time I see a new message here :)

@WillSquire
Copy link

@WillSquire WillSquire commented Jun 16, 2017

Unable to get @DanielSchwiperich's example working? Retrieving the error:

invalid spec: .:/var/www/project:cached: unknown option: cached

It doesn't like version being set to 2 either. Perhaps I'm missing something? Currently running 17.06.0-rc2-ce-mac14

@27Bslash6
Copy link

@27Bslash6 27Bslash6 commented Jun 18, 2017

@WillSquire What version of docker-compose are you using?

@metaskills
Copy link

@metaskills metaskills commented Oct 6, 2020

A story that is repeated time and time again recently. The Mutagen build rocks and for many solved years of frustration.

Check to that. I want something that just works. It would be nice if Docker on Mac was usable by default.

@leehambley
Copy link

@leehambley leehambley commented Oct 7, 2020

This thread is getting silly, has anyone actually profiled the various language/framework combos so that we commonly see here?

The mutagen option performed horribly for our admittedly large (105,000 files in the project dir) option. The gRPC FUSE one is also terrible. We happen to "know" that bootsnap (tries to cache Rails byte code files) actually slows our system booting because the syscalls checking for the cache status are slower than just loading it, let's say CPU vs. I/O bound. The least-worst option for our MacOS using colleagues is NFS with aggressive caching and disabling a/mtime tracking. For Linux users on Docker, it's actually fine (no surprise)

If we could agree on what strace incantation we could use to profile various applications start-up times, we might know better what we're aiming for.

strace -f -T -e trace=file -o ruby-2.4.x-rails-2.5-ubuntu-linux-docker-whatever <my command here>

(-f follows forked children, -T times syscalls, -e trace=file should trace filesystem related stuff (alias for something like exec,open,stat,chdir,read,write,accept,creat,link,unlink,mknod,chmod,chown,lseek,mount,umount,fstat,access,dup,pipe,chroot,lstat,symlink), -o specify an output file )

Should get us pretty close to a profile of what syscalls various frameworks are making when they boot and/or serve requests, hot and cold caches, and regular requests (i.e wordpress which I believe does a lot in the filesystem when actually serving a request).

For a boot of our app 2,137,662 file system related syscalls were made, 1,954,046 calls to open which all but 51,778 failed with ENOENT (Rails looking for files at the places they maybe exist on the class path), each failed call took nominally ~0.000056 seconds (so about 1:30 minutes spent looking for non-existent files).

Of the remaining ~180-200k calls about 150,000 are to stat/lstat, surprisingly with nearly 8,000 calls to rename all from bootstrap which take nearly a second.

Note, all the timings here are for me on Fedora Linux 33 on a x86_64 machine (Dell XPS 13" with an SSD).

My strace output is 345mbs and contains a few things (file paths, mostly) that maybe leak information about my app, so I'm not comfortable posting it in the RAW, and I wonder how useful it is. If people wanted to provide me in private with their strace outputs and information about their apps, and plugins/etc that they use, I'd be willing to write some kind of script to profile these.

@metaskills
Copy link

@metaskills metaskills commented Oct 8, 2020

If by silly you mean we are bouncing back and forth between usable to unusable file systems I would agree. Data from my post here docker/roadmap#7 (comment) which is a simple outside/in timing to load a very basic Rails/JavaScript project.

Stable (osxfs) Edge2.4.1.0 (gRPC-FUSE) Edge2.3.4.0 (mutagen)
125s 123s 4s
@stephen-turner
Copy link

@stephen-turner stephen-turner commented Oct 8, 2020

@metaskills I'm not sure you read @leehambley's comment carefully: he said "The mutagen option performed horribly" for his project.

We are not happy with the filesystem performance and we are still working on it. I've replied in more detail at docker/roadmap#7 (comment).

@metaskills
Copy link

@metaskills metaskills commented Oct 8, 2020

@stephen-turner @leehambley Most likely, I'm going cross eye'ed reading all this stuff :) and I appreciate the reply. Thanks everyone.

@ryansch
Copy link

@ryansch ryansch commented Oct 8, 2020

@leehambley I'm running mutagen sync with a rails app that contains ~13,700 files and the performance is fantastic. I've spent a lot of time working on the exact paths that I want mutagen to sync and which ones are either ignored or are in a separate docker volume.

I'm not sure if my perf is better because I have fewer files or if it's due to the path config.

@jaequery
Copy link

@jaequery jaequery commented Oct 8, 2020

@jaequery
Copy link

@jaequery jaequery commented Oct 8, 2020

@stephen-turner
Copy link

@stephen-turner stephen-turner commented Oct 8, 2020

We are looking at it.

@leehambley
Copy link

@leehambley leehambley commented Oct 8, 2020

If by silly you mean we are bouncing back and forth between usable to unusable file systems I would agree

Actually that nobody is talking about the profile of the requirements we have. Possibly mutagen was screaming fast because it answers all stat/lstat syscalls instantly with an epoch timestamp, who knows. Without knowing the profile of filesystem usage between Ruby, Node and the PHP users (I don't think other ecosystems were strongly represented in this thread) we're not really having an objective conversation that can help the Docker team, nor anyone else evaluate which solution might be best.

I don't have access to a Mutagen set-up, but here's a few bits of data from comparing booting my app on a 2020 MPB with SSD, and my laptop (the figures I posted a day ago). Mainline Docker latest version in both cases.

On average a filesystem related syscall seems to be 8-12× slower under osxfuse than native Linux. What I find strange however is that we don't really need real filesystem guarantees here, for a development filesystem we want fast reliable reads, metadata isn't super critical (if we have inotify events) and I suspect most writes in the containers to shared filesystems don't need to be entirely durable/consistently visible to the host.

Any deliberate design would come up with something like Mutagen, some highly optimized development focused filesystem. However without understanding the exact trade-offs, and requirements of languages and frameworks, us all just butting in with "Mutagen works for me", or "gRPC is too slow" doesn't help. strace is the tool we need, if we know that Ruby with Rails < 6 makes an ABSURD number of calls to open (it searches every path on the load path for every file, in our app with 384 gem dependencies that means ~250 failed calls to open for each of the hundreds of files we include), I suspect that Mutagen can't really improve the speed of an "open" call, or, indeed maybe it can, because it has a hot memory cache of what files are synched.

My ruby app also make a mind bogglingly high number of calls to stat and lstat, I'm quite sure that's because of bootsnap (tries to cache byte code to start faster), those syscalls in particular are pretty slow on osxfuse, compared to being 70 microseconds or less on native OS. I would, for example be willing to trade reliable stat/lstat calls for filesystem events, and ditch the caching, that's the situation my NFS using colleagues have where they can't rely on the a/mtime anyway, because we have it turned off.

@jaequery I speak only for myself, but requiring manual steps "go sudo edit the /etc/exports file" and all the other hoops mac users in particular have to jump through for NFS, which may, if I'm not mistaken even include disabling some SIP (system integrity protection?) to edit files under /etc, adding some other thing to the mix additionally is just raising the barrier to entry, when it's already borderline. Our team includes people who prefer to develop remotely on a linux VM using some terminal editor, because using Docker4Mac is just unacceptably slow.

@ryansch are you using Rails 6 or above? They significantly reduced the number of filesystem calls when they adopted Zeitwerk which is fantastic, our app is regrettably Rails 5.2 and we're struggling to migrate to 6.x as time permits. I had the pleasure to speak to Xavi who wrote Zeitwerk just the other day, and he confirmed that Zeitwerk doesn't scan every directory on the load path looking for files. It searches once, and requires relatively strict confirmance to the naming conventions to find files without pummelling the disk

@ryansch
Copy link

@ryansch ryansch commented Oct 8, 2020

@leehambley We're still on Rails 5.2 as well. I'm also quite excited to finish that upgrade.

@coredumperror
Copy link

@coredumperror coredumperror commented Oct 8, 2020

@leehambley I'd be happy to do some profiling for my use case, as I am personally seeing a monumental performance improvement with mutagen in my Django-based site (running on the Wagtail framework), and I'm actually seeing a significant performance loss with gRPC-FUSE.

Unfortunately, most of what you said in your comment went over my head, as I have never profiled filesystem performance before. If you could describe what would need to be done to get useful information about the difference between mutagen, osxfs, and gRPC-FUSE, I'd be happy to gather that info for my code shop's main project. Especially since all of us develop on Mac, and we've been badly chaffing for years under the frustrating performance loss incurred by osxfs.

One other thing that confuses me is this talk of how mutagen is "hard to use". I don't get it. I found out about this yesterday, when I updated to the newest Stable and saw the new gRPC-FUSE thing, then found the docker/roadmap#7 post while looking for info about it. So I installed Docker for Mac v2.3.4.0, did absolutely no other configuration, and got a ~10x performance improvement.

What's so "hard to use" about mutagen?

@jaequery
Copy link

@jaequery jaequery commented Oct 8, 2020

@leehambley
Copy link

@leehambley leehambley commented Oct 8, 2020

So the only thing to profile the filesystem is to do something like the strace line I posted above, that gives really detailed info, or, something like this, in the example bundle exec rails runner 'puts "hello"' is the smallest thing that boots my app and then exists.

# strace -c -f -e trace=file bundle exec rails runner 'puts "hello"'
strace: Process 61 attached
strace: Process 62 attached
/app/.bundle/gems/avro-1.8.2/lib/avro/schema.rb:350: warning: constant ::Fixnum is deprecated
/app/.bundle/gems/avro-1.8.2/lib/avro/schema.rb:350: warning: constant ::Fixnum is deprecated
strace: Process 63 attached
strace: Process 64 attached
strace: Process 65 attached
strace: Process 66 attached
strace: Process 67 attached
strace: Process 68 attached
strace: Process 69 attached
strace: Process 70 attached
strace: Process 71 attached
strace: Process 72 attached
strace: Process 73 attached
strace: Process 74 attached
strace: Process 75 attached
strace: Process 76 attached
strace: Process 77 attached
strace: Process 78 attached
strace: Process 79 attached
strace: Process 80 attached
strace: Process 81 attached
hello
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 96.26    5.319363           3   1930681   1900574 open
  2.24    0.123651           2     65904     54253 stat
  1.47    0.081192           2     36450       556 lstat
  0.01    0.000703           4       174       142 access
  0.01    0.000406           1       324           getcwd
  0.01    0.000278           2       180           chdir
  0.00    0.000095          16         6           execve
  0.00    0.000074          74         1           readlink
  0.00    0.000005           5         1         1 mkdir
------ ----------- ----------- --------- --------- ----------------
100.00    5.525767               2033721   1955526 total

This table shows that I spent (these times are native Docker on linux) 96% of the time in calls to open, and how many of those calls failed. I imagine this is why my app boots slowly, it doesn't really matter how fast the filesystem is, because I spend 5 seconds looking for 1.93M non-existent files.

To run this, you just need strace in your container, and to run it as root. For me on Debian derivative Ubuntu, that means apt-get install strace, probably there's other ways for Arch, or Alpine, I've no idea, but strace has been standard Linux fare for three decades, so it will be there, somehow.

@coredumperror
Copy link

@coredumperror coredumperror commented Oct 8, 2020

Hmmm, I don't know if there's a cli command I can run that will exercise the primary issue that I have with osxfs, which is very slow request times, specifically in the Wagtail admin console. It seems that the requests are slowed down because the admin is very template-heavy, so it loads a lot more files form disk than a non-admin request for a regular public page (which don't seem to suffer much from filesystem slowdown).

I'll see if I can find a manage.py command that hits the filesystem especially hard, though.

@cweagans
Copy link

@cweagans cweagans commented Oct 8, 2020

I speak only for myself, but requiring manual steps "go sudo edit the /etc/exports file" and all the other hoops mac users in particular have to jump through for NFS, which may, if I'm not mistaken even include disabling some SIP (system integrity protection?) to edit files under /etc, adding some other thing to the mix additionally is just raising the barrier to entry, when it's already borderline. Our team includes people who prefer to develop remotely on a linux VM using some terminal editor, because using Docker4Mac is just unacceptably slow.

@leehambley AFAIK, editing /etc/exports does not require disabling SIP. Since Docker for Mac already requests admin privs to do stuff during setup, it seems reasonable for it to auto-configure /etc/exports during that process as well. No need for it to be a manual thing.

@leehambley
Copy link

@leehambley leehambley commented Oct 8, 2020

Yeah, that's tricky, you can do the following then, if you know the pid of the thing which is slow, you can run the similar strace line with -p <pid>, that'll attach to a pre-existing pid (i.e literally just # strace -c -f -e trace=file -p <thepid>), quickly make a request, back to the container and hit ctrl+c, and it should dump a similar report.

@coredumperror
Copy link

@coredumperror coredumperror commented Oct 9, 2020

@leehambley Unfortunately, I'm unable to get strace -c -f -e trace=file -p <thepid> (replacing the pid with one of the ones for the gunicorn server that's actually running the code) to work. No matter what I do, even when I'm running as root, I get the following error message:
strace: attach: ptrace(PTRACE_SEIZE, 27): Operation not permitted

Everything I've read says that being root should prevent that, but even changing my gunicorn config to force it to run as root, rather than the 'gunicorn' user, it still gave that error. :(

However, I was able to profile my project's full test suite, which tests a lot of the admin pages, and does a lot of file accessing.

I got the following output with v2.3.4.0 and mutagen:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 97.13    6.939633           4   1723949   1708333 open
  2.21    0.157869           7     22358      4850 stat
  0.35    0.025218          92       274           unlinkat
  0.12    0.008623           4      1980         1 openat
  0.07    0.005040          30       163        94 access
  0.06    0.004435           4      1043         7 lstat
  0.03    0.002372           8       274           newfstatat
  0.01    0.000653          34        19         3 unlink
  0.01    0.000548          14        38        16 execve
  0.00    0.000244           7        34         2 readlink
  0.00    0.000084          14         6           mkdir
  0.00    0.000072           2        30           getcwd
  0.00    0.000066          66         1           rmdir
  0.00    0.000025          12         2         2 statfs
------ ----------- ----------- --------- --------- ----------------
100.00    7.144882               1750171   1713308 total

I got this with v2.4.1.0 and osxfs:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 98.71   19.380616          11   1725115   1709213 open
  1.02    0.200762           8     22371      4850 stat
  0.08    0.016615           8      1980         1 openat
  0.08    0.015589          57       273           unlinkat
  0.04    0.007124           6      1043         7 lstat
  0.02    0.004359          26       163        94 access
  0.02    0.003557          13       273           newfstatat
  0.02    0.003258          23       136           symlink
  0.00    0.000499          26        19         3 unlink
  0.00    0.000471          12        38        16 execve
  0.00    0.000347          10        34         2 readlink
  0.00    0.000176           5        30           getcwd
  0.00    0.000140          17         8           mkdir
  0.00    0.000015          15         1           rmdir
  0.00    0.000014           7         2         2 statfs
------ ----------- ----------- --------- --------- ----------------
100.00   19.633542               1751486   1714188 total

I got this with v2.4.1.0 and gRPC-FUSE:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.10   37.814068          21   1725115   1709213 open
  0.71    0.270399          12     22371      4850 stat
  0.06    0.023504          86       273           unlinkat
  0.06    0.023280          11      1980         1 openat
  0.03    0.011639          11      1043         7 lstat
  0.02    0.007463          27       273           newfstatat
  0.01    0.003673          22       163        94 access
  0.01    0.002601          19       136           symlink
  0.00    0.000652          34        19         3 unlink
  0.00    0.000586          15        38        16 execve
  0.00    0.000480          14        34         2 readlink
  0.00    0.000303          37         8           mkdir
  0.00    0.000287           9        30           getcwd
  0.00    0.000049          49         1           rmdir
  0.00    0.000047          23         2         2 statfs
------ ----------- ----------- --------- --------- ----------------
100.00   38.159031               1751486   1714188 total

So if I'm reading that right, mutagen is about 2.5x faster than osxfs, and about 5.5x faster than gRPC-FUSE, for this particular task.

I'd love to figure out how to properly attach to gunicorn and profile a page request, though. From manual timing tests with a stopwatch, I see a refresh on a particular specific admin take 8-10 seconds on osxfs, 17-20 seconds on gRPC-FUSE, and ~3 seconds on mutagen.

@mrmachine
Copy link

@mrmachine mrmachine commented Oct 9, 2020

@coredumperror @leehambley can you run the same strace tests with Dinghy (NFS)?

@coredumperror
Copy link

@coredumperror coredumperror commented Oct 9, 2020

@mrmachine Sorry, I gave it my best shot, but I couldn't get Dinghy to work at all. I tried the xhyve VM first, and it didn't work (I got an error about it not being able to convert a UUID to a MAC). Then I tried virtualbox, and it got a lot further (started the NFS mount), but then it timed out and crashed, too.

Maybe it's because I'm on Catalina? 🤷

@metaskills
Copy link

@metaskills metaskills commented Oct 9, 2020

Actually that nobody is talking about the profile of the requirements we have.

@leehambley I super appreciate your perspective and level of knowledge but I do want stay high level and report simple numbers. For example, my test Rails app has no bootsnap, etc. I wonder what the Docker team is actually testing when they make claims like:

Docker Desktop now uses gRPC-FUSE for file sharing by default. This has much faster file sharing and uses much less CPU than osxfs, especially when there are lots of file events on the host.

Are they doing a micro benchmarks like you see in JavaScript sites which dont really stack up to real world usage? I feel they should have a set of common language specific projects that exercise that vs asking all of us to measure things. I'd be willing to contribute a very basic Rails project that I think exemplifies most peoples use cases. Maybe I am misunderstand what you are asking or trying to help with. If so, I apologize. But from my perspective "does loading a Rails console or dev server" work fast or not. For years that has been false, for a brief moment it was true... then false. How is the Docker team measuring success here and with what test harness?

@leehambley
Copy link

@leehambley leehambley commented Oct 9, 2020

@coredumperror check https://blog.packagecloud.io/eng/2015/11/15/strace-cheat-sheet/#strace-ptrace_traceme-eperm-operation-not-permitted please that should fix it. (probably this means in the docker4mac VM, not on your host host)

@metaskills I agree with you in principle, but not in practice. We should be able to discuss whether or not n seconds is acceptable or not, but getting to a smaller value of n for more people, more of the time will need us to understand a bit better the lower level requirements (stracing various set-ups) and optimize accordingly. I'm afraid mutagen is faster at some things (e.g open/read) at the expense of being slower at other things (starting and stopping a Docker exec call, or noticing filesystem events). Mutagen is as fast as it is, because it's not really a shared filesystem, per-se, it's more like rsync.

I left a very long comment about differing trade-offs here docker/roadmap#7 (comment) which you may want to read, it touches on some of the things we've discussed here, but puts more emphasis on the difficulty of balancing the three aspects of perceived performance from a filesystem (as I see them)

@coredumperror if you want ping me off-line, and we can set-up a video call and I'll try and walk you through it. Contact info on my profile page.

@RileyMathews
Copy link

@RileyMathews RileyMathews commented Oct 9, 2020

I'm also experiencing file system performance issues while working on some rails/node applications inside docker. Interesting for a node project, in particular, I'm getting different performance gains/losses on GRPC-fuse depending on which npm command I'm running, maybe it has something to do with the CPU bound vs file bound tasks? I'll try to hop in here and provide some metrics I have gathered using strace. I am trying to figure out how to get a similar report running these commands on native MacOS, but I can't seem to get a similar command to strace working right now. I'm also unsure if the total time reported by strace is correct, as prefixing the entire strace command with 'time' usually reports somewhere in the averages I put next to each command. If someone can point out some mistake I'm making I'll be happy to re run these tests.

  • running docker 2.4.1.0 with GRPC-fuse

In centos based conatiner running a fairly slim node app...

  • strace -c -f -e trace=file npm run test (runs 46 jest tests across 5 test files, usually takes .5-2 seconds native, 10-15 seconds in container)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 59.87    1.021956          18     55325     24158 statx
 22.21    0.379124          26     14226      1447 openat
 16.80    0.286718           9     30181       254 lstat
  0.52    0.008927          23       380       192 open
  0.27    0.004691          22       211       145 stat
  0.18    0.003122          21       145        43 access
  0.08    0.001372          29        46        28 execve
  0.02    0.000348          26        13           readlink
  0.01    0.000249          24        10           newfstatat
  0.01    0.000194           7        26           getcwd
  0.00    0.000077          19         4         4 statfs
  0.00    0.000063          63         1           rename
  0.00    0.000058          58         1           chown
  0.00    0.000052          13         4         4 mkdir
  0.00    0.000044           6         7           chdir
  0.00    0.000030          30         1           chmod
------ ----------- ----------- --------- --------- ----------------
100.00    1.707025                100581     26275 total
  • npm run build-assets (builds production assets using webpack bundling JS/SCSS, takes 2-5 seconds native, 20-25 seconds in container)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 59.65    1.181004          28     40894     15136 statx
 23.96    0.474324          56      8438      1776 openat
 13.95    0.276198         175      1571      1561 readlink
  2.17    0.042984          32      1338      1191 access
  0.15    0.002990          31        94        40 open
  0.06    0.001240          28        43        19 stat
  0.05    0.000991          47        21        16 execve
  0.00    0.000076           9         8           getcwd
  0.00    0.000067          67         1           rename
  0.00    0.000043          43         1           chdir
  0.00    0.000035          35         1           chown
  0.00    0.000029          29         1           chmod
  0.00    0.000025           6         4         4 mkdir
  0.00    0.000000           0         2           unlink
------ ----------- ----------- --------- --------- ----------------
100.00    1.980006                 52417     19743 total
  • running docker 2.4.1.0 without GRPC-fuse

  • strace -c -f -e trace=file npm run test (15 - 18 seconds)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 59.96    0.819545          14     56126     24407 statx
 24.88    0.340103          23     14530      1496 openat
 13.95    0.190737           6     30181       254 lstat
  0.46    0.006317          16       387       193 open
  0.34    0.004620          30       151        50 access
  0.23    0.003169          14       212       145 stat
  0.07    0.000984          18        52        28 execve
  0.03    0.000470          24        19           readlink
  0.02    0.000323          10        32           getcwd
  0.01    0.000140          11        12           chdir
  0.01    0.000129          32         4           rename
  0.01    0.000127          12        10           newfstatat
  0.01    0.000080          20         4           chmod
  0.01    0.000070          17         4           chown
  0.00    0.000051           7         7         6 mkdir
  0.00    0.000049          12         4         4 statfs
------ ----------- ----------- --------- --------- ----------------
100.00    1.366914                101735     26583 total
  • strace -c -f -e trace=file npm run build-assets (35 - 40 seconds)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 65.75    1.196233          29     40894     15136 statx
 20.08    0.365289          43      8438      1776 openat
 11.34    0.206362         131      1571      1561 readlink
  2.55    0.046407          34      1338      1191 access
  0.16    0.002837          30        94        40 open
  0.07    0.001344          31        43        19 stat
  0.03    0.000502          23        21        16 execve
  0.01    0.000195          97         2           unlink
  0.01    0.000125          15         8           getcwd
  0.01    0.000122          30         4         4 mkdir
  0.00    0.000033          33         1           rename
  0.00    0.000017          17         1           chown
  0.00    0.000015          15         1           chmod
  0.00    0.000000           0         1           chdir
------ ----------- ----------- --------- --------- ----------------
100.00    1.819481                 52417     19743 total
@adriadrop
Copy link

@adriadrop adriadrop commented Oct 9, 2020

Not hating apple and still think its nice system but I gave up after years of riding on docker and vagrant and having less than optimal performance (and probably always will be like that). I bought dell xps tried a bit of windows and WSL2 but had some problems with composer and finally settled for linux, which makes most sense in the end as I(we) deploy things mostly on linux anway. Few days and you can get used to ubuntu very fast, nothing missing that I am used to on OSX . Docker runs smooth as it can be and I don think there will be anymore issues with it, I almost forget I have it how smooth it goes. As I work on drupal where number of files I use is around 35000 this will always be problematic on mac os, so I would recommend to go full linux. If not stop waisting your time with virtualizations on Mac and just use native build for some MAMP, MNMP stack. I saw very good example from Laravel community where there is a tool to build it locally which will run as fast as native build on linux https://laravel.com/docs/8.x/valet

@havoc-io
Copy link

@havoc-io havoc-io commented Oct 13, 2020

Copying from this comment:

Mutagen author here. I fully support Docker's decision and direction here, but I also appreciate the near-term pain that some developers are facing during this transition. To help out, I'd like to offer a workaround to (a) allow developers continue to use Mutagen with Docker for Mac and (b) allow this thread to focus on discussion of gRPC-FUSE development.

I've created a discussion on the Mutagen issue tracker that details how to use Mutagen manually to replicate the previous Docker for Mac caching functionality. This isn't quite as elegant as Docker's UI, but it will give power users more granular control over file synchronization and allow for continued discussion/experimentation.

In any case, I'd like to emphasize that any discussion on this workaround should take place on the Mutagen issue tracker—this isn't Docker's burden (though I'm happy if Docker developers want to join that discussion!).

I'm hoping this helps all parties involved.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
You can’t perform that action at this time.