podman takes 3 times as long as docker to pull or remove an image

[larrypl]

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

/kind bug

Description

On the same host, to the same file system, using the same image, doing ‘time docker pull’ and ‘time podman pull’, podman takes up to 3 times longer, root or rootless. With debug it appears that after the ‘storing signatures’ message there are untars for each layer that take the most amount of additional time.

Timings are similar when the image docker.io/library/golang:1.13.5 is used.

Steps to reproduce the issue:

1.podman pull

2.docker pull

3.podman rmi

4.docker rmi

Describe the results you received:
```$ podman --log-level debug pull docker://repo.corp.pinger.com/docker-local/golang:1.13.5
INFO[0000] running as rootless
DEBU[0000] Initializing boltdb state at /home/larryp/.local/share/containers/storage/libpod/bolt_state.db
DEBU[0000] Using graph driver vfs
DEBU[0000] Using graph root /home/larryp/.local/share/containers/storage
DEBU[0000] Using run root /run/user/1054
DEBU[0000] Using static dir /home/larryp/.local/share/containers/storage/libpod
DEBU[0000] Using tmp dir /run/user/1054/libpod/tmp
DEBU[0000] Using volume path /home/larryp/.local/share/containers/storage/volumes
DEBU[0000] Set libpod namespace to ""
DEBU[0000] [graphdriver] trying provided driver "vfs"
DEBU[0000] Initializing event backend journald
DEBU[0000] parsed reference into "[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5"
Trying to pull docker://repo.corp.pinger.com/docker-local/golang:1.13.5...DEBU[0000] reference rewritten from 'repo.corp.pinger.com/docker-local/golang:1.13.5' to 'repo.corp.pinger.com/docker-local/golang:1.13.5'
DEBU[0000] Trying to pull "repo.corp.pinger.com/docker-local/golang:1.13.5"
DEBU[0000] Using registries.d directory /etc/containers/registries.d for sigstore configuration
DEBU[0000] Using "default-docker" configuration
DEBU[0000] No signature storage configuration found for repo.corp.pinger.com/docker-local/golang:1.13.5
DEBU[0000] Looking for TLS certificates and private keys in /etc/docker/certs.d/repo.corp.pinger.com
DEBU[0000] GET https://repo.corp.pinger.com/v2/
DEBU[0000] Ping https://repo.corp.pinger.com/v2/ status 401
DEBU[0000] GET https://artifactory.corp.pinger.com:443/artifactory/api/docker/null/v2/token?account=larryp&scope=repository%3Adocker-local%2Fgolang%3Apull&service=artifactory.corp.pinger.com%3A443
DEBU[0000] GET https://repo.corp.pinger.com/v2/docker-local/golang/manifests/1.13.5
DEBU[0001] Using blob info cache at /home/larryp/.local/share/containers/cache/blob-info-cache-v1.boltdb
DEBU[0001] IsRunningImageAllowed for image docker:repo.corp.pinger.com/docker-local/golang:1.13.5
DEBU[0001] Using default policy section
DEBU[0001] Requirement 0: allowed
DEBU[0001] Overall: allowed
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
Getting image source signatures
DEBU[0001] Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json]
DEBU[0001] ... will first try using the original manifest unmodified
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469
DEBU[0001] Downloading /v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5
DEBU[0001] GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5
DEBU[0001] Detected compression format gzip
DEBU[0001] Using original blob without modification
DEBU[0001] Detected compression format gzip
DEBU[0001] Using original blob without modification
DEBU[0001] Detected compression format gzip
DEBU[0001] Using original blob without modification
Copying blob 184eb07e3845 [===>----------------------------------] 780.5KiB / 7.7MiB
Copying blob 4c7ecf8e366f [--------------------------------------] 241.4KiB / 51.9MiB
Copying blob 184eb07e3845 [=====>--------------------------------] 1.2MiB / 7.7MiB
Copying blob 4c7ecf8e366f [--------------------------------------] 464.0KiB / 51.9MiB
Copying blob 184eb07e3845 [==================>-------------------] 3.9MiB / 7.7MiB
Copying blob 4c7ecf8e366f [=>------------------------------------] 2.4MiB / 51.9MiB
Copying blob 184eb07e3845 [======================================] 7.7MiB / 7.7MiB
Copying blob 4c7ecf8e366f [===>----------------------------------] 5.5MiB / 51.9MiB
Copying blob 184eb07e3845 done
Copying blob 4c7ecf8e366f [===>----------------------------------] 5.8MiB / 51.9MiB
Copying blob 184eb07e3845 done
Copying blob 4c7ecf8e366f done
Copying blob bea73dfc87cd done
Copying blob 78524344c0c5 done
Copying blob 5879af8e4ff2 done
Copying blob 56f728fa3ddb done
Copying blob 3a0f9001c634 done
DEBU[0033] No compression detected
DEBU[0033] Using original blob without modification
Copying config a1072a0788 done
Writing manifest to image destination
Storing signatures
DEBU[0033] Start untar layer
DEBU[0037] Untar time: 3.519608529s
DEBU[0038] Start untar layer
DEBU[0039] Untar time: 0.511102642s
DEBU[0040] Start untar layer
DEBU[0040] Untar time: 0.503061514s
DEBU[0043] Start untar layer
DEBU[0046] Untar time: 3.841166762s
DEBU[0049] Start untar layer
DEBU[0053] Untar time: 3.799054692s
DEBU[0065] Start untar layer
DEBU[0072] Untar time: 7.09145142s
DEBU[0082] Start untar layer
DEBU[0082] Untar time: 0.063755192s
DEBU[0082] setting image creation date to 2019-12-05 22:19:54.952608448 +0000 UTC
DEBU[0082] created new image ID "a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7"
DEBU[0082] set names of image "a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7" to [repo.corp.pinger.com/docker-local/golang:1.13.5]
DEBU[0082] saved image metadata "{}"
DEBU[0083] parsed reference into "[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5"
a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7

docker (doesn't give timing in debug output):
```$ time docker --log-level debug pull repo.corp.pinger.com/docker-local/golang:1.13.5 | cat
1.13.5: Pulling from docker-local/golang
56f728fa3ddb: Pulling fs layer
184eb07e3845: Pulling fs layer
78524344c0c5: Pulling fs layer
4c7ecf8e366f: Pulling fs layer
bea73dfc87cd: Pulling fs layer
5879af8e4ff2: Pulling fs layer
3a0f9001c634: Pulling fs layer
bea73dfc87cd: Waiting
5879af8e4ff2: Waiting
3a0f9001c634: Waiting
4c7ecf8e366f: Waiting
184eb07e3845: Verifying Checksum
184eb07e3845: Download complete
78524344c0c5: Verifying Checksum
78524344c0c5: Download complete
4c7ecf8e366f: Verifying Checksum
4c7ecf8e366f: Download complete
56f728fa3ddb: Verifying Checksum
56f728fa3ddb: Download complete
3a0f9001c634: Verifying Checksum
3a0f9001c634: Download complete
56f728fa3ddb: Pull complete
184eb07e3845: Pull complete
78524344c0c5: Pull complete
bea73dfc87cd: Verifying Checksum
bea73dfc87cd: Download complete
4c7ecf8e366f: Pull complete
bea73dfc87cd: Pull complete
5879af8e4ff2: Verifying Checksum
5879af8e4ff2: Download complete
5879af8e4ff2: Pull complete
3a0f9001c634: Pull complete
Digest: sha256:67f20196fb8f69b83d44f958ea6e9994bab0e6fc860cb408a7eb06b45e4d536d
Status: Downloaded newer image for repo.corp.pinger.com/docker-local/golang:1.13.5
repo.corp.pinger.com/docker-local/golang:1.13.5

