接口耗时分析

使用 HttpRunner 实现 HTTP(S) 接口耗时分析

在对 HTTP 接口做测试时,大多数时候我们只需要关注接口的整体耗时。那如果测试发现接口整体耗时较长,我们是否可以更进一步地分析原因呢?

实际上,单次 HTTP(S) 请求是会包含多个步骤的,依次包括 DNS 解析、TCP 连接、TLS 握手、服务端处理、数据传输 5 个环节;如果是 HTTP 协议,由于少了 TLS 握手环节,因此会包含 4 个环节。

HttpRunner 从 v4.0 版本开始,新增支持了 HTTP 接口耗时详情的采集能力,我们可以通过该能力实现对接口整体耗时的诊断分析。

采集耗时详情

默认情况下,通过 hrp run 执行接口测试时,接口耗时详情信息是不会采集的。如果要开启,只需要增加一个参数 --http-stat 即可。

示例如下:

$ hrp run demo/testcases/demo_requests.yml --http-stat
查看运行日志
$ hrp startproject demo
$ hrp run demo/testcases/demo_requests.yml --http-stat
4:40PM INF Set log to color console other than JSON format.
4:40PM ??? Set log level
4:40PM INF [init] SetFailfast failfast=true
4:40PM INF [init] SetSaveTests saveTests=false
4:40PM INF [init] SetRequestsLogOn
4:40PM INF [init] SetHTTPStatOn
4:40PM INF load file path=demo/testcases/demo_requests.yml
4:40PM INF load testcases successfully count=1
4:40PM INF ensure python3 venv packages=["funppy"] python3=/Users/debugtalk/.hrp/venv/bin/python3
4:40PM INF python package is ready name=funppy version=0.4.3
4:40PM INF load hashicorp go plugin success path=/Users/debugtalk/MyProjects/HttpRunner-dev/httprunner/demo/debugtalk.py
4:40PM INF reset session runner
4:40PM INF run testcase start testcase="request methods testcase with functions"
4:40PM INF reset session runner
4:40PM INF run step start step="get with params" type=request-GET
4:40PM INF function GetNames called on host side
4:40PM INF call function via gRPC funcArgs=[1,2] funcName=sum_two_int
4:40PM INF call function success arguments=[1,2] funcName=sum_two_int output=3
4:40PM INF function GetNames called on host side
4:40PM INF call function via gRPC funcArgs=[] funcName=get_version
4:40PM INF call function success arguments=[] funcName=get_version output=0.4.3
-------------------- request --------------------
GET /get?foo1=bar11&foo2=bar21&sum_v=3 HTTP/1.1
Host: postman-echo.com
User-Agent: funplugin/0.4.3


==================== response ====================
Connected via TLSv1.2
HTTP/1.1 200 OK
Content-Length: 327
Connection: keep-alive
Content-Type: application/json; charset=utf-8
Date: Wed, 18 May 2022 08:40:45 GMT
Etag: W/"147-DFCO30rOwPI+4rpOE3phvU5pr+g"
Set-Cookie: sails.sid=s%3AkBCJ7WYvEkqRbTv2pC-gpM0rJQAYQ-6k.xYX5y2I%2B2pLRBkYF%2BBcfbo8V%2F8kMyTJM2ZxqqBSn1MM; Path=/; HttpOnly
Vary: Accept-Encoding

{"args":{"foo1":"bar11","foo2":"bar21","sum_v":"3"},"headers":{"x-forwarded-proto":"https","x-forwarded-port":"443","host":"postman-echo.com","x-amzn-trace-id":"Root=1-6284b10d-2636c23a45cb846420f8983f","user-agent":"funplugin/0.4.3","accept-encoding":"gzip"},"url":"https://postman-echo.com/get?foo1=bar11&foo2=bar21&sum_v=3"}
--------------------------------------------------

Connected to tcp: 34.205.194.84:443

  DNS Lookup   TCP Connection   TLS Handshake   Server Processing   Content Transfer
