Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

log: Add TimestampFormat and Timeformat. #514

Merged
merged 1 commit into from
Apr 20, 2017
Merged

Conversation

ChrisHines
Copy link
Member

@ChrisHines ChrisHines commented Apr 16, 2017

  • TimeFormat provides a value that defers formating timestamps until
    serialization, which improves performance when a log event is not
    serialized.
  • TimestampFormat is a convenience function to produce time Valuers
    with arbitrary time formats.
  • DefaultTimestamp and DefaultTimestampUTC are now created using
    TimestampFormat.

Benchmarks from log/level showing the benefits:

name                                              old time/op    new time/op    delta
/TimeContext/Baseline/Nop-8                          679ns ± 0%     358ns ± 0%  -47.25%  (p=0.008 n=5+5)
/TimeContext/Baseline/Logfmt-8                      1.41µs ± 0%    1.49µs ± 0%   +5.67%  (p=0.008 n=5+5)
/TimeContext/Baseline/JSON-8                        2.87µs ± 0%    2.87µs ± 0%     ~     (p=0.611 n=5+5)
/TimeContext/DisallowedLevel/Nop-8                   680ns ± 0%     360ns ± 0%  -47.13%  (p=0.008 n=5+5)
/TimeContext/DisallowedLevel/Logfmt-8                680ns ± 0%     359ns ± 0%  -47.18%  (p=0.008 n=5+5)
/TimeContext/DisallowedLevel/JSON-8                  680ns ± 0%     360ns ± 0%  -47.04%  (p=0.008 n=5+5)
/TimeContext/AllowedLevel/Nop-8                      688ns ± 0%     364ns ± 0%  -47.15%  (p=0.016 n=4+5)
/TimeContext/AllowedLevel/Logfmt-8                  1.42µs ± 0%    1.50µs ± 0%   +5.38%  (p=0.008 n=5+5)
/TimeContext/AllowedLevel/JSON-8                    2.88µs ± 0%    2.88µs ± 0%   +0.32%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/Nop-8              1.41µs ± 0%    1.07µs ± 1%  -24.43%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/Logfmt-8           3.26µs ± 0%    3.37µs ± 0%   +3.55%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/JSON-8             5.32µs ± 0%    5.34µs ± 0%   +0.53%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/Nop-8       1.41µs ± 0%    1.06µs ± 0%  -24.49%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/Logfmt-8    1.41µs ± 0%    1.06µs ± 0%  -24.53%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/JSON-8      1.41µs ± 0%    1.07µs ± 1%  -24.37%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/Nop-8          1.42µs ± 0%    1.07µs ± 0%  -24.54%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/Logfmt-8       3.26µs ± 1%    3.38µs ± 0%   +3.81%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/JSON-8         5.35µs ± 0%    5.34µs ± 0%     ~     (p=0.238 n=5+5)

name                                              old alloc/op   new alloc/op   delta
/TimeContext/Baseline/Nop-8                           352B ± 0%      352B ± 0%     ~     (all equal)
/TimeContext/Baseline/Logfmt-8                        352B ± 0%      400B ± 0%  +13.64%  (p=0.008 n=5+5)
/TimeContext/Baseline/JSON-8                        1.26kB ± 0%    1.31kB ± 0%   +3.80%  (p=0.008 n=5+5)
/TimeContext/DisallowedLevel/Nop-8                    352B ± 0%      352B ± 0%     ~     (all equal)
/TimeContext/DisallowedLevel/Logfmt-8                 352B ± 0%      352B ± 0%     ~     (all equal)
/TimeContext/DisallowedLevel/JSON-8                   352B ± 0%      352B ± 0%     ~     (all equal)
/TimeContext/AllowedLevel/Nop-8                       352B ± 0%      352B ± 0%     ~     (all equal)
/TimeContext/AllowedLevel/Logfmt-8                    352B ± 0%      400B ± 0%  +13.64%  (p=0.008 n=5+5)
/TimeContext/AllowedLevel/JSON-8                    1.26kB ± 0%    1.31kB ± 0%   +3.80%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/Nop-8                560B ± 0%      560B ± 0%     ~     (all equal)
/TimeCallerReqIDContext/Baseline/Logfmt-8             736B ± 0%      784B ± 0%   +6.52%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/JSON-8             1.85kB ± 0%    1.90kB ± 0%   +2.60%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/Nop-8         560B ± 0%      560B ± 0%     ~     (all equal)
/TimeCallerReqIDContext/DisallowedLevel/Logfmt-8      560B ± 0%      560B ± 0%     ~     (all equal)
/TimeCallerReqIDContext/DisallowedLevel/JSON-8        560B ± 0%      560B ± 0%     ~     (all equal)
/TimeCallerReqIDContext/AllowedLevel/Nop-8            560B ± 0%      560B ± 0%     ~     (all equal)
/TimeCallerReqIDContext/AllowedLevel/Logfmt-8         736B ± 0%      784B ± 0%   +6.52%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/JSON-8         1.85kB ± 0%    1.90kB ± 0%   +2.60%  (p=0.008 n=5+5)

