sniffer measurements of Bluetooth broadcast and observe

[BertLindeman]

Rationale

Discussion item 2818 made me measure broadcasts on a CityHub.
This is the result.

Setup

Receiver:
Raspberry Pi Pico 2 W, MicroPython, passive scan via the built-in bluetooth module.

ble_sniffer.py

"""
ble_sniffer.py
Minimal passive BLE scanner for Pico 2 W (MicroPython) that detects
Pybricks broadcast advertisements, LEGO manufacturer data, company ID
0x0397, and prints the decoded values.

Requires ble_pybricks.py (Kees Smit) in the same directory on the board.
"""
import time

import bluetooth
from micropython import const

from ble_pybricks import check_lego_manufacturer_id, get_list_of_values

_IRQ_SCAN_RESULT = const(5)
_IRQ_SCAN_DONE = const(6)

_ADV_TYPE_MANUFACTURER_DATA = const(0xFF)

# RSSI is mostly noise, so drop the report
SHOW_RSSI = False

# Burst tracking: repeats of the same (channel, values) payload get counted
# so the underlying advertisement repeat rate is visible without manually
# eyeballing timestamps.
_burst_key = None
_burst_first_ts = 0
_burst_last_ts = 0
_burst_count = 0

# Per-connection-state aggregates, keyed by the "host_connected_ble" flag
# (True/False) if the payload carries one as its 2nd value (see
# broadcast_rate_test.py), else keyed by None ("unknown"). This is what
# produces the final summary - the thing to actually compare across a
# tethered run and a standalone run.
_stats = {}


def _record_packet(conn, elapsed, is_repeat, gap):
    global _stats
    s = _stats.get(conn)
    if s is None:
        s = {"count": 0, "first_ts": elapsed, "last_ts": elapsed,
             "gap_sum": 0, "gap_count": 0, "min_gap": None, "max_gap": None}
        _stats[conn] = s
    s["count"] += 1
    s["last_ts"] = elapsed
    if is_repeat:
        s["gap_sum"] += gap
        s["gap_count"] += 1
        if s["min_gap"] is None or gap < s["min_gap"]:
            s["min_gap"] = gap
        if s["max_gap"] is None or gap > s["max_gap"]:
            s["max_gap"] = gap


def _flush_burst():
    global _burst_count
    if _burst_count > 1:
        span = time.ticks_diff(_burst_last_ts, _burst_first_ts)
        avg_gap = span / (_burst_count - 1)
        print("      -- burst: {} packets, span {}ms, avg gap {:.0f}ms".format(
            _burst_count, span, avg_gap))
    elif _burst_count == 1:
        print("      -- single packet, no repeat seen")
    _burst_count = 0


def _print_final_stats():
    print()
    print("=== summary (grouped by host_connected_ble) ===")
    if not _stats:
        print("no Pybricks broadcasts received")
        return
    labels = {True: "connected", False: "standalone", None: "unknown"}
    for conn in (True, False, None):
        s = _stats.get(conn)
        if not s:
            continue
        duration = time.ticks_diff(s["last_ts"], s["first_ts"])
        rate = (s["count"] / (duration / 1000)) if duration > 0 else float("nan")
        line = "{:>10}: {:4d} packets over {:6d}ms  ({:.2f} pkt/s)".format(
            labels[conn], s["count"], duration, rate)
        if s["gap_count"]:
            avg_gap = s["gap_sum"] / s["gap_count"]
            line += "  repeat gap avg {:.0f}ms (min {}, max {})".format(
                avg_gap, s["min_gap"], s["max_gap"])
        else:
            line += "  no repeats observed"
        print(line)


def _find_adv_structure(payload, adv_type):
    """Return the raw AD structure (length byte + type byte + data) for
    adv_type, or None. Keeping the length/type header intact matches what
    ble_pybricks.py expects (it indexes adv_data[0]=length, [1]=type,
    [2:4]=company id)."""
    i = 0
    n = len(payload)
    while i + 1 < n:
        length = payload[i]
        if length == 0:
            break
        if payload[i + 1] == adv_type:
            return bytes(payload[i:i + 1 + length])
        i += 1 + length
    return None


def _bt_irq(event, data):
    if event == _IRQ_SCAN_RESULT:
        addr_type, addr, adv_type, rssi, adv_data = data
        manu = _find_adv_structure(adv_data, _ADV_TYPE_MANUFACTURER_DATA)
        if manu and check_lego_manufacturer_id(manu):
            channel = manu[4]  # Pybricks broadcast channel, prefix to the data
            elapsed = time.ticks_diff(time.ticks_ms(), _start_ms)
            try:
                values = get_list_of_values(manu)
            except Exception as e:
                print("decode error:", e)
                return

            global _burst_key, _burst_first_ts, _burst_last_ts, _burst_count
            key = (channel, repr(values))
            if key == _burst_key:
                gap = time.ticks_diff(elapsed, _burst_last_ts)
                is_repeat = True
            else:
                _flush_burst()
                _burst_key = key
                _burst_first_ts = elapsed
                _burst_count = 0
                gap = 0
                is_repeat = False
            _burst_count += 1
            _burst_last_ts = elapsed

            # values == [counter, host_connected_ble] when broadcast_rate_test.py
            # is the sender; anything else (wrong length, plain int, etc.)
            # falls into the "unknown" bucket rather than raising.
            conn = values[1] if isinstance(values, list) and len(values) >= 2 else None
            _record_packet(conn, elapsed, is_repeat, gap)

            if SHOW_RSSI:
                print("{:5d} Channel {} (RSSI {:4d}): {}".format(elapsed, channel, rssi, values))
            else:
                print("{:5d} Channel {}: {}".format(elapsed, channel, values))
    elif event == _IRQ_SCAN_DONE:
        # duration_ms=0 below means continuous, so this normally won't
        # fire, but restart defensively if it ever does.
        ble.gap_scan(0, 30000, 30000, False)


ble = bluetooth.BLE()
ble.active(True)
ble.irq(_bt_irq)

