search

containers / podman

Podman: A tool for managing OCI containers and pods.
https://podman.io
Apache License 2.0
23.03k stars 2.35k forks source link

Rootless "podman system df" takes ~15 minutes on WSL2 Debian. #10104

Closed arctic-alpaca closed 3 years ago

arctic-alpaca commented 3 years ago

Is this a BUG REPORT or FEATURE REQUEST? (leave only one on its own line)

/kind bug

Description Hi, Rootless podman system df takes roughly 15 minutes to return a result. Same behaviour with the API. When using sudo, the result is almost instantaneous as expected, same for the api if started with sudo.

Steps to reproduce the issue:

  1. execute podman system df as non-root user on WSL2 Debian 10

OR

  1. ./podman system service unix:///home/`whoami`/podman.sock --log-level=debug --time=500
  2. curl --unix-socket /home/`whoami`/podman.sock http://d/v3.0.0/libpod/system/df

Describe the results you received: Nothing gets output, podman runs continuously and doesn't return until roughly 15 minutes later. ps aux shows podman system df -v running and using quite a bit of CPU.

xyz@DESKTOP:/mnt/c/Users/xyz$ ps aux | grep podman
xyz    1845  0.0  0.2  54856 28132 ?        S    14:41   0:00 podman
xyz    2242  0.0  0.3 1999464 42780 pts/2   Sl+  14:47   0:00 ./podman system df -v
xyz    2254 63.8  0.6 2075948 88664 pts/2   Sl+  14:47   4:27 ./podman system df -v
xyz    2850  0.0  0.0   6204   888 pts/1    S+   14:54   0:00 grep podman

Using the api, this is the log output by the api process (complete log until the call returned).

Eventual result of API call:

{"Images":[{"Repository":"docker.io/library/hello-world","Tag":"latest","ImageID":"d1165f2212346b2bab48cb01c1e39ee8ad1be46b87873d9ca7a4e434980a7726","Created":"2021-03-05T23:25:25.230064203Z","Size":19981,"SharedSize":0,"UniqueSize":19981,"Containers":3},{"Repository":"docker.io/selenium/standalone-chrome","Tag":"3.141.59","ImageID":"efa240b85d8122dec95cc04858fac10e3271deccc6595daa17f9e3ed217a6fa8","Created":"2021-03-11T11:46:12.169686095Z","Size":1038892354,"SharedSize":0,"UniqueSize":1038892354,"Containers":4}],"Containers":[{"ContainerID":"0e82e2cd19fe39a2b0349f57dc7d16491d36b78852ad27b5f82e6d8759e6599c","Image":"efa240b85d8122dec95cc04858fac10e3271deccc6595daa17f9e3ed217a6fa8","Command":["/opt/bin/entry_point.sh"],"LocalVolumes":0,"Size":1014502660,"RWSize":1533242,"Created":"2021-04-12T08:49:00.6421539+02:00","Status":"exited","Names":"happy_zhukovsky"},{"ContainerID":"1c16c369e94a42fee9ed35730f975dc23067119fa8e2f5ed95d539563cae8b89","Image":"d1165f2212346b2bab48cb01c1e39ee8ad1be46b87873d9ca7a4e434980a7726","Command":["/hello"],"LocalVolumes":0,"Size":13336,"RWSize":0,"Created":"2021-04-11T19:01:32.7316691+02:00","Status":"exited","Names":"pedantic_euler"},{"ContainerID":"266134916e561b2693747a5ee282de43bff15055b6c74c097beba8ad9faa357d","Image":"d1165f2212346b2bab48cb01c1e39ee8ad1be46b87873d9ca7a4e434980a7726","Command":["/hello"],"LocalVolumes":0,"Size":13336,"RWSize":0,"Created":"2021-04-11T19:01:01.2977046+02:00","Status":"exited","Names":"naughty_mcnulty"},{"ContainerID":"3a5d3bf7aab0db546aae56779cee068c67fb83918e5794318b514a57dd411e43","Image":"efa240b85d8122dec95cc04858fac10e3271deccc6595daa17f9e3ed217a6fa8","Command":["/opt/bin/entry_point.sh"],"LocalVolumes":0,"Size":1014502660,"RWSize":1534461,"Created":"2021-04-15T13:12:29.8527482+02:00","Status":"exited","Names":"naughty_bassi"},{"ContainerID":"3f02db778ce81679297c19f9369df5f53711f191da0e2e9fd1d0d4a27ba64f33","Image":"efa240b85d8122dec95cc04858fac10e3271deccc6595daa17f9e3ed217a6fa8","Command":["/opt/bin/entry_point.sh"],"LocalVolumes":0,"Size":1014502660,"RWSize":1533145,"Created":"2021-04-14T14:39:34.1455153+02:00","Status":"exited","Names":"bold_knuth"},{"ContainerID":"9881302aaf0decd6f722da7a85f6931123ffdc1a3076fd6f54954a3788377396","Image":"d1165f2212346b2bab48cb01c1e39ee8ad1be46b87873d9ca7a4e434980a7726","Command":["--cgroup-manager","cgroupfs"],"LocalVolumes":0,"Size":13336,"RWSize":0,"Created":"2021-04-11T19:01:24.2534117+02:00","Status":"configured","Names":"silly_zhukovsky"},{"ContainerID":"f0bc33420d6fd0b16a40b94c4c56788f7ef8a0e8ffb953d145fc3f61464322d9","Image":"efa240b85d8122dec95cc04858fac10e3271deccc6595daa17f9e3ed217a6fa8","Command":["/opt/bin/entry_point.sh"],"LocalVolumes":0,"Size":1014502660,"RWSize":1533437,"Created":"2021-04-11T19:06:05.57382+02:00","Status":"exited","Names":"distracted_lamport"}],"Volumes":[]}