[     40ms  |         284ms  |        579ms  |            359ms  |             0ms  ]
            |                |               |                   |                  |
   namelookup:40ms           |               |                   |                  |
                       connect:325ms         |                   |                  |
                                   pretransfer:905ms             |                  |
                                                     starttransfer:1264ms           |
                                                                                total:1264ms

4:40PM INF HTTP latency statistics httpstat(ms)={"Connect":325,"ContentTransfer":0,"DNSLookup":40,"NameLookup":40,"Pretransfer":905,"ServerProcessing":359,"StartTransfer":1264,"TCPConnection":284,"TLSHandshake":579,"Total":1264}
4:40PM INF extract value from=body.args.foo2 value=bar21
4:40PM INF set variable value=bar21 variable=foo3
4:40PM INF validate status_code assertMethod=eq checkExpr=status_code checkValue=200 checkValueType=int64 expectValue=200 expectValueType=int64 result=true
4:40PM INF validate body.args.foo1 assertMethod=eq checkExpr=body.args.foo1 checkValue=bar11 checkValueType=string expectValue=bar11 expectValueType=string result=true
4:40PM INF validate body.args.sum_v assertMethod=eq checkExpr=body.args.sum_v checkValue=3 checkValueType=string expectValue=3 expectValueType=string result=true
4:40PM INF validate body.args.foo2 assertMethod=eq checkExpr=body.args.foo2 checkValue=bar21 checkValueType=string expectValue=bar21 expectValueType=string result=true
4:40PM INF run step end exportVars={"foo3":"bar21"} step="get with params" success=true type=request
4:40PM INF run step start step="post raw text" type=request-POST
4:40PM INF call function via gRPC funcArgs=[] funcName=get_version
4:40PM INF call function success arguments=[] funcName=get_version output=0.4.3
-------------------- request --------------------
POST /post HTTP/1.1
Host: postman-echo.com
Content-Type: text/plain
User-Agent: funplugin/0.4.3

This is expected to be sent back as part of response body: bar12-config_bar2-bar32.
==================== response ====================
Connected via TLSv1.2
HTTP/1.1 200 OK
Content-Length: 433
Connection: keep-alive
Content-Type: application/json; charset=utf-8
Date: Wed, 18 May 2022 08:40:46 GMT
Etag: W/"1b1-5kSLP1LVtSRaFElEIXrDWLjtj/Q"
Set-Cookie: sails.sid=s%3A977L0stmdaA5kpweNYd-7xxMItFdhEDX.XYOoDmmav6hi1OJn6L1SAAlKg%2B8Y2XRnx4rShvgGoLc; Path=/; HttpOnly
Vary: Accept-Encoding

{"args":{},"data":"This is expected to be sent back as part of response body: bar12-config_bar2-bar32.","files":{},"form":{},"headers":{"x-forwarded-proto":"https","x-forwarded-port":"443","host":"postman-echo.com","x-amzn-trace-id":"Root=1-6284b10e-556c7d5c1aebb6d87ef2715b","content-length":"83","user-agent":"funplugin/0.4.3","content-type":"text/plain","accept-encoding":"gzip"},"json":null,"url":"https://postman-echo.com/post"}
--------------------------------------------------

  DNS Lookup   TCP Connection   TLS Handshake   Server Processing   Content Transfer
[      0ms  |           0ms  |          0ms  |            296ms  |             0ms  ]
            |                |               |                   |                  |
   namelookup:0ms            |               |                   |                  |
                       connect:0ms           |                   |                  |
                                   pretransfer:0ms               |                  |
                                                     starttransfer:296ms            |
                                                                                total:296ms

4:40PM INF HTTP latency statistics httpstat(ms)={"Connect":0,"ContentTransfer":0,"DNSLookup":0,"NameLookup":0,"Pretransfer":0,"ServerProcessing":296,"StartTransfer":296,"TCPConnection":0,"TLSHandshake":0,"Total":296}
4:40PM INF validate status_code assertMethod=eq checkExpr=status_code checkValue=200 checkValueType=int64 expectValue=200 expectValueType=int64 result=true
4:40PM INF validate body.data assertMethod=eq checkExpr=body.data checkValue="This is expected to be sent back as part of response body: bar12-config_bar2-bar32." checkValueType=string expectValue="This is expected to be sent back as part of response body: bar12-config_bar2-bar32." expectValueType=string result=true
4:40PM INF run step end exportVars=null step="post raw text" success=true type=request
4:40PM INF run step start step="post form data" type=request-POST
4:40PM INF call function via gRPC funcArgs=[] funcName=get_version
4:40PM INF call function success arguments=[] funcName=get_version output=0.4.3
-------------------- request --------------------
POST /post HTTP/1.1
Host: postman-echo.com
Content-Type: application/x-www-form-urlencoded
User-Agent: funplugin/0.4.3