real    0m40.690s
user    0m0.123s
sys     0m0.075s

Remove image times:

$ time podman --log-level debug rmi docker://repo.corp.pinger.com/docker-local/golang:1.13.5
INFO[0000] running as rootless                          
DEBU[0000] Initializing boltdb state at /home/larryp/.local/share/containers/storage/libpod/bolt_state.db 
DEBU[0000] Using graph driver vfs                       
DEBU[0000] Using graph root /home/larryp/.local/share/containers/storage 
DEBU[0000] Using run root /run/user/1054                
DEBU[0000] Using static dir /home/larryp/.local/share/containers/storage/libpod 
DEBU[0000] Using tmp dir /run/user/1054/libpod/tmp      
DEBU[0000] Using volume path /home/larryp/.local/share/containers/storage/volumes 
DEBU[0000] Set libpod namespace to ""                   
DEBU[0000] [graphdriver] trying provided driver "vfs"   
DEBU[0000] Initializing event backend journald          
DEBU[0000] parsed reference into "[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5" 
DEBU[0000] parsed reference into "[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]@a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7" 
DEBU[0000] exporting opaque data as blob "sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7" 
a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7

real    0m5.947s
user    0m1.019s
sys     0m4.672s

docker:
```$ time docker --log-level debug rmi repo.corp.pinger.com/docker-local/golang:1.13.5 | cat
Untagged: repo.corp.pinger.com/docker-local/golang:1.13.5
Untagged: repo.corp.pinger.com/docker-local/golang@sha256:67f20196fb8f69b83d44f958ea6e9994bab0e6fc860cb408a7eb06b45e4d536d
Deleted: sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
Deleted: sha256:c5de208b3de2473c9fd1e98d0c3d6dfbd2d6a9e0515af9180a66a2097164f746
Deleted: sha256:103f2438985ab065564cdaf020a5ceefe552c00f7906a0153acac6d45b6fe301
Deleted: sha256:3f4f3bebbb236d36783dd3108ded614cf6a7d4ffc2fd8512539a22308d7f4dee
Deleted: sha256:228b1144f6cb979c6d8e9ecc73eb57eb2fe98e2c78f76bdc9c7b4cd85dc02bde
Deleted: sha256:07d1c3b01bf4edbe5a27dbff1d7800b46a769bc3f732f6e09699e7d369ceec7a
Deleted: sha256:35c18235e46863994e0182bf8f655279ec47373688786aa7e22fd4cd76c19398
Deleted: sha256:f2b4f0674ba3e6119088fe8a98c7921ed850c48d4d76e8caecd7f3d57721b4cb

real 0m1.390s
user 0m0.042s
sys 0m0.044s

Another run with line timings:
```larryp@sj2-container03 ~:
$ time podman --log-level debug pull repo.corp.pinger.com/docker-local/golang:1.13.5 |& /tmp/ts -s %.T
00:00:00.005719 time="2019-12-21T19:28:05Z" level=info msg="running as rootless"
00:00:00.009862 time="2019-12-21T19:28:05Z" level=debug msg="Initializing boltdb state at /home/larryp/.local/share/containers/storage/libpod/bolt_state.db"
00:00:00.010057 time="2019-12-21T19:28:05Z" level=debug msg="Using graph driver vfs"
00:00:00.010121 time="2019-12-21T19:28:05Z" level=debug msg="Using graph root /home/larryp/.local/share/containers/storage"
00:00:00.010165 time="2019-12-21T19:28:05Z" level=debug msg="Using run root /run/user/1054"
00:00:00.010220 time="2019-12-21T19:28:05Z" level=debug msg="Using static dir /home/larryp/.local/share/containers/storage/libpod"
00:00:00.010258 time="2019-12-21T19:28:05Z" level=debug msg="Using tmp dir /run/user/1054/libpod/tmp"
00:00:00.010313 time="2019-12-21T19:28:05Z" level=debug msg="Using volume path /home/larryp/.local/share/containers/storage/volumes"
00:00:00.010688 time="2019-12-21T19:28:05Z" level=debug msg="Set libpod namespace to \"\""
00:00:00.010773 time="2019-12-21T19:28:05Z" level=debug msg="[graphdriver] trying provided driver \"vfs\""
00:00:00.011692 time="2019-12-21T19:28:05Z" level=debug msg="Initializing event backend journald"
00:00:00.012085 time="2019-12-21T19:28:05Z" level=debug msg="parsed reference into \"[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:00.012846 Trying to pull repo.corp.pinger.com/docker-local/golang:1.13.5...time="2019-12-21T19:28:05Z" level=debug msg="reference rewritten from 'repo.corp.pinger.com/docker-local/golang:1.13.5' to 'repo.corp.pinger.com/docker-local/golang:1.13.5'"
00:00:00.012901 time="2019-12-21T19:28:05Z" level=debug msg="Trying to pull \"repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:00.012943 time="2019-12-21T19:28:05Z" level=debug msg="Using registries.d directory /etc/containers/registries.d for sigstore configuration"
00:00:00.013293 time="2019-12-21T19:28:05Z" level=debug msg=" Using \"default-docker\" configuration"
00:00:00.013355 time="2019-12-21T19:28:05Z" level=debug msg=" No signature storage configuration found for repo.corp.pinger.com/docker-local/golang:1.13.5"
00:00:00.013402 time="2019-12-21T19:28:05Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/repo.corp.pinger.com"
00:00:00.013442 time="2019-12-21T19:28:05Z" level=debug msg="GET https://repo.corp.pinger.com/v2/"
00:00:00.149607 time="2019-12-21T19:28:05Z" level=debug msg="Ping https://repo.corp.pinger.com/v2/ status 401"
00:00:00.150125 time="2019-12-21T19:28:05Z" level=debug msg="GET https://artifactory.corp.pinger.com:443/artifactory/api/docker/null/v2/token?account=larryp&scope=repository%3Adocker-local%2Fgolang%3Apull&service=artifactory.corp.pinger.com%3A443"
00:00:00.625292 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/manifests/1.13.5"
00:00:00.700214 time="2019-12-21T19:28:06Z" level=debug msg="Using blob info cache at /home/larryp/.local/share/containers/cache/blob-info-cache-v1.boltdb"
00:00:00.700270 time="2019-12-21T19:28:06Z" level=debug msg="IsRunningImageAllowed for image docker:repo.corp.pinger.com/docker-local/golang:1.13.5"
00:00:00.700302 time="2019-12-21T19:28:06Z" level=debug msg=" Using default policy section"
00:00:00.700330 time="2019-12-21T19:28:06Z" level=debug msg=" Requirement 0: allowed"
00:00:00.700354 time="2019-12-21T19:28:06Z" level=debug msg="Overall: allowed"
00:00:00.700496 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7"
00:00:00.700569 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7"
00:00:00.764114 Getting image source signatures
00:00:00.764205 time="2019-12-21T19:28:06Z" level=debug msg="Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json]"
00:00:00.764276 time="2019-12-21T19:28:06Z" level=debug msg="... will first try using the original manifest unmodified"
00:00:00.765610 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271"
00:00:00.765684 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271"
00:00:00.766130 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae"
00:00:00.766212 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae"
00:00:00.766670 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab"
00:00:00.766762 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab"
00:00:00.767193 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed"
00:00:00.767282 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed"
00:00:00.767716 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5"
00:00:00.767806 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5"
00:00:00.768198 time="2019-12-21T19:28:06Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469"
00:00:00.768273 time="2019-12-21T19:28:06Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469"
00:00:00.910711 Copying blob sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271
00:00:00.910808 time="2019-12-21T19:28:06Z" level=debug msg="Detected compression format gzip"
00:00:00.910914 time="2019-12-21T19:28:06Z" level=debug msg="Using original blob without modification"
00:00:00.952382 Copying blob sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae
00:00:00.952471 time="2019-12-21T19:28:06Z" level=debug msg="Detected compression format gzip"
00:00:00.952518 time="2019-12-21T19:28:06Z" level=debug msg="Using original blob without modification"
00:00:00.985706 Copying blob sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed
00:00:00.985793 time="2019-12-21T19:28:06Z" level=debug msg="Detected compression format gzip"
00:00:00.985837 time="2019-12-21T19:28:06Z" level=debug msg="Using original blob without modification"
00:00:01.027399 Copying blob sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab
00:00:01.027473 time="2019-12-21T19:28:06Z" level=debug msg="Detected compression format gzip"
00:00:01.027534 time="2019-12-21T19:28:06Z" level=debug msg="Using original blob without modification"
00:00:01.385743 Copying blob sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469
00:00:01.385870 time="2019-12-21T19:28:06Z" level=debug msg="Detected compression format gzip"
00:00:01.385915 time="2019-12-21T19:28:06Z" level=debug msg="Using original blob without modification"
00:00:02.340320 Copying blob sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5
00:00:02.340451 time="2019-12-21T19:28:07Z" level=debug msg="Detected compression format gzip"
00:00:02.340505 time="2019-12-21T19:28:07Z" level=debug msg="Using original blob without modification"
00:00:03.294544 time="2019-12-21T19:28:08Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0"
00:00:03.294681 time="2019-12-21T19:28:08Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0"
00:00:03.452325 Copying blob sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0
00:00:03.452427 time="2019-12-21T19:28:09Z" level=debug msg="Detected compression format gzip"
00:00:03.452478 time="2019-12-21T19:28:09Z" level=debug msg="Using original blob without modification"
00:00:31.125179 Copying config sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
00:00:31.125307 time="2019-12-21T19:28:36Z" level=debug msg="No compression detected"
00:00:31.125352 time="2019-12-21T19:28:36Z" level=debug msg="Using original blob without modification"
00:00:31.485316 Writing manifest to image destination
00:00:31.485387 Storing signatures
00:00:31.551581 time="2019-12-21T19:28:37Z" level=debug msg="Start untar layer"
00:00:34.995131 time="2019-12-21T19:28:40Z" level=debug msg="Untar time: 3.443497384s"
00:00:39.211523 time="2019-12-21T19:28:44Z" level=debug msg="Start untar layer"
00:00:39.740073 time="2019-12-21T19:28:45Z" level=debug msg="Untar time: 0.528563495s"
00:00:42.012310 time="2019-12-21T19:28:47Z" level=debug msg="Start untar layer"
00:00:42.524122 time="2019-12-21T19:28:48Z" level=debug msg="Untar time: 0.511810003s"
00:00:43.853662 time="2019-12-21T19:28:49Z" level=debug msg="Start untar layer"
00:00:47.784185 time="2019-12-21T19:28:53Z" level=debug msg="Untar time: 3.930512543s"
00:00:50.047068 time="2019-12-21T19:28:55Z" level=debug msg="Start untar layer"
00:00:54.452059 time="2019-12-21T19:29:00Z" level=debug msg="Untar time: 4.40504032s"
00:01:01.528394 time="2019-12-21T19:29:07Z" level=debug msg="Start untar layer"
00:01:08.871007 time="2019-12-21T19:29:14Z" level=debug msg="Untar time: 7.34263789s"
00:01:20.648206 time="2019-12-21T19:29:26Z" level=debug msg="Start untar layer"
00:01:20.712171 time="2019-12-21T19:29:26Z" level=debug msg="Untar time: 0.063965127s"
00:01:20.855640 time="2019-12-21T19:29:26Z" level=debug msg="setting image creation date to 2019-12-05 22:19:54.952608448 +0000 UTC"
00:01:20.922299 time="2019-12-21T19:29:26Z" level=debug msg="created new image ID \"a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\""
00:01:21.065526 time="2019-12-21T19:29:26Z" level=debug msg="set names of image \"a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\" to [repo.corp.pinger.com/docker-local/golang:1.13.5]"
00:01:21.352432 time="2019-12-21T19:29:26Z" level=debug msg="saved image metadata \"{}\""
00:01:21.450900 time="2019-12-21T19:29:27Z" level=debug msg="parsed reference into \"[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:01:21.451030 a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7