Eventual result of command:

xyz@DESKTOP:/mnt/c/Users/xyz$ podman system df
TYPE           TOTAL   ACTIVE  SIZE     RECLAIMABLE
Images         2       2       1.039GB  0B (0%)
Containers     7       0       6.134MB  6.134MB (100%)
Local Volumes  0       0       0B       0B (0%)

Describe the results you expected: The command should return similarly fast as if the command would be run as root.

Additional information you deem important (e.g. issue happens only occasionally):

Tested with podman 3.0.1 and podman 3.2.0-dev static build from CI.

Output of podman version:

Version:      3.2.0-dev
API Version:  3.2.0-dev
Go Version:   go1.15.10
Git Commit:   6ff56ab50a10e2350013c4ff1bf4b8d5d7b5aa87-dirty
Built:        Tue Jan  1 01:00:00 1980
OS/Arch:      linux/amd64

Output of podman info --debug:

host:
  arch: amd64
  buildahVersion: 1.20.1-dev
  cgroupManager: cgroupfs
  cgroupVersion: v1
  conmon:
    package: 'conmon: /usr/libexec/podman/conmon'
    path: /usr/libexec/podman/conmon
    version: 'conmon version 2.0.27, commit: '
  cpus: 12
  distribution:
    distribution: debian
    version: "10"
  eventLogger: file
  hostname: DESKTOP-3COMHL6
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
    uidmap:
    - container_id: 0
      host_id: 1000
      size: 1
    - container_id: 1
      host_id: 100000
      size: 65536
  kernel: 5.4.72-microsoft-standard-WSL2
  linkmode: static
  memFree: 12945952768
  memTotal: 13348544512
  ociRuntime:
    name: crun
    package: 'crun: /usr/bin/crun'
    path: /usr/bin/crun
    version: |-
      crun version 0.18.1-7931a-dirty
      commit: 7931a1eab0590eff4041c1f74e2844b297c31cea
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    path: /tmp/podman-run-1000/podman/podman.sock
  security:
    apparmorEnabled: false
    capabilities: CAP_CHOWN,CAP_DAC_OVERRIDE,CAP_FOWNER,CAP_FSETID,CAP_KILL,CAP_NET_BIND_SERVICE,CAP_SETFCAP,CAP_SETGID,CAP_SETPCAP,CAP_SETUID,CAP_SYS_CHROOT
    rootless: true
    seccompEnabled: true
    selinuxEnabled: false
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: 'slirp4netns: /usr/bin/slirp4netns'
    version: |-
      slirp4netns version 1.1.8
      commit: unknown
      libslirp: 4.3.1-git
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.4.4
  swapFree: 4294967296
  swapTotal: 4294967296
  uptime: 50m 40.58s
registries:
  search:
  - docker.io
  - quay.io
store:
  configFile: /home/xyz/.config/containers/storage.conf
  containerStore:
    number: 7
    paused: 0
    running: 0
    stopped: 7
  graphDriverName: overlay
  graphOptions:
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: 'fuse-overlayfs: /usr/bin/fuse-overlayfs'
      Version: |-
        fusermount3 version: 3.4.1
        fuse-overlayfs: version 1.4
        FUSE library version 3.4.1
        using FUSE kernel interface version 7.27
  graphRoot: /home/xyz/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: extfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 2
  runRoot: /tmp/podman-run-1000/containers
  volumePath: /home/xyz/.local/share/containers/storage/volumes
version:
  APIVersion: 3.2.0-dev
  Built: 315532800
  BuiltTime: Tue Jan  1 01:00:00 1980
  GitCommit: 6ff56ab50a10e2350013c4ff1bf4b8d5d7b5aa87-dirty
  GoVersion: go1.15.10
  OsArch: linux/amd64
  Version: 3.2.0-dev

