了解AppEngine的Go运行时上的“运行时mcycles”和“ cpu_ms”记帐

Question

I have a Go/AppEngine app that I'm trying to fine-tune to optimize concurrent requests, which is currently cpu-bound. In the process of doing so, I'm seeing what look like anomalous values for cpu_ms in the logs, and average runtime mcycles in the dashboard.

I have a few different endpoints whose cpu use seems completely at odds with reality, but one in particular stands out. It's a simple handler that reads roughly as follows:

    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)
    }

The details of this code don't matter so much as the fact that it doesn't do much more than read a cookie/param and run a Printf on a very simple template string (maybe 100 characters or so).

As I write this, the AppEngine dashboard is reporting this endpoint as consuming 83 runtime mcycles average over the last hour, which seems surprisingly high. When I look at the top 20 log entries associated with these requests, I see an even stranger picture. Most of them are either ms=13 cpu_ms=0 or ms=13 cpu_ms=21 (I assume there's some quantization going on there). But about 10% are really odd, such as ms=148 cpu_ms=238!

So my actual question is this:

• How can an endpoint this simple possibly consume 83 average mcycles, and have such high variance?
  • Should I suspect GC pauses?
• How is it ever possible that cpu_ms > ms in the logs?

Answer 1

For the benefit of anyone that comes across this question in the future, here is the answer given by dsymonds on the google-appengine-go mailing list:

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.