From adf45b6125fe781c417a37970d2878dfde042513 Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Wed, 3 Aug 2022 17:55:50 +0800 Subject: [PATCH 1/8] add test cases for fields --- utils/log/loggers/test/benchmark_test.go | 24 +++++ utils/log/loggers/test/example_test.go | 19 ++++ utils/log/loggers/test/parallelism_test.go | 107 +++++++++++++++++++++ 3 files changed, 150 insertions(+) create mode 100644 utils/log/loggers/test/benchmark_test.go create mode 100644 utils/log/loggers/test/example_test.go create mode 100644 utils/log/loggers/test/parallelism_test.go diff --git a/utils/log/loggers/test/benchmark_test.go b/utils/log/loggers/test/benchmark_test.go new file mode 100644 index 00000000..fa3b5750 --- /dev/null +++ b/utils/log/loggers/test/benchmark_test.go @@ -0,0 +1,24 @@ +//go test -v -bench=. -run=none . +package loggers_test + +import ( + "context" + "fmt" + "testing" + + s "github.com/carousell/Orion/utils/log/loggers" +) + +func BenchmarkFromContext(b *testing.B) { + ctx := context.Background() + for i := 0; i < b.N; i++ { + s.FromContext(ctx) + } +} + +func BenchmarkFromAddToLogContext(b *testing.B) { + ctx := context.Background() + for i := 0; i < b.N; i++ { + s.AddToLogContext(ctx, fmt.Sprintf("key%d", i), "good value") + } +} diff --git a/utils/log/loggers/test/example_test.go b/utils/log/loggers/test/example_test.go new file mode 100644 index 00000000..82ea3999 --- /dev/null +++ b/utils/log/loggers/test/example_test.go @@ -0,0 +1,19 @@ +package loggers_test + +import ( + "context" + "fmt" + + s "github.com/carousell/Orion/utils/log/loggers" +) + +func ExampleFromContext() { + ctx := context.Background() + ctx = s.AddToLogContext(ctx, "indespensable", "amazing data") + ctx = s.AddToLogContext(ctx, "preciousData", "valuable key") + lf := s.FromContext(ctx) + fmt.Println(lf) + + // Output: + // map[indespensable:amazing data preciousData:valuable key] +} diff --git a/utils/log/loggers/test/parallelism_test.go b/utils/log/loggers/test/parallelism_test.go new file mode 100644 index 00000000..d89ebc3d --- /dev/null +++ b/utils/log/loggers/test/parallelism_test.go @@ -0,0 +1,107 @@ +//go test -race +package loggers_test + +import ( + "context" + "fmt" + "math/rand" + "sync" + "testing" + "time" + + s "github.com/carousell/Orion/utils/log/loggers" + "github.com/stretchr/testify/assert" +) + +const readWorkerCount = 5 +const writeWorkerCount = 5 + +func readWorker(idx int, ctx context.Context) { + lf := s.FromContext(ctx) + // simulate reading task + time.Sleep(time.Millisecond * 250) + fmt.Printf("Reader %d read from logfields %+v\n", idx, lf) +} + +func writeWorker(idx int, ctx context.Context) context.Context { + key := fmt.Sprintf("key%d", idx) + val := fmt.Sprintf("val%d", rand.Intn(10000)) + ctx = s.AddToLogContext(ctx, key, val) + time.Sleep(time.Millisecond * 250) + fmt.Printf("Writer %d wrote %s:%s\n", idx, key, val) + return ctx +} + +func TestParallelRead(t *testing.T) { + // LogContext init, non-paralel + ctx := context.Background() + ctx = s.AddToLogContext(ctx, "k1", "v1") + ctx = s.AddToLogContext(ctx, "k2", "v2") + + var wg sync.WaitGroup + for i := 1; i <= readWorkerCount; i++ { + wg.Add(1) + go func(j int) { + defer wg.Done() + readWorker(j, ctx) + }(i) + } + wg.Wait() +} + +func TestParallelWrite(t *testing.T) { + ctx := context.Background() + ctx = s.AddToLogContext(ctx, "test-key", "test-value") + + var wg sync.WaitGroup + for i := 1; i <= writeWorkerCount; i++ { + wg.Add(1) + go func(j int) { + defer wg.Done() + writeWorker(j, ctx) + }(i) + } + wg.Wait() + + lf := s.FromContext(ctx) + fmt.Println(lf) + + assert.Contains(t, lf, "test-key") + for i := 1; i <= writeWorkerCount; i++ { + key := fmt.Sprintf("key%d", i) + assert.Contains(t, lf, key) + } +} + +func TestParallelReadAndWrite(t *testing.T) { + ctx := context.Background() + ctx = s.AddToLogContext(ctx, "test-key", "test-value") + + var wgRead sync.WaitGroup + for i := 1; i <= readWorkerCount; i++ { + wgRead.Add(1) + go func(j int) { + defer wgRead.Done() + readWorker(j, ctx) + }(i) + } + var wgWrite sync.WaitGroup + for i := 1; i <= writeWorkerCount; i++ { + wgWrite.Add(1) + go func(j int) { + defer wgWrite.Done() + writeWorker(j, ctx) + }(i) + } + wgRead.Wait() + wgWrite.Wait() + + lf := s.FromContext(ctx) + fmt.Println(lf) + + assert.Contains(t, lf, "test-key") + for i := 1; i <= writeWorkerCount; i++ { + key := fmt.Sprintf("key%d", i) + assert.Contains(t, lf, key) + } +} From 9a44ef1c9c6bd8ff21276b4c86a41153f12344d3 Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Fri, 12 Aug 2022 18:03:04 +0800 Subject: [PATCH 2/8] add RWlock for logger --- utils/log/loggers/fields.go | 42 ++++++++++++++++++---- utils/log/loggers/test/benchmark_test.go | 3 ++ utils/log/loggers/test/parallelism_test.go | 6 ++-- 3 files changed, 41 insertions(+), 10 deletions(-) diff --git a/utils/log/loggers/fields.go b/utils/log/loggers/fields.go index 41105977..8855219a 100644 --- a/utils/log/loggers/fields.go +++ b/utils/log/loggers/fields.go @@ -2,6 +2,7 @@ package loggers import ( "context" + "sync" ) type logsContext string @@ -12,6 +13,10 @@ var ( //LogFields contains all fields that have to be added to logs type LogFields map[string]interface{} +type ProtectedLogFields struct { + Content LogFields + mtx sync.RWMutex +} // Add or modify log fields func (o LogFields) Add(key string, value interface{}) { @@ -28,14 +33,19 @@ func (o LogFields) Del(key string) { //AddToLogContext adds log fields to context. // Any info added here will be added to all logs using this context func AddToLogContext(ctx context.Context, key string, value interface{}) context.Context { - data := FromContext(ctx) + data := fromContext(ctx) + //Initialize if key doesn't exist if data == nil { - ctx = context.WithValue(ctx, contextKey, make(LogFields)) - data = FromContext(ctx) + ctx = context.WithValue(ctx, contextKey, &ProtectedLogFields{Content: make(LogFields)}) + data = fromContext(ctx) } m := ctx.Value(contextKey) - if data, ok := m.(LogFields); ok { - data.Add(key, value) + if data, ok := m.(*ProtectedLogFields); ok { + data.mtx.Lock() + defer data.mtx.Unlock() + // d := data.Content + // fmt.Printf("Address %p\n", d) + data.Content.Add(key, value) } return ctx } @@ -46,8 +56,26 @@ func FromContext(ctx context.Context) LogFields { return nil } if h := ctx.Value(contextKey); h != nil { - if logData, ok := h.(LogFields); ok { - return logData + if plf, ok := h.(*ProtectedLogFields); ok { + plf.mtx.RLock() + defer plf.mtx.RUnlock() + content := make(LogFields) + for k, v := range plf.Content { + content[k] = v + } + return content + } + } + return nil +} + +func fromContext(ctx context.Context) *ProtectedLogFields { + if ctx == nil { + return nil + } + if h := ctx.Value(contextKey); h != nil { + if plf, ok := h.(*ProtectedLogFields); ok { + return plf } } return nil diff --git a/utils/log/loggers/test/benchmark_test.go b/utils/log/loggers/test/benchmark_test.go index fa3b5750..935ce3dc 100644 --- a/utils/log/loggers/test/benchmark_test.go +++ b/utils/log/loggers/test/benchmark_test.go @@ -11,6 +11,9 @@ import ( func BenchmarkFromContext(b *testing.B) { ctx := context.Background() + for i := 0; i < 10000; i++ { + s.AddToLogContext(ctx, fmt.Sprintf("key%d", i), "good value") + } for i := 0; i < b.N; i++ { s.FromContext(ctx) } diff --git a/utils/log/loggers/test/parallelism_test.go b/utils/log/loggers/test/parallelism_test.go index d89ebc3d..2c586367 100644 --- a/utils/log/loggers/test/parallelism_test.go +++ b/utils/log/loggers/test/parallelism_test.go @@ -13,8 +13,8 @@ import ( "github.com/stretchr/testify/assert" ) -const readWorkerCount = 5 -const writeWorkerCount = 5 +const readWorkerCount = 50 +const writeWorkerCount = 50 func readWorker(idx int, ctx context.Context) { lf := s.FromContext(ctx) @@ -64,7 +64,7 @@ func TestParallelWrite(t *testing.T) { wg.Wait() lf := s.FromContext(ctx) - fmt.Println(lf) + fmt.Println("lf", lf) assert.Contains(t, lf, "test-key") for i := 1; i <= writeWorkerCount; i++ { From e1842a8823259d3575365aa9d6c702669efc4272 Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Tue, 30 Aug 2022 15:17:27 +0800 Subject: [PATCH 3/8] remove comments --- utils/log/loggers/fields.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/utils/log/loggers/fields.go b/utils/log/loggers/fields.go index 8855219a..a203815c 100644 --- a/utils/log/loggers/fields.go +++ b/utils/log/loggers/fields.go @@ -43,8 +43,6 @@ func AddToLogContext(ctx context.Context, key string, value interface{}) context if data, ok := m.(*ProtectedLogFields); ok { data.mtx.Lock() defer data.mtx.Unlock() - // d := data.Content - // fmt.Printf("Address %p\n", d) data.Content.Add(key, value) } return ctx From 686a325958861e65cdbeda8ff22d09c842e924fa Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Wed, 7 Sep 2022 16:58:18 +0800 Subject: [PATCH 4/8] remove print --- utils/log/loggers/test/parallelism_test.go | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/utils/log/loggers/test/parallelism_test.go b/utils/log/loggers/test/parallelism_test.go index 2c586367..c9d6150d 100644 --- a/utils/log/loggers/test/parallelism_test.go +++ b/utils/log/loggers/test/parallelism_test.go @@ -17,10 +17,9 @@ const readWorkerCount = 50 const writeWorkerCount = 50 func readWorker(idx int, ctx context.Context) { - lf := s.FromContext(ctx) + s.FromContext(ctx) // simulate reading task time.Sleep(time.Millisecond * 250) - fmt.Printf("Reader %d read from logfields %+v\n", idx, lf) } func writeWorker(idx int, ctx context.Context) context.Context { @@ -28,7 +27,6 @@ func writeWorker(idx int, ctx context.Context) context.Context { val := fmt.Sprintf("val%d", rand.Intn(10000)) ctx = s.AddToLogContext(ctx, key, val) time.Sleep(time.Millisecond * 250) - fmt.Printf("Writer %d wrote %s:%s\n", idx, key, val) return ctx } @@ -64,7 +62,6 @@ func TestParallelWrite(t *testing.T) { wg.Wait() lf := s.FromContext(ctx) - fmt.Println("lf", lf) assert.Contains(t, lf, "test-key") for i := 1; i <= writeWorkerCount; i++ { @@ -97,7 +94,6 @@ func TestParallelReadAndWrite(t *testing.T) { wgWrite.Wait() lf := s.FromContext(ctx) - fmt.Println(lf) assert.Contains(t, lf, "test-key") for i := 1; i <= writeWorkerCount; i++ { From 5d8f8ab4d13f7ef4acc659c1057961782013c226 Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Thu, 15 Sep 2022 11:11:04 +0800 Subject: [PATCH 5/8] use single wait group instead of two --- utils/log/loggers/test/parallelism_test.go | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/utils/log/loggers/test/parallelism_test.go b/utils/log/loggers/test/parallelism_test.go index c9d6150d..4f5a8a20 100644 --- a/utils/log/loggers/test/parallelism_test.go +++ b/utils/log/loggers/test/parallelism_test.go @@ -74,24 +74,22 @@ func TestParallelReadAndWrite(t *testing.T) { ctx := context.Background() ctx = s.AddToLogContext(ctx, "test-key", "test-value") - var wgRead sync.WaitGroup + var wg sync.WaitGroup for i := 1; i <= readWorkerCount; i++ { - wgRead.Add(1) + wg.Add(1) go func(j int) { - defer wgRead.Done() + defer wg.Done() readWorker(j, ctx) }(i) } - var wgWrite sync.WaitGroup for i := 1; i <= writeWorkerCount; i++ { - wgWrite.Add(1) + wg.Add(1) go func(j int) { - defer wgWrite.Done() + defer wg.Done() writeWorker(j, ctx) }(i) } - wgRead.Wait() - wgWrite.Wait() + wg.Wait() lf := s.FromContext(ctx) From 30f6411d93f2207ed45bb1d5eaecb85719844b2d Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Tue, 11 Oct 2022 13:39:24 +0800 Subject: [PATCH 6/8] unexpose protectedLogFields, content --- utils/log/loggers/fields.go | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/utils/log/loggers/fields.go b/utils/log/loggers/fields.go index a203815c..c8bf4edb 100644 --- a/utils/log/loggers/fields.go +++ b/utils/log/loggers/fields.go @@ -13,8 +13,8 @@ var ( //LogFields contains all fields that have to be added to logs type LogFields map[string]interface{} -type ProtectedLogFields struct { - Content LogFields +type protectedLogFields struct { + content LogFields mtx sync.RWMutex } @@ -36,14 +36,14 @@ func AddToLogContext(ctx context.Context, key string, value interface{}) context data := fromContext(ctx) //Initialize if key doesn't exist if data == nil { - ctx = context.WithValue(ctx, contextKey, &ProtectedLogFields{Content: make(LogFields)}) + ctx = context.WithValue(ctx, contextKey, &protectedLogFields{content: make(LogFields)}) data = fromContext(ctx) } m := ctx.Value(contextKey) - if data, ok := m.(*ProtectedLogFields); ok { + if data, ok := m.(*protectedLogFields); ok { data.mtx.Lock() defer data.mtx.Unlock() - data.Content.Add(key, value) + data.content.Add(key, value) } return ctx } @@ -54,11 +54,11 @@ func FromContext(ctx context.Context) LogFields { return nil } if h := ctx.Value(contextKey); h != nil { - if plf, ok := h.(*ProtectedLogFields); ok { + if plf, ok := h.(*protectedLogFields); ok { plf.mtx.RLock() defer plf.mtx.RUnlock() content := make(LogFields) - for k, v := range plf.Content { + for k, v := range plf.content { content[k] = v } return content @@ -67,12 +67,12 @@ func FromContext(ctx context.Context) LogFields { return nil } -func fromContext(ctx context.Context) *ProtectedLogFields { +func fromContext(ctx context.Context) *protectedLogFields { if ctx == nil { return nil } if h := ctx.Value(contextKey); h != nil { - if plf, ok := h.(*ProtectedLogFields); ok { + if plf, ok := h.(*protectedLogFields); ok { return plf } } From 0757306403f3b7f32d8b9787d4a0b9f3faa073fd Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Tue, 11 Oct 2022 13:50:24 +0800 Subject: [PATCH 7/8] reuse code from fromContext --- utils/log/loggers/fields.go | 19 +++++++------------ 1 file changed, 7 insertions(+), 12 deletions(-) diff --git a/utils/log/loggers/fields.go b/utils/log/loggers/fields.go index c8bf4edb..ed347426 100644 --- a/utils/log/loggers/fields.go +++ b/utils/log/loggers/fields.go @@ -50,19 +50,14 @@ func AddToLogContext(ctx context.Context, key string, value interface{}) context //FromContext fetchs log fields from provided context func FromContext(ctx context.Context) LogFields { - if ctx == nil { - return nil - } - if h := ctx.Value(contextKey); h != nil { - if plf, ok := h.(*protectedLogFields); ok { - plf.mtx.RLock() - defer plf.mtx.RUnlock() - content := make(LogFields) - for k, v := range plf.content { - content[k] = v - } - return content + if plf := fromContext(ctx); plf != nil { + plf.mtx.RLock() + defer plf.mtx.RUnlock() + content := make(LogFields) + for k, v := range plf.content { + content[k] = v } + return content } return nil } From b9a446ccff7ab57fc0210593d576d2d5718a4e04 Mon Sep 17 00:00:00 2001 From: Leonard Wen Date: Tue, 11 Oct 2022 14:22:39 +0800 Subject: [PATCH 8/8] remove code redundancy plf is already a pointer thus no need to refetch from ctx and cast again --- utils/log/loggers/fields.go | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/utils/log/loggers/fields.go b/utils/log/loggers/fields.go index ed347426..25d214dd 100644 --- a/utils/log/loggers/fields.go +++ b/utils/log/loggers/fields.go @@ -36,15 +36,12 @@ func AddToLogContext(ctx context.Context, key string, value interface{}) context data := fromContext(ctx) //Initialize if key doesn't exist if data == nil { - ctx = context.WithValue(ctx, contextKey, &protectedLogFields{content: make(LogFields)}) - data = fromContext(ctx) - } - m := ctx.Value(contextKey) - if data, ok := m.(*protectedLogFields); ok { - data.mtx.Lock() - defer data.mtx.Unlock() - data.content.Add(key, value) + data = &protectedLogFields{content: make(LogFields)} + ctx = context.WithValue(ctx, contextKey, data) } + data.mtx.Lock() + defer data.mtx.Unlock() + data.content.Add(key, value) return ctx }