Have you tested with the latest version of Podman and have you checked the Podman Troubleshooting Guide?

Yes

Additional environment details (AWS, VirtualBox, physical, etc.): Windows 10, WSL2, Debian 10, x64

mheon commented 3 years ago

Is this new behavior (IE only appeared in a recent release)? How many containers, images, and volumes do you have for the user running Podman?

arctic-alpaca commented 3 years ago

Is this new behavior (IE only appeared in a recent release)?

I only started using podman with version 3.0.1 and can't speak for older versions sorry.

How many containers, images, and volumes do you have for the user running Podman?

I wasn't actively using podman while testing this issue so no containers were running. I'm not entirely sure how to answer this question properly, so I hope this commands tell you, what you need to know. I'm happy to supply more information if needed.

xyz@DESKTOP:/mnt/c/Users/xyz$ podman volume ls
xyz@DESKTOP:/mnt/c/Users/xyz$ podman images list -a
REPOSITORY  TAG     IMAGE ID  CREATED  SIZE
xyz@DESKTOP:/mnt/c/Users/xyz$ podman container list -a
CONTAINER ID  IMAGE                                          COMMAND               CREATED     STATUS                   PORTS                   NAMES
266134916e56  docker.io/library/hello-world:latest           /hello                9 days ago  Exited (0) 9 days ago                            naughty_mcnulty
9881302aaf0d  docker.io/library/hello-world:latest           --cgroup-manager ...  9 days ago  Created                                          silly_zhukovsky
1c16c369e94a  docker.io/library/hello-world:latest           /hello                9 days ago  Exited (0) 9 days ago                            pedantic_euler
f0bc33420d6f  docker.io/selenium/standalone-chrome:3.141.59  /opt/bin/entry_po...  9 days ago  Exited (130) 9 days ago  0.0.0.0:4444->4444/tcp  distracted_lamport
0e82e2cd19fe  docker.io/selenium/standalone-chrome:3.141.59  /opt/bin/entry_po...  9 days ago  Exited (130) 9 days ago  0.0.0.0:4444->4444/tcp  happy_zhukovsky
3f02db778ce8  docker.io/selenium/standalone-chrome:3.141.59  /opt/bin/entry_po...  7 days ago  Exited (130) 6 days ago  0.0.0.0:4444->4444/tcp  bold_knuth
3a5d3bf7aab0  docker.io/selenium/standalone-chrome:3.141.59  /opt/bin/entry_po...  6 days ago  Exited (130) 5 days ago  0.0.0.0:4444->4444/tcp  naughty_bassi
xyz@DESKTOP:/mnt/c/Users/xyz$
mheon commented 3 years ago

No images listed, but container ls does show containers... that doesn't make any sense. Are the containers still usable (IE, does podman start on any of them work without error)?

arctic-alpaca commented 3 years ago

Every container starts up without errors from podman or the container itself besides 

9881302aaf0d  docker.io/library/hello-world:latest           --cgroup-manager ...  9 days ago  Created                                          silly_zhukovsky

This container returns 

xyz@DESKTOP-3COMHL6:/mnt/c/Users/xyz$ podman start -a 9881302aaf0d
Error: unable to start container 9881302aaf0decd6f722da7a85f6931123ffdc1a3076fd6f54954a3788377396: executable file `--cgroup-manager` not found in $PATH: No such file or directory: OCI not found

I think this is a container I passed --cgroup-manager=cgroupfs when running it when following this guide.

mheon commented 3 years ago

Ah - that's a simple fix, you put the --cgroup-manager flag too late (after the image name) in the command. So podman run hello-world --cgroup-manager=cgroupfs treats the flag as an argument to the container command - podman run --cgroup-manager=cgroupfs hello-world treats it as an argument to Podman.

Doesn't really expose the underlying issue here, though. Something is going on with image storage. @vrothberg @rhatdan @baude Ever seen something like this before - we clearly have images (containers are running) but podman image list shows nothing.

arctic-alpaca commented 3 years ago

I just realized I typed podman images list -a which lead to no results. podman image list -a on the other hand shows the images properly:

xyz@DESKTOP:/mnt/c/Users/xyz$ podman image list -a
REPOSITORY                            TAG       IMAGE ID      CREATED      SIZE
docker.io/selenium/standalone-chrome  3.141.59  efa240b85d81  5 weeks ago  1.04 GB
docker.io/library/hello-world         latest    d1165f221234  6 weeks ago  20 kB
mheon commented 3 years ago

So no error from images list? That's definitely a bug, invalid commands need to error.

mheon commented 3 years ago

To the original bug: the Selenium image is fairly large at 1gb, but not exceptional so, and it's only got ~20 layers. I see nothing obvious here that would cause an excessive amount of time be taken on podman system df.

arctic-alpaca commented 3 years ago

So no error from images list?

Yes, this is the complete output:

