Bad performance test ping/pong messages

[kharitonov1995]

I was using an old version of proto actor, now I saw the new version in Git and decided to upgrade. When I measured the number of message transfers, I saw that the processing is much faster in the old version.

The old version: (github.com/AsynkronIT/protoactor-go v0.0.0-20210125121722-bab29b9c335d)

goarch: amd64
pkg: go.num
cpu: Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
BenchmarkProto
BenchmarkProto-8 785658 1504 ns/op
PASS

New version: (commit:66c886e5; dev branch)

goos: linux
goarch: amd64
pkg: limitconcurrency
cpu: Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
BenchmarkProto
BenchmarkProto-8 198744 5538 ns/op
PASS

Code benchmark:

func testWork(ctx actor.Context) {
	if _, ok := ctx.Message().(string); ok {
		ctx.Respond("pong")
	}
}

func BenchmarkProto(b *testing.B) {
	system := actor.NewActorSystem()
	pid = system.Root.Spawn(actor.PropsFromFunc(testWork))
	for i := 0; i < b.N; i++ {
		_, err := system.Root.RequestFuture(pid, "ping", time.Second).Result()
		if err != nil {
			panic(err)
		}
	}
}

[rogeralsing]

I'll take a peek at this.
In this specific test, the code will mostly wait for the mailbox to start running. there shouldn't be any changes to this pipeline for the different versions.
Did you run the tests multiple times? just to eliminate any other work done by the computer

[kharitonov1995]

Thanks for the quick response! The PC is not doing any other work during the test. I tried to run it on another PC (several times), the result was the same.

[kharitonov1995]

Wrote a little test. Here you can also see that the number of ping-pong messages was significantly higher in the old version.

type actor1 struct {
	t        time.Time
	deadline time.Time
	pid2     *actor.PID
	cnt      int
}

func (a *actor1) Receive(ctx actor.Context) {
	switch m := ctx.Message().(type) {
	case *actor.Started:
		a.deadline = a.t.Add(time.Second)
		ctx.Request(a.pid2, "ping")
	case string:
		if time.Now().After(a.deadline) {
			fmt.Println("total: ", a.cnt)
			return
		}
		if m == "pong" {
			a.cnt++
			ctx.Request(a.pid2, "ping")
		}
	}
}

func main() {
	system := actor.NewActorSystem()
	pid2 := system.Root.Spawn(actor.PropsFromFunc(func(ctx actor.Context) {
		if msg, ok := ctx.Message().(string); ok && msg == "ping" {
			ctx.Respond("pong")
		}
	}))
	a := &actor1{
		t:    time.Now(),
		pid2: pid2,
	}
	system.Root.Spawn(actor.PropsFromProducer(func() actor.Actor {
		return a
	}))
	<-make(chan bool)
}

Results:

• OLD: total: 538204
• NEW: total: 80031

[rogeralsing]

Marking this up for grabs.
Nothing in the messaging pipeline has changed so I'm not really sure what could cause this.

[lrweck]

Just for reference, on a M1 Mac Pro I get around 280000 messages per second. @kharitonov1995 is this problem still happening?

[lrweck]

I'm looking at the pprof trace of this example and one thing stands out to me: there are a lot of goroutines being created. not all at the same time, but serially. The dispatcher/scheduler of the default mailbox is very strict about marking the mailbox as idle as soon as the mailbox is empty. that makes the goroutineDispatcher create a new goroutine everytime, which is cheap, but not free... I wonder if we could be more forgiving, or configurable

[lrweck]

relevant code:

protoactor-go/actor/mailbox.go

Lines 91 to 92 in 4900170

	m.schedule()
	}

protoactor-go/actor/mailbox.go

Lines 110 to 111 in 4900170

	m.dispatcher.Schedule(m.processMessages)
	}

protoactor-go/actor/mailbox.go

Lines 125 to 126 in 4900170

	if atomic.CompareAndSwapInt32(&m.schedulerStatus, idle, running) {
	// fmt.Printf("looping %v %v %v\n", sys, user, m.suspended)

[lrweck]

does that make sense @rogeralsing ?

[rogeralsing]

First of all, are we talking about the same example?

This is what I´m getting in the actor-inprocess-benchmark:

╭─ ~/git/asynkron/protoactor-go/examples/actor-inprocess-benchmark 
╰─❯ go run .                                                                                                                                                                                         
9:35PM INF actor system started lib=Proto.Actor system=DenvmXViZPpCmqfG8fcX8X id=DenvmXViZPpCmqfG8fcX8X
2024/04/03 21:35:22 Dispatcher Throughput			Elapsed Time			Messages per sec
2024/04/03 21:35:22 			300			490.002959ms			65305732
2024/04/03 21:35:25 			400			491.23ms			65142600
2024/04/03 21:35:27 			500			479.061041ms			66797328
2024/04/03 21:35:30 			600			472.697416ms			67696584
2024/04/03 21:35:32 			700			488.913542ms			65451244
2024/04/03 21:35:34 			800			477.550666ms			67008600
2024/04/03 21:35:37 			900			460.705542ms			69458680

Are you running something else?

[lrweck]

I ran the code @kharitonov1995 provided and used pprof to profile it. this benchmark kinda hides the "issue" i've described because there is almost always a message in the mailbox. The case i've described is that the scheduler has to run a new goroutine for each new message. because of the nature of the example @kharitonov1995 wrote, it is impossible to exist more that one message at a time in the mailbox, hence the schedulerState keeps changing between idle and running and creating new goroutines.

*edited

[rogeralsing]

I'm looking at the pprof trace of this example and one thing stands out to me: there are a lot of goroutines being created. not all at the same time, but serially. The dispatcher/scheduler of the default mailbox is very strict about marking the mailbox as idle as soon as the mailbox is empty. that makes the goroutineDispatcher create a new goroutine everytime, which is cheap, but not free... I wonder if we could be more forgiving, or configurable

IIRC we have tried various tricks here before, e.g. we have this bit in the mailbox:

	for {
		if i > t {
			i = 0
			runtime.Gosched()
		}

To keep the goroutine alive while there are more messages to consume, but still allow for other goroutines to do their work.
Currently we exit the out loop if the mailbox is eventually empty.
Maybe we should spin a few more times and do runtime.Gosched() each time to allow for new messages to arrive.

That might improve this benchmark, but hard to say what effect it has on real app code

[lrweck]

doing this makes the performance increase from ~280k to around 1 million for this particular test. Now, I know it is not a good idea to call runtime.Gosched() every other time, but I'm going to run some other benchmarks to make sure numbers are increased. maybe the default throuput can be decreased and that could help in general

i, t := 0, 0 // m.dispatcher.Throughput()
for {
	if i > t {
		i = 0
		runtime.Gosched()
	}
	i++
[...]