Volume with 1.5 mill files slow mounting

[runarmyklebust]

• [x] This is a bug report
• [ ] This is a feature request
• [X] I searched existing issues before opening this one

Expected behavior

Mounting a volume should be done within a timely fashion

Actual behavior

Mounting volume with default settings takes several minutes ith default mode (z), mode=rw instant.

Steps to reproduce the behavior

docker run --rm -it --name rmytest --volume myVolCreated:/data ubuntu:latest

The above command spends around 5 minutes to complete The output when inspecting the Mount:

"Mounts": [
            {
                "Type": "volume",
                "Name": "myVolCreated",
                "Source": "/var/lib/docker/volumes/myVolCreated/_data",
                "Destination": "/data",
                "Driver": "local",
                "Mode": "z",
                "RW": true,
                "Propagation": ""
            }
        ]

docker run --rm -it --name rmytest --volume myVolCreated:/data:rw ubuntu:latest

The above command is instant. The output when inspecting the Mount:

 "Mounts": [
            {
                "Type": "volume",
                "Name": "myVolCreated",
                "Source": "/var/lib/docker/volumes/myVolCreated/_data",
                "Destination": "/data",
                "Driver": "local",
                "Mode": "rw",
                "RW": true,
                "Propagation": ""
            }
        ],

The volume to be mounted has these properties:

niva-xpprod-new-server-j473kz2sa2vn _data # pwd
/var/lib/docker/volumes/myVolCreated/_data
niva-xpprod-new-server-j473kz2sa2vn _data # find . -type f | wc -l
1553687
niva-xpprod-new-server-j473kz2sa2vn myVolCreated # du -h ../_data -d 1
18G	./_data

Output of docker version:

Client:
 Version:           18.06.1-ce
 API version:       1.38
 Go version:        go1.10.3
 Git commit:        e68fc7a
 Built:             Tue Aug 21 17:24:56 2018
 OS/Arch:           linux/amd64
 Experimental:      false

Server:
 Engine:
  Version:          18.06.1-ce
  API version:      1.38 (minimum version 1.12)
  Go version:       go1.10.6
  Git commit:       e68fc7a
  Built:            Tue Aug 21 17:16:31 2018
  OS/Arch:          linux/amd64
  Experimental:     false

Output of docker info:

ec:niva-xpprod-new /repos/niva-xpprod-new$ docker info
Containers: 3
 Running: 3
 Paused: 0
 Stopped: 0
Images: 34
Server Version: 18.06.1-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 468a545b9edcd5932818eb9de8e72413e616e86e
runc version: 69663f0bd4b60df09991c08812a60108003fa340
init version: v0.13.2 (expected: fec3683b971d9c3ef73f284f176672c44b448662)
Security Options:
 seccomp
  Profile: default
 selinux
Kernel Version: 4.14.84-coreos
Operating System: Container Linux by CoreOS 1911.5.0 (Rhyolite)
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 7.793GiB
Name: REDACTED
ID: REDACTED
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Additional environment details (AWS, VirtualBox, physical, etc.)

[cpuguy83]

Did you(or could you?) strace this to see what exactly is the cause? Volume mounts are just a simple bind mount, we do not traverse files AFAIK.

[runarmyklebust]

Seems like its doing this for every file:

[pid  7178] lsetxattr("/var/lib/docker/volumes/myVolCreated/_data/blob/node/5f/7a/cd", "security.selinux", "system_u:object_r:svirt_lxc_file_t:s0", 37, 0) = 0
[pid  7178] lstat("/var/lib/docker/volumes/myVolCreated/_data/blob/node/5f/7a/cd/5f7acd095b74ab906bdd9db5ab0978c03aad359f", {st_mode=S_IFREG|0644, st_size=5255, ...}) = 0
[pid  7178] lsetxattr("/var/lib/docker/volumes/myVolCreated/_data/blob/node/5f/7a/cd/5f7acd095b74ab906bdd9db5ab0978c03aad359f", "security.selinux", "system_u:object_r:svirt_lxc_file_t:s0", 37, 0) = 0
[pid  7178] lstat("/var/lib/docker/volumes/myVolCreated/_data/blob/node/5f/7a/d6", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  7178] openat(AT_FDCWD, "/var/lib/docker/volumes/myVolCreated/_data/blob/node/5f/7a/d6", O_RDONLY|O_CLOEXEC) = 38
[pid  7178] epoll_ctl(5, EPOLL_CTL_ADD, 38, {EPOLLIN|EPOLLOUT|EPOLLRDHUP|EPOLLET, {u32=3055419488, u64=140585924952160}}) = -1 EPERM (Operation not permitted)
[pid  7178] epoll_ctl(5, EPOLL_CTL_DEL, 38, c4212ce29c) = -1 EPERM (Operation not permitted)
[pid  7178] getdents64(38, /* 3 entries */, 4096) = 112
[pid  7178] getdents64(38, /* 0 entries */, 4096) = 0
[pid  7178] close(38)

So, doing some research yesterday, I found this that seems to be related https://www.projectatomic.io/blog/2015/06/using-volumes-with-docker-can-cause-problems-with-selinux/ https://github.com/kubernetes/kubernetes/issues/42257

[runarmyklebust]

Ok, I verified that disabling the SeLinux label process removes the issue.

docker run --rm -it --name rmytest --security-opt label:disable --volume myVolCreated:/data ubuntu:latest

So I guess this can be closed, sry for the inconvenience.

[cpuguy83]

Hmm, I don't think we should be labeling files at every mount call, especially for local volumes.

I'll take a look at this.

[raquelhortab]

what can the side-effects of using --security-opt label:disable be? should there be any security concern related to that?

[jwenjian]

watching this issue, since I recently got similar when using kubernetes, all the files in the volume got relabeled (even with fixed selinux level label) which causing the ctime of the file changed every time when pod (re)created.

[aleksvujic]

Any progress on this issue? We have a volume with 1.000.000 files and 100.000 directories and our service is deployed in swarm mode. Initial start-up time is ~20 minutes which is way too long. How can we speed it up?