real    1m21.509s
user    1m25.608s
sys     0m25.206s
larryp@sj2-container03 ~:
$ time docker --log-level debug pull repo.corp.pinger.com/docker-local/golang:1.13.5 |& /tmp/ts -s %.T
00:00:00.640016 1.13.5: Pulling from docker-local/golang
00:00:00.640270 56f728fa3ddb: Pulling fs layer
00:00:00.640335 184eb07e3845: Pulling fs layer
00:00:00.640385 78524344c0c5: Pulling fs layer
00:00:00.640432 4c7ecf8e366f: Pulling fs layer
00:00:00.640478 bea73dfc87cd: Pulling fs layer
00:00:00.640520 5879af8e4ff2: Pulling fs layer
00:00:00.640570 4c7ecf8e366f: Waiting
00:00:00.640609 3a0f9001c634: Pulling fs layer
00:00:00.640720 3a0f9001c634: Waiting
00:00:00.640763 bea73dfc87cd: Waiting
00:00:00.640801 5879af8e4ff2: Waiting
00:00:02.588126 184eb07e3845: Verifying Checksum
00:00:02.588254 184eb07e3845: Download complete
00:00:03.242223 78524344c0c5: Verifying Checksum
00:00:03.242348 78524344c0c5: Download complete
00:00:12.731767 4c7ecf8e366f: Verifying Checksum
00:00:12.731869 4c7ecf8e366f: Download complete
00:00:16.705552 56f728fa3ddb: Verifying Checksum
00:00:16.705614 56f728fa3ddb: Download complete
00:00:16.822283 3a0f9001c634: Verifying Checksum
00:00:16.822390 3a0f9001c634: Download complete
00:00:20.011681 56f728fa3ddb: Pull complete
00:00:20.777367 184eb07e3845: Pull complete
00:00:21.465013 78524344c0c5: Pull complete
00:00:24.970674 bea73dfc87cd: Verifying Checksum
00:00:24.970782 bea73dfc87cd: Download complete
00:00:25.239101 4c7ecf8e366f: Pull complete
00:00:29.145073 bea73dfc87cd: Pull complete
00:00:30.540432 5879af8e4ff2: Verifying Checksum
00:00:30.540490 5879af8e4ff2: Download complete
00:00:38.316529 5879af8e4ff2: Pull complete
00:00:38.668013 3a0f9001c634: Pull complete
00:00:38.762351 Digest: sha256:67f20196fb8f69b83d44f958ea6e9994bab0e6fc860cb408a7eb06b45e4d536d
00:00:38.829753 Status: Downloaded newer image for repo.corp.pinger.com/docker-local/golang:1.13.5
00:00:38.830373 repo.corp.pinger.com/docker-local/golang:1.13.5

