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

[Daniel Fuchs]

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
>>>
>