foo1=config_bar1&foo2=bar23&foo3=bar21
==================== response ====================
Connected via TLSv1.2
HTTP/1.1 200 OK
Content-Length: 471
Connection: keep-alive
Content-Type: application/json; charset=utf-8
Date: Wed, 18 May 2022 08:40:46 GMT
Etag: W/"1d7-Q1SNpWmnmggpXlXx7yOS+xlhpp8"
Set-Cookie: sails.sid=s%3AFc8Du4G-VTCrgjl3A-rqp5_bP8dns2OQ.bSxaAM07Nl%2FIg7mLzqFYzhGy1EtlaXrj4Y3d9aNQ%2FJM; Path=/; HttpOnly
Vary: Accept-Encoding

{"args":{},"data":"","files":{},"form":{"foo1":"config_bar1","foo2":"bar23","foo3":"bar21"},"headers":{"x-forwarded-proto":"https","x-forwarded-port":"443","host":"postman-echo.com","x-amzn-trace-id":"Root=1-6284b10e-3c2749a8025fdf4d3eb177b2","content-length":"38","user-agent":"funplugin/0.4.3","content-type":"application/x-www-form-urlencoded","accept-encoding":"gzip"},"json":{"foo1":"config_bar1","foo2":"bar23","foo3":"bar21"},"url":"https://postman-echo.com/post"}
--------------------------------------------------

  DNS Lookup   TCP Connection   TLS Handshake   Server Processing   Content Transfer
[      0ms  |           0ms  |          0ms  |            346ms  |             3ms  ]
            |                |               |                   |                  |
   namelookup:0ms            |               |                   |                  |
                       connect:0ms           |                   |                  |
                                   pretransfer:0ms               |                  |
                                                     starttransfer:346ms            |
                                                                                total:349ms

4:40PM INF HTTP latency statistics httpstat(ms)={"Connect":0,"ContentTransfer":3,"DNSLookup":0,"NameLookup":0,"Pretransfer":0,"ServerProcessing":346,"StartTransfer":346,"TCPConnection":0,"TLSHandshake":0,"Total":349}
4:40PM INF validate status_code assertMethod=eq checkExpr=status_code checkValue=200 checkValueType=int64 expectValue=200 expectValueType=int64 result=true
4:40PM INF validate body.form.foo1 assertMethod=eq checkExpr=body.form.foo1 checkValue=config_bar1 checkValueType=string expectValue=config_bar1 expectValueType=string result=true
4:40PM INF validate body.form.foo2 assertMethod=eq checkExpr=body.form.foo2 checkValue=bar23 checkValueType=string expectValue=bar23 expectValueType=string result=true
4:40PM INF validate body.form.foo3 assertMethod=eq checkExpr=body.form.foo3 checkValue=bar21 checkValueType=string expectValue=bar21 expectValueType=string result=true
4:40PM INF run step end exportVars=null step="post form data" success=true type=request
4:40PM INF run testcase end testcase="request methods testcase with functions"
4:40PM INF quit hashicorp plugin process

查看耗时详情

在上面的运行日志中,可以在接口的响应中看到如下信息:

  • 当次 HTTP 请求连接的服务器 IP:Port
  • 当次 HTTP 请求的详细耗时

生成 summary 文件

如果我们还想将 HTTP 接口耗时详情数据保存为结构化的数据,那我们可以再额外指定 -s--save-tests 参数,即可存储到 summary.json 文件。

$ hrp run demo/testcases/demo_requests.yml --http-stat --save-tests

