diff --git a/management/server/grpcserver.go b/management/server/grpcserver.go index 677e8559a..4bfecdd21 100644 --- a/management/server/grpcserver.go +++ b/management/server/grpcserver.go @@ -168,9 +168,11 @@ func (s *GRPCServer) Sync(req *proto.EncryptedMessage, srv proto.ManagementServi defer func() { if s.appMetrics != nil { s.appMetrics.GRPCMetrics().CountSyncRequestDuration(time.Since(reqStart)) + log.WithContext(ctx).Infof("Sync request from peer %s took %v", peerKey.String(), time.Since(reqStart)) } }() + syncbody := time.Now() // nolint:staticcheck ctx = context.WithValue(ctx, nbContext.PeerIDKey, peerKey.String()) @@ -224,6 +226,8 @@ func (s *GRPCServer) Sync(req *proto.EncryptedMessage, srv proto.ManagementServi log.WithContext(ctx).Debugf("Sync: took %v", time.Since(reqStart)) + log.WithContext(ctx).Info("Sync body after the filter for peer %s took %v", peerKey.String(), time.Since(syncbody)) + return s.handleUpdates(ctx, accountID, peerKey, peer, updates, srv) } @@ -483,10 +487,13 @@ func (s *GRPCServer) Login(ctx context.Context, req *proto.EncryptedMessage) (*p if s.appMetrics != nil { s.appMetrics.GRPCMetrics().CountLoginRequestDuration(time.Since(reqStart)) } + log.WithContext(ctx).Infof("Login request from peer %s took %v", peerKey.String(), time.Since(reqStart)) }() if s.appMetrics != nil { s.appMetrics.GRPCMetrics().CountLoginRequest() } + + bodytime := time.Now() //nolint ctx = context.WithValue(ctx, nbContext.PeerIDKey, peerKey.String()) accountID, err := s.accountManager.GetAccountIDForPeerKey(ctx, peerKey.String()) @@ -544,6 +551,7 @@ func (s *GRPCServer) Login(ctx context.Context, req *proto.EncryptedMessage) (*p log.WithContext(ctx).Warnf("failed encrypting peer %s message", peer.ID) return nil, status.Errorf(codes.Internal, "failed logging in peer") } + log.WithContext(ctx).Info("Login body after the filter for peer %s took %v", peerKey.String(), time.Since(bodytime)) return &proto.EncryptedMessage{ WgPubKey: s.wgKey.PublicKey().String(), diff --git a/management/server/loginfilter.go b/management/server/loginfilter.go index 43ded14d6..b1c9bf0b3 100644 --- a/management/server/loginfilter.go +++ b/management/server/loginfilter.go @@ -66,6 +66,7 @@ func newLoginFilterWithCfg(cfg *config) *loginFilter { func (l *loginFilter) allowLogin(wgPubKey string, metaHash uint64) bool { now := time.Now() l.mu.RLock() + // defer l.mu.RUnlock() defer func() { l.mu.RUnlock() log.Infof("allowLogin duration for %s: %v", wgPubKey, time.Since(now)) @@ -88,6 +89,7 @@ func (l *loginFilter) allowLogin(wgPubKey string, metaHash uint64) bool { func (l *loginFilter) addLogin(wgPubKey string, metaHash uint64) { now := time.Now() l.mu.Lock() + // defer l.mu.Unlock() defer func() { l.mu.Unlock() log.Infof("addLogin duration for %s: %v", wgPubKey, time.Since(now)) diff --git a/management/server/loginfilter_test.go b/management/server/loginfilter_test.go index 3137dac87..882d1a6bd 100644 --- a/management/server/loginfilter_test.go +++ b/management/server/loginfilter_test.go @@ -3,6 +3,7 @@ package server import ( "hash/fnv" "math" + "math/rand" "strconv" "strings" "testing" @@ -249,3 +250,26 @@ func getMacAddress(nas []nbpeer.NetworkAddress) string { } return strings.Join(macs, "/") } + +func BenchmarkLoginFilter_ParallelLoad(b *testing.B) { + filter := newLoginFilterWithCfg(testAdvancedCfg()) + numKeys := 100000 + pubKeys := make([]string, numKeys) + for i := range numKeys { + pubKeys[i] = "PUB_KEY_" + strconv.Itoa(i) + } + + b.ResetTimer() + b.RunParallel(func(pb *testing.PB) { + r := rand.New(rand.NewSource(time.Now().UnixNano())) + + for pb.Next() { + key := pubKeys[r.Intn(numKeys)] + meta := r.Uint64() + + if filter.allowLogin(key, meta) { + filter.addLogin(key, meta) + } + } + }) +}