print("Scanning for Pybricks broadcasts (Ctrl-C to stop)...")
_start_ms = time.ticks_ms()
# duration_ms=0 -> scan forever, interval_us=30000, window_us=30000,
# active_scan=False -> passive (no scan requests, matches Pybricks observe)
ble.gap_scan(0, 30000, 30000, False)

# gap_scan() is non-blocking: it schedules background scanning and returns
# immediately. Without something keeping the script alive here, execution
# reaches the end of the file and the run tool (mpremote/Thonny) resets the
# board, killing the scan before it produces anything.
try:
    while True:
        time.sleep_ms(500)
except KeyboardInterrupt:
    print("stopping scan")
    _flush_burst()
    ble.gap_scan(None)
    ble.active(False)
    _print_final_stats()

Hub:
City Hub, Pybricks v4.1.0b2

Hub-side test program:

CityHub program broadcast_transmit_demo.py

"""
ble_broadcast_observe.py
Runs on the Pybricks City Hub. Three ways of running broadcast + observe
together, to isolate whether the OP's reported RX-blocked-during-TX
behaviour comes from simultaneous broadcast+observe itself, or from the
stop/resume transition between "sending" and "not sending".

MODE 1 "swap"        - a new BLERadio object each phase: TX-only for
                        TX_WINDOW_MS, then RX-only for RX_WINDOW_MS.
                        Mirrors the OP's current implementation.

MODE 2 "static-pause" - one BLERadio instance for the whole run, both
                        broadcast_channel and observe_channels set from
                        the start. TX is paused with broadcast(None) and
                        resumed with broadcast(value) each cycle.

MODE 3 "static-continuous" - same dual-role radio as MODE 2, but TX is
                        NEVER paused: broadcast(new_value) is called
                        back-to-back with no broadcast(None) in between.

Two additional variables, both previously untested:

POLL_OBSERVE  - if True, actively call radio.observe(RX_CHANNEL) at a
                steady interval during every "listening" period, instead
                of just leaving observe_channels configured and never
                reading from it. Rules in/out a lazy-start scanner.

SETTLE_MS     - short pause inserted right after every BLERadio(...)
                construction, before it's used. Most examples construct
                the radio once outside any loop; MODE 1's per-cycle
                teardown/rebuild is the unusual case this guards against.

Broadcasts (counter, host_connected_ble) each cycle, same as
broadcast_rate_test.py, so ble_sniffer.py's per-burst stats and final
summary work unchanged. Run all three x tethered/standalone, ideally
with POLL_OBSERVE True vs False, to see whether either variable moves
the standalone numbers at all.

Only the broadcast side is externally observable with a sniffer, this
can't confirm what the hub itself received, only whether outgoing
transmissions stay regular under each approach.
"""
from pybricks.hubs import ThisHub
from pybricks.messaging import BLERadio
from pybricks.tools import wait

MODE = 2          # 1 = swap radio instances, 2 = static + pause/resume, 3 = static + never pause
POLL_OBSERVE = False   # actively call radio.observe() during listening periods
SETTLE_MS = 0        # pause after constructing/reconfiguring the radio, before using it
POLL_INTERVAL_MS = 50  # how often to call radio.observe() while "listening"

TX_CHANNEL = 0x66
RX_CHANNEL = 0x77
TX_WINDOW_MS = 200   # matches the OP's measured TX slot
RX_WINDOW_MS = 800   # "listening"/paused gap between TX bursts (modes 1 & 2)

hub = ThisHub()


def _wait_and_observe(total_ms, radio):
    """Wait out total_ms. If POLL_OBSERVE, actively call radio.observe()
    every POLL_INTERVAL_MS instead of a single blind wait, exercises the
    receive path rather than just leaving it configured and unused."""
    if not POLL_OBSERVE:
        wait(total_ms)
        return
    elapsed = 0
    while elapsed < total_ms:
        step = min(POLL_INTERVAL_MS, total_ms - elapsed)
        radio.observe(RX_CHANNEL)  # result unused - we only care that it's called
        wait(step)
        elapsed += step


if MODE in (2, 3):
    # One radio for the whole run: both roles configured up front.
    radio = BLERadio(broadcast_channel=TX_CHANNEL, observe_channels=[RX_CHANNEL])
    wait(SETTLE_MS)

counter = 0
while True:
    connected = hub.system.info()["host_connected_ble"]

    if MODE == 1:
        # Swap approach: separate radio objects for TX-only and RX-only.
        radio = BLERadio(broadcast_channel=TX_CHANNEL, observe_channels=[])
        wait(SETTLE_MS)
        radio.broadcast((counter, connected))
        wait(TX_WINDOW_MS)
        radio = BLERadio(broadcast_channel=None, observe_channels=[RX_CHANNEL])
        wait(SETTLE_MS)
        _wait_and_observe(RX_WINDOW_MS, radio)
    elif MODE == 2:
        # Static + pause: same radio object throughout; broadcast(None)
        # pauses TX without touching the observe configuration.
        radio.broadcast((counter, connected))
        wait(TX_WINDOW_MS)
        radio.broadcast(None)
        _wait_and_observe(RX_WINDOW_MS, radio)
    else:
        # Static + continuous: same radio object, TX never stops.
        radio.broadcast((counter, connected))
        _wait_and_observe(TX_WINDOW_MS + RX_WINDOW_MS, radio)

    counter += 1

• Broadcast-only baseline: Just radio.broadcast(value) on a timer, no observe_channels set at all.
• Mode 1 "swap": A new BLERadio object per phase: TX-only for 200ms, then RX-only for 800ms.
• Mode 2 "static-pause": One BLERadio for the whole run, both broadcast_channel and observe_channels set up front. TX paused with broadcast(None), resumed with broadcast(value).
• Mode 3 "static-continuous": Same dual-role radio as mode 2, but TX is never paused, broadcast(new_value) called back-to-back.

Added two more variables to modes 1-3:

