Compatibility with rs/logbench

[Juneezee]

I like this logger a lot because it has zero dependencies and an intuitive API. Therefore, I hope that it can gain more popularity among the Go community.

I have created a draft pull request rs/logbench#4 in the rs/logbench repository to include this logger. However, this logger currently does not pass the validation of logbench, more details can be found in rs/logbench#4.

To pass the logbench validation, this logger must

1. Allow timestamp to be disabled
2. Support different encoder for Time and Duration

[phuslu]

thanks for that, looking into.

[phuslu]

changed Duration output to float/int on dcbf2d6
but for Time output, seems that this logger's output is same as zerolog ?

[phuslu]

1. Allow timestamp to be disabled

Currently I cannot found a simple/pretty way to disable time filed. But seems that https://github.com/rs/logbench could bypass this scenario case?

[Juneezee]

Currently I cannot found a simple/pretty way to disable time filed. But seems that https://github.com/rs/logbench could bypass this scenario case?

Thanks for your swift response.

As you can see in this line main_test.go#L356 and main_test.go#L435, currently the test expects no timestamp from all supported loggers. The easiest way I could think of to bypass this for phuslu/log is to add delete(got, "time") before main_test.go#L435.

I hope that commit dcbf2d6 does not cause negative impact to the performance?

[phuslu]

thanks for indicated this, I will continue considering it.

And the latest Dur/Durs implementation, I believe it should be faster.

[Juneezee]

but for Time output, seems that this logger's output is same as zerolog ?

I don't think it's the same. In the test case below, main_test.go#L73 is passing time.Unix(0, 0) to zerolog's Info().Time() is outputting 0 here because zerolog_test.go#L11 has set zerolog.TimeFieldFormat to "", which defaults to zerolog.TimeFormatUnix.

Currently there is no way to set TimeFormat(key string, timefmt string, t time.Time) to Unix timestamp, which is why the Time() output is different from zerolog's output.

--- FAIL: Test/PhusluLog/Enabled/NoContext/Fields/Time (0.00s)
    main_test.go:440: invalid output: mismatch at ["time"]: type mismatch string vs float64; obtained "1970-01-01T07:30:00+07:30"; expected 0
        got: {"ts":1613153093,"level":"info","time":"1970-01-01T07:30:00+07:30","message":"some string with a somewhat realistic length"}
        
        want: {"level":"info","message":"some string with a somewhat realistic length","time":0}

---

The easiest way I could think of to bypass this for phuslu/log is to add delete(got, "time") before main_test.go#L435.

I just added delete(got, "ts"). It seems to work, but it is not removing the ts field when Time(), Times(), Dur(), or Durs() is used. I wonder whether this is a bug within the Go language or this logger?

--- FAIL: Test/PhusluLog/Enabled/NoContext/Fields/Durations (0.00s)
    main_test.go:440: invalid output: mismatch at ["duration"][0]: type mismatch string vs float64; obtained "0s"; expected 0
        got: {"ts":1613153913,"level":"info","duration":["0s","1ms","2ms","3ms","4ms","5ms","6ms","7ms","8ms","9ms"],"message":"some string with a somewhat realistic length"}
        
        want: {"duration":[0,1,2,3,4,5,6,7,8,9],"level":"info","message":"some string with a somewhat realistic length"}

--- FAIL: Test/PhusluLog/Enabled/NoContext/Fields/Duration (0.00s)
    main_test.go:440: invalid output: mismatch at ["duration"]: type mismatch string vs float64; obtained "0s"; expected 0
        got: {"ts":1613153913,"level":"info","duration":"0s","message":"some string with a somewhat realistic length"}
        
        want: {"duration":0,"level":"info","message":"some string with a somewhat realistic length"}

EDIT: delete(got, "ts") does work. It was a small issue with t.Errorf that caused it to print the unmodified version of got.

[phuslu]

I tried fix Time limitation issue in TimeFormat method be54b1e

Please take a look, thanks

[phuslu]

tried fix TimeFormat and Time again on 47c682d

[Juneezee]

TimeFormat("time", log.TimeFormatUnix, time.Unix(0, 0)) is giving an invalid JSON output on commit 47c682d.

