docker pull 和 push 的性能分析

从单docker daemon和registry之间的pull/push出发，分析docker pull/push 的瓶颈所在，为优化效率打下基础。

0. 测试环境

基本架构：没有docker index，所有操作发生在daemon和registry之间

镜像：

# docker images --tree   
Warning: '--tree' is deprecated, it will be removed soon. See usage.
├─9247a3750813 Virtual Size: 85.1 MB
│ └─a92b1d9f0ca5 Virtual Size: 1.078 GB Tags: 10.180.156.6:5000/bigtest2:latest

网络环境：docker daemon和registry之间为千兆网络，带宽足够大。

1. docker push 日志分析及registry put对比测试

在客户端做一次docker push的时候，观察registry端日志，刨去无关的一些日志后，如下：

10.180.156.11 - - [02/Apr/2015:03:25:55 +0000] "GET /v2/ HTTP/1.1" 404 233 "-" "Go 1.1 package http"
10.180.156.11 - - [02/Apr/2015:03:25:55 +0000] "GET /v1/_ping HTTP/1.1" 200 2 "-" "Go 1.1 package http"
02/Apr/2015:03:25:55 +0000 DEBUG: args = {'namespace': 'library', 'repository': u'bigtest2'}
02/Apr/2015:03:25:55 +0000 ERROR: <?xml version="1.0" encoding="UTF-8"?>
10.180.156.11 - - [02/Apr/2015:03:25:55 +0000] "PUT /v1/repositories/bigtest2/ HTTP/1.1" 200 2 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:25:55 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
02/Apr/2015:03:25:55 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
02/Apr/2015:03:25:55 +0000 DEBUG: api_error: Image not found
10.180.156.11 - - [02/Apr/2015:03:25:55 +0000] "GET /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:25:55 +0000 DEBUG: api_error: Image not found
10.180.156.11 - - [02/Apr/2015:03:25:55 +0000] "GET /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:25:55 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
10.180.156.11 - - [02/Apr/2015:03:25:56 +0000] "PUT /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/json HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
===3秒===
02/Apr/2015:03:25:57 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
===34秒===
10.180.156.11 - - [02/Apr/2015:03:26:31 +0000] "PUT /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/layer HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:26:31 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
10.180.156.11 - - [02/Apr/2015:03:26:31 +0000] "PUT /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/checksum HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:26:31 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
10.180.156.11 - - [02/Apr/2015:03:26:32 +0000] "PUT /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/json HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
===6秒===
02/Apr/2015:03:26:37 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
===325秒===
10.180.156.11 - - [02/Apr/2015:03:32:02 +0000] "PUT /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/layer HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:32:02 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
10.180.156.11 - - [02/Apr/2015:03:32:03 +0000] "PUT /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/checksum HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:32:03 +0000 DEBUG: args = {'tag': u'latest', 'namespace': 'library', 'repository': u'bigtest2'}
02/Apr/2015:03:32:03 +0000 DEBUG: [put_tag] namespace=library; repository=bigtest2; tag=latest
10.180.156.11 - - [02/Apr/2015:03:32:03 +0000] "PUT /v1/repositories/bigtest2/tags/latest HTTP/1.1" 200 4 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:03:32:03 +0000 DEBUG: args = {'images': True, 'namespace': 'library', 'repository': u'bigtest2'}
10.180.156.11 - - [02/Apr/2015:03:32:03 +0000] "PUT /v1/repositories/bigtest2/images HTTP/1.1" 204 - "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"

可以发现，对于一个2层的镜像，整个push的时间可以分成几段

操作|耗时|百分比
|:—-|:—|:—
put json1|3s|0.8%
put layer1|34s|9.2%
put json2|6s|1.6%
put layer2|325s|87.6%
总耗时|371s|100%

也就是说，在做put layer1和put layer2时消耗了96.8%的时间。那么，纯的对registry服务做同样文件的PUT操作，会消耗多少时间呢？

# time curl -X PUT  -H "Transfer-Encoding: chunked" --data-binary @layer-a92b1 "http://10.180.156.6:5000/v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/layer"
true
real    0m44.571s
user    0m0.302s
sys 0m1.341s