在生成的 summary.json 文件中,会新增一个 httpstat 字段。

"httpstat": {
    "Connect": 313,
    "ContentTransfer": 0,
    "DNSLookup": 10,
    "NameLookup": 10,
    "Pretransfer": 868,
    "ServerProcessing": 487,
    "StartTransfer": 1355,
    "TCPConnection": 302,
    "TLSHandshake": 554,
    "Total": 1356
},
查看完整 summary.json
{
    "success": true,
    "stat": {
        "testcases": {
            "total": 1,
            "success": 1,
            "fail": 0
        },
        "teststeps": {
            "total": 3,
            "successes": 3,
            "failures": 0
        }
    },
    "time": {
        "start_at": "2022-05-18T17:48:11.302224+08:00",
        "duration": 3.017276084
    },
    "platform": {
        "httprunner_version": "v4.1.0-alpha",
        "go_version": "go1.16.3",
        "platform": "darwin-amd64"
    },
    "details": [
        {
            "name": "request methods testcase with functions",
            "success": true,
            "stat": {
                "total": 3,
                "successes": 3,
                "failures": 0
            },
            "time": {
                "start_at": "2022-05-18T17:48:12.393419+08:00",
                "duration": 1.9261071140000001
            },
            "in_out": {
                "config_vars": {
                    "expect_foo1": "config_bar1",
                    "expect_foo2": "config_bar2",
                    "foo1": "config_bar1",
                    "foo2": "config_bar2"
                },
                "export_vars": {
                    "foo3": "bar21"
                }
            },
            "records": [
                {
                    "name": "get with params",
                    "step_type": "request",
                    "success": true,
                    "elapsed_ms": 1356,
                    "httpstat": {
                        "Connect": 313,
                        "ContentTransfer": 0,
                        "DNSLookup": 10,
                        "NameLookup": 10,
                        "Pretransfer": 868,
                        "ServerProcessing": 487,
                        "StartTransfer": 1355,
                        "TCPConnection": 302,
                        "TLSHandshake": 554,
                        "Total": 1356
                    },
                    "data": {
                        "success": true,
                        "req_resps": {
                            "request": {
                                "headers": {
                                    "User-Agent": "funplugin/0.4.3"
                                },
                                "method": "GET",
                                "params": {
                                    "foo1": "bar11",
                                    "foo2": "bar21",
                                    "sum_v": 3
                                },
                                "url": "/get"
                            },
                            "response": {
                                "body": "{\n    \"args\": {\n    \"foo1\": \"bar11\",\n    \"foo2\": \"bar21\",\n    \"sum_v\": \"3\"\n},\n    \"headers\": {\n    \"accept-encoding\": \"gzip\",\n    \"host\": \"postman-echo.com\",\n    \"user-agent\": \"funplugin/0.4.3\",\n    \"x-amzn-trace-id\": \"Root=1-6284c0dd-5979be0b353e154c3c196ef6\",\n    \"x-forwarded-port\": \"443\",\n    \"x-forwarded-proto\": \"https\"\n},\n    \"url\": \"https://postman-echo.com/get?foo1=bar11\\u0026foo2=bar21\\u0026sum_v=3\"\n}",
                                "cookies": {
                                    "sails.sid": "s%3APe-sKLKTurWDcSqQs5K1xq_k0f2yjA04.ow4l8OLzWTQrhFZ0XqvFjvhiFNW2CdJitQs6w9Xdf9g"
                                },
                                "headers": {
                                    "Connection": "keep-alive",
                                    "Content-Length": "327",
                                    "Content-Type": "application/json; charset=utf-8",
                                    "Date": "Wed, 18 May 2022 09:48:13 GMT",
                                    "Etag": "W/\"147-FN1NxFZ5B4Vt2onH1Pi1CRYRsMw\"",
                                    "Set-Cookie": "sails.sid=s%3APe-sKLKTurWDcSqQs5K1xq_k0f2yjA04.ow4l8OLzWTQrhFZ0XqvFjvhiFNW2CdJitQs6w9Xdf9g; Path=/; HttpOnly",
                                    "Vary": "Accept-Encoding"
                                },
                                "proto": "HTTP/1.1",
                                "status_code": 200
                            }
                        },
                        "validators": [
                            {
                                "check": "status_code",
                                "assert": "eq",
                                "expect": 200,
                                "check_value": 200,
                                "check_result": "pass"
                            },
                            {
                                "check": "body.args.foo1",
                                "assert": "eq",
                                "expect": "bar11",
                                "check_value": "bar11",
                                "check_result": "pass"
                            },
                            {
                                "check": "body.args.sum_v",
                                "assert": "eq",
                                "expect": "3",
                                "check_value": "3",
                                "check_result": "pass"
                            },
                            {
                                "check": "body.args.foo2",
                                "assert": "eq",
                                "expect": "bar21",
                                "check_value": "bar21",
                                "check_result": "pass"
                            }
                        ]
                    },
                    "content_size": 327,
                    "export_vars": {
                        "foo3": "bar21"
                    }
                },
                {
                    "name": "post raw text",
                    "step_type": "request",
                    "success": true,
                    "elapsed_ms": 279,
                    "httpstat": {
                        "Connect": 0,
                        "ContentTransfer": 0,
                        "DNSLookup": 0,
                        "NameLookup": 0,
                        "Pretransfer": 0,
                        "ServerProcessing": 278,
                        "StartTransfer": 278,
                        "TCPConnection": 0,
                        "TLSHandshake": 0,
                        "Total": 279
                    },
                    "data": {
                        "success": true,
                        "req_resps": {
                            "request": {
                                "body": "This is expected to be sent back as part of response body: bar12-config_bar2-bar32.",
                                "data": "This is expected to be sent back as part of response body: $foo1-$foo2-$foo3.",
                                "headers": {
                                    "Content-Type": "text/plain",
                                    "User-Agent": "funplugin/0.4.3"
                                },
                                "method": "POST",
                                "url": "/post"
                            },
                            "response": {
                                "body": "{\n    \"args\": {\n    \n},\n    \"data\": \"This is expected to be sent back as part of response body: bar12-config_bar2-bar32.\",\n    \"files\": {\n    \n},\n    \"form\": {\n    \n},\n    \"headers\": {\n    \"accept-encoding\": \"gzip\",\n    \"content-length\": \"83\",\n    \"content-type\": \"text/plain\",\n    \"host\": \"postman-echo.com\",\n    \"user-agent\": \"funplugin/0.4.3\",\n    \"x-amzn-trace-id\": \"Root=1-6284c0dd-1b706c817978b13925ac792f\",\n    \"x-forwarded-port\": \"443\",\n    \"x-forwarded-proto\": \"https\"\n},\n    \"json\": null,\n    \"url\": \"https://postman-echo.com/post\"\n}",
                                "cookies": {
                                    "sails.sid": "s%3AoGlPJKhkyFGgMNO6dRTrnUQXkOFcDV7J.rWIbyDkCGdPUTVbwUfY3FOXaM2cpB2UqTD3WeJoysYM"
                                },
                                "headers": {
                                    "Connection": "keep-alive",
                                    "Content-Length": "433",
                                    "Content-Type": "application/json; charset=utf-8",
                                    "Date": "Wed, 18 May 2022 09:48:13 GMT",
                                    "Etag": "W/\"1b1-WQ+Yr/smdfmnFbXNXSAqoNA3NEE\"",
                                    "Set-Cookie": "sails.sid=s%3AoGlPJKhkyFGgMNO6dRTrnUQXkOFcDV7J.rWIbyDkCGdPUTVbwUfY3FOXaM2cpB2UqTD3WeJoysYM; Path=/; HttpOnly",
                                    "Vary": "Accept-Encoding"
                                },
                                "proto": "HTTP/1.1",
                                "status_code": 200
                            }
                        },
                        "validators": [
                            {
                                "check": "status_code",
                                "assert": "eq",
                                "expect": 200,
                                "check_value": 200,
                                "check_result": "pass"
                            },
                            {
                                "check": "body.data",
                                "assert": "eq",
                                "expect": "This is expected to be sent back as part of response body: bar12-config_bar2-bar32.",
                                "check_value": "This is expected to be sent back as part of response body: bar12-config_bar2-bar32.",
                                "check_result": "pass"
                            }
                        ]
                    },
                    "content_size": 433
                },
                {
                    "name": "post form data",
                    "step_type": "request",
                    "success": true,
                    "elapsed_ms": 281,
                    "httpstat": {
                        "Connect": 0,
                        "ContentTransfer": 2,
                        "DNSLookup": 0,
                        "NameLookup": 0,
                        "Pretransfer": 0,
                        "ServerProcessing": 278,
                        "StartTransfer": 278,
                        "TCPConnection": 0,
                        "TLSHandshake": 0,
                        "Total": 281
                    },
                    "data": {
                        "success": true,
                        "req_resps": {
                            "request": {
                                "body": "foo1=config_bar1&foo2=bar23&foo3=bar21",
                                "data": "foo1=$foo1&foo2=$foo2&foo3=$foo3",
                                "headers": {
                                    "Content-Type": "application/x-www-form-urlencoded",
                                    "User-Agent": "funplugin/0.4.3"
                                },
                                "method": "POST",
                                "url": "/post"
                            },
                            "response": {
                                "body": "{\n    \"args\": {\n    \n},\n    \"data\": \"\",\n    \"files\": {\n    \n},\n    \"form\": {\n    \"foo1\": \"config_bar1\",\n    \"foo2\": \"bar23\",\n    \"foo3\": \"bar21\"\n},\n    \"headers\": {\n    \"accept-encoding\": \"gzip\",\n    \"content-length\": \"38\",\n    \"content-type\": \"application/x-www-form-urlencoded\",\n    \"host\": \"postman-echo.com\",\n    \"user-agent\": \"funplugin/0.4.3\",\n    \"x-amzn-trace-id\": \"Root=1-6284c0de-7f630abf452e3ed902142dbb\",\n    \"x-forwarded-port\": \"443\",\n    \"x-forwarded-proto\": \"https\"\n},\n    \"json\": {\n    \"foo1\": \"config_bar1\",\n    \"foo2\": \"bar23\",\n    \"foo3\": \"bar21\"\n},\n    \"url\": \"https://postman-echo.com/post\"\n}",
                                "cookies": {
                                    "sails.sid": "s%3Ad4GCMWZYweUHgfRn3NuhmVbnuXWPu5ZB.4huCHJKsnJdJmcPO06Xbm%2BethQarbyuFJ%2ByGJedYEfo"
                                },
                                "headers": {
                                    "Connection": "keep-alive",
                                    "Content-Length": "471",
                                    "Content-Type": "application/json; charset=utf-8",
                                    "Date": "Wed, 18 May 2022 09:48:14 GMT",
                                    "Etag": "W/\"1d7-vanGqEJBDhXGImIQEVhDyL56LlQ\"",
                                    "Set-Cookie": "sails.sid=s%3Ad4GCMWZYweUHgfRn3NuhmVbnuXWPu5ZB.4huCHJKsnJdJmcPO06Xbm%2BethQarbyuFJ%2ByGJedYEfo; Path=/; HttpOnly",
                                    "Vary": "Accept-Encoding"
                                },
                                "proto": "HTTP/1.1",
                                "status_code": 200
                            }
                        },
                        "validators": [
                            {
                                "check": "status_code",
                                "assert": "eq",
                                "expect": 200,
                                "check_value": 200,
                                "check_result": "pass"
                            },
                            {
                                "check": "body.form.foo1",
                                "assert": "eq",
                                "expect": "config_bar1",
                                "check_value": "config_bar1",
                                "check_result": "pass"
                            },
                            {
                                "check": "body.form.foo2",
                                "assert": "eq",
                                "expect": "bar23",
                                "check_value": "bar23",
                                "check_result": "pass"
                            },
                            {
                                "check": "body.form.foo3",
                                "assert": "eq",
                                "expect": "bar21",
                                "check_value": "bar21",
                                "check_result": "pass"
                            }
                        ]
                    },
                    "content_size": 471
                }
            ],
            "root_dir": ""
        }
    ]
}