了解 AppEngine 的 Go 运行时的“runtime mcycles”和“cpu_ms”计费答案

【问题标题】：Understanding "runtime mcycles" and "cpu_ms" accounting on AppEngine's Go runtime了解 AppEngine 的 Go 运行时的“runtime mcycles”和“cpu_ms”计费
【发布时间】：2014-05-01 20:47:36
【问题描述】：

我有一个 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 runtime mcycles，这似乎高得惊人。当我查看与这些请求相关的前 20 个日志条目时，我看到了一张更奇怪的图片。他们中的大多数要么是ms=13 cpu_ms=0 要么是ms=13 cpu_ms=21（我假设那里正在进行一些量化）。但大约 10% 的人真的很奇怪，例如 ms=148 cpu_ms=238!

所以我的实际问题是这样的：

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

【问题讨论】：

标签： google-app-engine go

【解决方案1】：

为了将来遇到此问题的任何人的利益，以下是 dsymonds 在 google-appengine-go 邮件列表中给出的答案：

cpu_ms 和相关的会计措施是遗留下来的旧的计费结构，至少部分基于 CPU 消耗。现在从这个角度来看是没有意义的，我如果这些数字有些荒谬，也不会感到惊讶。

Go 运行时没有将 CPU 时间归因于单独的请求，在并发中这样做也不是很容易处理运行。归因本质上是统计的，这可能说明因为你看到的奇怪。

【讨论】：