RFR: 8072645: java.util.logging should use java.time to get more precise time stamps

Daniel Fuchs daniel.fuchs at oracle.com
Thu Feb 19 15:19:26 UTC 2015 

On 18/02/15 12:11, Stephen Colebourne wrote:
> In LogRecord, the Javadoc of getInstant():
> "Get event time."
> could be
> "Gets the instant that the event ocurred."

done.

> In LogRecord, the Javadoc of setInstant():
> "Set event time."
> could be
> "Sets the instant that the event ocurred."
> (matching change to @param)

done.


> I'd prefer to see the other methods in the class have their Javadoc
> changed from "Get" to Gets" and from "Set" to "Sets" to conform with
> Javadoc norms, but understand if this causes CCC issues.

Agreed - but I will need to obtain a CCC approval for this change,
and I'd prefer to leave the specdiff uncluttered.
I will log an RFE for a doc cleanup.


> In PlatformLogger.
> There should be no need to assign to a static constant:
>   private static final Clock systemUTC = Clock.systemUTC();
> However, Clock.systemUTC() needs to be fixed:
> https://bugs.openjdk.java.net/browse/JDK-8073394

Ahah. I hadn't seen this RFE. Thanks for pointing it out.
This RFE (JDK-8073394) won't need any CCC so it should be an easy
quick fix. Given that, I agree that it's better to remove the
static systemUTC fields (removed from PlatformLogger and LogRecord).
I will also take care of JDK-8073394 later on then.


> This
>   ZonedDateTime zdt = ZonedDateTime.ofInstant(systemUTC.instant(), zoneId);
> can be replaced with
>   ZonedDateTime zdt = ZonedDateTime.now(zoneId);

done.

> Again, the implementation of the better method isn't perfectly optimised.
>
> The default format used in String.format does not need to time-zone,
> just the local date/time. As such, in theory a LocalDateTime could be
> used. But, since the format can be changed by the user, a
> ZonedDateTime is needed (probably not worth being clever here).

Yes - that was my reasoning too. ZonedDateTime seems to be the
more resilient to format changes.

> Where you assign ZoneId.systemDefault() to a final instance variable,
> it is being locked for the lifetime of that object. I cannot
> immediately tell what the lifetime of the objects are. I also suspect
> that few if any will want to change their time-zone half way through
> logging.

I don't think we should bother with this possibility.

The PlatformLogger's simple logger may either never be
released (if JUL is not used - meaning, if there is no user
specified logging.properties file and if nobody calls
LogManager.getLogManager()) - or it will be replaced by a
plain logger - in which case the j.u.l.Formatter will
be used - and the j.u.l.Formatter will usually have the
same life-time than the Handler on which it is set.
(usually, until reset() or readConfiguration() is called).


> XMLFormatter has a reviewer's comment that will need to be removed
> before committing.

Will do before pushing. At the moment I'm still hoping it will catch
the eye of an XML/DTD expert :-)

> In LogRecordWithNanosAPI you check the instant contents rather than
> just the instant:
>   assertEquals(record.getInstant().getEpochSecond(),
> record2.getInstant().getEpochSecond(),
> "getInstant().getEpochSecond()");
>   assertEquals(record.getInstant().getNano(),
> record2.getInstant().getNano(), "getInstant().getNano()");
>   assertEquals(record.getInstant().toEpochMilli(),
> record2.getInstant().toEpochMilli(), "getInstant().toEpochMilli()");
> could be
>   assertEquals(record.getInstant(), record2.getInstant(), "getInstant()");
> There are probably other instances of this point.

Right. I'm not very motivated to change the LogRecord* tests.
What happened is that I wrote these tests based on the use of
LogRecord.setMillis/getMillis and
LogRecord.getNanoAdjustment/setNanoAdjustment - and then had to
update them when we decided to drop
LogRecord.getNanoAdjustment/setNanoAdjustment and changed the
implementation of getMillis/setMillis to work on top of instant.

As a consequence, the test have probably become a bit more complex
and cluttered than they would have been if I had written them
directly against the later version of the API.

However I believe they still do the job - I have been careful
to add some additional tests to verify the new implementation of
getMillis/setMillis - I don't believe I left any cracks.

The important point is to verify the consistency of getMillis/getInstant
and setMillis/setInstant as well as checking that nothing is lost
in the serialization - I believe the tests are good enough in that
respect.

> Hope that helps

It does! I am grateful :-)

Here is the updated webrev.
http://cr.openjdk.java.net/~dfuchs/webrev_8072645/webrev.02/

best regards,

-- daniel

> Stephen
>
>
>
> On 17 February 2015 at 19:33, Daniel Fuchs <daniel.fuchs at oracle.com> wrote:
>> Hi,
>>
>> Here is a new webrev - which should contain all the feedback received
>> so far:
>>
>> #1 LogRecord uses serialPersistentFields for serialization, and
>>     contains an Instant instead of the two fields millis +
>>     nanoAdjustment.
>> #2 getMillis/setMillis are deprecated, replaced by getInstant/setInstant
>>     getNanoAdjustment/setNanoAdjustment have been dropped.
>>
>> [Thanks Peter for prototyping these 2 first changes!]
>>
>> #3 XMLFormatter uses ISO_INSTANT to print the instant in the date field.
>>     new constructor has been dropped. printNanos property is renamed into
>>     useInstant.
>> #4 SimpleFormatter still uses ZonedDateTime - for compatibility and
>>     flexibility and because it proved to be faster than Date [1].
>> #5 Tests have been updated WRT to the changes above.
>> #6 various doc tweaks compared to last webrev
>>
>> new webrev:
>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/webrev.01/
>>
>> specdiff updated in place (unfortunately the serial form does
>> not show up):
>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/specdiff-logging-time/overview-summary.html
>>
>> best regards,
>>
>> -- daniel
>>
>> [1] benchmarks related to formatting the date:
>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/benchmarks.html
>>
>>
>>
>> On 16/02/15 20:24, Daniel Fuchs wrote:
>>>
>>> Hi Stephen,
>>>
>>> Thanks again for your support and suggestions!
>>>
>>> On 14/02/15 14:03, Daniel Fuchs wrote:
>>>>
>>>> If I'm not mistaken the previous SimpleFormatter used to use
>>>> java.util.Date
>>>> and printed the time in the local time zone. I have tried to keep this
>>>> behavior.
>>>> I'm not sure we would want to change it to print the time in the UTC
>>>> time zone
>>>> by default. A lot of developers use logging for debugging - and when
>>>> reading
>>>> debug messages on the console I usually prefer to see the time in my own
>>>> time zone.
>>>>
>>>> Would there be a more efficient way to keep the default formatting of
>>>> the time
>>>> in the SimpleFormatter?
>>>
>>>
>>> I spent part of the day reading the documentation & trying out the
>>> various TemporalAccessors and DateTimeFormatters...
>>>
>>> I have also done some microbenchmark measurements (jmh) WRT
>>> the performance  of formatting a date/time.
>>> Results can be seen here [1]:
>>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/benchmarks.html
>>>
>>> What it shows is that when using String.format (as the SimpleFormatter
>>> is specified to do), then using ZonedDateTime is actually an improvement
>>> over using Date.
>>>
>>> Now that I have read a bit more about LocalDateTime, ZonedDateTime,
>>> Date, and Instant, I do agree with you that for recording an event time,
>>> printing the Instant is the better alternative.
>>> However, since SimpleFormatter has always printed the local date,
>>> I would tend to want to keep it that way.
>>>
>>> So I'm going to propose to keep using ZonedDateTime in
>>> the SimpleFormatter, as I believe it's what gives it the maximum of
>>> flexibility - WRT to using String.format (+ we will get some
>>> boost as bonus by no longer using Date).
>>> If you strongly feel that java.util.logging should offer a better
>>> alternative - then maybe we should log an RFE to explore it?
>>>
>>> Things are - I believe - a bit different for the XMLFormatter.
>>> First, the XMLFormatter is not specified to use String.format, so
>>> it gives us a bit more flexibility.
>>> In addition we already need to tweak the format in order to introduce
>>> the new <nanos> element - (or should it be <nanoOfMilli> as Peter
>>> suggested?).
>>>
>>> So for the XMLFormatter, and given the results of my
>>> microbenchmark [1], here is what I would suggest:
>>>
>>> #1 rename the property printNanos into useInstant
>>> #2 if useInstant is false, use the old code for formatting the
>>>      date (the old appendISO8601() method) and omit the <nanos>
>>>      element - so applications that specify useInstant=false should
>>>      see the same formatting than before, without paying the
>>>      performance cost that using ZonedDateTime would bring.
>>> #3 if useInstant is absent - or not false, then we use the 'new'
>>>      format. The <date> element will contain the instant printed
>>>      using DateTimeFormatter.ISO_INSTANT, and the <nanos> element
>>>      will be printed after <millis>
>>>
>>> Does that sound right? If so I will include these changes in my
>>> next webrev, once I have digested the feedback sent by Peter :-)
>>>
>>> Best regards,
>>>
>>> -- daniel
>>>
>>> [1] microbenchmark:
>>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/benchmarks.html
>>>
>>>
>>>>
>>>>> (The webrev is broken wrt zones as it stores ZoneId.systemDefault() in a
>>>>> static constant, but that method depends on the mutable
>>>>> TimeZone.getDefault() ).
>>>>
>>>>
>>>> Would making it a final (non static) variable be better?
>>>> I now wonder whether there should be a way to configure the time zone for
>>>> an instance of SimpleFormatter (something like what I did with
>>>> 'printNanos'
>>>> for the XMLFormatter).
>>>>
>>>>> LogReecord.getInstantUTC() should be getInstant().
>>>>>
>>>>> (An Instant is fully defined as a concept, and it cannot be in or not in
>>>>> UTC).
>>>>
>>>>
>>>> Right. Thanks for pointing that out.
>>>>>
>>>>> In SimpleFormatter, you have {@code java.util.loggin} (missing a "g").
>>>>
>>>>
>>>> Good catch.
>>>>
>>>>> In XMLFormatter, instead of using DateTimeFormatter.ISO_LOCAL_DATE_TIME,
>>>>> create a new instance of DateTimeFormatter that does not output the
>>>>> fraction of a second. That way, there is no need to use
>>>>> truncatedTo(SECONDS).
>>>>>
>>>>> StringBuilder appends can be used directly with formatters:
>>>>>
>>>>> sb.append(ZonedDateTime.ofInstant(time, zoneId).format(dtformatter));
>>>>>
>>>>> replace with
>>>>>
>>>>> dtformatter.formatTo(ZonedDateTime.ofInstant(time, zoneId), sb);
>>>>
>>>>
>>>> Will look into this.
>>>>
>>>> Thanks again for your review! This is quite helpful.
>>>>
>>>> -- daniel
>>>>
>>>>
>>>>>
>>>>> thanks
>>>>> Stephen
>>>>>
>>>>>
>>>>>
>>>>> On 13 Feb 2015 14:57, "Daniel Fuchs" <daniel.fuchs at oracle.com> wrote:
>>>>>
>>>>>> Hi,
>>>>>>
>>>>>> Please find below a patch for:
>>>>>>
>>>>>> 8072645: java.util.logging should use java.time to get more
>>>>>>            precise time stamps
>>>>>>
>>>>>>
>>>>>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/webrev.00/
>>>>>>
>>>>>> specdiff:
>>>>>> http://cr.openjdk.java.net/~dfuchs/webrev_8072645/
>>>>>> specdiff-logging-time/java/util/logging/package-summary.html
>>>>>>
>>>>>> Overview:
>>>>>> ---------
>>>>>>
>>>>>> The patch is made of the following pieces:
>>>>>>
>>>>>>    - LogRecord uses java.time.Clock's systemClock to get an
>>>>>>      Instant in the best available resolution.
>>>>>>
>>>>>>      The instant is split into a number of milliseconds (a long)
>>>>>>      and a nanosecond adjustment (an int).
>>>>>>      The number of milliseconds is the same than what would have
>>>>>>      been obtained by calling System.currentTimeMillis().
>>>>>>
>>>>>>    - LogRecord acquires a new serializable int nanoAdjustement field,
>>>>>>      which can be used together with the number of milliseconds
>>>>>>      to reconstruct the instant.
>>>>>>
>>>>>>    - SimpleFormatter is updated to pass a ZoneDateTime
>>>>>>      instance to String.format, instead of a Date.
>>>>>>
>>>>>>      The effect of that is that the format string can now
>>>>>>      be configure to print the full instant precision, if
>>>>>>      needed.
>>>>>>
>>>>>>    - XMLformatter will add a new <nanos> element after the
>>>>>>      <millis> element - if the value of the nanoAdjustment
>>>>>>      field is not 0.
>>>>>>
>>>>>>      The <date> string will also contain the nano second
>>>>>>      adjustment as well as the zone offset as formatted by
>>>>>>      DateTimeFormatter.ISO_OFFSET_DATE_TIME
>>>>>>
>>>>>> Compatibility considerations:
>>>>>> -----------------------------
>>>>>>
>>>>>> - The serial for of log record is backward/forward compatible.
>>>>>>     I added a test to verify that.
>>>>>>
>>>>>> - XMLFormatter has acquired a new configurable property
>>>>>>     '<FQCN>.printNanos' which allows to revert to the old
>>>>>>     XML format, should the new format cause issues in
>>>>>>     existing applications.
>>>>>>
>>>>>> - The logger.dtd will need to be updated, to support the
>>>>>>     new optional <nanos> element. And for this matter,
>>>>>>     should we update the logger.dtd or rather define a
>>>>>>     logger-v2.dtd?
>>>>>>     See planned modification:
>>>>>>
>>>>>> <http://cr.openjdk.java.net/~dfuchs/webrev_8072645/logger-
>>>>>> dtd/logger.dtd.frames.html>
>>>>>>
>>>>>> best regards,
>>>>>>
>>>>>> -- daniel
>>>>>>
>>>>
>>>
>>

More information about the core-libs-dev mailing list