--- FAIL: Test/PhusluLog/Enabled/NoContext/Fields/Time (0.00s)
    main_test.go:433: invalid JSON output: invalid character '0' after object key:value pair: {"ts":1613198149,"level":"info","time":0000000000,"message":"some string with a somewhat realistic length"}

Also TimesFormat needs to be updated too 🥰

[phuslu]

sorry, it's an over-optimized issue. I fallback to an normal implementation and also update TimesFormat, thanks.

[Juneezee]

Thanks for your hard work so far! Happy 🐮 year

I have temporary enabled GitHub Pages on my logbench fork, you can view the benchmark results on the web UI here or the text format here. You can exclude some loggers by clicking on them like so

Unfortunately, phuslu/log is not the fastest according to the benchmark results. I believe this is because other loggers have their timestamp disabled, while we are having timestamp included in the log.

Also phuslu/log doesn't have results for WithContext benchmark because it doesn't have something like zerolog's With().Fields(...) yet.

[phuslu]

Thank you!

while we are having timestamp included in the log.

True, maybe we need added a special field named like

const TimeFieldDisabled = "\b"

To let we also disable the timestampl

[phuslu]

Indeed i sent a pr at imkira/go-loggers-bench#6 before

I very agree that imkira/go-loggers-bench enables time filed for each logger forcely.

[Juneezee]

True, maybe we need added a special field named like

const TimeFieldDisabled = "\b"

To let we also disable the timestamp

My primary intention of adding this logger into logbench is to get a more in-depth insight of the performance benchmark. This is because the GitHub Actions is very limited, i.e. it doesn't benchmark fields other than Str() and Int(). I doubt the Go community will accept that this logger is indeed the fastest unless they see a comprehensive benchmark.

I am considering to use this logger in one of my production project as it is dependency free (I love minimal dependencies 🤣) and the performance seems promising. At the same time, this logger lacks a little bit in customisation.

If there is a way to provide more options to customise the logger behaviour, while not harming the performance and making the code less readable, then I will definitely choose this logger over another.

[phuslu]

Tried to hide the time filed but the code changes are ugly and trivial.

This lib already be widely used in our internal company, serves 5 billion requests and writes same amount logs per day.
The 2 points you have mentioned,

1. minimal dependencies
2. simple and clean interface

is the most important motivation of this lib.

During the implementation progress, we found that time filed usual is a must have thing. And its formatting is the most visible cost of log entry. That's why we introduce a handwriting formatting function for it.

So as your see, time field of this is first field and hard to be omitted.
Sorry for "lacks of customization", I have to say it's a trade off.

[Juneezee]

During the implementation progress, we found that time filed usual is a must have thing. And its formatting is the most visible cost of log entry. That's why we introduce a handwriting formatting function for it.

So as your see, time field of this is first field and hard to be omitted.
Sorry for "lacks of customization", I have to say it's a trade off.

Yes, I agree with you completely. There is no reason to omit the time field as that would make debugging harder, especially in a production environment.

I was confused by the logbench benchmark measurements initially as well. Then I realised that the whole benchmark is more focusing on single field performance, e.g. how efficient does it take to log a single Int() etc, and this is normally an indication of the code efficiency.

I believe this is a good logger library, maybe we can add more benchmark into the GitHub Actions rather than relying on imkira/go-loggers-bench or rs/logbench. I'm closing this issue now since there is no point in forcing this library to be compatible with logbench. Peace out ✌️

[phuslu]

thanks for your support.

I align to go-logger-bench codes in latest readme, and the github action result is here https://github.com/phuslu/log/runs/1910179311

I think the result makes convincing.

[phuslu]

Added two common(I think) cases to benchmarks, caller and printf fe07883

The result shows this lib‘s competitiveness

BenchmarkZapCaller-4         	 3723448	      3250 ns/op	     440 B/op	       4 allocs/op
BenchmarkZeroLogCaller-4     	 3401059	      3438 ns/op	     264 B/op	       3 allocs/op
BenchmarkPhusLogCaller-4     	 9022386	      1388 ns/op	     216 B/op	       2 allocs/op
BenchmarkZapPrintf-4         	 6355765	      1904 ns/op	      96 B/op	       2 allocs/op
BenchmarkZeroLogPrintf-4     	 8513709	      1413 ns/op	      96 B/op	       2 allocs/op
BenchmarkPhusLogPrintf-4     	13171816	       901 ns/op	      16 B/op	       1 allocs/op