问题描述
希望有人能指出我正确的方向。我们继承了一个商店网站的 vcl。
基本设置是：
Nginx ssl 终止 -> varnish -> varnish rr 到 4 个 apache 后端
设置工作正常，但是当我们将其置于任何形式的负载下（大约 250 个并发）时，Nginx 开始报告它无法连接到 varnish：
2021/07/23 12:08:15 [error] 25348#25348: *7223 upstream timed out (110: Connection timed out) while reading upstream,client: xx,server: _,request: "GET / HTTP /1.1”，上游：“http://xx/”，主机：“xx”
并且清漆报告它已经损坏了管道：
* << Request >> 5996617
- Begin req 5996616 rxreq
- Timestamp Start: 1627038436.200604 0.000000 0.000000
- Timestamp Req: 1627038436.200604 0.000000 0.000000
- ReqStart xx 42403
- ReqMethod GET
- ReqURL /
- ReqProtocol HTTP/1.1
- ReqHeader X-Real-IP: xx
- ReqHeader X-Forwarded-For: xx
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Port: 443
- ReqHeader Host: xx
- ReqHeader Connection: close
- ReqHeader Accept: */*
- ReqHeader Accept-Language: en
- ReqHeader User-Agent: Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0; .NET CLR 1.1.4322; .NET CLR 1.0.3705; .NET CLR 2.0.50727; .NET CLR 3.0.04506.648; .NET CLR 3.5.21022; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729)
- ReqHeader Accept-Encoding: gzip,deflate
- ReqHeader Dotcom-ProxyIDTag: 13
- ReqUnset X-Forwarded-For: xx
- ReqHeader X-Forwarded-For: xx,xx
- VCL_call RECV
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqURL /
- ReqHeader Surrogate-Capability: shopware=ESI/1.0
- ReqUnset X-Forwarded-Proto: https
- ReqHeader X-Forwarded-Proto: https
- ReqHeader X-UA-Device: desktop
- ReqHeader X-UA-vendor: generic
- ReqHeader X-UA-Forced: no
- ReqUnset Accept-Encoding: gzip,deflate
- ReqHeader Accept-Encoding: gzip
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Hit 4653975
- VCL_call HIT
- VCL_acl NO_MATCH editors
- VCL_return deliver
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Date: Fri,23 Jul 2021 10:54:07 GMT
- RespHeader Server: Apache
- RespHeader Expires: Thu,19 Nov 1981 08:52:00 GMT
- RespHeader Pragma: no-cache
- RespHeader Cache-Control: max-age=14400,public,s-maxage=14400
- RespHeader X-Shopware-Allow-Nocache: admin-1,price-1
- RespHeader X-Shopware-Cache-Id: ;c3;
- RespHeader Set-Cookie: session=; path=/
- RespHeader Set-Cookie: lastAffiliate=na; path=/
- RespHeader Server-Id: web3
- RespHeader Content-Type: text/html; charset=UTF-8
- RespHeader X-Content-Length: 17190
- RespHeader content-encoding: gzip
- RespHeader vary: Accept-Encoding
- RespHeader X-Varnish: 5996617 4653975
- RespHeader Age: 788
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- VCL_acl NO_MATCH editors
- RespUnset X-Shopware-Allow-Nocache: admin-1,price-1
- RespUnset X-Shopware-Cache-Id: ;c3;
- RespUnset Cache-Control: max-age=14400,s-maxage=14400
- RespHeader Cache-Control: max-age=0,private
- RespUnset Set-Cookie: session=; path=/
- RespUnset Set-Cookie: lastAffiliate=na; path=/
- RespHeader X-Cache: HIT
- RespHeader X-Cache-Hits: 3611
- VCL_return deliver
- Timestamp Process: 1627038436.200763 0.000159 0.000159
- RespHeader Accept-Ranges: bytes
- RespHeader transfer-encoding: chunked
- Debug "RES_MODE 18"
- RespHeader Connection: close
- Link req 5996618 esi
- Debug "Write error,retval = -1,len = 14,errno = broken pipe"
- Timestamp Resp: 1627038513.810060 77.609456 77.609297
- ReqAcct 522 0 522 456 5368 5824
- End
Uptime mgt: 1+04:38:26 Hitrate n: 10 21 21
Uptime child: 1+04:38:26 avg(n): 0.4843 0.4762 0.4762
NAME CURRENT CHANGE AVERAGE AVG_10 AVG_100 AVG_1000
MAIN.uptime 1+04:38:26
MAIN.sess_conn 10107 5.99 . 4.97 4.89 4.89
MAIN.client_req_400 9 0.00 . 0.00 0.00 0.00
MAIN.client_req 10815 5.99 . 4.97 4.89 4.89
MAIN.cache_hit 14952 8.99 . 7.83 7.69 7.69
MAIN.cache_miss 16483 8.99 . 7.83 7.69 7.69
MAIN.backend_conn 890 0.00 . 0.18 0.15 0.15
MAIN.backend_reuse 24251 7.99 . 10.20 10.14 10.14
MAIN.backend_recycle 25012 9.99 . 10.55 10.38 10.38
MAIN.fetch_length 24022 9.99 . 10.55 10.38 10.38
MAIN.fetch_chunked 755 0.00 . 0.00 0.00 0.00
MAIN.fetch_eof 2 0.00 . 0.00 0.00 0.00
MAIN.fetch_none 33 0.00 . 0.00 0.00 0.00
MAIN.fetch_304 319 0.00 . 0.00 0.00 0.00
MAIN.fetch_Failed 13 0.00 . 0.00 0.00 0.00
MAIN.pools 2 0.00 . 2.00 2.00 2.00
MAIN.threads 600 0.00 . 600.00 600.00 600.00
MAIN.threads_created 738 0.00 . 0.00 0.00 0.00
MAIN.threads_destroyed 138 0.00 . 0.00 0.00 0.00
MAIN.busy_sleep 35286304 62859.00 342.00 34852.46 32989.42 32989.42
MAIN.busy_wakeup 51 0.00 . 0.00 0.00 0.00
MAIN.sess_queued 138 0.00 . 0.00 0.00 0.00
MAIN.n_object 344 -2.00 . 344.38 344.33 344.33
MAIN.n_objectcore 598 0.00 . 600.20 601.14 601.14
MAIN.n_objecthead 865 0.00 . 865.00 865.00 865.00
vvv MAIN.uptime INFO 1-25/96
并非所有请求都失败，概率约为 70%。
后端几乎没有受到影响，即使我删除了 Nginx 并且只是在 http 上使用 varnish 接受 http 连接的网站，也会发生 varnish 错误。
在 Centos7 上运行 4.1.11（也尝试过 v6，在 Centos8 和 Ubuntu 20 上也试过）。打开的文件增加了，似乎没有资源被最大化。
任何指针表示赞赏。我觉得忙碌的睡眠是我应该寻找的地方，但看不到它继续增长的任何理由。
谢谢
- Timestamp Start: 1627115035.167388 0.000000 0.000000
- BereqMethod GET
- BereqURL /?action=shopMenu&controller=index&module=widgets&sCategory=3
- BereqProtocol HTTP/1.1
- BereqHeader X-Real-IP:
- BereqHeader X-Forwarded-Port: 443
- BereqHeader Accept: */*
- BereqHeader Accept-Language: en
- BereqHeader User-Agent: Mozilla/5.0 (compatible; MSIE 10.0; Windows NT 6.1; Trident/6.0; .NET CLR 1.1.4322; .NET CLR 1$
- BereqHeader Dotcom-ProxyIDTag: 5
- BereqHeader Host:
- BereqHeader X-Forwarded-For:
- BereqHeader Surrogate-Capability: shopware=ESI/1.0
- BereqHeader X-Forwarded-Proto: https
- BereqHeader X-UA-Device: desktop
- BereqHeader X-UA-vendor: generic
- BereqHeader X-UA-Forced: no
- BereqHeader Accept-Encoding: gzip
- BereqHeader X-Varnish: 4489358
- VCL_call BACKEND_FETCH
- VCL_return fetch
- BackendOpen 414 boot.web4 50444
- BackendStart
- Timestamp Bereq: 1627115035.167506 0.000118 0.000118
- Timestamp Beresp: 1627115035.368178 0.200790 0.200672
- BerespProtocol HTTP/1.1
- BerespStatus 200
- BerespReason OK
- BerespHeader Date: Sat,24 Jul 2021 08:23:55 GMT
后端正在快速响应这些请求，我在 Apache 中没有看到任何失败的请求。我需要考虑在 vcl 中缓存这些请求吗？
解决方法
日志的有趣之处在于我们正在处理缓存命中。这应该意味着超时不是由缓慢的后端引起的。
但是，以下日志行可能表明 ESI 子请求导致超时：
- Link req 5996618 esi
- Debug "Write error,retval = -1,len = 14,errno = Broken pipe"
- Timestamp Resp: 1627038513.810060 77.609456 77.609297
ESI 子请求
此 ESI 子请求的事务 ID 为 5996618，Timestamp 日志行的最后一列值显示 Varnish 77 秒生成响应，而之前的 Timstamp 条目仅在 159 微秒，如下图所示：
- Timestamp Process: 1627038436.200763 0.000159 0.000159
一个合理的假设是，ESI 占位符代表必须来自后端的有状态数据，并且可能需要一些时间，尤其是在负载较重的情况下。
我还假设损坏的管道不是由 Varnish 引起的，而是由 Nginx 超时引起的。这是有道理的，因为 Nginx 不会永远等待。
下一步
下一步是检查完整日志，包括 ESI 调用的日志项。
根据 ESI 调用的目的，我们可以看看如何从源头减轻一些压力并使响应时间恢复正常。
如果这个 ESI 子请求端点被命中太多，合成响应并在 Varnish 中执行一些决策是有意义的。
另一种方法是通过在 Redis 中存储投影数据，在您的应用程序中对该端点使用更快的数据访问。
如果您需要更多帮助，请更详细地描述 ESI 情况，添加完整的日志，也可能添加完整的 VCL 文件以供参考。
关于您的 Pastebin 链接的评论
我在 https://pastebin.com/nMwd72B4 中看到的是响应速度非常快的 ESI 子请求。其中一些 ESI 调用会被缓存，其他则不会。
命中未命中
但我发现您的 VCL 配置存在一个大问题：
set beresp.ttl = 0s;
set beresp.uncacheable = true;
return (deliver);
不可缓存的数据永远不应该出现在等待列表中，因为 Varnish 的内置请求合并功能永远无法并行满足这些请求。所以它们最终被串行处理，这是非常非常慢的。尤其是在重载的情况下。
通常，不可缓存的响应会添加到 Hit-For-Miss 缓存中，其中缓存了不缓存的决定。听起来很讽刺，但确实有用。
Hit-For-Miss 列表中的对象将自动绕过等待列表。这是针对具有 set beresp.uncacheable = true 的响应完成的。
你的问题是 TTL 设置为零，这是一个很大的禁忌！
内置 VCL 行为将 Hit-For-Miss 对象的 TTL 设置为 2 分钟，如 https://github.com/varnishcache/varnish-cache/blob/6.0/bin/varnishd/builtin.vcl#L164 所示。
这是您需要的：
set beresp.ttl = 120s;
set beresp.uncacheable = true;
return (deliver);
我并不是说这会解决您的所有问题，但它可能有助于提高性能，因为序列化将不再有效。
注意缓存 Set-Cookie 标头
我还在包含 Set-Cookie 标头的日志中看到了相当多的缓存命中。
Varnish 的内置 VCL 行为不会缓存包含 https://github.com/varnishcache/varnish-cache/blob/6.0/bin/varnishd/builtin.vcl#L158 中所见的 Set-Cookie 标头的对象，因为 Set-Cookie 标头暗示的个性化级别不适用于收到回复的每个人。
如果这是故意的，请忽略此评论。如果没有，以下是您的一些选择：
- 尽可能去掉
Set-Cookie标头 - 对某些包含
Set-Cookie标头的响应绕过缓存。 - 覆盖 VCL 代码中
Set-Cookie标头的值
我没有看到任何缓慢的响应
您提供的 Pastbin 链接不包含任何特别慢的 Timestamp 标签。也许这些日志项是在系统负载不大时记录的。
我很想看到完整的日志事务，包括与我在您的原始问题中看到的 - Timestamp Resp: 1627038513.810060 77.609456 77.609297 的性能相匹配的 ESI 子请求。
但是，请务必关注候补名单的部分，也许这会解决您的问题。