google-app-engine - 了解 AppEngine 的 Go 运行时上的 "runtime mcycles"和 "cpu_ms"会计

Question

我有一个 Go/AppEngine 应用程序，我正在尝试对其进行微调以优化当前受 cpu 限制的并发请求。在这样做的过程中，我看到日志中的 cpu_ms 和仪表板中的 average runtime mcycles 看起来像是异常值。

我有几个不同的端点，它们的 CPU 使用情况似乎与现实完全不符，但其中一个特别突出。这是一个简单的处理程序，大致如下所示:

    func ThangHandler(w http.ResponseWriter, r *http.Request) {
        ctx := appengine.NewContext(r)

        var orgId string
        cookie, err := r.Cookie(orgCookieKey)
        if err != nil || cookie.Value == "" {
            // Check URL params as a fallback.
            r.ParseForm()
            orgId = r.Form.Get("orgId")
            if orgId == "" {
                util.HttpError(ctx, w, http.StatusForbidden)
                return
            }
        } else {
            orgId = cookie.Value
        }

        w.Header().Set("Content-Type", "application/json; charset=utf-8")
        fmt.Fprintf(w, simpleTemplate, orgId, r.Host, "true", host)
    }

这段代码的细节并不重要，因为它只是读取 cookie/param 并在非常简单的模板字符串(可能 100 个字符左右)上运行 Printf。

在我撰写本文时，AppEngine 仪表板报告此端点在过去一小时内平均消耗了 83 个运行时 mcycles，这似乎高得惊人。当我查看与这些请求关联的前 20 个日志条目时，我看到了一幅更奇怪的画面。其中大部分是 ms=13 cpu_ms=0 或 ms=13 cpu_ms=21(我假设那里正在进行一些量化)。但大约 10% 是真的奇怪的，例如 ms=148 cpu_ms=238!

所以我的实际问题是:

• 如此简单的端点怎么可能消耗 83 个平均 mcycles，并且具有如此高的方差？
  • 我应该怀疑 GC 暂停吗？
• 日志中cpu_ms > ms 怎么可能？

Answer 1

为了以后遇到这个问题的任何人的利益，这里是 dsymonds 在 google-appengine-go 邮件列表中给出的答案:

The cpu_ms and related accounting measures are legacy holdovers from the old billing structure, which was based at least partly on CPU consumption. Nowadays it is meaningless from that perspective, and I wouldn't be surprised if those numbers are somewhat nonsensical.

There's nothing in the Go runtime done to attribute CPU time to separate requests, nor is it really tractable to do so in a concurrent runtime. The attributing is statistical in nature, which may account for the weirdness you are seeing.