【问题标题】:Extremely slow play framework 2.3 request handling code极慢播放框架2.3请求处理代码
【发布时间】:2016-03-27 12:40:16
【问题描述】:

我正面临方法性能极慢的问题:

HttpRequestDecoder.unfoldAndFireMessageReceived()

Future$PromiseCompletingRunnable.run()

这两种方法使用服务器中每个事务大约一半的时间。它发生在低吞吐量和高使用时间。

例如,在凌晨 1 点,只有我向应用程序发出请求,我在新的遗物中得到了如下图:

在这个事务中,只有这两个方法消耗了整整一秒,甚至比通过休眠访问数据库更慢!再一次,应用程序中只有一个用户。

如果事务较重,则需要更多时间:

在这种情况下,这两种方法平均消耗 2.5 秒,而我自己的代码消耗 1.5 秒,总共需要 4 秒。我当时认为这可能只是对新遗物指标的误导。也许 newrelic 显示了这些方法的名称,但它实际上是我编写的代码。所以我决定得到一个像这样的自定义指标:

playController(){
//Start timer
//do the job
//stop the timer() and send metric to new relic
//return;
}

结果是我的代码需要 1.5 秒。所以真正消耗这个时间的是播放请求处理程序。

当负载高时,这种行为正在杀死我的应用程序。当吞吐量约为每分钟 500 个请求时,这两种方法最多可以消耗 20 秒(不是真正的高吞吐量!),但我的代码保持稳定在最多 3 秒。

我真的不认为这是一个线程问题,因为它甚至在只有一个用户时发生,但是当有很多并发请求时它变得非常有问题。我尝试更改文档中提到的“同步应用程序”的线程数,但我没有得到任何性能变化,甚至变得更糟。

我真的很关心这个问题,因为在play的邮件列表中有一个类似的案例,两年多没有答案!:

http://grokbase.com/t/gg/play-framework/159bzf7r9p/help-to-understand-newrelic-report-for-slow-transactions-2-1-4

在 StackOverflow 中甚至还有一个类似的问题,但对于 play 2.1 没有答案且没有明显的活动:

Slow transactions in NewRelic having Play Framework as backend

有什么想法会导致这种行为吗?

【问题讨论】:

  • 您使用的是哪个版本的newrelic代理?此外,代理本身可能会增加一些开销:discuss.newrelic.com/t/java-agent-overhead/26870
  • 另外,既然您说您使用的是 Hibernate,我只能假设您正在对数据库进行块/同步访问。您应该尝试为您的线程池尝试不同的配置。
  • 嗨@mar​​cospereira。我正在使用新的遗物 3.25.0。我不认为 newrelic 是问题,因为我正在试验非常缓慢的响应,所以我决定实施 newrelic。换句话说,在性能问题出现后才实施新的遗物。关于 Hibernate,我几乎可以肯定这不是数据库/ORM 问题,因为我正在使用自定义指标(没有 newrelic 提供的默认值)测量时间,并且 services-daos-queries 的执行速度非常快。
  • @marcospereira 感谢马科斯的帮助。问题是新的,不是开销,而是错误的度量记录。就像您提到的问题是数据库访问,但是由于 newrelic 报告说 10% 的事务时间是数据库访问,这误导了团队很多时间!我们使用许多分析器、慢查询日志和 AppDynamics 发现了这个问题。

标签: java performance playframework playframework-2.0 netty


【解决方案1】:

所以一个月后我终于可以说这个问题已经解决了。答案是根本没有问题。 新的 relic 默认检测无法正确报告 Play Framework 2 事务消耗的时间,我什至可以说任何运行在 Netty 上的异步框架。

为了得出这个结论,我必须在最有问题的交易中包含一些自定义指标,只是为了发现我的自定义检测使用的时间比新遗物报告的要少。

之后,我使用 firebug 在客户端进行了测试,报告的时间与我的自定义指标相匹配。

就在一周前,我在 newrelic 论坛上发现了这篇文章:

https://docs.newrelic.com/docs/agents/java-agent/frameworks/disable-scala-netty-akka-play-2-instrumentation

在禁用 netty、akka 的所有检测并在 newrelic 配置文件中使用这些行后,我终于开始通过默认检测获得实际时间:

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

在新遗物文件中说:

如果您愿意,您可以选择禁用部分或全部此工具 发现报告的指标对您没有价值,或者如果 仪器会产生比您想要的更多的开销。如果你 有选择地禁用一些仪器,一些部分 活动不会被报告,您的总时间将被低估。

但恕我直言,它应该说:

如果您愿意,可以选择禁用所有这些检测 获得切合实际的指标。

为什么会有这种行为?我只能猜测 Play 和 Netty 通过许多事务重用池中的一些线程,并且 newrelic 代理无法正确区分数据库和 netty 消耗的时间,复制应用程序消耗的实际时间,有时甚至增加三倍。

这个问题严重误导了我的团队(以及项目的发起人)。我并不完全责怪 Newrelic,这个工具很有帮助,但这给我留下了一个教训,不要只相信一个工具。

【讨论】:

    猜你喜欢
    • 2014-02-28
    • 1970-01-01
    • 1970-01-01
    • 2015-11-10
    • 1970-01-01
    • 2012-08-17
    • 1970-01-01
    • 2014-10-22
    • 1970-01-01
    相关资源
    最近更新 更多