real    0m38.883s
user    0m0.159s
sys     0m0.093s
larryp@sj2-container03 ~:
$ time podman --log-level debug rmi repo.corp.pinger.com/docker-local/golang:1.13.5 |& /tmp/ts -s %.T
00:00:00.007874 time="2019-12-21T19:25:25Z" level=info msg="running as rootless"
00:00:00.011706 time="2019-12-21T19:25:25Z" level=debug msg="Initializing boltdb state at /home/larryp/.local/share/containers/storage/libpod/bolt_state.db"
00:00:00.011984 time="2019-12-21T19:25:25Z" level=debug msg="Using graph driver vfs"
00:00:00.012052 time="2019-12-21T19:25:25Z" level=debug msg="Using graph root /home/larryp/.local/share/containers/storage"
00:00:00.012112 time="2019-12-21T19:25:25Z" level=debug msg="Using run root /run/user/1054"
00:00:00.012150 time="2019-12-21T19:25:25Z" level=debug msg="Using static dir /home/larryp/.local/share/containers/storage/libpod"
00:00:00.012187 time="2019-12-21T19:25:25Z" level=debug msg="Using tmp dir /run/user/1054/libpod/tmp"
00:00:00.012235 time="2019-12-21T19:25:25Z" level=debug msg="Using volume path /home/larryp/.local/share/containers/storage/volumes"
00:00:00.012684 time="2019-12-21T19:25:25Z" level=debug msg="Set libpod namespace to \"\""
00:00:00.012741 time="2019-12-21T19:25:25Z" level=debug msg="[graphdriver] trying provided driver \"vfs\""
00:00:00.013969 time="2019-12-21T19:25:25Z" level=debug msg="Initializing event backend journald"
00:00:00.014261 time="2019-12-21T19:25:25Z" level=debug msg="parsed reference into \"[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:00.020780 time="2019-12-21T19:25:25Z" level=debug msg="parsed reference into \"[vfs@/home/larryp/.local/share/containers/storage+/run/user/1054]@a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\""
00:00:00.022238 time="2019-12-21T19:25:25Z" level=debug msg="exporting opaque data as blob \"sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\""
00:00:06.279905 a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7

