清漆超时

Question

希望有人能指出我正确的方向。我们继承了一个用于商店网站的 vcl。

基本设置是：

nginx ssl 终止 -> varnish -> varnish rr 到 4 个 apache 后端

设置工作正常，但是当我们将其置于任何形式的负载下（大约 250 个并发）时，nginx 开始报告它无法连接到 varnish：

2021/07/23 12:08:15 [错误] 25348#25348: *7223 上游超时（110：连接超时）同时读取上游，客户端：xx，服务器：_，请求：“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, public, 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 连接，也会发生清漆错误。

在 Centos7 上运行 4.1.11（也尝试过 v6，在 Centos8 和 Ubuntu 20 上只是以防万一）。打开的文件增加了，似乎没有资源被最大化。

任何指针表示赞赏。我觉得忙碌的睡眠是我应该寻找的地方，但看不到它继续增长的任何理由。

谢谢

---

看起来命中正在生成一个 esi 子请求：

-   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 中缓存这些请求？

Answer 1

日志的有趣之处在于我们正在处理缓存命中。这应该意味着超时不是由缓慢的后端引起的。

但是，以下日志行可能表明 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 行为不会缓存包含 Set-Cookie 标头的对象，如 https://github.com/varnishcache/varnish-cache/blob/6.0/bin/varnishd/builtin.vcl#L158 所示，因为 Set-Cookie 标头意味着某种程度的个性化不适用于接收响应的每个人。

如果这是故意的，请忽略此评论。如果没有，这些是您的一些选择：

• 尽可能去掉Set-Cookie 标头
• 为某些包含Set-Cookie 标头的响应绕过缓存。
• 覆盖 VCL 代码中 Set-Cookie 标头的值

我没有看到任何缓慢的响应

您提供的 Pastbin 链接不包含任何特别慢的 Timestamp 标记。也许这些日志项是在系统负载不大时记录的。

我很想看到一个完整的日志事务，包括 ESI 子请求，与我在您原来的问题中看到的 - Timestamp Resp: 1627038513.810060 77.609456 77.609297 的性能相匹配。

但是，请务必关注关于等候名单的部分，也许这会解决您的问题。