xyz@DESKTOP:/mnt/c/Users/xyz$ podman images list
REPOSITORY  TAG     IMAGE ID  CREATED  SIZE
xyz@DESKTOP:/mnt/c/Users/xyz$
mheon commented 3 years ago

Alright. podman images is the original command for listing images (before the podman image alias existed). What I did not realize is that podman image accepts an argument, the name of the image to list... So your command was trying to list all images named list. This is a little confusing, but unfortunately I think it's been baked in for so long we can't really change it.

arctic-alpaca commented 3 years ago

Just to confirm that this is working correctly and just as you said:

xyz@DESKTOP:/mnt/c/Users/xyz$ podman images hello
REPOSITORY                     TAG     IMAGE ID      CREATED      SIZE
docker.io/library/hello-world  latest  d1165f221234  6 weeks ago  20 kB
chadcatlett commented 3 years ago

I'm also seeing the same thing on Fedora 32(will be upgrading as soon as I can).

❯ podman version
Version:      2.2.1
API Version:  2.1.0
Go Version:   go1.14.10
Built:        Tue Dec  8 09:37:43 2020
OS/Arch:      linux/amd64
❯ podman info -D
host:
  arch: amd64
  buildahVersion: 1.18.0
  cgroupManager: systemd
  cgroupVersion: v2
  conmon:
    package: conmon-2.0.27-1.fc32.x86_64
    path: /usr/bin/conmon
    version: 'conmon version 2.0.27, commit: 253f230b3f653ff8ed47efbfffa52f0ae3f1820d'
  cpus: 88
  distribution:
    distribution: fedora
    version: "32"
  eventLogger: journald
  hostname: *redacted*
  idMappings:
    gidmap:
    - container_id: 0
      host_id: 20439
      size: 1
    - container_id: 1
      host_id: 200000
      size: 100000
    uidmap:
    - container_id: 0
      host_id: 20439
      size: 1
    - container_id: 1
      host_id: 200000
      size: 100000
  kernel: 5.11.16-100.fc32.x86_64
  linkmode: dynamic
  memFree: 399182725120
  memTotal: 404299915264
  ociRuntime:
    name: crun
    package: crun-0.17-1.fc32.x86_64
    path: /usr/bin/crun
    version: |-
      crun version 0.17
      commit: 0e9229ae34caaebcb86f1fde18de3acaf18c6d9a
      spec: 1.0.0
      +SYSTEMD +SELINUX +APPARMOR +CAP +SECCOMP +EBPF +CRIU +YAJL
  os: linux
  remoteSocket:
    path: /run/user/20439/podman/podman.sock
  rootless: true
  slirp4netns:
    executable: /usr/bin/slirp4netns
    package: slirp4netns-1.1.8-1.fc32.x86_64
    version: |-
      slirp4netns version 1.1.8
      commit: d361001f495417b880f20329121e3aa431a8f90f
      libslirp: 4.3.1
      SLIRP_CONFIG_VERSION_MAX: 3
      libseccomp: 2.5.0
  swapFree: 34359734272
  swapTotal: 34359734272
  uptime: 1h 50m 9.47s (Approximately 0.04 days)
registries:
  search:
  - registry.fedoraproject.org
  - registry.access.redhat.com
  - registry.centos.org
  - docker.io
store:
  configFile: /home/ccatlett/.config/containers/storage.conf
  containerStore:
    number: 9
    paused: 0
    running: 0
    stopped: 9
  graphDriverName: overlay
  graphOptions:
    overlay.mount_program:
      Executable: /usr/bin/fuse-overlayfs
      Package: fuse-overlayfs-1.4.0-1.fc32.x86_64
      Version: |-
        fusermount3 version: 3.9.1
        fuse-overlayfs: version 1.4
        FUSE library version 3.9.1
        using FUSE kernel interface version 7.31
  graphRoot: /home/ccatlett/.local/share/containers/storage
  graphStatus:
    Backing Filesystem: xfs
    Native Overlay Diff: "false"
    Supports d_type: "true"
    Using metacopy: "false"
  imageStore:
    number: 68
  runRoot: /run/user/20439/containers
  volumePath: /home/ccatlett/.local/share/containers/storage/volumes
version:
  APIVersion: 2.1.0
  Built: 1607438263
  BuiltTime: Tue Dec  8 09:37:43 2020
  GitCommit: ""
  GoVersion: go1.14.10
  OsArch: linux/amd64
  Version: 2.2.1
github-actions[bot] commented 3 years ago

A friendly reminder that this issue had no activity for 30 days.

rhatdan commented 3 years ago

@giuseppe Is this improved with the latest fuse-overlay changes?

giuseppe commented 3 years ago

This was an issue in older c/storage versions. It is fixed in the last version

rhatdan commented 3 years ago

Closing since it is fixed in the main branch.