• POLL_OBSERVE (actively call radio.observe(channel) on a timer during listening periods, instead of just leaving observe_channels configured and unread).
• SETTLE_MS (a short pause after constructing/reconfiguring a BLERadio, before using it).

---

Results

Baseline, broadcast only, no observe channel defined.

State	Packets	Duration	Rate	Avg gap	Gap range
connected	1490	52.1s	28.57 pkt/s	35ms	22-109ms
standalone	1465	53.0s	27.65 pkt/s	36ms	3-149ms

No meaningful difference. This is the reference point everything below is measured against.

---

Modes 1-3 with POLL_OBSERVE and SETTLE_MS varied.

Mode	Poll observe	Settle	State	Packets	Duration	Rate	Avg gap	Gap range
1	False	0ms	connected	1402	67.2s	20.86 pkt/s	47ms	22-214ms
1	False	0ms	standalone	61	63.8s	0.96 pkt/s	563ms	125-1759ms
1	True	0ms	connected	1153	61.3s	18.80 pkt/s	52ms	22-209ms
1	True	0ms	standalone	252	63.5s	3.97 pkt/s	209ms	33-746ms
1	True	50ms	connected	1203	62.2s	19.33 pkt/s	51ms	2-245ms
1	True	50ms	standalone	185	62.1s	2.98 pkt/s	233ms	34-901ms
2	False	0ms	connected	181	60.8s	2.98 pkt/s	44ms	2-122ms
2	False	0ms	standalone	5	4.2s	1.20 pkt/s	97ms	dies at ~4s
2	True	0ms	connected	240	60.8s	3.95 pkt/s	43ms	23-119ms
2	True	0ms	standalone	36	61.7s	0.58 pkt/s	89ms	64-133ms
2	True	50ms	connected	239	61.8s	3.87 pkt/s	45ms	3-119ms
2	True	50ms	standalone	49	61.9s	0.79 pkt/s	79ms	65-134ms
3	False	0ms	connected	1343	61.4s	21.88 pkt/s	46ms	2-214ms
3	False	0ms	standalone	68	88.2s	0.77 pkt/s	561ms	158-1664ms
3	True	0ms	connected	1287	63.5s	20.25 pkt/s	49ms	21-275ms
3	True	0ms	standalone	240	62.2s	3.86 pkt/s	216ms	26-841ms
3	True	50ms	connected	1427	61.4s	23.22 pkt/s	43ms	19-181ms
3	True	50ms	standalone	295	84.6s	3.49 pkt/s	217ms	26-931ms

---

What the raw log looks like

This is mode 3, poll observe on, settle 50ms, standalone. The value changes once a second; each row is one received packet:

60069 Channel 102: [60, False]
60105 Channel 102: [60, False]
60170 Channel 102: [60, False]
60235 Channel 102: [60, False]
60434 Channel 102: [60, False]
60499 Channel 102: [60, False]
60596 Channel 102: [60, False]
60694 Channel 102: [60, False]
60791 Channel 102: [60, False]
60887 Channel 102: [60, False]
61017 Channel 102: [60, False]
      -- burst: 11 packets, span 948ms, avg gap 95ms
61143 Channel 102: [61, False]
61272 Channel 102: [61, False]
61398 Channel 102: [61, False]
61559 Channel 102: [61, False]
61717 Channel 102: [61, False]
61875 Channel 102: [61, False]
62064 Channel 102: [61, False]
      -- burst: 7 packets, span 921ms, avg gap 154ms
62254 Channel 102: [62, False]
62444 Channel 102: [62, False]
62662 Channel 102: [62, False]
62884 Channel 102: [62, False]
63103 Channel 102: [62, False]
      -- burst: 5 packets, span 849ms, avg gap 212ms
63324 Channel 102: [63, False]
      -- single packet, no repeat seen
65297 Channel 102: [64, False]
      -- single packet, no repeat seen
65639 Channel 102: [65, False]
65981 Channel 102: [65, False]
      -- burst: 2 packets, span 342ms, avg gap 342ms
66698 Channel 102: [66, False]
      -- single packet, no repeat seen

This is not a slow rate, it is a very fluctuating one.

---

Interpretation

• Broadcast-only is unaffected by connection state.
  The problem only shows up once observe_channels is used and also broadcast_channel, dual-role is the trigger.
• Mode 2 has a second, separate, connection-independent bug?.
  It's the worst performer connected (3.79 pkt/s vs ~19-23 pkt/s for modes 1 and 3) and the only one that simply stops standalone rather than degrading. broadcast(None) followed by broadcast(value) on the same radio object doesn't reliably restart transmission, mode 1's full object recreation and mode 3's "never stop" approach, both avoid this because neither exercises that specific resume path.
• Actively polling radio.observe() measurably helps standalone, but doesn't fix it.
  Modes 1 and 3 standalone go from ~0.95-1.03 pkt/s (observe configured but never read) to ~3-4 pkt/s (observe actively polled), a real, repeatable improvement, but still a lot below the ~28 pkt/s baseline or the ~19-23 pkt/s connected dual-role rate.
• SETTLE_MS made no consistent difference in either direction across every mode it was tested on. This is not a factor here.

---

Caveats

• Tested on a City Hub on v4.1.0b2, with one sniffer and no second transmitting hub.
• No data about other hub types, other firmware versions.

---

Bottom line

• Dual-role (broadcast + observe together) is slow and reproducible:

  • roughly 3-4 pkt/s best case,
  • versus ~20-28 pkt/s connected-broadcast-only.

• Mode 2's pause/resume pattern has its own, separate bug?

• If it is helpful, I could do similar measurements on another firmwarelevel.

[toyotafj40]

Hi Bert,
Thanks for taking the time to confirm the 'questionable' performance of the BLERadio/Hub.

There was one other observation that I wanted to add.
After the hub was started, the first burst reply of packets always sent a lots of packets, then subsequent bursts quickly fell away to just one packet inside the 400mS Tx window.

Hopefully you can open the BLERadio firmware driver and get some improvement towards a reliable Rx/Tx handshake operation.

{wishlist} While you are there, can you expose the packet count since last 'observe' or 'broadcast' as radio.count.in(channel) and radio.count.out()

[BertLindeman]

Hi Peter,

There was one other observation that I wanted to add. After the hub was started, the first burst reply of packets always sent a lots of packets, then subsequent bursts quickly fell away to just one packet inside the 400mS Tx window.

No idea how to measure that on the sniffer side.

Hopefully you can open the BLERadio firmware driver and get some improvement towards a reliable Rx/Tx handshake operation.

That is out of my scope.

{wishlist} While you are there, can you expose the packet count since last 'observe' or 'broadcast' as radio.count.in(channel) and radio.count.out()

This is also a request for the developers.

Will follow up with these measurements on CityHub FW 3.61 v4.0.1 as I do not have 3.6.1 anymore.

[BertLindeman]

Does a Pybricks hub send data slower when it is not connected to a PC? (round 2, two firmware versions)

Why this test

A LEGO hub can send small updates over Bluetooth while also listening for updates from other hubs at the same time.
Earlier, shorter tests showed this can slow down a lot when the hub is not connected to a PC.
This round repeats the same tests, but for a full 5 minutes each instead of 1 minute,
and on two different hub software versions:

• the current official version V4.0.1
• and a newer test (beta) version v4.1.0b2.

The goal is more reliable numbers, and to see if both versions behave the same way.

Results

Firmware	Sending method	Reads while waiting	Startup wait	PC connected	Duration	Packets	Speed	Avg repeat gap	Avg repeats/update
v4.0.1 (stable)	pause between updates	no	0ms	yes	5.1 min	1162	3.76/s	44ms	3.8 (1-7)
v4.1.0b2 (beta)	pause between updates	no	0ms	yes	5.1 min	1369	4.43/s	40ms	4.5 (1-7)
v4.0.1 (stable)	pause between updates	no	0ms	no	0.1 min	5	1.23/s	n/a	1.0 (1-1)
v4.1.0b2 (beta)	pause between updates	no	0ms	no	0.1 min	4	1.28/s	n/a	1.0 (1-1)
v4.0.1 (stable)	pause between updates	yes	0ms	yes	6.0 min	1458	4.08/s	41ms	4.1 (1-7)
v4.1.0b2 (beta)	pause between updates	yes	0ms	yes	5.7 min	1541	4.55/s	38ms	4.6 (1-7)
v4.0.1 (stable)	pause between updates	yes	0ms	no	5.2 min	205	0.65/s	85ms	1.4 (1-3)
v4.1.0b2 (beta)	pause between updates	yes	0ms	no	5.3 min	240	0.75/s	80ms	1.4 (1-3)
v4.0.1 (stable)	pause between updates	yes	50ms	yes	5.1 min	1023	3.34/s	46ms	3.4 (1-7)
v4.1.0b2 (beta)	pause between updates	yes	50ms	yes	5.2 min	1425	4.59/s	39ms	4.6 (2-7)
v4.0.1 (stable)	pause between updates	yes	50ms	no	5.3 min	201	0.64/s	83ms	1.4 (1-3)
v4.1.0b2 (beta)	pause between updates	yes	50ms	no	5.2 min	223	0.71/s	81ms	1.4 (1-3)
v4.0.1 (stable)	never pause	no	0ms	yes	5.1 min	6746	21.85/s	45ms	21.9 (11-29)
v4.1.0b2 (beta)	never pause	no	0ms	yes	5.1 min	6233	20.29/s	49ms	20.3 (1-29)
v4.0.1 (stable)	never pause	no	0ms	no	5.4 min	116	0.36/s	523ms	1.3 (1-7)
v4.1.0b2 (beta)	never pause	no	0ms	no	5.1 min	107	0.35/s	354ms	1.3 (1-7)
v4.0.1 (stable)	never pause	yes	0ms	yes	5.0 min	7088	23.51/s	42ms	23.5 (2-31)
v4.1.0b2 (beta)	never pause	yes	0ms	yes	5.3 min	6338	19.94/s	50ms	20.0 (3-29)
v4.0.1 (stable)	never pause	yes	0ms	no	5.1 min	1073	3.50/s	228ms	3.6 (1-15)
v4.1.0b2 (beta)	never pause	yes	0ms	no	5.2 min	249	0.79/s	76ms	1.4 (1-3)
v4.0.1 (stable)	never pause	yes	50ms	yes	5.4 min	6064	18.80/s	52ms	18.8 (5-29)
v4.1.0b2 (beta)	never pause	yes	50ms	yes	5.2 min	6176	19.87/s	49ms	19.9 (8-29)
v4.0.1 (stable)	never pause	yes	50ms	no	5.3 min	1109	3.50/s	222ms	3.6 (1-14)
v4.1.0b2 (beta)	never pause	yes	50ms	no	5.3 min	1224	3.86/s	215ms	3.9 (1-14)

Column meaning, in plain words:

• "Sending method" is how the hub was told to send updates: pausing in between each one, or never pausing at all.
• "Reads while waiting" is whether the hub actively checked for incoming data, instead of just being ready to receive but never checking.
• "Speed" is how many updates per second actually arrived at the listener.
• "Duration" The time that data was seen on the sniffer program. But all test lasted at east 5 mnutes.
• "Avg repeats/update" is how many times each update was repeated in a row on average, since the hub normally repeats the same update several times before moving to the next one.

One malformed (unreadable) packet was seen once, in the "never pause, does not read while waiting, not connected" test on the stable firmware. It did not happen in any other test. Although in previous tests it was sparingly seen.

Connected runs:

4.0.1   pause poll=no  settle= 0ms PC    |  3.76/s ########
4.1.0b2 pause poll=no  settle= 0ms PC    |  4.43/s #########

4.0.1   pause poll=yes settle= 0ms PC    |  4.08/s #########
4.1.0b2 pause poll=yes settle= 0ms PC    |  4.55/s ##########

4.0.1   pause poll=yes settle=50ms PC    |  3.34/s #######
4.1.0b2 pause poll=yes settle=50ms PC    |  4.59/s ##########

4.0.1   never poll=no  settle= 0ms PC    | 21.85/s ##############################################
4.1.0b2 never poll=no  settle= 0ms PC    | 20.29/s ###########################################

4.0.1   never poll=yes settle= 0ms PC    | 23.51/s ##################################################
4.1.0b2 never poll=yes settle= 0ms PC    | 19.94/s ##########################################

4.0.1   never poll=yes settle=50ms PC    | 18.80/s ########################################
4.1.0b2 never poll=yes settle=50ms PC    | 19.87/s ##########################################

Not-connected (no-PC) runs only:

4.0.1   pause poll=no  settle= 0ms no-PC |  1.23/s ################
4.1.0b2 pause poll=no  settle= 0ms no-PC |  1.28/s #################

4.0.1   pause poll=yes settle= 0ms no-PC |  0.65/s ########
4.1.0b2 pause poll=yes settle= 0ms no-PC |  0.75/s ##########

4.0.1   pause poll=yes settle=50ms no-PC |  0.64/s ########
4.1.0b2 pause poll=yes settle=50ms no-PC |  0.71/s #########

4.0.1   never poll=no  settle= 0ms no-PC |  0.36/s #####
4.1.0b2 never poll=no  settle= 0ms no-PC |  0.35/s #####

4.0.1   never poll=yes settle= 0ms no-PC |  3.50/s #############################################
4.1.0b2 never poll=yes settle= 0ms no-PC |  0.79/s ##########

4.0.1   never poll=yes settle=50ms no-PC |  3.50/s #############################################
4.1.0b2 never poll=yes settle=50ms no-PC |  3.86/s ##################################################

Conclusion

• The slowdown when the hub is not connected to a PC happens on both firmware versions, including the current official stable release. This is not just a beta issue.
• When connected to a PC, "never pause" sending is fast and steady (about 19-24 updates per second). "Pause between updates" sending is much slower even while connected (about 3-5 updates per second) - a separate weak spot in that method, unrelated to the PC connection.
• When not connected to a PC, the best result seen was about 3.5-3.9 updates per second (never pause, and actively reading while waiting). The worst was under 1 update every 2 seconds, or in one case, the hub almost completely stopped sending after only a few seconds.
• The numbers vary a lot between test runs, even with the exact same settings. One test (never pause, reading while waiting, no startup wait, beta firmware) got only 0.79 updates per second, while the same settings with a 50ms startup wait added got 3.86 updates per second - almost 5 times faster - even though a startup wait made no consistent difference anywhere else.
  This suggests the slowdown itself is unpredictable from run to run, not a fixed, reliable number.

[dlech]

Here is another firmware to try. 😄

If it works right, we should be getting 20 updates per second or so (unless movehub is the broadcaster).

pybricks/pybricks-micropython#500

[BertLindeman]

Thanks David. Will try after I get really awake.

[BertLindeman]

Does PR#500 fix the "hub sends data slower when not connected to a PC" problem?

Why this test

Earlier tests showed that a LEGO hub sending and listening for Bluetooth updates at the same time gets much slower when it is not connected to a PC, sometimes almost completely stopping.

David looked into it and found a cause A fix PR 500 was made.

This post repeats the same tests as before, and one much longer on a hub running that fix, to check whether it actually solves the problem.

Results

All three firmware versions, side by side, same tests and programs as before:

Firmware	Sending method	Reads while waiting	Startup wait	PC connected	Duration	Packets	Speed	Avg repeat gap	Avg repeats/update
v4.0.1 (stable)	pause between updates	no	0ms	yes	5.1 min	1162	3.76/s	44ms	3.8 (1-7)
v4.1.0b2 (beta)	pause between updates	no	0ms	yes	5.1 min	1369	4.43/s	40ms	4.5 (1-7)
PR#500 (24164b8d)	pause between updates	no	0ms	yes	5.2 min	1448	4.62/s	38ms	4.7 (2-7)
v4.0.1 (stable)	pause between updates	no	0ms	no	0.1 min	5	1.23/s	n/a	1.0 (1-1)
v4.1.0b2 (beta)	pause between updates	no	0ms	no	0.1 min	4	1.28/s	n/a	1.0 (1-1)
PR#500 (24164b8d)	pause between updates	no	0ms	no	5.2 min	1661	5.35/s	36ms	5.4 (1-8)
v4.0.1 (stable)	pause between updates	yes	0ms	yes	6.0 min	1458	4.08/s	41ms	4.1 (1-7)
v4.1.0b2 (beta)	pause between updates	yes	0ms	yes	5.7 min	1541	4.55/s	38ms	4.6 (1-7)
PR#500 (24164b8d)	pause between updates	yes	0ms	yes	5.2 min	1372	4.40/s	40ms	4.4 (1-7)
v4.0.1 (stable)	pause between updates	yes	0ms	no	5.2 min	205	0.65/s	85ms	1.4 (1-3)
v4.1.0b2 (beta)	pause between updates	yes	0ms	no	5.3 min	240	0.75/s	80ms	1.4 (1-3)
PR#500 (24164b8d)	pause between updates	yes	0ms	no	5.8 min	1974	5.67/s	35ms	5.7 (2-8)
v4.0.1 (stable)	pause between updates	yes	50ms	yes	5.1 min	1023	3.34/s	46ms	3.4 (1-7)
v4.1.0b2 (beta)	pause between updates	yes	50ms	yes	5.2 min	1425	4.59/s	39ms	4.6 (2-7)
PR#500 (24164b8d)	pause between updates	yes	50ms	yes	5.3 min	1444	4.57/s	38ms	4.6 (1-7)
v4.0.1 (stable)	pause between updates	yes	50ms	no	5.3 min	201	0.64/s	83ms	1.4 (1-3)
v4.1.0b2 (beta)	pause between updates	yes	50ms	no	5.2 min	223	0.71/s	81ms	1.4 (1-3)
PR#500 (24164b8d)	pause between updates	yes	50ms	no	5.2 min	1833	5.86/s	34ms	5.9 (3-8)
v4.0.1 (stable)	never pause	no	0ms	yes	5.1 min	6746	21.85/s	45ms	21.9 (11-29)
v4.1.0b2 (beta)	never pause	no	0ms	yes	5.1 min	6233	20.29/s	49ms	20.3 (1-29)
PR#500 (24164b8d)	never pause	no	0ms	yes	5.4 min	7762	24.01/s	41ms	24.1 (8-29)
v4.0.1 (stable)	never pause	no	0ms	no	5.4 min	116	0.36/s	523ms	1.3 (1-7)
v4.1.0b2 (beta)	never pause	no	0ms	no	5.1 min	107	0.35/s	354ms	1.3 (1-7)
PR#500 (24164b8d)	never pause	no	0ms	no	5.3 min	1820	5.69/s	35ms	5.7 (3-8)
v4.0.1 (stable)	never pause	yes	0ms	yes	5.0 min	7088	23.51/s	42ms	23.5 (2-31)
v4.1.0b2 (beta)	never pause	yes	0ms	yes	5.3 min	6338	19.94/s	50ms	20.0 (3-29)
PR#500 (24164b8d)	never pause	yes	0ms	yes	5.3 min	8217	25.80/s	39ms	25.9 (20-32)
v4.0.1 (stable)	never pause	yes	0ms	no	5.1 min	1073	3.50/s	228ms	3.6 (1-15)
v4.1.0b2 (beta)	never pause	yes	0ms	no	5.2 min	249	0.79/s	76ms	1.4 (1-3)
PR#500 (24164b8d)	never pause	yes	0ms	no	5.3 min	1865	5.89/s	34ms	5.9 (1-8)
v4.0.1 (stable)	never pause	yes	50ms	yes	5.4 min	6064	18.80/s	52ms	18.8 (5-29)
v4.1.0b2 (beta)	never pause	yes	50ms	yes	5.2 min	6176	19.87/s	49ms	19.9 (8-29)
PR#500 (24164b8d)	never pause	yes	50ms	yes	5.6 min	8330	24.90/s	40ms	24.9 (2-32)
v4.0.1 (stable)	never pause	yes	50ms	no	5.3 min	1109	3.50/s	222ms	3.6 (1-14)
v4.1.0b2 (beta)	never pause	yes	50ms	no	5.3 min	1224	3.86/s	215ms	3.9 (1-14)
PR#500 (24164b8d)	never pause	yes	50ms	no	5.3 min	1753	5.55/s	35ms	5.6 (1-7)