# time curl -X PUT  -H "Transfer-Encoding: chunked" --data-binary @layer-9247a "http://10.180.156.6:5000/v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/layer"
true
real    0m4.277s
user    0m0.029s
sys 0m0.130s

2. docker pull 日志分析及registry get对比测试

类似上个节，继续做pull的日志分析

10.180.156.11 - - [02/Apr/2015:08:54:16 +0000] "GET /v2/ HTTP/1.1" 404 233 "-" "Go 1.1 package http"
10.180.156.11 - - [02/Apr/2015:08:54:16 +0000] "GET /v1/_ping HTTP/1.1" 200 2 "-" "Go 1.1 package http"
02/Apr/2015:08:54:16 +0000 DEBUG: args = {'namespace': 'library', 'repository': u'bigtest2'}
10.180.156.11 - - [02/Apr/2015:08:54:16 +0000] "GET /v1/repositories/bigtest2/images HTTP/1.1" 200 152 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:54:16 +0000 DEBUG: args = {'namespace': u'library', 'repository': u'bigtest2'}
02/Apr/2015:08:54:16 +0000 DEBUG: [get_tags] namespace=library; repository=bigtest2
10.180.156.11 - - [02/Apr/2015:08:54:16 +0000] "GET /v1/repositories/library/bigtest2/tags HTTP/1.1" 200 78 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:54:16 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
10.180.156.11 - - [02/Apr/2015:08:54:16 +0000] "GET /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/ancestry HTTP/1.1" 200 136 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:54:16 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
10.180.156.11 - - [02/Apr/2015:08:54:17 +0000] "GET /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/json HTTP/1.1" 200 619 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:54:17 +0000 DEBUG: args = {'image_id': u'9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f'}
===6秒===
10.180.156.11 - - [02/Apr/2015:08:54:23 +0000] "GET /v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/layer HTTP/1.1" 200 37124367 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:54:24 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
===42秒===
02/Apr/2015:08:55:06 +0000 DEBUG: api_error: Image not found
10.180.156.11 - - [02/Apr/2015:08:55:06 +0000] "GET /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/json HTTP/1.1" 404 28 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:55:06 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
10.180.156.11 - - [02/Apr/2015:08:55:06 +0000] "GET /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/json HTTP/1.1" 200 1172 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"
02/Apr/2015:08:55:07 +0000 DEBUG: args = {'image_id': u'a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5'}
===2秒===
10.180.156.11 - - [02/Apr/2015:08:56:08 +0000] "GET /v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/layer HTTP/1.1" 200 420084375 "-" "docker/1.5.0 go/go1.4.1 git-commit/a8a31ef kernel/3.13.0-32-generic os/linux arch/amd64"

可以发现，对于一个2层的镜像，整个pull的时间可以分成几段

操作|耗时|百分比
|:—-|:—|:—
get json1|6s|5.1%
get layer1|42s|36.2%
get json2|0s|0%
get layer2|2s|1.7%
总耗时|116s|100%

对比直接从registry上get测试

# time curl -X GET  -H "Transfer-Encoding: chunked" -o layer-9247a-down "http://10.180.156.6:5000/v1/images/9247a37508136a5fe916f4f87bfa2aa47f2edf8fc1a1ce787445b606d8fdbf9f/layer"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100 35.4M  100 35.4M    0     0  25.3M      0  0:00:01  0:00:01 --:--:-- 25.3M

real    0m1.409s
user    0m0.036s
sys 0m0.233s

# time curl -X GET  -H "Transfer-Encoding: chunked" -o layer-a92b1-down "http://10.180.156.6:5000/v1/images/a92b1d9f0ca59cefd024a5f2f2d23e2d617b3e67cc2363c94998006fa87e60e5/layer"
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  400M  100  400M    0     0  19.2M      0  0:00:20  0:00:20 --:--:-- 24.5M

real    0m20.771s
user    0m0.381s
sys 0m2.501s

3. 结论

从单个操作看，docker push/pull的50%以上的耗时在docker daemon，做分层、打tar包、checksum等。在这方面registry层的优化已经意义不大。

(责任编辑：IT)

搜索

热门标签: