fix #44 - add latency and throuhput tests to confirm claim of < 10ms latency

[littlebee]

I think we can maybe actually say "< 1ms" latency. This is either incredible or incredulous, but here are the results of the new test on my M3 mac.

You can see the console output for pytest in real-time using the -s switch:

python -m pytest -s -vv tests/integration_tests/test_hub_state_monitor.py -k test_round_trip_latency

console output from test:

all messages received
average latency: 0.0008089423179626464
self.recv_latencies=[0.001405954360961914, 0.0018727779388427734, 0.0019431114196777344, 0.0018532276153564453, 0.001676797866821289, 0.0015139579772949219, 0.001190185546875, 0.0013790130615234375, 0.001477956771850586, 0.001196146011352539, 0.0010442733764648438, 0.0008192062377929688, 0.0007250308990478516, 0.0008268356323242188, 0.0008161067962646484, 0.0008730888366699219, 0.0010399818420410156, 0.0011720657348632812, 0.0014410018920898438, 0.0012750625610351562, 0.0014789104461669922, 0.0012049674987792969, 0.0013289451599121094, 0.0011909008026123047, 0.0011000633239746094, 0.0008671283721923828, 0.000993967056274414, 0.001001119613647461, 0.0008308887481689453, 0.0007801055908203125, 0.0006339550018310547, 0.0006420612335205078, 0.0007908344268798828, 0.0006737709045410156, 0.0010879039764404297, 0.0011370182037353516, 0.00110626220703125, 0.0010831356048583984, 0.0010619163513183594, 0.0009341239929199219, 0.0008161067962646484, 0.0007150173187255859, 0.0006711483001708984, 0.0007171630859375, 0.0007269382476806641, 0.0006499290466308594, 0.0007700920104980469, 0.0007569789886474609, 0.0006341934204101562, 0.0005826950073242188, 0.0006799697875976562, 0.0005700588226318359, 0.0006158351898193359, 0.0005900859832763672, 0.0005960464477539062, 0.0005719661712646484, 0.0005297660827636719, 0.0007688999176025391, 0.0007901191711425781, 0.0008249282836914062, 0.0006468296051025391, 0.0006680488586425781, 0.0006241798400878906, 0.000579833984375, 0.0005500316619873047, 0.0005638599395751953, 0.0005950927734375, 0.0005931854248046875, 0.000553131103515625, 0.0005838871002197266, 0.0005362033843994141, 0.0005471706390380859, 0.0006079673767089844, 0.0006451606750488281, 0.0006289482116699219, 0.0006880760192871094, 0.0005388259887695312, 0.0005528926849365234, 0.0004961490631103516, 0.0004990100860595703, 0.0004649162292480469, 0.0005080699920654297, 0.0005121231079101562, 0.000530242919921875, 0.0005080699920654297, 0.0005252361297607422, 0.0005025863647460938, 0.0005331039428710938, 0.0005087852478027344, 0.0005068778991699219, 0.0004990100860595703, 0.0006000995635986328, 0.0006089210510253906, 0.0005371570587158203, 0.0005397796630859375, 0.0004680156707763672, 0.0004611015319824219, 0.000453948974609375, 0.00045418739318847656, 0.0004258155822753906]
overall_duration=0.04756283760070801
p90 latency: 0.0007278080824967269
throughput: 2102.4817913410498 messsages per second
PASSEDstopping 1 services
stopping basic_bot.services.central_hub
stopping test mode process...
Stopped service: basic_bot.services.central_hub with PID 25337
20250206-192709 INFO: central_hub socket disconnected.  Reconnecting in 5 sec...

[littlebee]

Here is the same test ouput running in Pi5 Bookworm 64:

all messages received
average latency: 0.0007216763496398925
self.recv_latencies=[0.0008289813995361328, 0.0010194778442382812, 0.0008957386016845703, 0.0008783340454101562, 0.00086212158203125, 0.0008575916290283203, 0.0008361339569091797, 0.0008237361907958984, 0.0008296966552734375, 0.0007958412170410156, 0.0007848739624023438, 0.0007877349853515625, 0.0007660388946533203, 0.0007910728454589844, 0.0007596015930175781, 0.0007121562957763672, 0.000705718994140625, 0.000789642333984375, 0.0007441043853759766, 0.0007364749908447266, 0.0008144378662109375, 0.0007860660552978516, 0.0006957054138183594, 0.0006661415100097656, 0.0007336139678955078, 0.0006830692291259766, 0.0007183551788330078, 0.0006592273712158203, 0.0006759166717529297, 0.0006520748138427734, 0.0005984306335449219, 0.0006811618804931641, 0.0007076263427734375, 0.0006840229034423828, 0.0007219314575195312, 0.0006577968597412109, 0.0006799697875976562, 0.0006382465362548828, 0.0006778240203857422, 0.0006353855133056641, 0.0009431838989257812, 0.0008220672607421875, 0.0007941722869873047, 0.0007522106170654297, 0.0007681846618652344, 0.0007736682891845703, 0.0007233619689941406, 0.0006749629974365234, 0.0006814002990722656, 0.0006546974182128906, 0.0007724761962890625, 0.0007703304290771484, 0.0006961822509765625, 0.0006494522094726562, 0.0006892681121826172, 0.0007128715515136719, 0.0008020401000976562, 0.0007498264312744141, 0.0007169246673583984, 0.0006749629974365234, 0.0006635189056396484, 0.0007524490356445312, 0.0007443428039550781, 0.0007021427154541016, 0.0006868839263916016, 0.000667572021484375, 0.0007433891296386719, 0.0007290840148925781, 0.0007550716400146484, 0.0006866455078125, 0.0006649494171142578, 0.0007143020629882812, 0.0007114410400390625, 0.0006327629089355469, 0.0006318092346191406, 0.0006270408630371094, 0.0006392002105712891, 0.0006949901580810547, 0.0006940364837646484, 0.0006985664367675781, 0.0006742477416992188, 0.0007250308990478516, 0.0007448196411132812, 0.0008056163787841797, 0.0010347366333007812, 0.0008366107940673828, 0.0007450580596923828, 0.0007030963897705078, 0.0006422996520996094, 0.0006015300750732422, 0.0006456375122070312, 0.0006256103515625, 0.0006923675537109375, 0.0007131099700927734, 0.0006575584411621094, 0.0005812644958496094, 0.0006134510040283203, 0.0006201267242431641, 0.0004036426544189453, 0.0004673004150390625]
overall_duration=0.05681633949279785
p90 latency: 0.0007033374283339951
throughput: 1760.0570697215753 messsages per second
PASSEDstopping 1 services
stopping basic_bot.services.central_hub
stopping test mode process...
Stopped service: basic_bot.services.central_hub with PID 2277

[littlebee]

It just occurred to me that this is all with full logging happening everywhere. Shut the front door! The test helper starts the central_hub service with BB_ENV=test which causes all log.debug messages in addition to .info and .error. It also sets the BB_LOG_ALL_MESSAGES=1 which causes central hub to brutally force log (stdout.flush() after each) every inbound and outbound message.

"Damn future computers are fast", says me from 1994.

[littlebee]

This was not testing basic_bot and was redundant with the diagnostic tests in basic_bot.debug