Column meaning:

• "Sending method" is how the hub was told to send updates: pausing in between each one, or never pausing at all.
• "Reads while waiting" is whether the hub actively checked for incoming data, instead of just being ready to receive but never checking.
• "Speed" is how many updates per second actually arrived at the listener.
• "Duration" The time that data was seen on the sniffer program. All test lasted at least 5 minutes.
• "Avg repeats/update" is how many times each update was repeated in a row on average, since the hub normally repeats the same update several times before moving to the next one.

No malformed (unreadable) packets were seen in any of the 13 tests on this firmware, including the long one below. The earlier firmware versions had 1 such packet in the tests.

All tests lasted at least 5 minutes. On the earlier firmware versions, two "not connected" tests stopped sending data after only a few seconds even though the test kept running for the full 5 minutes; on PR#500 firmware, the same two tests ran the full 5 minutes with data the whole time.

The long test

One extra test ran for about 32 minutes: sending method "pause between updates", reading while waiting, 50ms startup wait, not connected to a PC (the same settings as one of the rows above), just left running much longer to check whether the speed holds up over time.

Cut into 5-minute chunks, the speed per chunk was: 5.93, 5.68, 5.76, 6.05, 5.84, 5.73, then 2.46 for the last partial chunk.

The gap between one group of repeated updates and the next never went above 1 second anywhere in the whole 32 minutes. On the earlier firmware, a similar long test fluctuated between almost nothing and near-normal speed within the same run, with gaps up to a minute long. This one did not do that: it stayed steady the whole time.

Speed at a glance

Same numbers as the "Speed" column, as bars, so the difference is easier to see. Each chart uses its own scale (PC-connected speeds are much higher than not-connected ones, so putting them on the same scale would make the not-connected bars too small to read).

PC connected, same scale (0 to 25.80 updates/sec):

4.0.1   pause poll=no  settle= 0ms |  3.76/s #######
4.1.0b2 pause poll=no  settle= 0ms |  4.43/s #########
PR#500  pause poll=no  settle= 0ms |  4.62/s #########

4.0.1   pause poll=yes settle= 0ms |  4.08/s ########
4.1.0b2 pause poll=yes settle= 0ms |  4.55/s #########
PR#500  pause poll=yes settle= 0ms |  4.40/s #########

4.0.1   pause poll=yes settle=50ms |  3.34/s ######
4.1.0b2 pause poll=yes settle=50ms |  4.59/s #########
PR#500  pause poll=yes settle=50ms |  4.57/s #########

4.0.1   never poll=no  settle= 0ms | 21.85/s ##########################################
4.1.0b2 never poll=no  settle= 0ms | 20.29/s #######################################
PR#500  never poll=no  settle= 0ms | 24.01/s ###############################################

4.0.1   never poll=yes settle= 0ms | 23.51/s ##############################################
4.1.0b2 never poll=yes settle= 0ms | 19.94/s #######################################
PR#500  never poll=yes settle= 0ms | 25.80/s ##################################################

4.0.1   never poll=yes settle=50ms | 18.80/s ####################################
4.1.0b2 never poll=yes settle=50ms | 19.87/s #######################################
PR#500  never poll=yes settle=50ms | 24.90/s ################################################

Not connected (no-PC), same scale (0 to 5.89 updates/sec):

4.0.1   pause poll=no  settle= 0ms |  1.23/s ##########
4.1.0b2 pause poll=no  settle= 0ms |  1.28/s ###########
PR#500  pause poll=no  settle= 0ms |  5.35/s #############################################