real    0m6.333s
user    0m1.111s
sys     0m4.800s
larryp@sj2-container03 ~:
$ time docker --log-level debug rmi repo.corp.pinger.com/docker-local/golang:1.13.5 |& /tmp/ts -s %.T
00:00:01.343585 Untagged: repo.corp.pinger.com/docker-local/golang:1.13.5
00:00:01.343865 Untagged: repo.corp.pinger.com/docker-local/golang@sha256:67f20196fb8f69b83d44f958ea6e9994bab0e6fc860cb408a7eb06b45e4d536d
00:00:01.343899 Deleted: sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
00:00:01.343923 Deleted: sha256:c5de208b3de2473c9fd1e98d0c3d6dfbd2d6a9e0515af9180a66a2097164f746
00:00:01.343946 Deleted: sha256:103f2438985ab065564cdaf020a5ceefe552c00f7906a0153acac6d45b6fe301
00:00:01.343969 Deleted: sha256:3f4f3bebbb236d36783dd3108ded614cf6a7d4ffc2fd8512539a22308d7f4dee
00:00:01.343992 Deleted: sha256:228b1144f6cb979c6d8e9ecc73eb57eb2fe98e2c78f76bdc9c7b4cd85dc02bde
00:00:01.344014 Deleted: sha256:07d1c3b01bf4edbe5a27dbff1d7800b46a769bc3f732f6e09699e7d369ceec7a
00:00:01.344037 Deleted: sha256:35c18235e46863994e0182bf8f655279ec47373688786aa7e22fd4cd76c19398
00:00:01.344060 Deleted: sha256:f2b4f0674ba3e6119088fe8a98c7921ed850c48d4d76e8caecd7f3d57721b4cb

real    0m1.397s
user    0m0.090s
sys     0m0.048s

Describe the results you expected:
Equivalent timings for docker and podman operations

Additional information you deem important (e.g. issue happens only occasionally):
Consistently between 2 and 3 times as long with podman versus docker for pulls.

Output of podman version:

Version:            1.4.4
RemoteAPI Version:  1
Go Version:         go1.10.3
OS/Arch:            linux/amd64

Docker version:

Client: Docker Engine - Community
 Version:           19.03.4
 API version:       1.40
 Go version:        go1.12.10
 Git commit:        9013bf583a
 Built:             Fri Oct 18 15:52:22 2019
 OS/Arch:           linux/amd64
 Experimental:      false

Server: Docker Engine - Community
 Engine:
  Version:          19.03.4
  API version:      1.40 (minimum version 1.12)
  Go version:       go1.12.10
  Git commit:       9013bf583a
  Built:            Fri Oct 18 15:50:54 2019
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.2.10
  GitCommit:        b34a5c8af56e510852c35414db4c1f4fa6172339
 runc:
  Version:          1.0.0-rc8+dev
  GitCommit:        3e425f80a8c931f88e6d94a8c831b9d5aa481657
 docker-init:
  Version:          0.18.0
  GitCommit:        fec3683

