Skip to content

Commit f348184

Browse files
YangruiEmmaYangruiEmma
committed
debug: add log for debug discovery
1 parent 1f307f2 commit f348184

7 files changed

Lines changed: 41 additions & 16 deletions

File tree

‎client/middlewares.go‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -95,6 +95,7 @@ func newResolveMWBuilder(lbf *lbcache.BalancerFactory) endpoint.MiddlewareBuilde
9595
if remote.GetInstance() != nil {
9696
return next(ctx, request, response)
9797
}
98+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start get balancer")
9899
lb, err := lbf.Get(ctx, dest)
99100
if err != nil {
100101
return kerrors.ErrServiceDiscovery.WithCause(err)
@@ -108,10 +109,13 @@ func newResolveMWBuilder(lbf *lbcache.BalancerFactory) endpoint.MiddlewareBuilde
108109
default:
109110
}
110111

112+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start get picker")
111113
// we always need to get a new picker every time, because when downstream update deployment,
112114
// we may get an old picker that include all outdated instances which will cause connect always failed.
113-
picker := lb.GetPicker()
115+
picker := lb.GetPicker(ctx)
116+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start get instance")
114117
ins := picker.Next(ctx, request)
118+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end get instance")
115119
if ins == nil {
116120
err = kerrors.ErrNoMoreInstance.WithCause(fmt.Errorf("last error: %w", lastErr))
117121
} else {

‎pkg/loadbalance/consist.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -312,7 +312,7 @@ func (cb *consistBalancer) AddToDaemon() {
312312
}
313313

314314
// GetPicker implements the Loadbalancer interface.
315-
func (cb *consistBalancer) GetPicker(e discovery.Result) Picker {
315+
func (cb *consistBalancer) GetPicker(ctx context.Context, e discovery.Result) Picker {
316316
var ci *consistInfo
317317
if e.Cacheable {
318318
cii, ok := cb.cachedConsistInfo.Load(e.CacheKey)

‎pkg/loadbalance/lbcache/cache.go‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -163,7 +163,9 @@ func (b *BalancerFactory) Get(ctx context.Context, target rpcinfo.EndpointInfo)
163163
return val.(*Balancer), nil
164164
}
165165
val, err, _ := b.sfg.Do(desc, func() (interface{}, error) {
166+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start Resolve, desc=%s", desc)
166167
res, err := b.resolver.Resolve(ctx, desc)
168+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end Resolve, desc=%s", desc)
167169
if err != nil {
168170
return nil, err
169171
}
@@ -173,8 +175,11 @@ func (b *BalancerFactory) Get(ctx context.Context, target rpcinfo.EndpointInfo)
173175
target: desc,
174176
}
175177
bl.res.Store(res)
178+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start getSharedTicker")
176179
bl.sharedTicker = getSharedTicker(bl, b.opts.RefreshInterval)
180+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end getSharedTicker")
177181
b.cache.Store(desc, bl)
182+
klog.CtxErrorf(ctx, "KITEX-DEBUG: put balancer[desc=%s] into cache", desc)
178183
return bl, nil
179184
})
180185
if err != nil {
@@ -224,10 +229,10 @@ func (bl *Balancer) GetResult() (res discovery.Result, ok bool) {
224229
}
225230

226231
// GetPicker equal to loadbalance.Balancer without pass discovery.Result, because we cache the result
227-
func (bl *Balancer) GetPicker() loadbalance.Picker {
232+
func (bl *Balancer) GetPicker(ctx context.Context) loadbalance.Picker {
228233
atomic.StoreInt32(&bl.expire, 0)
229234
res := bl.res.Load().(discovery.Result)
230-
return bl.b.balancer.GetPicker(res)
235+
return bl.b.balancer.GetPicker(ctx, res)
231236
}
232237

233238
func (bl *Balancer) close() {

‎pkg/loadbalance/loadbalancer.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ type Picker interface {
2929

3030
// Loadbalancer generates pickers for the given service discovery result.
3131
type Loadbalancer interface {
32-
GetPicker(discovery.Result) Picker
32+
GetPicker(context.Context, discovery.Result) Picker
3333
Name() string // unique key
3434
}
3535

‎pkg/loadbalance/weighted_balancer.go‎

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
package loadbalance
1818

1919
import (
20+
"context"
2021
"sync"
2122

2223
"golang.org/x/sync/singleflight"
@@ -54,28 +55,31 @@ func NewWeightedRandomBalancer() Loadbalancer {
5455
}
5556

5657
// GetPicker implements the Loadbalancer interface.
57-
func (wb *weightedBalancer) GetPicker(e discovery.Result) Picker {
58+
func (wb *weightedBalancer) GetPicker(ctx context.Context, e discovery.Result) Picker {
5859
if !e.Cacheable {
59-
picker := wb.createPicker(e)
60+
picker := wb.createPicker(ctx, e)
6061
return picker
6162
}
6263

6364
picker, ok := wb.pickerCache.Load(e.CacheKey)
6465
if !ok {
6566
picker, _, _ = wb.sfg.Do(e.CacheKey, func() (interface{}, error) {
66-
p := wb.createPicker(e)
67+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start createPicker, CacheKey=%s, instanceSize=%d", e.CacheKey, len(e.Instances))
68+
p := wb.createPicker(ctx, e)
69+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end createPicker, CacheKey=%s", e.CacheKey)
6770
wb.pickerCache.Store(e.CacheKey, p)
6871
return p, nil
6972
})
7073
}
7174
return picker.(Picker)
7275
}
7376

74-
func (wb *weightedBalancer) createPicker(e discovery.Result) (picker Picker) {
77+
func (wb *weightedBalancer) createPicker(ctx context.Context, e discovery.Result) (picker Picker) {
7578
instances := make([]discovery.Instance, len(e.Instances)) // removed zero weight instances
7679
weightSum := 0
7780
balance := true
7881
cnt := 0
82+
klog.CtxErrorf(ctx, "KITEX-DEBUG: createPicker, begin iterator")
7983
for idx, instance := range e.Instances {
8084
weight := instance.Weight()
8185
if weight <= 0 {
@@ -89,6 +93,7 @@ func (wb *weightedBalancer) createPicker(e discovery.Result) (picker Picker) {
8993
}
9094
cnt++
9195
}
96+
klog.CtxErrorf(ctx, "KITEX-DEBUG: createPicker, end iterator, size=%d", len(instances))
9297
instances = instances[:cnt]
9398
if len(instances) == 0 {
9499
return new(DummyPicker)
@@ -99,7 +104,9 @@ func (wb *weightedBalancer) createPicker(e discovery.Result) (picker Picker) {
99104
if balance {
100105
picker = newRoundRobinPicker(instances)
101106
} else {
102-
picker = newWeightedRoundRobinPicker(instances)
107+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start newWeightedRoundRobinPicker")
108+
picker = newWeightedRoundRobinPicker(ctx, instances)
109+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end newWeightedRoundRobinPicker")
103110
}
104111
default: // random
105112
if balance {
@@ -116,7 +123,7 @@ func (wb *weightedBalancer) Rebalance(change discovery.Change) {
116123
if !change.Result.Cacheable {
117124
return
118125
}
119-
wb.pickerCache.Store(change.Result.CacheKey, wb.createPicker(change.Result))
126+
wb.pickerCache.Store(change.Result.CacheKey, wb.createPicker(context.Background(), change.Result))
120127
}
121128

122129
// Delete implements the Rebalancer interface.

‎pkg/loadbalance/weighted_balancer_test.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -43,13 +43,13 @@ func TestWeightedBalancer_GetPicker(t *testing.T) {
4343
t.Run(tc.Name, func(t *testing.T) {
4444
balancer := tc.factory()
4545
// nil
46-
picker := balancer.GetPicker(discovery.Result{})
46+
picker := balancer.GetPicker(context.Background(), discovery.Result{})
4747
test.Assert(t, picker != nil)
4848
dp, ok := picker.(*DummyPicker)
4949
test.Assert(t, ok && dp != nil)
5050

5151
// invalid
52-
picker = balancer.GetPicker(discovery.Result{
52+
picker = balancer.GetPicker(context.Background(), discovery.Result{
5353
Instances: []discovery.Instance{
5454
discovery.NewInstance("tcp", "addr1", -10, nil),
5555
discovery.NewInstance("tcp", "addr2", -20, nil),
@@ -74,7 +74,7 @@ func TestWeightedBalancer_GetPicker(t *testing.T) {
7474
discovery.NewInstance("tcp", "addr2", 20, nil),
7575
discovery.NewInstance("tcp", "addr3", 30, nil),
7676
}
77-
picker = balancer.GetPicker(discovery.Result{
77+
picker = balancer.GetPicker(context.Background(), discovery.Result{
7878
Instances: insList,
7979
})
8080
test.Assert(t, picker != nil)
@@ -85,7 +85,7 @@ func TestWeightedBalancer_GetPicker(t *testing.T) {
8585
discovery.NewInstance("tcp", "addr2", 10, nil),
8686
discovery.NewInstance("tcp", "addr3", 10, nil),
8787
}
88-
picker = balancer.GetPicker(discovery.Result{
88+
picker = balancer.GetPicker(context.Background(), discovery.Result{
8989
Instances: insList,
9090
})
9191
test.Assert(t, picker != nil)

‎pkg/loadbalance/weighted_round_robin.go‎

Lines changed: 10 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@ import (
2121
"sync"
2222

2323
"github.com/bytedance/gopkg/lang/fastrand"
24+
"github.com/cloudwego/kitex/pkg/klog"
2425

2526
"github.com/cloudwego/kitex/pkg/discovery"
2627
)
@@ -37,7 +38,7 @@ type wrrNode struct {
3738
current int
3839
}
3940

40-
func newWeightedRoundRobinPicker(instances []discovery.Instance) Picker {
41+
func newWeightedRoundRobinPicker(ctx context.Context, instances []discovery.Instance) Picker {
4142
wrrp := new(WeightedRoundRobinPicker)
4243
wrrp.iterator = newRound()
4344

@@ -59,7 +60,9 @@ func newWeightedRoundRobinPicker(instances []discovery.Instance) Picker {
5960
}
6061
wrrp.vcapacity = uint64(totalWeight)
6162
wrrp.vnodes = make([]discovery.Instance, wrrp.vcapacity)
63+
klog.CtxErrorf(ctx, "KITEX-DEBUG: newWeightedRoundRobinPicker, vsize=%d, vcapacity=%d", wrrp.vsize)
6264
wrrp.buildVirtualWrrNodes(wrrVNodesBatchSize)
65+
klog.CtxErrorf(ctx, "KITEX-DEBUG: newWeightedRoundRobinPicker, vsize=%d", wrrp.vsize)
6366
return wrrp
6467
}
6568

@@ -78,6 +81,9 @@ type WeightedRoundRobinPicker struct {
7881

7982
// Next implements the Picker interface.
8083
func (wp *WeightedRoundRobinPicker) Next(ctx context.Context, request interface{}) (ins discovery.Instance) {
84+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start Loadbalance")
85+
defer func() { klog.CtxErrorf(ctx, "KITEX-DEBUG: end Loadbalance, nodeSize=%d", len(wp.vnodes)) }()
86+
// iterator must start from 0, because we need warmup the vnode at beginning
8187
idx := wp.iterator.Next() % wp.vcapacity
8288
// fast path
8389
if wp.vnodes[idx] != nil {
@@ -94,7 +100,10 @@ func (wp *WeightedRoundRobinPicker) Next(ctx context.Context, request interface{
94100
if idx > vtarget {
95101
vtarget = idx
96102
}
103+
104+
klog.CtxErrorf(ctx, "KITEX-DEBUG: start buildVirtualWrrNodes, wp.vsize=%d, vcapacity=%d", wp.vsize, wp.vcapacity)
97105
wp.buildVirtualWrrNodes(vtarget)
106+
klog.CtxErrorf(ctx, "KITEX-DEBUG: end buildVirtualWrrNodes, wp.vsize=%d", wp.vsize)
98107
return wp.vnodes[idx]
99108
}
100109

0 commit comments

Comments
 (0)