RFR (S): 8008314 - Unimplemented() Atomic::load breaks the applications

[Jesper Wilhelmsson]

Hi Dean,

Using count() is a good suggestion. It would require a larger change though 
since the rotatingFileStream doesn't use the _position and _precount variables 
right now and they aren't properly updated as you noted. There are places in the 
code that uses count() to find information about the logfiles. I suspect there 
could be a really unlikely bug hiding here: If a long running program happens to 
wrap the _precount variable at the end of a line, calls to count() would return 
zero and believe that there is no logging in progress.

Regarding thread saftey there is no difference in using count() to using the 
current _bytes_written (none of them are thread safe), and since this bug is 
about removing the use of atomic add, I'd prefer to keep the change small.

There are other things in rotatingFileStream that would benefit from an 
overview. For instance there are two constructors that are identical apart from 
a minor detail. I'd like to clean this up and remove the duplicated code - 
especially as only one of the constructors are ever used.

Are you OK with my current change if I'll create a separate CR to look in to the 
potential problem with count() and to do this cleanup?
/Jesper


On 20/2/13 4:54 AM, Dean Long wrote:
> How about using "if (count() < (jlong)GCLogFileSize)" and
> "set_position(0);set_count(0);" in
> rotate_log(), then removing_bytes_written?  However be aware that count() grows
> even when
> _file == NULL, because write() calls update_position() unconditionally.
>
> dl
>
> On 2/19/2013 8:58 AM, Jesper Wilhelmsson wrote:
>> Hi,
>>
>> The counter that is protected by the atomic add is only used to decide when to
>> switch to the next file in the rotating log file scheme. Even with the atomic
>> add it is not an exact limit since we only check the limt at a sefepoint and
>> we will always write a whole log message at a time.
>>
>> I ran several tests with most GC logging turned on with and without the atomic
>> add and I see no significant difference in the sizes of the log files.
>>
>> I have a new patch where I remove the atomic add:
>>
>> HS24: http://cr.openjdk.java.net/~jwilhelm/8008314/webrev.2.hs24/
>> HS25: http://cr.openjdk.java.net/~jwilhelm/8008314/webrev.2.hs25/
>>
>> Let me know if you feel confident in pushing this.
>> /Jesper
>>
>>
>> On 19/2/13 1:52 PM, Bengt Rutisson wrote:
>>> On 2/19/13 12:39 PM, David Holmes wrote:
>>>> I'm also indebted to Bengt for spotting that - hadn't realized the 'x' types
>>>> were intptr_t typedefs.
>>>>
>>>> But backing up a step, this code is not obviously thread-safes, or if it is it
>>>> must be by a lock at a higher level - so why do we need an atomic update of
>>>> the _bytes_written value?
>>>
>>> Yes, this is something we discussed at lunch today. It looks like calling
>>> update_position() without some kind of locking is unsafe. This is not introduced
>>> only by the rotatingFileStream. All the outputStream implmentations does this.
>>> Looks scary to me. I don't really understand how this works in a safe way. Maybe
>>> it doesn't.
>>>
>>> We are not doing any locking higher up in the call chain as far as I can see.
>>>
>>> Bengt
>>>
>>>>
>>>> David
>>>>
>>>> On 19/02/2013 8:18 PM, Jesper Wilhelmsson wrote:
>>>>> Bengt,
>>>>>
>>>>> Thanks for catching this! I should listen to Ted's mother, nothing good
>>>>> happens after 2am[1].
>>>>>
>>>>> I wasn't aware that jint was 32-bit on all platforms. Using 32-bit
>>>>> atomic add like this won't work, back to the drawing board.
>>>>>
>>>>> The one quick solution I can think of right now that won't be awful
>>>>> would be to limit GcLogFileSize to 32 bit. I'm not sure how quick a fix
>>>>> it will be though since it may require a CCC approval...
>>>>>
>>>>> /Jesper
>>>>>
>>>>>
>>>>> [1] http://en.wikipedia.org/wiki/Nothing_Good_Happens_After_2_A.M.
>>>>>
>>>>>
>>>>> On 19/2/13 9:08 AM, Bengt Rutisson wrote:
>>>>>>
>>>>>> Hi Jesper,
>>>>>>
>>>>>> Thanks for fixing this! I don't feel very comfortable with this code,
>>>>>> so don't
>>>>>> consider this a full review. Just a couple of comments:
>>>>>>
>>>>>> It seems to make sense to use uintx for _bytes_written since the flag
>>>>>> to control
>>>>>> the file size, GCLogFileSize, is uintx. But since the atomics you use are
>>>>>> handling jint I think it looks a bit suspicious. jint is always 32
>>>>>> bits and
>>>>>> uintx can be 32 or 64 bit. So, what happens here if _bytes_written is
>>>>>> 64 bit?
>>>>>>
>>>>>>   457     Atomic::add((jint)count, (jint*)&_bytes_written);
>>>>>>
>>>>>> If _bytes_written is 0x00000000FFFFFFFF and count is 1, I would guess
>>>>>> that we
>>>>>> get 0x0 instead of 0x0000000100000000.
>>>>>>
>>>>>> Also, in rotatingFileStream::rotate_log() you changed to:
>>>>>>
>>>>>> if (_bytes_written <= GCLogFileSize) return;
>>>>>>
>>>>>> instead of :
>>>>>>
>>>>>> if (_bytes_writen < (jlong)GCLogFileSize) return;
>>>>>>
>>>>>> isn't this a problem since you set _bytes_written to UINT_MAX if we
>>>>>> wrap around?
>>>>>> If someone sets GCLogFileSize on the command line to be UINT_MAX we
>>>>>> will never
>>>>>> rotate the file, right?
>>>>>>
>>>>>> Also, we only call rotate_log() when we start a safepoint. If we wrap
>>>>>> around
>>>>>> once in write() but then call it again before a safepoint happens we can
>>>>>> probably set _bytes_written to a value that looks small enough to not
>>>>>> have to
>>>>>> rotate the log. It seems to me that we would need a separate flag to
>>>>>> say that we
>>>>>> written enough to rotate the log.
>>>>>>
>>>>>> Bengt
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 2/19/13 7:25 AM, Jesper Wilhelmsson wrote:
>>>>>>> Hi,
>>>>>>>
>>>>>>> Please review the following change:
>>>>>>>
>>>>>>> Webrev: http://cr.openjdk.java.net/~jwilhelm/8008314/
>>>>>>>
>>>>>>> Bug: https://jbs.oracle.com/bugs/browse/JDK-8008314
>>>>>>>
>>>>>>>
>>>>>>> The use of atomic::add(jlong,jlong*) breaks everything on ARM since
>>>>>>> it uses
>>>>>>> atomic::load(jlong) which isn't implemented.
>>>>>>>
>>>>>>> The add was used to update a counter in rotating log file handling,
>>>>>>> but it
>>>>>>> turns out that the counter that was updated doesn't need to be a jlong.
>>>>>>>
>>>>>>> The counter is used to indicate that it is time to do a log file
>>>>>>> rotation and
>>>>>>> by adding a saftey catch for overflow, we can use an uintx for the
>>>>>>> counter.
>>>>>>>
>>>>>>> In practice this means that the upper "limit" for the log file size
>>>>>>> becomes
>>>>>>> UINX_MAX-1 (used to be UINT_MAX) since I change from < to <= in the
>>>>>>> comparison
>>>>>>> to the limit, but since this is not a hard limit the difference will
>>>>>>> only be
>>>>>>> noticeable when someone has written UINT_MAX characters to the log
>>>>>>> file and
>>>>>>> the next write will end up in the next log file part instead of in
>>>>>>> the same
>>>>>>> (which one could argue is a more correct behavior).
>>>>>>>
>>>>>>> Sine I changed all places where the counter was used I also fixed a
>>>>>>> typo in
>>>>>>> its name.
>>>>>>>
>>>>>>> Thanks,
>>>>>>> /Jesper
>>>>>>
>>>
>