4.0.1   pause poll=yes settle= 0ms |  0.65/s ######
4.1.0b2 pause poll=yes settle= 0ms |  0.75/s ######
PR#500  pause poll=yes settle= 0ms |  5.67/s ################################################

4.0.1   pause poll=yes settle=50ms |  0.64/s #####
4.1.0b2 pause poll=yes settle=50ms |  0.71/s ######
PR#500  pause poll=yes settle=50ms |  5.86/s ##################################################

4.0.1   never poll=no  settle= 0ms |  0.36/s ###
4.1.0b2 never poll=no  settle= 0ms |  0.35/s ###
PR#500  never poll=no  settle= 0ms |  5.69/s ################################################

4.0.1   never poll=yes settle= 0ms |  3.50/s ##############################
4.1.0b2 never poll=yes settle= 0ms |  0.79/s #######
PR#500  never poll=yes settle= 0ms |  5.89/s ##################################################

4.0.1   never poll=yes settle=50ms |  3.50/s ##############################
4.1.0b2 never poll=yes settle=50ms |  3.86/s #################################
PR#500  never poll=yes settle=50ms |  5.55/s ###############################################

Conclusion

• The fix works. Not-connected speed went from a range of about 0.35 to 3.9 updates per second (and sometimes dying almost completely) up to a steady 5.3 to 5.9 updates per second across every test and stayed steady for the full 32 minutes of the long test, with no long silent stretches anywhere.
• The "pause between updates" sending method, which used to be slow even while connected to a PC, is still somewhat slower than "never pause" while connected - that separate weak spot was not part of this fix and is still there.
• No malformed packets showed up anywhere in this round of testing, including the 32-minute run, versus one earlier on the older firmware.
• Not-connected speed is now close to, though still a bit below, connected speed for the "never pause" method (about 5.6-5.9 versus 24-26 updates per second). There is still a real gap between connected and not-connected, just a much smaller one than before.

[dlech]

I updated pybricks/pybricks-micropython#500 with some new parameters to test and also rebased it on current master which should fix the stdio issues on the cityhub as well.

[BertLindeman]

on it. Thanks

[toyotafj40]

Dear All,
Here are extracts of code that I am using for my project:

• Sniffer (runs on esp32 with BLE)
• Heartbeat sending Tx packets every 2 seconds (runs on esp32 with BLE)
• Hub receive/response (runs on CityHub as BLERadioTest.py)

Packet_Capture.cpp

Heartbeat.cpp

BLERadioTest.py

As soon as Heartbeat starts, it polls the CityHub, which broadcasts responses for each valid received group of packets.

The sniffer sees all the 12-Byte packets from Channel 102 (0x66) and 119 (0x77)

Hub Receive
    94mS   Channel 102: 97 03 66 00 C7 E0 48 03 02 04 09 56 
   353mS   Channel 119: 97 03 77 00 C8 60 48 03 02 B4 6F 44 
Hub Send

97 03 = Manf Code
66/77 = Channel
00 = Header Marker
C7/C8 = Tuple Type = Send or Receive
plus 7 data bytes in the tuple

For the Hub BLE Radio, timers are Stopwatch-based, to minimise the load on the BLE chip and not running in the main loop. 'observe' occurs every 100ms and 'broadcast' STOP occurs 500ms after Transmit begins. This actually provides non-blocking and allows receive of other 'speed' commands from the remote control.

The main reason to stop the broadcast is the need to share the response channel with other hubs.

[BertLindeman]

Pybricks BLE sniffer results - PR#500#2 (319f5ffc7)

Generated from sniffer_PR#500_2_log.zip (12 log files parsed).

Results

Sending method	Reads while waiting	Startup wait	PC connected	Duration	Packets	Speed	Avg repeat gap	Avg repeats/update
pause between updates	no	0ms	yes	5.2 min	1150	3.65/s	47ms	3.7 (1-7)
pause between updates	no	0ms	no	5.1 min	684	2.23/s	66ms	2.3 (1-5)
pause between updates	yes	0ms	yes	5.0 min	1029	3.44/s	45ms	3.5 (1-7)
pause between updates	yes	0ms	no	5.2 min	765	2.45/s	63ms	2.5 (1-5)
pause between updates	yes	50ms	yes	5.0 min	1086	3.61/s	46ms	3.6 (1-7)
pause between updates	yes	50ms	no	5.2 min	798	2.54/s	63ms	2.6 (1-5)
never pause	no	0ms	yes	5.0 min	5562	18.44/s	53ms	18.5 (11-26)
never pause	no	0ms	no	5.0 min	3729	12.31/s	79ms	12.3 (5-19)
never pause	yes	0ms	yes	5.2 min	6632	21.36/s	46ms	21.5 (11-29)
never pause	yes	0ms	no	5.2 min	3962	12.74/s	77ms	12.8 (7-20)
never pause	yes	50ms	yes	5.4 min	6423	19.98/s	49ms	20.1 (12-31)
never pause	yes	50ms	no	5.2 min	4060	12.96/s	75ms	13.0 (7-19)

Malformed (undecodable) packets seen: 0 while connected, 0 while not connected.

Speed at a glance

Tests indicated with PR#500#2 is githash 319f5ffc7

PC connected:

4.0.1    pause poll=no  settle= 0ms |  3.76/s #######
4.1.0b2  pause poll=no  settle= 0ms |  4.43/s #########
PR#500   pause poll=no  settle= 0ms |  4.62/s #########
PR#500#2 pause poll=no  settle= 0ms |  3.65/s #######

4.0.1    pause poll=yes settle= 0ms |  4.08/s ########
4.1.0b2  pause poll=yes settle= 0ms |  4.55/s #########
PR#500   pause poll=yes settle= 0ms |  4.40/s #########
PR#500#2 pause poll=yes settle= 0ms |  3.44/s ######

4.0.1    pause poll=yes settle=50ms |  3.34/s ######
4.1.0b2  pause poll=yes settle=50ms |  4.59/s #########
PR#500   pause poll=yes settle=50ms |  4.57/s #########
PR#500#2 pause poll=yes settle=50ms |  3.61/s #######

4.0.1    never poll=no  settle= 0ms | 21.85/s ##########################################
4.1.0b2  never poll=no  settle= 0ms | 20.29/s #######################################
PR#500   never poll=no  settle= 0ms | 24.01/s ###############################################
PR#500#2 never poll=no  settle= 0ms | 18.44/s ##################################

4.0.1    never poll=yes settle= 0ms | 23.51/s ##############################################
4.1.0b2  never poll=yes settle= 0ms | 19.94/s #######################################
PR#500   never poll=yes settle= 0ms | 25.80/s ##################################################
PR#500#2 never poll=yes settle= 0ms | 21.36/s #########################################

4.0.1    never poll=yes settle=50ms | 18.80/s ####################################
4.1.0b2  never poll=yes settle=50ms | 19.87/s #######################################
PR#500   never poll=yes settle=50ms | 24.90/s ################################################
PR#500#2 never poll=yes settle=50ms | 19.98/s #######################################

Not connected:

4.0.1    pause poll=no  settle= 0ms |  1.23/s ##########
4.1.0b2  pause poll=no  settle= 0ms |  1.28/s ###########
PR#500   pause poll=no  settle= 0ms |  5.35/s #############################################
PR#500#2 pause poll=no  settle= 0ms |  2.23/s ####################

4.0.1    pause poll=yes settle= 0ms |  0.65/s ######
4.1.0b2  pause poll=yes settle= 0ms |  0.75/s ######
PR#500   pause poll=yes settle= 0ms |  5.67/s ################################################
PR#500#2 pause poll=yes settle= 0ms |  2.45/s #####################

4.0.1    pause poll=yes settle=50ms |  0.64/s #####
4.1.0b2  pause poll=yes settle=50ms |  0.71/s ######
PR#500   pause poll=yes settle=50ms |  5.86/s ##################################################
PR#500#2 pause poll=yes settle=50ms |  2.54/s ######################

4.0.1    never poll=no  settle= 0ms |  0.36/s ###
4.1.0b2  never poll=no  settle= 0ms |  0.35/s ###
PR#500   never poll=no  settle= 0ms |  5.69/s ################################################
PR#500#2 never poll=no  settle= 0ms | 12.31/s ####################################################################################################

4.0.1    never poll=yes settle= 0ms |  3.50/s ##############################
4.1.0b2  never poll=yes settle= 0ms |  0.79/s #######
PR#500   never poll=yes settle= 0ms |  5.89/s ##################################################
PR#500#2 never poll=yes settle= 0ms | 12.74/s ###################################################################################################

4.0.1    never poll=yes settle=50ms |  3.50/s ##############################
4.1.0b2  never poll=yes settle=50ms |  3.86/s #################################
PR#500   never poll=yes settle=50ms |  5.55/s ###############################################
PR#500#2 never poll=yes settle=50ms | 12.96/s #########################################################################################################################

[dlech]

What is the pause for?

When connected, is it counting only advertisement packets or all packets?

[BertLindeman]

What is the pause for?

To see if the pause makes "room"

When connected, is it counting only advertisement packets or all packets?

All adverticements with LEGO manufactor id.
Connected or not connected.

[dlech]

OK, I think I understand well enough what is going on now.

And I think we should do some more tuning, but it will need a modified experiment.

Bert has just been looking at advertisements, but we need to balance time for all of the different things.

Apparently, we had all of the hubs set to observe all of the time when observing is enabled (and not a connection in the city/technic hub case). So this is why the advertisement rate was so low.

For most of the hubs, we have the advertisement rate to 25ms which means that it tries to advertise every 25 to 35ms (there is a random 0-10ms added on always to prevent aliasing issues - that's just how BLE works and can't be adjusted).

In the two commits of the pull request I made, the observe is set to a 50% duty cycle so that it can observe half the time and broadcast half the time. The first attempt, the observe window (and therefore broadcast window) was 20ms, which was smaller that the advertisement interval, so even when not observing, the advertisement might not have been within that window and got dropped. The second attempt has a 35ms window, so an advertisement pretty much always happens. That is why we saw the ~12.5/s rate (disconnected) - it is a bit less than 1/2 of the ~28/s baseline that was measured.

For the connected case, on city/technic hubs, there is actually separate set of interval/window parameters that I didn't change yet. They are set to observe all of the time too, but apparently the connection trumps the observing and the advertisement apparently piggy-backs on the connection. So this is why we never saw a change in connected numbers with the pull request changes. However, the fact that it is advertising at ~22/s compared to the ~28/s baseline means that it is advertising almost all of the time and never observing. So this explains why observing doesn't work well while connected on these hubs.

We should be able to tweak things though to make more time for observing. We can reduce the time slot used by the connection. This will make stdio slower but observing would work better while connected.

For the experiment, we probably need to make a special firmware that logs the timestamp of every advertisement received from another hub that is broadcasting. And also use a sniffer to see when it is advertising.

And we would need to do all of the combinations.

Hub A = received advertisements recorded by firmware
Hub B = emitted advertisements recorded by sniffer

Hub A	Hub B
only observing	only broadcasting
only observing	broadcasting while connected
only observing	broadcasting and observing
only observing	broadcasting and observing and connected
broadcasting and observing	only broadcasting
broadcasting and observing	broadcasting while connected
broadcasting and observing	broadcasting and observing
broadcasting and observing	broadcasting and observing and connected
observing while connected	only broadcasting
observing while connected	broadcasting while connected
observing while connected	broadcasting and observing
observing while connected	broadcasting and observing and connected
broadcasting and observing and connected	only broadcasting
broadcasting and observing and connected	broadcasting while connected
broadcasting and observing and connected	broadcasting and observing
broadcasting and observing and connected	broadcasting and observing and connected

Maybe we could use sensors to coordinate between hubs to go through the observing/broadcasting combinations, then we would only have to run two tests, the connected and disconnected.