Output of podman info --debug:

debug:
  compiler: gc
  git commit: ""
  go version: go1.10.3
  podman version: 1.4.4
host:
  BuildahVersion: 1.9.0
  Conmon:
    package: podman-1.4.4-2.el7.centos.x86_64
    path: /usr/libexec/podman/conmon
    version: 'conmon version 0.3.0, commit: unknown'
  Distribution:
    distribution: '"centos"'
    version: "7"
  MemFree: 8728756224
  MemTotal: 12411658240
  OCIRuntime:
    package: containerd.io-1.2.10-3.2.el7.x86_64
    path: /usr/bin/runc
    version: |-
      runc version 1.0.0-rc8+dev
      commit: 3e425f80a8c931f88e6d94a8c831b9d5aa481657
      spec: 1.0.1-dev
  SwapFree: 0
  SwapTotal: 0
  arch: amd64
  cpus: 24
  hostname: sj2-container03
  kernel: 3.10.0-957.1.3.el7.x86_64
  os: linux
  rootless: true
  uptime: 235h 12m 24.42s (Approximately 9.79 days)
registries:
  blocked: null
  insecure: null
  search:
  - registry.centos.org
  - registry.access.redhat.com
  - docker.io
  - quay.io
store:
  ConfigFile: /home/larryp/.config/containers/storage.conf
  ContainerStore:
    number: 1
  GraphDriverName: vfs
  GraphOptions: null
  GraphRoot: /home/larryp/.local/share/containers/storage
  GraphStatus: {}
  ImageStore:
    number: 1
  RunRoot: /run/user/1054
  VolumePath: /home/larryp/.local/share/containers/storage/volumes

Docker:

Client:
 Debug Mode: true

Server:
 Containers: 3
  Running: 2
  Paused: 0
  Stopped: 1
 Images: 1
 Server Version: 19.03.4
 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 ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: b34a5c8af56e510852c35414db4c1f4fa6172339
 runc version: 3e425f80a8c931f88e6d94a8c831b9d5aa481657
 init version: fec3683
 Security Options:
  seccomp
   Profile: default
 Kernel Version: 3.10.0-957.1.3.el7.x86_64
 Operating System: CentOS Linux 7 (Core)
 OSType: linux
 Architecture: x86_64
 CPUs: 24
 Total Memory: 11.56GiB
 Name: sj2-container03
 ID: 53IT:3OKR:B7MY:DO3J:QVJ2:YUHH:R6SN:W6NR:3ZFT:42CD:M5HC:X2UH
 Docker Root Dir: /var/lib/docker
 Debug Mode: false
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  127.0.0.0/8
 Live Restore Enabled: false

Package info (e.g. output of rpm -q podman or apt list podman):

docker-ce-19.03.4-3.el7.x86_64
podman-1.4.4-2.el7.centos.x86_64

Additional environment details (AWS, VirtualBox, physical, etc.):
physical system, CentOS 7.6

[st1971]

I'm not a member of this project, but on the surface this does not look to be an like for like comparison, with podman you are running rootless which means that you have an overhead of userspace overlay-fs and user namespaces. Docker does not have these as it's running as root.

What do the timings look like if you try 'sudo podman pull' which would be closer to a like for like comparison.

[larrypl]

