notifyAll() number of invocations difference while profiling

Question

I have implemented a simple profiler with JVMTI to display the invocation on wait() and notifyAll(). As a test case I am using the. producer consumer example of Oracle. I have the following three events:

• notifyAll() is invoked
• wait() is invoked
• wait() is left

The wait() invocation and when its left it profiled by using the events MonitorEnter and MonitorExit. The notifyAll() invocation is profiled when a method with name notifyAll is exited.

Now I have the following results, the first is from the profiler itself and the second is from Java, where I have placed the appropriate System.out.println statement.

    // 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()

Has someone an explanation from what this discrepancy comes from? notifyAll() is called so many times. I was told this might be due to false-positive responses from the request of Java to the operating system.

A notifyAll() request it sent to the operating system and a false-positive response is sent, where it seems like the request was sucessfull. Since notifyAll is logged by profiling method invocation instead of MonitorEnter it could explain why this does not happen with wait.

I forgot to say, I didn't run the programs separately, both logs are from the same execution.

Aditional Information

Originally added as an answer, moved to the question by extraneon:

I think I found out where some of the additional notifyAll are coming from, I added the profiling of the method context in which notifyAll is called:

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

But even without these external calls, there are plteny of notifyAll calls which do not show up in the printf debugging.

Answer 1

I spent some time analyzing the Producer-Consumer example provided by Oracle and your output (profiler and Java program). There are some strange things on your outputs besides the several unexpected notifyAll():

1. we should expect the wait() method to execute 4 times (the String array manipulated by the producer has 4 elements). The result of your profiler shows that it only executed three times.

2. Another thing that is quite strange is the numbering of the threads in the output of the profiler. The example has two threads, however your profiler executes all the code in one thread, i.e. Thread-1, while Thread-0 just executes notifyAll().

3. The example code provided is correctly programmed from a concurrent perspective and language perspective: wait() and notifyAll() are in synchronized methods to ensure control over the monitor; wait condition is within a while loop with the notifies correctly placed in the end of the methods. However, I noticed that the catch (InterruptedException e) block is empty, which means that if the thread that is waiting is interrupted, the notifyAll() method will be executed. This can be a cause for the several unexpected notifyAll().

In conclusion, without performing some modifications in the code and perform some extra tests, it won't be easy to figure out where the problem comes from.

As a side note, I'll leave this link Creating a Debugging and Profiling Agent with JVMTI for the curious ones that want to play with JVMTI.

Answer 2

If you have a race condition in your code, a profiler can slow down the code enough to either show or hide an error in your code. (I like to run my program in a profiler, just to show up race conditions.)

As notifyAll() will only notify wait()ing threads, calling wait() after the notifyAll() is likely to result in missing the notify. i.e. its stateless, it doesn't know you called notify before.

If you slow down your application the notifyAll() can be delayed until after the wait() starts.