diff --git a/.gitignore b/.gitignore index b008471..9d5f1a5 100644 --- a/.gitignore +++ b/.gitignore @@ -13,3 +13,4 @@ # ide .idea/ +*.iml diff --git a/FUTURE.md b/FUTURE.md index 703b0a1..deb4cbb 100644 --- a/FUTURE.md +++ b/FUTURE.md @@ -1,10 +1,17 @@ ## ✒ 未来版本的新特性 (Features in future version) -### v0.0.12 -* 时间格式化操作中 time.Time.AppendFormat 消耗性能很多,思考优化方案 +### v0.1.1 +* 完善 DurationRollingFile 结构,加入文件个数限制 +* 完善 SizeRollingFile 结构,加入文件个数限制 + +### v0.1.0 +* 重构目前 Logger 的设计,主要是 handler 的设计 +* 增加配置文件的支持,考虑以包为单位控制日志的配置 +* 时间默认不做格式化,当需要输出处理的时候可以保证更高的性能 ### v0.0.11 * 支持日志输出为 Json 形式,通过增加 JSON 日志处理器实现 +* 使用时间缓存机制优化时间格式化操作性能消耗过多的问题,性能再次提升 50% ### v0.0.10 * 扩展了 Logger 的方法,可以获取到内部的属性,为日志处理器做准备 diff --git a/HISTORY.md b/HISTORY.md index 1aa20ad..0d36c1e 100644 --- a/HISTORY.md +++ b/HISTORY.md @@ -1,5 +1,10 @@ ## ✒ 历史版本的特性介绍 (Features in old version) +### v0.0.11 +> 此版本发布于 2020-03-23 +* 支持日志输出为 Json 形式,通过增加 JSON 日志处理器实现 +* 使用时间缓存机制优化时间格式化操作性能消耗过多的问题,性能再次提升 50% + ### v0.0.10 > 此版本发布于 2020-03-10 * 扩展了 Logger 的方法,可以获取到内部的属性,为日志处理器做准备 diff --git a/README.en.md b/README.en.md index 72e8149..213c826 100644 --- a/README.en.md +++ b/README.en.md @@ -2,7 +2,7 @@ [![License](./license.svg)](https://www.apache.org/licenses/LICENSE-2.0.html) -**logit** is a easy-to-use and level-based logger for [GoLang](https://golang.org) applications. +**logit** is an easy-to-use and level-based logger for [GoLang](https://golang.org) applications. [阅读中文版的 Read me](./README.md). @@ -10,17 +10,20 @@ * Modularization design, easy to extend your logger with wrapper and handler * Level-based logging, and there are four levels to use -* Log Function supports, it is a better way to output a very long log. +* Log Function supports, it is a better way to output a very long log * Enable or disable Logger, you can disable or switch to a higher level in your production environment -* Log file supports, and you can customer the name of your log file. -* Duration rolling supports, which means it will roll to a new log file by duration automatically, such as one day one log file. -* File size rolling supports, which means it will roll to a new log file by file size automatically, such as one 64 MB one log file. -* Log handler supports, you can extend logger with your own log handler easily. +* Log file supports, and you can customer the name of your log file +* Duration rolling supports, which means it will roll to a new log file by duration automatically, such as one day one log file +* File size rolling supports, which means it will roll to a new log file by file size automatically, such as one 64 MB one log file +* Log handler supports, you can extend logger with your own log handler easily * High-performance supports, by avoiding to call runtime.Caller -* Time format supports, you can format time in your way. +* Time format supports, you can format time in your way +* Log as Json string supports, by using provided JsonLoggerHandler _Check [HISTORY.md](./HISTORY.md) and [FUTURE.md](./FUTURE.md) to get more information._ +> We will redesign some part of logit for more concise and convenient, check branch v0.1.x to learn more information. + ### 🚀 Installation The only requirement is the [Golang Programming Language](https://golang.org). @@ -39,7 +42,7 @@ module your_project_name go 1.14 require ( - github.com/FishGoddess/logit v0.0.10 + github.com/FishGoddess/logit v0.0.11 ) ``` @@ -79,7 +82,7 @@ func main() { // If you have a long log and it is made of many variables, try this: // The msg is the return value of msgGenerator. - logit.DebugFunction(func() string { + logit.DebugFunc(func() string { // Use time as the source of random number generator. r := rand.New(rand.NewSource(time.Now().Unix())) return "debug rand int: " + strconv.Itoa(r.Intn(100)) @@ -109,10 +112,11 @@ $ go test -v ./_examples/benchmarks_test.go -bench=. -benchtime=1s | test case | times ran (large is better) | ns/op (small is better) | features | extension | | -----------|--------|-------------|-------------|-------------| -| **logit** |   572947 | 1939 ns/op | powerful | high | +| **logit** | 1190984 | 1006 ns/op | powerful | high | +| zap |   401043 | 2793 ns/op | normal | normal | | logrus |   158262 | 7751 ns/op | normal | normal | -| Golog |   751064 | 1614 ns/op | normal | normal | -| Golang log | 1000000 | 1019 ns/op | not good | none | +| golog |   751064 | 1614 ns/op | normal | normal | +| golang log | 1000000 | 1019 ns/op | not good | none | > Environment:I7-6700HQ CPU @ 2.6 GHZ, 16 GB RAM @@ -124,10 +128,11 @@ $ go test -v ./_examples/benchmarks_test.go -bench=. -benchtime=1s **2. v0.0.7 and lower versions use some functions of fmt, and these functions is expensive** **because of reflect (for judging the parameter v interface{}). Actually, these judgements** -**are redundant in a logger. The more effective output will be used in v0.0.8 and higher versions.** +**are redundant in a logger. The more effective output is used in v0.0.8 and higher versions.** **3. After checking the benchmarks of v0.0.8 version, we found that time format takes a lots of time** -**because of time.Time.AppendFormat. We are finding a more effective way to fix it, maybe fixed in higher version!** +**because of time.Time.AppendFormat. In v0.0.11 and higher versions, we use time cache mechanism to** +**reduce the times of time format. However, is it worth to replace time format operation with concurrent competition?** ### 👥 Contributing diff --git a/README.md b/README.md index 81b0552..e988f39 100644 --- a/README.md +++ b/README.md @@ -9,7 +9,7 @@ ### 🥇 功能特性 * 独特的日志输出模块设计,使用 wrapper 和 handler 装载特定的模块,实现扩展功能 -* 支持日志级别控制,一共有四个日志级别,分别是 debug,info,warn 和 error。 +* 支持日志级别控制,一共有四个日志级别,分别是 debug,info,warn 和 error * 支持日志记录函数,使用回调的形式获取日志内容,对长日志内容的组织逻辑会更清晰 * 支持开启或者关闭日志功能,线上环境可以关闭或调高日志级别 * 支持记录日志到文件中,并且可以自定义日志文件名 @@ -18,9 +18,12 @@ * 增加日志处理器模块,支持用户自定义日志处理逻辑,具有很高的扩展能力 * 支持不输出文件信息,避免 runtime.Caller 方法的调用,具有很高的性能 * 支持调整时间格式化输出,让用户自定义时间输出的格式 +* 支持以 Json 形式输出日志信息,更方便后续对日志进行解析 _历史版本的特性请查看 [HISTORY.md](./HISTORY.md)。未来版本的新特性和计划请查看 [FUTURE.md](./FUTURE.md)。_ +> 未来的 v0.1.0 以及更高的版本将会做一次设计上的重构,尽可能保持代码的简洁和功能的易用性,更多信息请查看 v0.1.x 分支。 + ### 🚀 安装方式 唯一需要的依赖就是 [Golang 运行环境](https://golang.org). @@ -39,7 +42,7 @@ module your_project_name go 1.14 require ( - github.com/FishGoddess/logit v0.0.10 + github.com/FishGoddess/logit v0.0.11 ) ``` @@ -79,7 +82,7 @@ func main() { // If you have a long log and it is made of many variables, try this: // The msg is the return value of msgGenerator. - logit.DebugFunction(func() string { + logit.DebugFunc(func() string { // Use time as the source of random number generator. r := rand.New(rand.NewSource(time.Now().Unix())) return "debug rand int: " + strconv.Itoa(r.Intn(100)) @@ -109,10 +112,11 @@ $ go test -v ./_examples/benchmarks_test.go -bench=. -benchtime=1s | 测试 | 单位时间内运行次数 (越大越好) | 每个操作消耗时间 (越小越好) | 功能性 | 扩展性 | | -----------|--------|-------------|-------------|-------------| -| **logit** |   572947 | 1939 ns/op | 强大 | 高 | +| **logit** | 1190984 | 1006 ns/op | 强大 | 高 | +| zap |   401043 | 2793 ns/op | 正常 | 正常 | | logrus |   158262 | 7751 ns/op | 正常 | 正常 | -| Golog |   751064 | 1614 ns/op | 正常 | 正常 | -| Golang log | 1000000 | 1019 ns/op | 一般 | 无 | +| golog |   751064 | 1614 ns/op | 正常 | 正常 | +| golang log | 1000000 | 1019 ns/op | 一般 | 无 | > 测试环境:I7-6700HQ CPU @ 2.6 GHZ,16 GB RAM @@ -127,7 +131,8 @@ $ go test -v ./_examples/benchmarks_test.go -bench=. -benchtime=1s **判断是可以省略的,可以减少很多运行时操作时间!v0.0.8 版本开始使用了更有效率的输出方式!** **3. 经过对 v0.0.8 版本的性能检测,发现时间格式化操作消耗了接近一半的处理时间,** -**主要体现在 time.Time.AppendFormat 的调用上。目前正在思考优化方案,或许会在之后的版本中解决!** +**主要体现在 time.Time.AppendFormat 的调用上。在 v0.0.11 版本中使用了时间缓存机制进行优化,** +**目前存在一个疑惑就是使用并发竞争去换取时间格式化的性能消耗究竟值不值得?** ### 👥 贡献者 diff --git a/_examples/benchmarks_test.go b/_examples/benchmarks_test.go index 1ff733f..d36a224 100644 --- a/_examples/benchmarks_test.go +++ b/_examples/benchmarks_test.go @@ -11,6 +11,8 @@ import ( "github.com/FishGoddess/logit" //"github.com/kataras/golog" //"github.com/sirupsen/logrus" + //"go.uber.org/zap" + //"go.uber.org/zap/zapcore" ) // 仅为测试用,不输出任何信息的写出器 @@ -110,4 +112,34 @@ func BenchmarkLogLogger(b *testing.B) { // for i := 0; i < b.N; i++ { // logTask() // } -//} \ No newline at end of file +//} + +// 测试标准库 zap 日志记录器的速度 +//func BenchmarkZapLogger(b *testing.B) { +// +// // 测试用的日志记录器 +// config := zap.NewProductionEncoderConfig() +// config.EncodeTime = zapcore.RFC3339TimeEncoder +// // 这里选用了 JSONEncoder,因为 JSONEncoder 比 ConsoleEncoder 的性能提升了接近 63% +// jsonEncoder := zapcore.NewJSONEncoder(config) +// nopWriteSyncer := zapcore.AddSync(&nopWriter{}) +// core := zapcore.NewCore(jsonEncoder, nopWriteSyncer, zapcore.DebugLevel) +// logger := zap.New(core) +// defer logger.Sync() +// +// // 测试用的日志任务 +// logTask := func() { +// logger.Debug("debug...") +// logger.Info("info...") +// logger.Warn("warning...") +// logger.Error("error...") +// } +// +// // 开始性能测试 +// b.ReportAllocs() +// b.StartTimer() +// +// for i := 0; i < b.N; i++ { +// logTask() +// } +//} diff --git a/_examples/logger.go b/_examples/logger.go index d8738da..122d200 100644 --- a/_examples/logger.go +++ b/_examples/logger.go @@ -55,7 +55,7 @@ func main() { // If you have a long log and it is made of many variables, try this: // The msg is the return value of msgGenerator. - logger.DebugFunction(func() string { + logger.DebugFunc(func() string { // Use time as the source of random number generator. r := rand.New(rand.NewSource(time.Now().Unix())) return "debug rand int: " + strconv.Itoa(r.Intn(100)) diff --git a/_examples/logger_handler.go b/_examples/logger_handler.go index 8ed92f3..b9a5479 100644 --- a/_examples/logger_handler.go +++ b/_examples/logger_handler.go @@ -31,7 +31,7 @@ func main() { // Create a logger holder. // Default handler is logit.DefaultLoggerHandler. logger := logit.NewLogger(os.Stdout, logit.InfoLevel) - logger.Info("before logging...") + logger.Info("before adding handlers...") // Customize your own handler. handlers1 := func(logger *logit.Logger, level logit.LoggerLevel, now time.Time, msg string) bool { @@ -56,4 +56,8 @@ func main() { logger.SetHandlers(handlers1, handlers2) fmt.Println("fmt =========================================") logger.Info("after setting handlers...") + + // If you want to log as Json string, try JsonLoggerHandler: + logger.SetHandlers(logit.JsonLoggerHandler) + logger.Info("I am a Json string!") } diff --git a/doc.go b/doc.go index dbe83ce..c6e5093 100644 --- a/doc.go +++ b/doc.go @@ -19,7 +19,7 @@ /* Package logit provides an easy way to use foundation for your logging operations. -1. The basic usage: +1. the basic usage: // Log messages with four levels. // Notice that the default level is info, so first line of debug message @@ -63,7 +63,7 @@ Package logit provides an easy way to use foundation for your logging operations // If you have a long log and it is made of many variables, try this: // The msg is the return value of msgGenerator. - logger.DebugFunction(func() string { + logger.DebugFunc(func() string { // Use time as the source of random number generator. r := rand.New(rand.NewSource(time.Now().Unix())) return "debug rand int: " + strconv.Itoa(r.Intn(100)) @@ -140,7 +140,7 @@ Package logit provides an easy way to use foundation for your logging operations // Create a logger holder. // Default handler is logit.DefaultLoggerHandler. logger := logit.NewLogger(os.Stdout, logit.InfoLevel) - logger.Info("before logging...") + logger.Info("before adding handlers...") // Customize your own handler. handlers1 := func(logger *logit.Logger, level logit.LoggerLevel, now time.Time, msg string) bool { @@ -166,8 +166,12 @@ Package logit provides an easy way to use foundation for your logging operations fmt.Println("fmt =========================================") logger.Info("after setting handlers...") + // If you want to log as Json string, try JsonLoggerHandler: + logger.SetHandlers(logit.JsonLoggerHandler) + logger.Info("I am a Json string!") + */ package logit // import "github.com/FishGoddess/logit" -// Version is the version string representation of the "logit" package. -const Version = "0.0.10" +// Version is the version string representation of logit. +const Version = "v0.0.11" diff --git a/logger_extension.go b/logger_extension.go index ef04e54..0756a5c 100644 --- a/logger_extension.go +++ b/logger_extension.go @@ -94,30 +94,30 @@ func NewDefaultSizeRollingLogger(directory string, level LoggerLevel) *Logger { return NewSizeRollingLogger(directory, 64*wrapper.MB, level) } -// DebugFunction will output msg as a debug message. +// DebugFunc will output msg as a debug message. // The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func (l *Logger) DebugFunction(msgGenerator func() string) { +func (l *Logger) DebugFunc(msgGenerator func() string) { l.Debug(msgGenerator()) } -// InfoFunction will output msg as an info message. +// InfoFunc will output msg as an info message. // The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func (l *Logger) InfoFunction(msgGenerator func() string) { +func (l *Logger) InfoFunc(msgGenerator func() string) { l.Info(msgGenerator()) } -// WarnFunction will output msg as a warn message. -// The msg is the return value of messageGenerator. +// WarnFunc will output msg as a warn message. +// The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func (l *Logger) WarnFunction(msgGenerator func() string) { +func (l *Logger) WarnFunc(msgGenerator func() string) { l.Warn(msgGenerator()) } -// ErrorFunction will output msg as an error message. -// The msg is the return value of messageGenerator. +// ErrorFunc will output msg as an error message. +// The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func (l *Logger) ErrorFunction(messageGenerator func() string) { - l.Error(messageGenerator()) +func (l *Logger) ErrorFunc(msgGenerator func() string) { + l.Error(msgGenerator()) } diff --git a/logger_extension_test.go b/logger_extension_test.go index 52a0d2b..dad04b1 100644 --- a/logger_extension_test.go +++ b/logger_extension_test.go @@ -98,16 +98,26 @@ func TestNewDefaultSizeRollingLogger(t *testing.T) { // 测试输出日志是从函数中生成的几个方法 func TestLoggerLogFunction(t *testing.T) { logger := NewStdoutLogger(DebugLevel) - logger.DebugFunction(func() string { + logger.DebugFunc(func() string { return "debug rand int: " + strconv.Itoa(rand.Intn(100)) }) - logger.InfoFunction(func() string { + logger.InfoFunc(func() string { return "info rand int: " + strconv.Itoa(rand.Intn(100)) }) - logger.WarnFunction(func() string { + logger.WarnFunc(func() string { return "warn rand int: " + strconv.Itoa(rand.Intn(100)) }) - logger.ErrorFunction(func() string { + logger.ErrorFunc(func() string { return "error rand int: " + strconv.Itoa(rand.Intn(100)) }) } + +// 测试 JsonLoggerHandler 是否正常 +func TestLoggerJsonLoggerHandler(t *testing.T) { + logger := NewStdoutLogger(DebugLevel) + logger.SetHandlers(JsonLoggerHandler) + logger.Debug("Debug message...") + logger.Info("Info message...") + logger.Warn("Warn message...") + logger.Error("Error message...") +} diff --git a/logger_handler.go b/logger_handler.go index 2b0431f..adb0dea 100644 --- a/logger_handler.go +++ b/logger_handler.go @@ -19,6 +19,7 @@ package logit import ( + "sync" "time" ) @@ -39,6 +40,44 @@ func (lh LoggerHandler) handle(logger *Logger, level LoggerLevel, now time.Time, // The log handled by this handler will be like "[Info] [2020-03-06 16:10:44] msg". // If you want to customize, just code your own handler, then replace it! func DefaultLoggerHandler(logger *Logger, level LoggerLevel, now time.Time, msg string) bool { - logger.Writer().Write([]byte("[" + PrefixOf(level) + "] [" + now.Format(logger.FormatOfTime()) + "] " + msg + "\n")) + //logger.Writer().Write([]byte("[" + PrefixOf(level) + "] [" + now.Format(logger.FormatOfTime()) + "] " + msg + "\n")) + logger.Writer().Write([]byte("[" + PrefixOf(level) + "] [" + formatTime(now, logger.FormatOfTime()) + "] " + msg + "\n")) return true } + +// JsonLoggerHandler is the handler which handles log as a Json string. +// The log handled by this handler will be like `{"level":"debug", "time":"2020-03-22 22:35:00", "msg":"log content..."}`. +func JsonLoggerHandler(logger *Logger, level LoggerLevel, now time.Time, msg string) bool { + //logger.Writer().Write([]byte(`{"level":"` + PrefixOf(level) + `", "time":"` + now.Format(logger.FormatOfTime()) + `", "msg":"` + msg + `"}` + "\n")) + logger.Writer().Write([]byte(`{"level":"` + PrefixOf(level) + `", "time":"` + formatTime(now, logger.FormatOfTime()) + `", "msg":"` + msg + `"}` + "\n")) + return true +} + +// ********************************************************** +// For experiment. +// This is a time cache mechanism and you know that this is an experiment. +// We don't know if this mechanism is worth yet. You should know that time format operation +// takes lots of time, but concurrent competition does it, too. So is it worth to replace time +// format operation with concurrent competition? Only time will tell us! +var nowInUnix = time.Unix(0, 0).Unix() +var nowFormatOfTime = "0" +var nowFormatted = "0" +var mutexForNow = &sync.Mutex{} + +// formatTime is for formatting time. +// Use a global formatted time to cache the current time +// for avoiding formatting too much times in the same second. +func formatTime(now time.Time, formatOfTime string) string { + mutexForNow.Lock() + defer mutexForNow.Unlock() + + // 使用 != 而不是 > 是为了防止时钟回拨时日志记录时间不正确的情况 + if nowInUnix != now.Unix() || nowFormatOfTime != formatOfTime { + nowInUnix = now.Unix() + nowFormatOfTime = formatOfTime + nowFormatted = now.Format(formatOfTime) + } + return nowFormatted +} + +// ********************************************************** diff --git a/logger_test.go b/logger_test.go index 3c9a8cb..3d653d1 100644 --- a/logger_test.go +++ b/logger_test.go @@ -152,7 +152,7 @@ func TestLoggerHandlers(t *testing.T) { // 显示每个日志处理器的地址 logger.Info("handlers 个数:" + strconv.Itoa(len(handlers))) - logger.InfoFunction(func() string { + logger.InfoFunc(func() string { builder := strings.Builder{} for _, handler := range handlers { builder.WriteString(fmt.Sprintf("%p ", &handler)) diff --git a/logit.go b/logit.go index 71f9d06..bf581c4 100644 --- a/logit.go +++ b/logit.go @@ -97,32 +97,32 @@ func Error(msg string) { defaultLogger.log(callDepthOfDefaultLogger, ErrorLevel, msg) } -// DebugFunction will output msg as a debug message. +// DebugFunc will output msg as a debug message. // The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func DebugFunction(msgGenerator func() string) { - defaultLogger.DebugFunction(msgGenerator) +func DebugFunc(msgGenerator func() string) { + defaultLogger.DebugFunc(msgGenerator) } -// InfoFunction will output msg as an info message. +// InfoFunc will output msg as an info message. // The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func InfoFunction(msgGenerator func() string) { - defaultLogger.InfoFunction(msgGenerator) +func InfoFunc(msgGenerator func() string) { + defaultLogger.InfoFunc(msgGenerator) } -// WarnFunction will output msg as a warn message. -// The msg is the return value of messageGenerator. +// WarnFunc will output msg as a warn message. +// The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func WarnFunction(msgGenerator func() string) { - defaultLogger.WarnFunction(msgGenerator) +func WarnFunc(msgGenerator func() string) { + defaultLogger.WarnFunc(msgGenerator) } -// ErrorFunction will output msg as an error message. -// The msg is the return value of messageGenerator. +// ErrorFunc will output msg as an error message. +// The msg is the return value of msgGenerator. // This is a better way to output a long log made of many variables. -func ErrorFunction(messageGenerator func() string) { - defaultLogger.ErrorFunction(messageGenerator) +func ErrorFunc(msgGenerator func() string) { + defaultLogger.ErrorFunc(msgGenerator) } // ChangeWriterTo changes current writer to newWriter.