Sorry, I should have mentioned I tried that. Here's the timing for a pull:
```larryp@sj2-container03 ~:
$ time sudo podman --log-level debug pull repo.corp.pinger.com/docker-local/golang:1.13.5 |& /tmp/ts -s %.T
00:00:00.018229 time="2019-12-22T18:24:57Z" level=debug msg="Initializing boltdb state at /var/lib/containers/storage/libpod/bolt_state.db"
00:00:00.018437 time="2019-12-22T18:24:57Z" level=debug msg="Using graph driver overlay"
00:00:00.018506 time="2019-12-22T18:24:57Z" level=debug msg="Using graph root /var/lib/containers/storage"
00:00:00.018551 time="2019-12-22T18:24:57Z" level=debug msg="Using run root /var/run/containers/storage"
00:00:00.018593 time="2019-12-22T18:24:57Z" level=debug msg="Using static dir /var/lib/containers/storage/libpod"
00:00:00.018633 time="2019-12-22T18:24:57Z" level=debug msg="Using tmp dir /var/run/libpod"
00:00:00.018697 time="2019-12-22T18:24:57Z" level=debug msg="Using volume path /var/lib/containers/storage/volumes"
00:00:00.019166 time="2019-12-22T18:24:57Z" level=debug msg="Set libpod namespace to \"\""
00:00:00.019256 time="2019-12-22T18:24:57Z" level=debug msg="[graphdriver] trying provided driver \"overlay\""
00:00:00.019362 time="2019-12-22T18:24:57Z" level=debug msg="cached value indicated that overlay is supported"
00:00:00.019429 time="2019-12-22T18:24:57Z" level=debug msg="cached value indicated that metacopy is not being used"
00:00:00.022032 time="2019-12-22T18:24:57Z" level=debug msg="cached value indicated that native-diff is usable"
00:00:00.022097 time="2019-12-22T18:24:57Z" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=true, usingMetacopy=false"
00:00:00.023461 time="2019-12-22T18:24:57Z" level=debug msg="Initializing event backend journald"
00:00:00.023910 time="2019-12-22T18:24:57Z" level=info msg="Found CNI network podman (type=bridge) at /etc/cni/net.d/87-podman-bridge.conflist"
00:00:00.029508 time="2019-12-22T18:24:57Z" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/var/run/containers/storage]repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:00.030141 Trying to pull repo.corp.pinger.com/docker-local/golang:1.13.5...time="2019-12-22T18:24:57Z" level=debug msg="reference rewritten from 'repo.corp.pinger.com/docker-local/golang:1.13.5' to 'repo.corp.pinger.com/docker-local/golang:1.13.5'"
00:00:00.030238 time="2019-12-22T18:24:57Z" level=debug msg="Trying to pull \"repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:00.030289 time="2019-12-22T18:24:57Z" level=debug msg="Using registries.d directory /etc/containers/registries.d for sigstore configuration"
00:00:00.030628 time="2019-12-22T18:24:57Z" level=debug msg=" Using \"default-docker\" configuration"
00:00:00.030713 time="2019-12-22T18:24:57Z" level=debug msg=" No signature storage configuration found for repo.corp.pinger.com/docker-local/golang:1.13.5"
00:00:00.030760 time="2019-12-22T18:24:57Z" level=debug msg="Looking for TLS certificates and private keys in /etc/docker/certs.d/repo.corp.pinger.com"
00:00:00.030805 time="2019-12-22T18:24:57Z" level=debug msg="GET https://repo.corp.pinger.com/v2/"
00:00:00.187697 time="2019-12-22T18:24:57Z" level=debug msg="Ping https://repo.corp.pinger.com/v2/ status 401"
00:00:00.187791 time="2019-12-22T18:24:57Z" level=debug msg="GET https://artifactory.corp.pinger.com:443/artifactory/api/docker/null/v2/token?account=larryp&scope=repository%3Adocker-local%2Fgolang%3Apull&service=artifactory.corp.pinger.com%3A443"
00:00:00.700629 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/manifests/1.13.5"
00:00:00.777273 time="2019-12-22T18:24:58Z" level=debug msg="Using blob info cache at /var/lib/containers/cache/blob-info-cache-v1.boltdb"
00:00:00.777355 time="2019-12-22T18:24:58Z" level=debug msg="IsRunningImageAllowed for image docker:repo.corp.pinger.com/docker-local/golang:1.13.5"
00:00:00.777426 time="2019-12-22T18:24:58Z" level=debug msg=" Using default policy section"
00:00:00.777468 time="2019-12-22T18:24:58Z" level=debug msg=" Requirement 0: allowed"
00:00:00.777521 time="2019-12-22T18:24:58Z" level=debug msg="Overall: allowed"
00:00:00.777581 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7"
00:00:00.777629 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7"
00:00:00.844449 Getting image source signatures
00:00:00.844506 time="2019-12-22T18:24:58Z" level=debug msg="Manifest has MIME type application/vnd.docker.distribution.manifest.v2+json, ordered candidate list [application/vnd.docker.distribution.manifest.v2+json, application/vnd.docker.distribution.manifest.v1+prettyjws, application/vnd.oci.image.manifest.v1+json, application/vnd.docker.distribution.manifest.v1+json]"
00:00:00.844546 time="2019-12-22T18:24:58Z" level=debug msg="... will first try using the original manifest unmodified"
00:00:00.845540 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271"
00:00:00.845597 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271"
00:00:00.846113 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab"
00:00:00.846246 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab"
00:00:00.846548 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469"
00:00:00.846620 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469"
00:00:00.846925 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5"
00:00:00.847004 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5"
00:00:00.847473 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed"
00:00:00.847555 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed"
00:00:00.847963 time="2019-12-22T18:24:58Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae"
00:00:00.848037 time="2019-12-22T18:24:58Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae"
00:00:01.032806 Copying blob sha256:5879af8e4ff2d56fe90f9472e209d1434992aa0d187c0131004604b2d862c271
00:00:01.032864 time="2019-12-22T18:24:58Z" level=debug msg="Detected compression format gzip"
00:00:01.032896 time="2019-12-22T18:24:58Z" level=debug msg="Using original blob without modification"
00:00:01.066056 Copying blob sha256:4c7ecf8e366fa7e930e07589f1d6a4353d0f6d1e8c34aafea6e8a637b0c7e9ab
00:00:01.066171 time="2019-12-22T18:24:58Z" level=debug msg="Detected compression format gzip"
00:00:01.066226 time="2019-12-22T18:24:58Z" level=debug msg="Using original blob without modification"
00:00:01.107741 Copying blob sha256:bea73dfc87cdeb7a72b53169749e7b3ecaec4e6b49930e958705d0fc10bff469
00:00:01.107896 time="2019-12-22T18:24:58Z" level=debug msg="Detected compression format gzip"
00:00:01.107970 time="2019-12-22T18:24:58Z" level=debug msg="Using original blob without modification"
00:00:01.141112 Copying blob sha256:56f728fa3ddba80e4a410f3d1c2e4f83d33ac1beb5605a7434c0821f6716b1b5
00:00:01.141273 time="2019-12-22T18:24:58Z" level=debug msg="Detected compression format gzip"
00:00:01.141338 time="2019-12-22T18:24:58Z" level=debug msg="Using original blob without modification"
00:00:01.685329 Copying blob sha256:78524344c0c59608daad0071dc32b07683238d0434af44394779cb7c723394ed
00:00:01.685439 time="2019-12-22T18:24:59Z" level=debug msg="Detected compression format gzip"
00:00:01.685491 time="2019-12-22T18:24:59Z" level=debug msg="Using original blob without modification"
00:00:02.618609 Copying blob sha256:184eb07e38451006ba28605348eb56a657d85a395856beed5937bf2755032eae
00:00:02.618751 time="2019-12-22T18:25:00Z" level=debug msg="Detected compression format gzip"
00:00:02.618799 time="2019-12-22T18:25:00Z" level=debug msg="Using original blob without modification"
00:00:06.036955 time="2019-12-22T18:25:03Z" level=debug msg="Downloading /v2/docker-local/golang/blobs/sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0"
00:00:06.037085 time="2019-12-22T18:25:03Z" level=debug msg="GET https://repo.corp.pinger.com/v2/docker-local/golang/blobs/sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0"
00:00:06.243622 Copying blob sha256:3a0f9001c6343723e0b1a3c1440fd67727b69d4a9e65946862adffc75d904ae0
00:00:06.243700 time="2019-12-22T18:25:03Z" level=debug msg="Detected compression format gzip"
00:00:06.243746 time="2019-12-22T18:25:03Z" level=debug msg="Using original blob without modification"
00:00:32.645337 Copying config sha256:a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7
00:00:32.645478 time="2019-12-22T18:25:30Z" level=debug msg="No compression detected"
00:00:32.645545 time="2019-12-22T18:25:30Z" level=debug msg="Using original blob without modification"
00:00:33.005459 Writing manifest to image destination
00:00:33.005590 Storing signatures
00:00:33.065806 time="2019-12-22T18:25:30Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/f2b4f0674ba3e6119088fe8a98c7921ed850c48d4d76e8caecd7f3d57721b4cb/diff"
00:00:36.962765 time="2019-12-22T18:25:34Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/2a567f2ad7fb6e902011911383f2a792de3ae39830b58084353d947981da4b0b/diff"
00:00:37.724189 time="2019-12-22T18:25:35Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/51f4237d89596ad592cdc809ea897fc002ce3ae38e903e623cd2ae0835cc87db/diff"
00:00:38.453604 time="2019-12-22T18:25:35Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/c203a5e0f15b2b1bc9f87453a1473ad7481a724c5e5414c2551f7c3cbf3de3e5/diff"
00:00:42.693125 time="2019-12-22T18:25:40Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/3ae3d6f27251054b01fee2ccf9014f2ef544682856f32d1b76215d62f869936b/diff"
00:00:47.580260 time="2019-12-22T18:25:44Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/42ef69203ad500d3d0f516ae4ea6efaa836e11277ea8b88f46b2d1327c6206eb/diff"
00:00:55.719362 time="2019-12-22T18:25:53Z" level=debug msg="Applying tar in /var/lib/containers/storage/overlay/5c2e5bd0c7b5a0a92bb7cdf77f18485a71feaebbbdf42c90abfc5b33f41319ab/diff"
00:00:55.935694 time="2019-12-22T18:25:53Z" level=debug msg="setting image creation date to 2019-12-05 22:19:54.952608448 +0000 UTC"
00:00:55.993986 time="2019-12-22T18:25:53Z" level=debug msg="created new image ID \"a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\""
00:00:56.160278 time="2019-12-22T18:25:53Z" level=debug msg="set names of image \"a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7\" to [repo.corp.pinger.com/docker-local/golang:1.13.5]"
00:00:56.382563 time="2019-12-22T18:25:53Z" level=debug msg="saved image metadata \"{}\""
00:00:56.478966 time="2019-12-22T18:25:53Z" level=debug msg="parsed reference into \"[overlay@/var/lib/containers/storage+/var/run/containers/storage]repo.corp.pinger.com/docker-local/golang:1.13.5\""
00:00:56.479108 a1072a0788901abf246e0447a8c4d409918a4fc93c8ad129981d448df4d75ca7

real 0m56.592s
user 1m23.781s
sys 0m16.101s
```
In this case it was faster but still significantly longer than docker, although I see that the copying config step took a long time, as opposed to the tar extraction.

