JVMTI callback SampledObjectAlloc always fires for first allocation in a new thread

[Jean Christophe Beyler]

Hi Markus,

No it's fine. I figured out what I was doing wrong by just opening my eyes
(number of sampling vs number of samples in my cache...); I saw the same
issue (not that I doubted actually) and reviewed the code paths. It is a
1-liner to fix this but I'm just working on the test and ensuring it passes,
Jc

On Wed, Jun 17, 2020 at 1:00 AM Markus Gaisbauer <markus.gaisbauer at gmail.com>
wrote:

> Please forget about the Windows thing. I forgot that my colleague saw the
> same 0xf1f1f1f1f1f1f1f1 also on Linux.
>
> Markus
>
> On Wed, Jun 17, 2020 at 9:57 AM Markus Gaisbauer <
> markus.gaisbauer at gmail.com> wrote:
>
>> Hi Jean,
>>
>> Thank you for having a look at this.
>>
>> I attached the code of my basic JVMTI agent. I ran my tests on Windows.
>> Maybe this 0xf1f1f1f1f1f1f1f1 is a Windows thing and Linux initializes the
>> memory to all zeros.
>>
>> Regards,
>> Markus
>>
>>
>> On Tue, Jun 16, 2020 at 2:25 AM Jean Christophe Beyler <
>> jcbeyler at google.com> wrote:
>>
>>> Hi Markus,
>>>
>>> I played around adding your Java code in the testing framework and I
>>> don't get exactly the same failure as you do. Basically, I get about 5%
>>> samples compared to the number of threads, whereas you seem to get a sample
>>> for each element. Could you add the code you used for the agent so I can
>>> see if you are doing something different than I am in that regard?
>>>
>>> This doesn't change the issue, I'm just curious why you seem to be
>>> exposing it more. I'm still digging into what would be the right solution
>>> for this.
>>>
>>> Thanks,
>>> Jc
>>>
>>> On Mon, Jun 15, 2020 at 9:53 AM Jean Christophe Beyler <
>>> jcbeyler at google.com> wrote:
>>>
>>>> Hi Markus,
>>>>
>>>> I created:
>>>> https://bugs.openjdk.java.net/browse/JDK-8247615
>>>>
>>>> And I'll see what needs to be done for it :)
>>>> Jc
>>>>
>>>> On Fri, Jun 5, 2020 at 3:45 AM Markus Gaisbauer <
>>>> markus.gaisbauer at gmail.com> wrote:
>>>>
>>>>> Hi,
>>>>>
>>>>> JVMTI callback SampledObjectAlloc is currently always called for the
>>>>> first allocation of a thread. This generates a lot of bias in an
>>>>> application that regularly starts new threads.
>>>>>
>>>>> I tested this with latest Java 11 and Java 15.
>>>>>
>>>>> E.g. here is a sample that creates 100 threads and allocates one
>>>>> object in each thread.
>>>>>
>>>>>     public class AllocationProfilingBiasReproducer {
>>>>>         public static void main(String[] args) throws Exception {
>>>>>             for (int i = 0; i < 100; i++) {
>>>>>                 new Thread(new Task(), "Task " + i).start();
>>>>>                 Thread.sleep(1);
>>>>>             }
>>>>>             Thread.sleep(1000);
>>>>>         }
>>>>>         private static class Task implements Runnable {
>>>>>             @Override
>>>>>             public void run() {
>>>>>                 new A();
>>>>>             }
>>>>>         }
>>>>>         private static class A {
>>>>>         }
>>>>>     }
>>>>>
>>>>> I built a simple JVMTI agent that registers SampledObjectAlloc
>>>>> callback and sets interval to 1 MB with SetHeapSamplingInterval. The
>>>>> callback simply logs thread name and class name of allocated object.
>>>>>
>>>>> I see the following output:
>>>>>
>>>>> SampledObjectAlloc Ljava/lang/String; via Task 0
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 1
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 2
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 3
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 4
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 5
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 6
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 7
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 8
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 9
>>>>> SampledObjectAlloc LAllocationProfilingBiasReproducer$A; via Task 10
>>>>> ...
>>>>>
>>>>> This is not expected.
>>>>>
>>>>> I set a breakpoint in my SampledObjectAlloc callback and observed the
>>>>> following:
>>>>>
>>>>> In MemAllocator::Allocation::notify_allocation_jvmti_sampler() the
>>>>> local var bytes_since_last is always 0xf1f1f1f1f1f1f1f1 for first
>>>>> allocation of a thread. So first allocation is always reported to my agent.
>>>>>
>>>>> ThreadLocalAllocBuffer::_bytes_since_last_sample_point does not seem
>>>>> to be explicitly initialized before accessing it for the first time. I
>>>>> assume 0xf1f1f1f1f1f1f1f1  is a default value provided by some Hotspot
>>>>> allocator. Only after the first event fired,
>>>>> notify_allocation_jvmti_sampler
>>>>> calls ThreadLocalAllocBuffer::set_sample_end which initializes
>>>>> _bytes_since_last_sample_point to a proper value.
>>>>>
>>>>> I am looking for someone who could create a JIRA ticket for this.
>>>>>
>>>>> Regards,
>>>>> Markus
>>>>>
>>>>
>>>>
>>>> --
>>>>
>>>> Thanks,
>>>> Jc
>>>>
>>>
>>>
>>> --
>>>
>>> Thanks,
>>> Jc
>>>
>>

-- 

Thanks,
Jc
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20200617/45175df0/attachment.htm>