Fix #116 - sub millisecond duration should now be measured by default #117
Conversation
domgreen
changed the title
Codecov Report
@@ Coverage Diff @@
## master #117 +/- ##
=======================================
Coverage 73.06% 73.06%
=======================================
Files 36 36
Lines 1277 1277
=======================================
Hits 933 933
Misses 295 295
Partials 49 49
Continue to review full report at Codecov.
|
| func TestDurationToTimeMillisField(t *testing.T) { | ||
| val := DurationToTimeMillisField(time.Microsecond * 100) | ||
| assert.Equal(t, val.Type, zapcore.Float32Type, "should be a float type") | ||
| assert.Equal(t, math.Float32frombits(uint32(val.Integer)), float32(0.1), "sub millisecond values should be correct") |
There was a problem hiding this comment.
math.Float32frombits(uint32( feels like it's relying on knowledge of zap internals, is there any other way we can get the processed value?
There was a problem hiding this comment.
This was a tricky one to figure out, wasnt sure of it myself tbh but couldn't think of a way to do it without knowing how zapFlags worked.
If we had #114 merged we could probably grab it off the log line in an interceptor test and assert its not 0 therefore not testing this method directly.
logging/logrus/options_test.go
Outdated
|
|
||
| func TestDurationToTimeMillisField(t *testing.T) { | ||
| _, val := DurationToTimeMillisField(time.Microsecond * 100) | ||
| assert.Equal(t, val.(float32), float32(0.1), "sub millisecond values should be correct") |
| func TestDurationToTimeMillisField(t *testing.T) { | ||
| val := DurationToTimeMillisField(time.Microsecond * 100) | ||
| assert.Equal(t, val.Type, zapcore.Float32Type, "should be a float type") | ||
| assert.Equal(t, math.Float32frombits(uint32(val.Integer)), float32(0.1), "sub millisecond values should be correct") |
|
The alternative for these tests now #114 is merged is to do: @devnev @artsiukhou @mwitkow what do you think? |
|
Have updated the PR so that it is inline with the above comments. No longer testing via the |
|
ok, the problem here is that if we do it this way, we will have really long, unreasonable floats. A float for a millisecond counter is fine, as long as we cap it's precision to /10 or /100 of a millisecond. |
|
@mwitkow Couple of options I could think of:
I do think it's valuable recording less than 0ms as seeing logs with |
|
@mwitkow have gone for 2 ... setting all outputs to have 3dp. |
|
@mwitkow it is also now inline with httpware have a sample here to show outputs https://play.golang.org/p/SFpG5u9fWI |
Currently issue #116 is raised due to sub ms durations being logged as 0ms we can fix this by casting the duration to a float before we do the division.
This change will mean that if your
grpc.time_msis greater than one it will be represented as a whole number of ms10otherwise it will be displayed to 3 decimal places0.542.