Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

add connection times histogram #626

Merged
merged 7 commits into from Sep 19, 2022
Merged

add connection times histogram #626

merged 7 commits into from Sep 19, 2022

Conversation

ldemailly
Copy link
Member

As you requested @howardjohn

ex.:

% go run . load -a  -connection-reuse 4 -n 32 -c 4 -nocatchup -qps 4  https://httpbin.org/status/200
Fortio dev running at 4 queries per second, 8->8 procs, for 32 calls: https://httpbin.org/status/200
16:36:56 I httprunner.go:102> Starting http test for https://httpbin.org/status/200 with 4 threads at 4.0 qps and parallel warmup, with connection reuse [4, 4]
Starting at 4 qps with 4 thread(s) [gomax 8] : exactly 32, 8 calls each (total 32 + 0)
16:37:04 I periodic.go:808> T003 ended after 8.07513475s : 8 calls. qps=0.9906955422632421
16:37:04 I periodic.go:808> T001 ended after 8.075134834s : 8 calls. qps=0.9906955319577269
16:37:04 I periodic.go:808> T002 ended after 8.075261667s : 8 calls. qps=0.990679971732983
16:37:04 I periodic.go:808> T000 ended after 8.279228959s : 8 calls. qps=0.9662735551362592
Ended after 8.279327584s : 32 calls. qps=3.865
Sleep times : count 28 avg 0.96779572 +/- 0.1425 min 0.677604017 max 1.070371576 sum 27.09828
Aggregated Function Time : count 32 avg 0.16807453 +/- 0.138 min 0.07142125 max 0.465166625 sum 5.37838488
# range, mid point, percentile, count
>= 0.0714213 <= 0.08 , 0.0757106 , 65.62, 21
> 0.18 <= 0.2 , 0.19 , 68.75, 1
> 0.25 <= 0.3 , 0.275 , 75.00, 2
> 0.3 <= 0.35 , 0.325 , 87.50, 4
> 0.35 <= 0.4 , 0.375 , 90.62, 1
> 0.45 <= 0.465167 , 0.457583 , 100.00, 3
# target 50% 0.0778553
# target 75% 0.3
# target 90% 0.39
# target 99% 0.463549
# target 99.9% 0.465005
Error cases : no data
# Socket and IP used for each connection:
[0]   2 socket used, resolved to [18.207.88.57:443] connection timing : count 2 avg 0.24029735 +/- 0.0102 min 0.23009375 max 0.250500958 sum 0.480594708
[1]   2 socket used, resolved to [52.45.189.24:443 (1), 54.236.79.58:443 (1)] connection timing : count 2 avg 0.24741869 +/- 0.01099 min 0.236425167 max 0.258412209 sum 0.494837376
[2]   2 socket used, resolved to [44.207.168.240:443] connection timing : count 2 avg 0.24210123 +/- 0.01765 min 0.224453083 max 0.259749375 sum 0.484202458
[3]   2 socket used, resolved to [54.236.79.58:443 (1), 52.45.189.24:443 (1)] connection timing : count 2 avg 0.24513125 +/- 0.00845 min 0.236681084 max 0.253581417 sum 0.490262501
Connection time histogram (s) : count 8 avg 0.24373713 +/- 0.01263 min 0.224453083 max 0.259749375 sum 1.94989704
# range, mid point, percentile, count
>= 0.224453 <= 0.25 , 0.237227 , 50.00, 4
> 0.25 <= 0.259749 , 0.254875 , 100.00, 4
# target 50% 0.25
# target 75% 0.254875
# target 90% 0.2578
# target 99% 0.259554
# target 99.9% 0.25973
Sockets used: 8 (for perfect keepalive, would be 4)
Uniform: false, Jitter: false
IP addresses distribution:
54.236.79.58:443: 2
44.207.168.240:443: 2
18.207.88.57:443: 2
52.45.189.24:443: 2
Code 200 : 32 (100.0 %)
Response Header Sizes : count 32 avg 236 +/- 0 min 236 max 236 sum 7552
Response Body/Total Sizes : count 32 avg 236 +/- 0 min 236 max 236 sum 7552
All done 32 calls (plus 0 warmup) 168.075 ms avg, 3.9 qps
Successfully wrote 4003 bytes of Json data to 2022-09-18-163656_httpbin_org_status_200_MacBook_Air.json

You can see connection time min/avg/p50 is higher than total time min/avg/p50 (because we reuse each socket 4x so amortize down in this case)