name                                              old allocs/op  new allocs/op  delta
/TimeContext/Baseline/Nop-8                           8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)
/TimeContext/Baseline/Logfmt-8                        8.00 ± 0%      8.00 ± 0%     ~     (all equal)
/TimeContext/Baseline/JSON-8                          27.0 ± 0%      27.0 ± 0%     ~     (all equal)
/TimeContext/DisallowedLevel/Nop-8                    8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)
/TimeContext/DisallowedLevel/Logfmt-8                 8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)
/TimeContext/DisallowedLevel/JSON-8                   8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)
/TimeContext/AllowedLevel/Nop-8                       8.00 ± 0%      7.00 ± 0%  -12.50%  (p=0.008 n=5+5)
/TimeContext/AllowedLevel/Logfmt-8                    8.00 ± 0%      8.00 ± 0%     ~     (all equal)
/TimeContext/AllowedLevel/JSON-8                      27.0 ± 0%      27.0 ± 0%     ~     (all equal)
/TimeCallerReqIDContext/Baseline/Nop-8                9.00 ± 0%      8.00 ± 0%  -11.11%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/Baseline/Logfmt-8             14.0 ± 0%      14.0 ± 0%     ~     (all equal)
/TimeCallerReqIDContext/Baseline/JSON-8               38.0 ± 0%      38.0 ± 0%     ~     (all equal)
/TimeCallerReqIDContext/DisallowedLevel/Nop-8         9.00 ± 0%      8.00 ± 0%  -11.11%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/Logfmt-8      9.00 ± 0%      8.00 ± 0%  -11.11%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/DisallowedLevel/JSON-8        9.00 ± 0%      8.00 ± 0%  -11.11%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/Nop-8            9.00 ± 0%      8.00 ± 0%  -11.11%  (p=0.008 n=5+5)
/TimeCallerReqIDContext/AllowedLevel/Logfmt-8         14.0 ± 0%      14.0 ± 0%     ~     (all equal)
/TimeCallerReqIDContext/AllowedLevel/JSON-8           38.0 ± 0%      38.0 ± 0%     ~     (all equal)

@omeid
Copy link

omeid commented Apr 17, 2017

One of the best traits of go-kit in general, and log package, is the minimal interface.

If TimestampFormat on it's own is enough; I think TimeFormat should be unexported so to keep the log package interface minimal and afford to not commit to the implementation.

log/value.go Outdated
// TimestampFormat returns a Valuer that produces a TimeFormat value from
// layout and the time returned by t. Users will probably want to use
// DefaultTimestamp or DefaultTimestampUTC.
func TimestampFormat(t func() time.Time, layout string) Valuer {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • An alternate name to consider instead of t: now.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using now makes sense to me, but I think t can also be fine, if it's explained a bit more didactically; I think I want the comment here to explain the "why" rather than the "what", e.g.

// TimestampFormat can be used to create custom time formats for log timestamps.
// The t function will be invoked to get the time to format; unless you're doing
// something tricky, pass time.Now. The layout string is passed to Time.Format.
//
// Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which
// are TimestampFormats that use the RFC3339Nano format.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm going to stick with the name t because the returned time doesn't have to represent the current time. I agree that the comment will need to be reworded when TimeFormat is not exported. Thanks for the wordsmithing.

log/value.go Outdated
}

// A TimeFormat represents an instant in time and a layout used when
// marshaling to a text format.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  • If this does stay an exported type, consider mentioning that the layout must be one accepted by time.Time.Format.

@ChrisHines ChrisHines requested a review from peterbourgon April 19, 2017 00:59
Copy link
Member

@peterbourgon peterbourgon left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A couple of minor things I'd like to see addressed, but overall LGTM!

log/value.go Outdated
// TimestampFormat returns a Valuer that produces a TimeFormat value from
// layout and the time returned by t. Users will probably want to use
// DefaultTimestamp or DefaultTimestampUTC.
func TimestampFormat(t func() time.Time, layout string) Valuer {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using now makes sense to me, but I think t can also be fine, if it's explained a bit more didactically; I think I want the comment here to explain the "why" rather than the "what", e.g.

// TimestampFormat can be used to create custom time formats for log timestamps.
// The t function will be invoked to get the time to format; unless you're doing
// something tricky, pass time.Now. The layout string is passed to Time.Format.
//
// Most users will want to use DefaultTimestamp or DefaultTimestampUTC, which
// are TimestampFormats that use the RFC3339Nano format.

log/value.go Outdated
type TimeFormat struct {
Time time.Time
Layout string
}
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As others have said, I think this can be safely unexported?

log/value.go Outdated

// MarshalText implements encoding.TextMarshaller.
func (tf TimeFormat) MarshalText() (text []byte, err error) {
b := make([]byte, 0, len(tf.Layout)+10)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you constize this literal 10 so we get a name with some semantic meaning?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can add a brief comment, but I don't know what to name the constant? Do you have any suggestions?

For reference, the technique is a reduction of the standard library code for time.Time.Format, seen here: https://golang.org/src/time/format.go?s=14285:14327#L437. Unfortunately that code doesn't provide any naming help or even document why they picked 10.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh! Well, if the magic number is OK there, I reckon it's OK here too. Nevermind my request.

@ChrisHines
Copy link
Member Author

Thanks for the input everyone. I'll make updates based on your feedback this evening.

- TimestampFormat is a function to produce time Valuers with arbitrary time
  formats.
- The Valuer generates values of the unexported type timeFormat, a value
  that defers formating timestamps until serialization, which improves
  performance when a log event is not serialized.
- DefaultTimestamp and DefaultTimestampUTC are now created using
  TimestampFormat.
@ChrisHines ChrisHines merged commit bc4df5b into master Apr 20, 2017
@ChrisHines ChrisHines deleted the defer-time-format branch April 27, 2017 01:05
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants