Configurable network limits

[gbanasiak]

Async transport has the following hard-coded limits:

Thespian/thespian/system/transport/asyncTransportBase.py

Lines 37 to 40 in acf5cb2

	MAX_PENDING_TRANSMITS = 20
	MAX_QUEUED_TRANSMITS = 950
	QUEUE_TRANSMIT_UNBLOCK_THRESHOLD = 780
	DROP_TRANSMITS_LEVEL = MAX_QUEUED_TRANSMITS + 100

In setups with high number of actors these arbitrary limits might be too small for the actor system to operate correctly. I'd like to have an option to modify these values through environment variables.

There's an existing PR for this: #75

[gbanasiak]

Sharing some experiences here, perhaps that's useful.

I'm using Rally to run some scale tests. Rally uses multiple Thespian actors with multiprocTCPBase. The main fan-out is between DriverActor and its children - Workers. In an example scale test scenario I'm using 8 hosts (actor systems) forming a convention with a single convention leader. DriverActor actor sits on host with convention leader, while Workers on all of the hosts. There are 512 Workers, 64 on each of the hosts.

With this amount of sockets used by DriverActor process the first hurdle is #78. After addressing it I've noticed Dropping TX: overloaded messages from admin process on the convention leader at the time Worker actors are being created. I found it interesting there's no preceding TX-only mode for the admin process, it went right into hard drops. By looking at earlier activity I've noticed a big volume of LogRecord messages going from admin process to Logging actor. These were DEBUG logs despite the fact that actor system is initialized with logDefs where the minimum log level is INFO (I'm using recent Thespian snapshot + #81). These logs were coming from actorSystemCapabilityCheck() static method in a class which is a base class for all the Thespian actors in Rally (src). Is there a way to avoid these DEBUG logs being forwarded? Why was it enough to trigger transmit drops? The math goes like this I think: there are 512 workers, for every of them we have one debug log for every actor system while checking system capabilities, 512 * 8 = 4096 >> 1050.

After removal of those logs the Dropping TX: overloaded symptom was still there. I've noticed yet another source of unnecessary logs sent from admin process to the Logging actor on the convention leader but these were of WARNING level. As per documentation, WARNING level and above has special handling, so perhaps this explains it, but it's not clear to me why I saw those logs sent from admin to logger. What is the flow for these WARNING logs exactly?

actor (non-leader) --> Logger (non-leader) --> admin (leader) --> Logger (leader) ???

After adjusting the log level below WARNING I finally got rid of Dropping TX: overloaded on the admin process while using default network limits, but Rally was still not working correctly. After further debugging I've noticed wake-up messages are not delivered as they should to DriverActor.

Expected state (wake-up every second + additional reset_relative_time wake-ups after task completion):

2024-12-18 13:39:29.183654 p98216 I    Starting Actor esrally.driver.driver.DriverActor at ActorAddr-(T|:35547) (parent ActorAddr-(T|:32881), admin ActorAddr-(T|:1900), srcHash None)
[..]
2024-12-18 13:40:30.191873 p98216 dbg  actualTransmit of TransportIntent(ActorAddr-(T|:32881)-pending-ExpiresIn_0:04:59.999855-<class 'esrally.driver.driver.TaskFinished'>-<esrally.driver.driver.TaskFinished object at 0x7e728730b750>-quit_0:04:59.999846)
2024-12-18 13:40:30.982485 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:31.194042 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, reset_relative_time))
2024-12-18 13:40:31.986859 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:32.991090 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:33.995327 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:34.999551 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:36.003742 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:36.111482 p98216 dbg  actualTransmit of TransportIntent(ActorAddr-(T|:32881)-pending-ExpiresIn_0:04:59.999915-<class 'esrally.driver.driver.TaskFinished'>-<esrally.driver.driver.TaskFinished object at 0x7e728749f850>-quit_0:04:59.999907)
2024-12-18 13:40:37.007690 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:37.132081 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, reset_relative_time))
2024-12-18 13:40:38.011713 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:39.015822 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:40.019870 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:41.024128 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 13:40:42.028270 p98216 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:35547), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
[..]

Unhealthy state (at one point periodic wake-ups just stop):

2024-12-18 12:25:41.775077 p57186 I    Starting Actor esrally.driver.driver.DriverActor at ActorAddr-(T|:43023) (parent ActorAddr-(T|:42815), admin ActorAddr-(T|:1900), srcHash None)
[..]
2024-12-18 12:26:10.109429 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 12:26:11.115304 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 12:26:45.308907 p57186 dbg  actualTransmit of TransportIntent(ActorAddr-(T|:42815)-pending-ExpiresIn_0:04:59.999860-<class 'esrally.driver.driver.TaskFinished'>-<esrally.driver.driver.TaskFinished object at 0x72aba8206890>-quit_0:04:59.999850)
2024-12-18 12:26:46.312456 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, reset_relative_time))
2024-12-18 12:26:50.381623 p57186 dbg  actualTransmit of TransportIntent(ActorAddr-(T|:42815)-pending-ExpiresIn_0:04:59.999900-<class 'esrally.driver.driver.TaskFinished'>-<esrally.driver.driver.TaskFinished object at 0x72aba85a8490>-quit_0:04:59.999891)
2024-12-18 12:26:51.395110 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, reset_relative_time))
2024-12-18 12:26:56.436611 p57186 dbg  actualTransmit of TransportIntent(ActorAddr-(T|:42815)-pending-ExpiresIn_0:04:59.999898-<class 'esrally.driver.driver.TaskFinished'>-<esrally.driver.driver.TaskFinished object at 0x72aba7e16890>-quit_0:04:59.999890)
[..]

At the time the first missing wake-up should have been received DriverActor could have been in TX-only mode I think:

2024-12-18 12:26:10.109429 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 12:26:11.115304 p57186 dbg  ACTOR got ReceiveEnvelope(from: ActorAddr-(T|:43023), <class 'thespian.actors.WakeupMessage'> msg: WakeupMessage(0:00:01, None))
2024-12-18 12:26:12.072182 p57186 Warn Entering tx-only mode to drain excessive queue (950 > 950, drain-to 780 in Expires_in_0:04:56.857268)
<--- next wake-up should come here
2024-12-18 12:26:12.120927 p57186 Warn Exited tx-only mode after draining excessive queue (950)
2024-12-18 12:26:12.183576 p57186 Warn Entering tx-only mode to drain excessive queue (950 > 950, drain-to 780 in Expires_in_0:04:56.776630)

Edit: TX-only mode is unavoidable in current Rally implementation, as there are 2 messages sent from DriverActor to each Worker instance in quick succession -Bootstrap and StartWorker. 2 * 512 = 1024 > 950.

It would be useful to have some warning or error in that case. Rally schedules next wake-up as part of processing of the previous wake-up. That's fragile - even a single wake-up drop breaks this process. Is there a better way?

Anyways, after lifting the limits, TX-only mode is avoided so wake-ups work correctly.

[kquick]

Configurability has been added and merged and will be released soon. I'd like to leave this open to think more about the issues raised by @gbanasiak above.