{
  "RunType": "HTTP",
  "Labels": "httpbin.org/status/200 , MacBook-Air",
  "StartTime": "2022-09-18T16:36:56.296767-07:00",
  "RequestedQPS": "4",
  "RequestedDuration": "exactly 32 calls",
  "ActualQPS": 3.865048178772485,
  "ActualDuration": 8279327584,
  "NumThreads": 4,
  "Version": "dev",
  "DurationHistogram": {
    "Count": 32,
    "Min": 0.07142125,
    "Max": 0.465166625,
    "Sum": 5.378384876,
    "Avg": 0.168074527375,
    "StdDev": 0.13797295167128187,
    "Data": [
      {
        "Start": 0.07142125,
        "End": 0.08,
        "Percent": 65.625,
        "Count": 21
      },
      {
        "Start": 0.18,
        "End": 0.2,
        "Percent": 68.75,
        "Count": 1
      },
      {
        "Start": 0.25,
        "End": 0.3,
        "Percent": 75,
        "Count": 2
      },
      {
        "Start": 0.3,
        "End": 0.35000000000000003,
        "Percent": 87.5,
        "Count": 4
      },
      {
        "Start": 0.35000000000000003,
        "End": 0.4,
        "Percent": 90.625,
        "Count": 1
      },
      {
        "Start": 0.45,
        "End": 0.465166625,
        "Percent": 100,
        "Count": 3
      }
    ],
    "Percentiles": [
      {
        "Percentile": 50,
        "Value": 0.0778553125
      },
      {
        "Percentile": 75,
        "Value": 0.3
      },
      {
        "Percentile": 90,
        "Value": 0.39
      },
      {
        "Percentile": 99,
        "Value": 0.46354885166666665
      },
      {
        "Percentile": 99.9,
        "Value": 0.46500484766666667
      }
    ]
  },
  "ErrorsDurationHistogram": {
    "Count": 0,
    "Min": 0,
    "Max": 0,
    "Sum": 0,
    "Avg": 0,
    "StdDev": 0,
    "Data": null
  },
  "Exactly": 32,
  "Jitter": false,
  "Uniform": false,
  "NoCatchUp": true,
  "RunID": 0,
  "AccessLoggerInfo": "",
  "ID": "2022-09-18-163656_httpbin_org_status_200_MacBook_Air",
  "RetCodes": {
    "200": 32
  },
  "IPCountMap": {
    "18.207.88.57:443": 2,
    "44.207.168.240:443": 2,
    "52.45.189.24:443": 2,
    "54.236.79.58:443": 2
  },
  "Insecure": false,
  "CACert": "",
  "Cert": "",
  "Key": "",
  "UnixDomainSocket": "",
  "URL": "https://httpbin.org/status/200",
  "NumConnections": 1,
  "Compression": false,
  "DisableFastClient": false,
  "HTTP10": false,
  "DisableKeepAlive": false,
  "AllowHalfClose": false,
  "FollowRedirects": false,
  "Resolve": "",
  "HTTPReqTimeOut": 3000000000,
  "UserCredentials": "",
  "ContentType": "",
  "Payload": "",
  "LogErrors": true,
  "SequentialWarmup": false,
  "ConnReuseRange": [
    4,
    4
  ],
  "NoResolveEachConn": false,
  "Offset": 0,
  "Resolution": 0.001,
  "Sizes": {
    "Count": 32,
    "Min": 236,
    "Max": 236,
    "Sum": 7552,
    "Avg": 236,
    "StdDev": 0,
    "Data": [
      {
        "Start": 236,
        "End": 236,
        "Percent": 100,
        "Count": 32
      }
    ]
  },
  "HeaderSizes": {
    "Count": 32,
    "Min": 236,
    "Max": 236,
    "Sum": 7552,
    "Avg": 236,
    "StdDev": 0,
    "Data": [
      {
        "Start": 236,
        "End": 236,
        "Percent": 100,
        "Count": 32
      }
    ]
  },
  "Sockets": [
    2,
    2,
    2,
    2
  ],
  "SocketCount": 8,
  "ConnectionStats": {
    "Count": 8,
    "Min": 0.224453083,
    "Max": 0.259749375,
    "Sum": 1.949897043,
    "Avg": 0.243737130375,
    "StdDev": 0.012627738138411356,
    "Data": [
      {
        "Start": 0.224453083,
        "End": 0.25,
        "Percent": 50,
        "Count": 4
      },
      {
        "Start": 0.25,
        "End": 0.259749375,
        "Percent": 100,
        "Count": 4
      }
    ],
    "Percentiles": [
      {
        "Percentile": 50,
        "Value": 0.25
      },
      {
        "Percentile": 75,
        "Value": 0.2548746875
      },
      {
        "Percentile": 90,
        "Value": 0.2577995
      },
      {
        "Percentile": 99,
        "Value": 0.2595543875
      },
      {
        "Percentile": 99.9,
        "Value": 0.25972987625
      }
    ]
  },
  "AbortOn": 0
}

@codecov
Copy link

codecov bot commented Sep 18, 2022

Codecov Report

Base: 88.4% // Head: 88.5% // Increases project coverage by +0.0% 🎉

Coverage data is based on head (712d5ff) compared to base (0fa8982).
Patch coverage: 92.6% of modified lines in pull request are covered.

Additional details and impacted files
@@          Coverage Diff           @@
##           master    #626   +/-   ##
======================================
  Coverage    88.4%   88.5%           
======================================
  Files          30      30           
  Lines        4320    4340   +20     
======================================
+ Hits         3821    3839   +18     
- Misses        335     336    +1     
- Partials      164     165    +1     
Impacted Files Coverage Δ
periodic/periodic.go 93.6% <ø> (ø)
stats/stats.go 97.4% <ø> (ø)
fhttp/httprunner.go 88.1% <85.7%> (-0.4%) ⬇️
fhttp/http_client.go 84.4% <100.0%> (+0.2%) ⬆️

Help us with your feedback. Take ten seconds to tell us how you rate us. Have a feature suggestion? Share it here.

☔ View full report at Codecov.
📢 Do you have feedback about the report comment? Let us know in this issue.

@ldemailly
Copy link
Member Author

@howardjohn going to merge this and another MR to make 1.38.0 but do feel free to comment after the facts and I can do follow ups later as needed. Also was wondering for instance if the access log(s) should include the info.

@ldemailly ldemailly merged commit c72b231 into master Sep 19, 2022
@ldemailly ldemailly deleted the connect_timing branch September 19, 2022 20:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants