非常慢的播放框架2.3请求处理代码 [英] Extremely slow play framework 2.3 request handling code
问题描述
我的方法表现非常缓慢：
HttpRequestDecoder.unfoldAndFireMessageReceived（）
和
未来$ PromiseCompletingRunnable。 run（）
这两种方法使用服务器中每个事务的大约一半时间。它发生在低输入和高使用时间。
例如，凌晨1点只有我对应用程序的请求我得到了这样的新遗物图：
在此交易中，只有这两种方法消耗1整秒，甚至更慢，通过休眠访问数据库！再一次，应用程序中只有一个用户。
如果交易较重，则需要更多时间：
在这种情况下，当我自己的代码消耗1.5秒时，这两种方法平均消耗2.5秒，总计4秒。我觉得那个时刻可能只是误导了新的遗物标准。也许newrelic会显示这些方法名称，但它确实是我编写的代码。所以我决定得到一个这样的自定义指标：
playController（）{
//启动计时器
//执行作业
//停止计时器（）并将指标发送到新文件
// return;
}
结果是我的代码耗时1.5秒。所以这次是真正的游戏请求处理程序。
这种行为在高负载时会杀死我的应用程序。当throghput每分钟大约500个请求（实际上不是高吞吐量！）时，这两种方法最多可消耗20秒。但是我的代码保持稳定在最多3秒。
我真的不认为这是一个线程问题，因为它甚至在有一个用户时发生，但是当有很多并发请求时它会变得非常棘手。我尝试改变同步应用程序的线程数量，例如文档提及，但我没有得到任何性能变化，甚至变得更糟。
我真的很关心这个问题，因为在两年多的游戏邮件列表中有类似的情况而没有答案！：
甚至还有一个类似于StackOverflow的问题，但对于没有回答和没有明显活动的游戏2.1：
任何想法是什么可能导致这种行为？
所以一个月后我终于可以说这个问题已经解决了。答案是，根本没有问题。 新版本的默认工具无法正确报告Play Framework 2交易消耗的时间，我甚至可以说任何在Netty上运行的异步框架。
<为了得出这个结论，我必须在最有问题的交易中加入一些自定义指标，以发现我的自定义工具使用的时间少于新文件所报告的时间。
<之后我在客户端使用firebug进行测试，报告的时间与我的自定义指标相符。
就在一周前，我在newrelic论坛中发现了这篇文章：
在禁用netty，akka的所有检测并在newrelic配置文件中使用这些行后最后通过默认检测开始获得实际时间：
common：& default_settings
class_transformer：
＃禁用所有Akka乐器
com.newrelic.instrumentation.akka-2.0：
启用：false
com.newrelic.instrumentation.akka-2.1：
启用： false
com.newrelic.instrumentation.akka-2.2：
启用：false
＃禁用所有Netty工具
com.newrelic.instrumentation.netty-3.4：
enabled：false
com.newrelic.instrumentation.netty-3.8：
enabled：false
com.newrelic.instrumentation.netty-4.0.0：
enabled：false
com.newrelic.instrumentation.netty-4.0.8：
启用：false
＃禁用所有Play 2乐器
com.newrelic.instrumentation.play-2.1 ：
启用：false
com.newrelic.instrumentation.play-2.2：
enabled：false
com.ne wrelic.instrumentation.play-2.3：
启用：false
＃在版本3.22中新增，Play 2.4工具不尊重
＃较旧的play2_instrumentation配置设置
com.newrelic。 instrumentation.play-2.4：
启用：false
＃禁用所有Scala语言工具
com.newrelic.instrumentation.scala-2.9.3：
enabled： false
在新的文件中说：
如果
发现所报告的指标对您没有价值，或者如果
工具产生的开销超出您的预算，您可以选择禁用部分或全部此工具。喜欢。如果您
选择性地禁用某些工具，则不会报告
活动的某些部分，并且您的总时间将被低估。
但恕我直言应该说：
如果你想要$ b $，你可以选择禁用所有这些仪器b获得实际指标。
为什么会出现这种情况？我只能猜测Play和Netty通过许多事务重用池中的一些线程，并且newrelic代理无法正确分离数据库消耗的时间和netty，重复并且有时会使应用程序消耗的实际时间重复三次。 / p>
这个问题严重误导了我的团队（以及项目的发起人）。我并不完全责怪Newrelic，这个工具很有帮助，但这让我作为一个教训，不要只相信一个工具。
I'm facing extremely slow performance of methods:
HttpRequestDecoder.unfoldAndFireMessageReceived()
and
Future$PromiseCompletingRunnable.run()
This two methods use around half of the time of every transaction in the server. It happens under low troughtput and during high usage hours.
For example, at 1am with only me doing requests to the aplication I get graphs in new relic like these:
In this transaction only those two methods consume 1 full second, even slower that access the database via hibernate! Once again, only one user in the application.
If the transaction is heavier it takes even more time:
In this case, this two methods consume 2.5 seconds average when my own code consumes 1.5 seconds giving a total of 4 seconds. I thougth at that moment that maybe this was only a misleading of new relic metric. Maybe newrelic was showing this methods names but it was really code written by me. So I decided to get a custom metric like this:
playController(){
//Start timer
//do the job
//stop the timer() and send metric to new relic
//return;
}
And the result was that my code was taking 1.5 seconds. So it is really play request handler who is consuming this time.
This behaivour is killing my app when having a high load. This two methods can consume up to 20 seconds when the throghput is around 500 request per minute (not really a high throughput!) but my code keeps steady at max 3 seconds.
I really don't think this is a thread problem, because it even happends when there's a single user, but it become really problematic when having many concurrent requests. I tried changing the number of threads for "synchronous apps" like documentation mention but I didn't get any performance change, it even got worse.
I am really concerned about this problem because there's a similar case in the mailing lists of play with more than two years and no answer!:
There's even a question that is similar in StackOverflow but for play 2.1 without answer and no aparent activity:
Slow transactions in NewRelic having Play Framework as backend
Any ideas what can be causing this behavior?
So after a month I finally can say this issue is solved. And the answer is that there's no issue at all. New relic default instrumentation does not report correctly the time consumed by Play Framework 2 transactions and I could even say by any async framework that runs over Netty.
To get to that conclusion I had to include some custom metrics to the most problematic transactions just to discover that my custom instrumentation uses way less time than the reported by new relic.
After that I tested in the client using firebug and the times reported match my custom metrics.
Just a week ago I discovered this post in newrelic forums:
And after disabling all the instrumentation for netty, akka and play with this lines in newrelic configuration file I finally started to get realistic times by the default instrumentation:
common: &default_settings
class_transformer:
# Disable all Akka instrumentations
com.newrelic.instrumentation.akka-2.0:
enabled: false
com.newrelic.instrumentation.akka-2.1:
enabled: false
com.newrelic.instrumentation.akka-2.2:
enabled: false
# Disable all Netty instrumentations
com.newrelic.instrumentation.netty-3.4:
enabled: false
com.newrelic.instrumentation.netty-3.8:
enabled: false
com.newrelic.instrumentation.netty-4.0.0:
enabled: false
com.newrelic.instrumentation.netty-4.0.8:
enabled: false
# Disable all Play 2 instrumentations
com.newrelic.instrumentation.play-2.1:
enabled: false
com.newrelic.instrumentation.play-2.2:
enabled: false
com.newrelic.instrumentation.play-2.3:
enabled: false
# New in Release 3.22, the Play 2.4 instrumentation does not respect
# the older play2_instrumentation configuration setting
com.newrelic.instrumentation.play-2.4:
enabled: false
# Disable all Scala-language instrumentations
com.newrelic.instrumentation.scala-2.9.3:
enabled: false
In newrelic documentations says:
You may choose to disable some or all of this instrumentation if you find that the metrics reported aren't valuable to you, or if the instrumentation incurs more overhead than you would like. If you selectively disable some of the instrumentation, some segments of activity will not be reported and your total time will be understated.
But IMHO it should say:
You may choose to disable ALL of this instrumentation if you want to get realistic metrics.
Why this behavior? I can only guess that Play and Netty reuses some threads in a pool by many transactions and newrelic agent is not able to separate correctly which time is consumed by the database and by netty, duplicating and sometimes triplicating the real times consumed by the application.
This problem mislead my team (and the sponsors of the project) drastically. I don't fully blame Newrelic, this tool is helpful but this left me as a lesson to don't trust only in one tool.
这篇关于非常慢的播放框架2.3请求处理代码的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！