[github-actions[bot]]

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

[vrothberg]

@larrypl, thanks for opening the issue!

I cannot reproduce your observation. Podman and Docker pull have quite the same performance. One observation I see in your logs is that the Podman binary is built with go 1.10 while Docker is built with go 1.12. This might have a significant impact on the download speed as both Podman and Docker are using golang's http stack.

Another problem with reproducing your observations is that there seems to be some kind of proxy (i.e., repo.corp.pinger.com/docker-local/golang:1.13.5).

[larrypl]

@vrothbert - thanks for taking a look!
I'm using the CentOS 7.6-provided docker (docker-ce) and podman; I didn't realize they used different versions of go - thanks for catching that! I'll see if I can test with a newer version of podman somewhere.
The repo.corp.pinger.com link is an Artifactory repository where the artifact actually resides, not a proxy, so I don't think that's part of the problem.

[larrypl]

@vrothbert - thanks for taking a look!
I'm using the CentOS 7.6-provided docker (docker-ce) and podman; I didn't realize they used different versions of go - thanks for catching that! I'll see if I can test with a newer version of podman somewhere.
The repo.corp.pinger.com link is an Artifactory repository where the artifact actually resides, not a proxy, so I don't think that's part of the problem.

[larrypl]

Initial tests seem to indicate that podman 1.4.4-4 is faster than 1.4.4-2!

[vrothberg]

Thanks for checking, @larrypl! I will close the issue. Feel free to re-open if you continue to see performance differences.