✨ Add customTags in logger middleware Config #2188

Skyenought · 2022-11-01T12:58:58Z

Description

Please include a summary of the change and which issue is fixed. Please also include relevant motivation and context. List any dependencies that are required for this change.
Explain the details for making this change. What existing problem does the pull request solve?

Fixes #2187

Type of change

Please delete options that are not relevant.

Bug fix (non-breaking change which fixes an issue)
New feature (non-breaking change which adds functionality)
Breaking change (fix or feature that would cause existing functionality to not work as expected)
This change requires a documentation update

Checklist:

For new functionalities I follow the inspiration of the express js framework and built them similar in usage
I have performed a self-review of my own code
I have commented my code, particularly in hard-to-understand areas
I have made corresponding changes to the documentation - https://github.com/gofiber/docs for https://docs.gofiber.io/
I have added tests that prove my fix is effective or that my feature works
New and existing unit tests pass locally with my changes
If new dependencies exist, I have checked that they are really necessary and agreed with the maintainers/community (we want to have as few dependencies as possible)
I tried to make my code as fast as possible with as few allocations as possible
For new code I have written benchmarks so that they can be analyzed and improved

Commit formatting:

Use emojis on commit messages so it provides an easy way of identifying the purpose or intention of a commit. Check out the emoji cheatsheet here: https://gitmoji.carloscuesta.me/

efectn · 2022-11-01T13:34:34Z

Can you send here old and new benchmark comparision

Skyenought · 2022-11-01T13:49:16Z

Can you send here old and new benchmark comparision

