notifyAll() 分析时的调用次数差异答案

【问题标题】：notifyAll() number of invocations difference while profilingnotifyAll() 分析时的调用次数差异
【发布时间】：2011-08-17 15:51:43
【问题描述】：

我已经使用 JVMTI 实现了一个简单的分析器来显示在 wait() 和 notifyAll() 上的调用。作为测试用例，我正在使用。 producer consumer example of Oracle。我有以下三个事件：

notifyAll() 被调用
wait() 被调用
wait() 已离开

wait() 调用及其离开时使用事件MonitorEnter 和MonitorExit 对其进行分析。当退出名为 notifyAll 的方法时，将分析 notifyAll() 调用。

现在我有以下结果，第一个来自分析器本身，第二个来自 Java，我在其中放置了适当的 System.out.println 语句。

    // Profiler:
    Thread-1 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 left wait()
    Thread-1 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 left wait()
    Thread-1 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 left wait()
    Thread-1 invoked notifyAll()

    // Java:
    Thread-0 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-1 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 invoked notifyAll()
    Thread-0 invoked notifyAll()
    Thread-1 invoked wait()
    Thread-1 invoked notifyAll()

有人解释了这种差异的来源吗？ notifyAll() 被调用了很多次。有人告诉我这可能是由于 Java 对操作系统的请求的误报响应造成的。

将notifyAll() 请求发送到操作系统并发送误报响应，看起来请求已成功。由于notifyAll 是通过分析方法调用而不是MonitorEnter 记录的，因此可以解释为什么等待不会发生这种情况。

我忘了说，我没有单独运行程序，两个日志来自同一个执行。

附加信息

最初是作为答案添加的，被外挂移动到问题：

我想我发现了一些额外的 notifyAll 来自哪里，我添加了调用 notifyAll 的方法上下文的分析：

723519: Thread-1 invoked notifyAll() in Consumer.take
3763279: Thread-0 invoked notifyAll() in Producer.put
4799016: Thread-0 invoked notifyAll() in Producer.put
6744322: Thread-0 invoked notifyAll() in Producer.put
8450221: Thread-0 invoked notifyAll() in Producer.put
10108959: Thread-0 invoked notifyAll() in Producer.put
39278140: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
40725024: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
42003869: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
58448450: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
60236308: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
61601587: Thread-1 invoked notifyAll() in java.util.ResourceBundle.endLoading
70489811: Thread-1 invoked notifyAll() in Consumer.take
75068409: Thread-1 invoked wait() in Drop.take
75726202: Thread-1 left wait() in Drop.take
77035733: Thread-1 invoked notifyAll() in Consumer.take
81264978: Thread-1 invoked notifyAll() in Consumer.take
85810491: Thread-1 invoked wait() in Drop.take
86477385: Thread-1 left wait() in Drop.take
87775126: Thread-1 invoked notifyAll() in Consumer.take

但即使没有这些外部调用，也有很多 notifyAll 调用不会出现在 printf 调试中。

【问题讨论】：

在处理并发代码时使用 system.out/err 进行跟踪是一个可怕的想法。 Logging/System.out/err 只是强加显式同步 + 额外的缓存一致性。显示导致问题的真实代码，我会看看有什么可以解决的。
@bestsss 我不是在谈论显示的事件顺序，而是对 notifyAll 的调用总数。那你的论点还成立吗？上面链接了真实的代码，它是 Oracle The Java Tutorials 的一个例子。
有更多的通知是正常的，原因很简单，不是每个'通知'都会唤醒发现另一个处于'等待'状态的线程。但是，添加跟踪可能会使问题恶化。我觉得这种行为完全正常。我确实使用 CAS（比较和设置/交换）来避免进入同步块并广泛调用通知。
@bestsss：你的意思是，对 notifyAll() 的一次调用可能看起来像一个（printf-debugging），但实际上更频繁（分析）？有人告诉我，实现 notifyAll() 的系统调用可能很自然，所以必须再次调用它。这将与您的论点“不是每个线程都被发现唤醒”相匹配。我被告知要查看 pthread 联机帮助页中的条件变量。我已经调查过了，但是在调用 pthread_cond_broadcast 时我找不到任何错误状态。尽管这看起来很自然，但我希望在某处有一个文档说明为什么会发生这种情况。

标签： java multithreading profiling jvmti

【解决方案1】：

如果您的代码中存在竞争条件，分析器可以减慢代码速度，以显示或隐藏代码中的错误。（我喜欢在分析器中运行我的程序，只是为了显示竞争条件。）

由于 notifyAll() 只会通知 wait() 线程，在 notifyAll() 之后调用 wait() 很可能导致错过通知。即它是无状态的，它不知道你之前调用过 notify。

如果您降低应用程序的速度，notifyAll() 可能会延迟到 wait() 启动之后。

【讨论】：

@Peter-Layrey：结果来自同一次执行，这意味着 Java 输出也是被注入的分析器代理减慢的代码。所以这并不能解释为什么在一开始就经常调用 notifyAll。
确实如此。我很惊讶它来自同一次运行，因为第一个“等待左”被打印但在第二个不是。您对这怎么可能有任何想法？
@Peter-Lawrey：因为我忘记为 left wait() 放置 println，这是正常的 - 我应该包含它。但是重点是 notifyAll 还是您认为这与它有关？
可能不是，这让我很困惑。我不知道为什么 notifyAll 似乎被调用的次数比实际调用的次数多。也许您在每个等待的对象上看到了 notifyAll()（按通知的数量）

【解决方案2】：

我花了一些时间分析 Oracle 提供的 Producer-Consumer 示例和您的输出（分析器和 Java 程序）。除了几个意想不到的notifyAll()，你的输出还有一些奇怪的东西：

我们应该期望 wait() 方法执行 4 次（生产者操作的 String 数组有 4 个元素）。您的分析器的结果显示它只执行三遍。
另一件非常奇怪的事情是分析器输出中的线程编号。该示例有两个线程，但是您的分析器在一个线程中执行所有代码，即Thread-1，而Thread-0 只执行notifyAll()。
提供的示例代码从并发角度和语言角度正确编程：wait() 和notifyAll() 采用同步方法，以确保对监视器的控制；等待条件在 while 循环内，通知正确放置在方法的末尾。但是，我注意到catch (InterruptedException e)块是空的，这意味着如果正在等待的线程被中断，notifyAll()方法将被执行。这可能是导致多个意外notifyAll() 的原因。

总之，如果不对代码进行一些修改并进行一些额外的测试，要找出问题的根源并不容易。

作为旁注，我会将这个链接 Creating a Debugging and Profiling Agent with JVMTI 留给那些想玩 JVMTI 的好奇者。

【讨论】：

到第二点：分析器在一个线程中执行所有代码是什么意思？这没有发生，Java 程序像任何其他程序一样启动，是注入的分析代理中的唯一添加。
@platzhirsch 在分析器输出中，您有两个线程：Thread-0 和 Thread-1。但是所有应用程序输出都由Thread-1 打印。好吧，我假设这是因为Thread-0 不输出任何wait String。