JNDI 查找时间的巨大差异答案

【问题标题】：Huge variance in JNDI lookup timesJNDI 查找时间的巨大差异
【发布时间】：2011-08-30 09:06:00
【问题描述】：

在 Weblogic 10.3 上运行的旧版 J2EE Web 应用程序的响应时间存在巨大差异。该系统由运行在同一台物理服务器机器上的两个 Weblogic 服务器实例（前端和后端）和一个运行在单独主机上的 Oracle 数据库组成。每次登录系统时间超过四秒时，外部测量工具都会提醒我们。最近，这些警告频繁出现。查看处理登录请求的 servlet 编写的日志可以发现，时间都花在了从前端到后端的 EJB 调用上。

测量时间示例：

time    ms   
8:40:43 25
8:42:14 26
8:44:04 26
8:44:25 26
8:44:47 26
8:46:06 26
8:46:41 7744
8:47:00 27
8:47:37 27
8:49:00 26
8:49:37 26
8:50:03 8213
8:50:57 27
8:51:04 26
8:51:06 25
8:57:26 2545
8:58:13 26
9:00:06 5195

可以看出，大部分请求（70%，取自更大的样本）都能及时完成，但其中很大一部分需要很长时间才能完成。

在测量时间内执行的步骤如下：

提供身份验证接口（前端）的会话 bean 的 JNDI 查找
调用会话bean的认证方法（前端->后端）
从连接池（后端）保留 JDBC 连接
对用户数据库进行查询（表大小非常适中，应正确索引表）（后端）
读取结果集，创建 POJO 用户对象（后端）
返回 POJO 用户对象（后端->前端）

服务器机器上的负载非常小（99% 空闲），用户数量非常适中。 Weblogic 报告的可用内存量在两台服务器上在 60% 和 90% 之间变化。垃圾收集被记录。主要收集很少见，并且在确实发生时会在 2-3 秒内完成。此外，当看到较长的响应时间时，主要的 GC 事件似乎不会同时发生。繁忙时间和非繁忙时间都会出现较长的响应时间。 JDBC 连接池最大大小当前设置为 80，大于并发用户数。

更新：

获得了重新启动系统的权限，并添加了更多性能日志记录。日志清楚地表明JNDI查找是花费时间的部分：

03:01:23.977 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms
03:14:47.179 PERFORMANCE: looking up foo.bar.Bar from JNDI took 2332 ms
03:15:55.040 PERFORMANCE: looking up foo.bar.Bar from JNDI took 1585 ms
03:29:25.548 PERFORMANCE: looking up foo.bar.Bar from JNDI took 7 ms
03:31:09.010 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms
03:44:25.587 PERFORMANCE: looking up foo.bar.Bar from JNDI took 6 ms
03:46:00.289 PERFORMANCE: looking up foo.bar.Bar from JNDI took 7 ms
03:59:28.028 PERFORMANCE: looking up foo.bar.Bar from JNDI took 2052 ms

查看前后端的GC日志，发现慢速JNDI查找时GC没有完成。

创建会话时通过以下方式获取上下文：

Hashtable ht = new Hashtable();
ht.put(Context.PROVIDER_URL, url);
ht.put(Context.INITIAL_CONTEXT_FACTORY, "weblogic.jndi.WLInitialContextFactory");
jndiContext = new InitialContext(ht);

其中url 是一个t3 url，指向后端服务器的DNS 名称和端口。这应该没问题吧？

首先想到的是缓存从 JNDI 获得的引用，至少这是 10 年前的首选方式......但是 Weblogic 的 InitialContext 实现不应该已经做这个缓存，或者它真的获取每次调用时后端服务器的引用？

什么可能导致频繁缓慢的 JNDI 查找？是否有解决方法（例如缓存引用有帮助）？

【问题讨论】：

您是否尝试在上述步骤之间放置日志消息，以确定哪些步骤占用了大部分额外时间？
做到了。这是 JNDI 查找。请参阅上面编辑过的问题。
还有一件事：消除简单明显的东西可能很有用，所以：你检查过那台机器上的硬盘吗？也可能是硬件故障这样简单的事情！
获取上下文的 Hashtable.put 代码是绝对标准的。您是否有单独的时间让反射调用“创建”和“调用” - 之前和之后？
反射调用 100% 的时间在几毫秒内完成，所以没有问题。问题在于 JNDI 查找，它通常在 5-7 毫秒内完成，但通常需要很长时间。此外，服务器运行的时间越长，时间越长。

标签： java performance weblogic weblogic-10.x

【解决方案1】：

那么是什么导致了这种相当不稳定的行为呢？

我们所说的任何话都可能是猜测。除了玩那个游戏，这里有一些调查问题的建议：

尝试使用分析器查看时间花费在哪里。
尝试使用网络工具（如 WireShark）查看是否存在异常网络流量。
在关键点添加一些日志记录/跟踪以查看时间流向。
寻找Thread.sleep(...) 来电。（哎呀......这是一个猜测。）

【讨论】：

+1：分析器最有可能找到花费时间的地方。我会尝试创建一个负载测试来加载测试以重现问题。如果您能找到某个特定操作是否会导致问题，那么它可能会提供有用的信息。
感谢您的建议！问题是这个问题发生在生产服务器上，到目前为止我们还不能在测试服务器上重现这个问题。我们将在下一个补丁中添加更多日志记录，并可能在测试环境中使用负载生成器和分析器来深入研究问题。
您甚至可以在生产服务器上执行上述大部分操作。是的，它可能会在您的调查期间对性能产生一定影响，但影响不会比您已经遭受的问题更糟。（只需确保您可以快速“退出”任何临时调查更改。）
除非您可以在测试中重现问题，否则您必须对生产进行概要分析。它不应该对您的时间产生太大影响。我建议你使用像 YourKit 这样的商业分析器（如果你没有现金，可以使用 eval）而不是 VisualVM，它是免费的，但结果可能很嘈杂。

【解决方案2】：

作为第一步，我会尝试通过记录每个步骤所花费的时间来找出问题的执行部分。这样您就可以消除不相关的事情并专注于正确的领域，当您弄清楚任何可能会再次发布在这里，以便人们可以提供具体的建议。

【讨论】：

【解决方案3】：

正如 StephenC 所说，其中一些是猜测，中间没有足够的日志语句。您已经清楚地列出了事务中的每个元素，但我假设您没有可以打开的 logger.debug，它上面有时间戳。

一些问题：

每个前端和后端 bean 的池中有多少个 bean - 它应该是 weblogic-ejb-jar.xml 的 max-beans-in-free-pool 元素

如果您对后端 EJB 的请求多于可用的 bean，则将出现等待堆积。

同样在 JDBC 方面，您可以使用 Weblogic 控制台来监控任何与获取连接的争用 - 您是否在 JDBC 监控选项卡中点击了高计数和等待？这应该是接下来要检查的事情。

【讨论】：

谢谢，我检查了max-beans-in-free-pool。它是100，所以它应该不是问题。请参阅我编辑的问题以及更多信息。毕竟有一个调试开关......
对，任何与 GC 模式的链接，然后通过反射我想知道在年轻空间和服务器 GC 中加载的许多类是否与响应时间尖峰相吻合。签入控制台
检查了 GC 日志，在缓慢的 JNDI 查找期间似乎没有任何 GC 活动。重启确实有点帮助：偶尔的长时间查找仍然存在，但它们不再那么长也不再频繁。