Seems to have slowed down :-(

old

goos: linux
goarch: amd64                                     
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       5582337               219.6 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5000182               237.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5331586               215.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5741889               209.6 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   5.683s

PASS

new

goos: linux  
goarch: amd64
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       1649736               706.7 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1761847               732.1 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1704952               673.5 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1722056               674.2 ns/op           320 B/op          7 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   7.636s

PASS

ReneWerner87 · 2022-11-01T14:14:58Z

Ok then just try to improve a little bit

Skyenought · 2022-11-01T14:58:28Z

Ok then just try to improve a little bit

I will try, even though it is a bit difficult for me

Skyenought · 2022-11-02T05:29:45Z

Ok then just try to improve a little bit

It's hard to optimize this code at my level, so it looks like I'll have to close this PR :-<

ReneWerner87 · 2022-11-02T06:39:13Z

We can try to support you

Skyenought · 2022-11-02T06:40:49Z

We can try to support you

Really? Thx !

middleware/logger/logger.go

Skyenought · 2022-11-02T09:12:22Z

Can you send here old and new benchmark comparision

Seems to have slowed down :-(

old

goos: linux
goarch: amd64                                     
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       5582337               219.6 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5000182               237.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5331586               215.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5741889               209.6 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   5.683s

PASS

new

goos: linux  
goarch: amd64
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       1649736               706.7 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1761847               732.1 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1704952               673.5 ns/op           320 B/op          7 allocs/op
Benchmark_Logger-2       1722056               674.2 ns/op           320 B/op          7 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   7.636s

PASS

better than before:

goos: linux  
goarch: amd64
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       2779996               439.7 ns/op            80 B/op          2 allocs/op
Benchmark_Logger-2       2711770               433.0 ns/op            80 B/op          2 allocs/op
Benchmark_Logger-2       2692728               437.2 ns/op            80 B/op          2 allocs/op
Benchmark_Logger-2       2676159               452.4 ns/op            80 B/op          2 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   6.884s

Skyenought · 2022-11-04T02:55:57Z

use switch

goos: linux
goarch: amd64                                     
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       5582337               219.6 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5000182               237.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5331586               215.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       5741889               209.6 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   5.683s

PASS

use map

goos: linux                                       
goarch: amd64                                     
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz    
Benchmark_Logger
Benchmark_Logger-2       4919536               244.3 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4852894               256.5 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4817518               243.4 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4551956               249.3 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   5.968s

Skyenought · 2022-11-10T03:43:24Z

I don't think it's a problem with my code that the check didn't pass, right?

ReneWerner87 · 2022-11-10T05:19:10Z

No, will look at the pull request in the next few days
Currently there is a lot to do

Skyenought · 2022-11-10T05:30:14Z

No, will look at the pull request in the next few days Currently there is a lot to do

I'm sorry to bother you, but I'm just confused about the PR not passing.

ReneWerner87 · 2022-11-10T07:03:17Z

its because of the vulnerability check
can you please refresh your branch with the current master

li-jin-gou · 2022-11-10T07:49:42Z

No, will look at the pull request in the next few days Currently there is a lot to do

I'm sorry to bother you, but I'm just confused about the PR not passing.

This issue has been fixed and you need to update the code & this change requires a documentation update

middleware/logger/logger.go

ReneWerner87 · 2022-11-15T11:27:56Z

@Skyenought can you check my last comment and refresh the branch
will wait with the release for this feature

Skyenought · 2022-11-15T16:03:29Z

Now logger support custom tags like "reqHeader:x-key"

goos: linux                                       
goarch: amd64                                     
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       4537462               266.2 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4529635               278.0 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4531717               267.3 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       4247362               276.5 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   5.962s

middleware/logger/config.go

middleware/logger/logger.go

ReneWerner87 · 2022-11-17T13:09:01Z

no i mean to the benchmark you shared at the beginning with the map and the switch

in the last one where you compared switch and map there was a gap of 100ns
#2188 (comment)

in the first one there was only a gap of 20ns
#2188 (comment)

ReneWerner87 · 2022-11-17T13:10:40Z

first bench

last bench

Skyenought · 2022-11-17T13:14:40Z

no i mean to the benchmark you shared at the beginning with the map and the switch

in the last one where you compared switch and map there was a gap of 100ns #2188 (comment)

in the first one there was only a gap of 20ns #2188 (comment)

The latest comparison is between the map logic of my code and your map logic:

if index := strings.Index(tag, ":"); index != -1 {
	if logFunc, ok := tagFunctionMap[tag[0:index+1]]; ok {
		return logFunc(buf, c, w, tag)
	}
}
			
if index := strings.Index(tag, ":"); index != -1 {
	result := subStr(tag, 0, index+1)
	logFunc := tagFunctionMap[result]
	return logFunc(buf, c, w, tag)
}

ReneWerner87 · 2022-11-17T13:17:15Z

yes i know, i also mean the other comments with the benchmarks

Skyenought · 2022-11-17T13:21:55Z

I find that whenever I use map to match tags, either your changes to the map logic or my changes, it becomes less performant than switch matching

ReneWerner87 · 2022-11-17T15:49:41Z

will push an optimized version later

Skyenought · 2022-11-17T15:51:31Z

Thank you for the code review

ReneWerner87 · 2022-11-17T16:29:14Z

05dabe7
not 100% done but i pushed it
maybe you can check it on your machine -> need more manual testing

Skyenought · 2022-11-17T16:33:31Z

05dabe7 not 100% done but i pushed it maybe you can check it on your machine -> need more manual testing

ok

ReneWerner87 · 2022-11-17T16:52:13Z

Is it now better/faster on your machine?

Skyenought · 2022-11-17T16:55:20Z

yes, at now faster than before:

goos: linux  
goarch: amd64
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       3469314               362.5 ns/op            16 B/op          1 allocs/op
Benchmark_Logger-2       3439934               351.2 ns/op            16 B/op          1 allocs/op
Benchmark_Logger-2       3618189               333.2 ns/op            16 B/op          1 allocs/op
Benchmark_Logger-2       3367159               344.4 ns/op            16 B/op          1 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   6.262s

before

goos: linux
goarch: amd64
pkg: github.com/gofiber/fiber/v2/middleware/logger
cpu: Intel(R) Core(TM) i5-1035G1 CPU @ 1.00GHz
Benchmark_Logger
Benchmark_Logger-2       3122877               386.0 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       3019996               385.9 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       3146631               382.3 ns/op             0 B/op          0 allocs/op
Benchmark_Logger-2       3159733               388.7 ns/op             0 B/op          0 allocs/op
PASS
ok      github.com/gofiber/fiber/v2/middleware/logger   6.380s

ReneWerner87 · 2022-11-17T17:12:02Z

But not faster than the master with the benchmark adjustment? Maybe it's because of the stuff we add to the context.

Skyenought · 2022-11-17T17:15:54Z

if not add something in context, we couldn`t get some message.

It's 1:13 am in my time zone, so I'm off to bed. I wish you all the best

ReneWerner87 · 2022-11-17T21:52:55Z

benchmark with format "${bytesReceived} ${bytesSent} ${status} ${reqHeader:test}" and local in handler:
master:

Benchmark_Logger-12    	 4105185	       293.7 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4130638	       290.5 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4085211	       288.9 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4149218	       292.5 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4114450	       290.6 ns/op	       0 B/op	       0 allocs/op

feature branch:

Benchmark_Logger-12    	 4541797	       262.4 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4541694	       261.9 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4574413	       261.2 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4519794	       261.1 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4617871	       260.0 ns/op	       0 B/op	       0 allocs/op

benchmark with default format "[${time}] ${status} - ${latency} ${method} ${path}\n" and local in handler:
master:

Benchmark_Logger-12    	 1840008	       628.7 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1882804	       636.4 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1841458	       684.7 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1883836	       662.0 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1851812	       643.3 ns/op	       8 B/op	       1 allocs/op

feature branch:

Benchmark_Logger-12    	 1690204	       808.4 ns/op	      56 B/op	       3 allocs/op
Benchmark_Logger-12    	 1479172	       758.2 ns/op	      56 B/op	       3 allocs/op
Benchmark_Logger-12    	 1578549	       771.2 ns/op	      56 B/op	       3 allocs/op
Benchmark_Logger-12    	 1557202	       763.5 ns/op	      56 B/op	       3 allocs/op
Benchmark_Logger-12    	 1551295	       828.1 ns/op	      56 B/op	       3 allocs/op

for these allocations i created a task in the code
https://github.com/Skyenought/fiber/blob/04eb75ab93784b0cf12b8e569b9496f4adac0f70/middleware/logger/logger.go#L159

reason for the allocations are the storing of the user values
https://github.com/Skyenought/fiber/blob/feat/switch2map/middleware/logger/logger.go#L168

we should try something like this (v3)

fiber/middleware/logger/logger.go

Lines 104 to 108 in debdb8c

    
           data := &LoggerData{ 
        
           	Pid:           pid, 
        
           	ErrPaddingStr: errPaddingStr, 
        
           	Timestamp:     timestamp, 
        
           }

fiber/middleware/logger/logger.go

Lines 157 to 159 in debdb8c

    
           data.ChainErr = chainErr 
        
           data.Start = start 
        
           data.Stop = stop

but with a sync pool

middleware/logger/templateChain.go

ReneWerner87 · 2022-11-18T09:57:22Z

After the usage of syncPool and data structs

benchmark with format "${bytesReceived} ${bytesSent} ${status} ${reqHeader:test}" and local in handler:
master:

Benchmark_Logger-12    	 4105185	       293.7 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4130638	       290.5 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4085211	       288.9 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4149218	       292.5 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4114450	       290.6 ns/op	       0 B/op	       0 allocs/op

feature branch:

Benchmark_Logger-12    	 4293021	       290.3 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4115019	       287.7 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4231435	       287.5 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4059115	       284.3 ns/op	       0 B/op	       0 allocs/op
Benchmark_Logger-12    	 4272568	       281.6 ns/op	       0 B/op	       0 allocs/op

benchmark with default format "[${time}] ${status} - ${latency} ${method} ${path}\n" and local in handler:
master:

Benchmark_Logger-12    	 1840008	       628.7 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1882804	       636.4 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1841458	       684.7 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1883836	       662.0 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1851812	       643.3 ns/op	       8 B/op	       1 allocs/op

feature branch:

Benchmark_Logger-12    	 1907866	       663.8 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1835814	       641.3 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1710475	       633.3 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1789392	       652.6 ns/op	       8 B/op	       1 allocs/op
Benchmark_Logger-12    	 1888110	       645.6 ns/op	       8 B/op	       1 allocs/op

ReneWerner87 · 2022-11-18T10:11:46Z

@Skyenought @li-jin-gou @hunterzhang86 iam done now -> performance is the same like before but with the feature
can you recheck the code

ReneWerner87 · 2022-11-18T10:12:36Z

if that is gemerged I will start the release

li-jin-gou · 2022-11-18T10:42:47Z

@Skyenought @li-jin-gou @hunterzhang86 iam done now -> performance is the same like before but with the feature can you recheck the code

very cool👍🏻

Skyenought · 2022-11-18T11:56:47Z

Almost the same performance now 👍🏻

efectn added the ✏️ Feature label Nov 1, 2022

li-jin-gou reviewed Nov 2, 2022

View reviewed changes

middleware/logger/logger.go Outdated Show resolved Hide resolved

Skyenought force-pushed the feat/switch2map branch from d9cf204 to 2449071 Compare November 2, 2022 09:08

Skyenought force-pushed the feat/switch2map branch 2 times, most recently from 78e1d4c to addc718 Compare November 4, 2022 02:53

Skyenought force-pushed the feat/switch2map branch from addc718 to 34d2a39 Compare November 10, 2022 07:06

Skyenought mentioned this pull request Nov 10, 2022

Update logger.md to add custom tags feature gofiber/docs#295

Closed

Skyenought force-pushed the feat/switch2map branch from 34d2a39 to 4b0e067 Compare November 15, 2022 06:42

ReneWerner87 reviewed Nov 15, 2022

View reviewed changes

middleware/logger/logger.go Show resolved Hide resolved

Skyenought force-pushed the feat/switch2map branch 2 times, most recently from 4e4fa61 to 02ac453 Compare November 15, 2022 15:53

ReneWerner87 reviewed Nov 16, 2022

View reviewed changes

middleware/logger/config.go Outdated Show resolved Hide resolved

ReneWerner87 reviewed Nov 16, 2022

View reviewed changes

middleware/logger/logger.go Outdated Show resolved Hide resolved

ReneWerner87 reviewed Nov 16, 2022

View reviewed changes

middleware/logger/logger.go Outdated Show resolved Hide resolved

ReneWerner87 self-assigned this Nov 17, 2022

improve logger performance

05dabe7

improve logger performance

04eb75a

hunterzhang86 reviewed Nov 18, 2022

View reviewed changes

middleware/logger/templateChain.go Outdated Show resolved Hide resolved

improve logger performance

866e05d

ReneWerner87 approved these changes Nov 18, 2022

View reviewed changes

efectn approved these changes Nov 18, 2022

View reviewed changes

li-jin-gou approved these changes Nov 18, 2022

View reviewed changes

improve logger performance

516ef47

ReneWerner87 merged commit e8f8cb6 into gofiber:master Nov 18, 2022

li-jin-gou mentioned this pull request Nov 22, 2022

feat: add ShutdownWithTimeout function #2228

Merged

✨ Add customTags in logger middleware Config #2188

✨ Add customTags in logger middleware Config #2188

Conversation

Skyenought commented Nov 1, 2022 • edited Loading

Description

Type of change

Checklist:

Commit formatting:

efectn commented Nov 1, 2022

Skyenought commented Nov 1, 2022

ReneWerner87 commented Nov 1, 2022

Skyenought commented Nov 1, 2022

Skyenought commented Nov 2, 2022

ReneWerner87 commented Nov 2, 2022

Skyenought commented Nov 2, 2022

Skyenought commented Nov 2, 2022 • edited Loading

Skyenought commented Nov 4, 2022

Skyenought commented Nov 10, 2022

ReneWerner87 commented Nov 10, 2022

Skyenought commented Nov 10, 2022

ReneWerner87 commented Nov 10, 2022

li-jin-gou commented Nov 10, 2022

ReneWerner87 commented Nov 15, 2022

Skyenought commented Nov 15, 2022

ReneWerner87 commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022 • edited Loading

ReneWerner87 commented Nov 17, 2022

Skyenought commented Nov 17, 2022

ReneWerner87 commented Nov 17, 2022

ReneWerner87 commented Nov 18, 2022

ReneWerner87 commented Nov 18, 2022

ReneWerner87 commented Nov 18, 2022

li-jin-gou commented Nov 18, 2022

Skyenought commented Nov 18, 2022

Skyenought commented Nov 1, 2022 •

edited

Loading

Skyenought commented Nov 2, 2022 •

edited

Loading

Skyenought commented Nov 17, 2022 •

edited

Loading