英文:
Understanding "runtime mcycles" and "cpu_ms" accounting on AppEngine's Go runtime
问题
我有一个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/参数并在一个非常简单的模板字符串上运行Printf之外并没有做太多事情(大约100个字符左右)。
在我写这篇文章的时候,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
是如何可能的?
英文:
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?
答案1
得分: 2
对于将来遇到这个问题的任何人,以下是dsymonds在google-appengine-go邮件列表上给出的答案:
cpu_ms和相关的计费措施是旧计费结构的遗留物,该结构至少部分基于CPU消耗。现在从这个角度来看它是没有意义的,如果这些数字有些荒谬,我也不会感到惊讶。
Go运行时没有为单独的请求分配CPU时间,也没有在并发运行时中追踪这样做的可行性。归因是统计性质的,这可能解释了你所看到的奇怪现象。
英文:
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.
通过集体智慧和协作来改善编程学习和解决问题的方式。致力于成为全球开发者共同参与的知识库,让每个人都能够通过互相帮助和分享经验来进步。
评论