BLE performance analysis with pyshark

Output from BLE Analysis

When working on a Bluetooth Low-Energy (BLE) data connection the nRF Sniffer (firmware and Wireshark plugin) can be a helpful tool (see the “Getting started with nRF sniffer” section at the end of this post for some setup hints). You do need to buy some Nordic Semiconductor hardware but the low-cost nRF52840 Dongle works well for most circumstances in my experience and you can’t argue with a full solution for fifteen bucks or so. The Wireshark UI is also pretty good for deeply inspecting individual packets or short sequences but the snag comes when you have a ton of collected data and you want to track performance over a lot of BLE interactions such as negotiating Data-Length-Extension (DLE) / MTU size / physical layer speed or sequences of your own devising such as device command-response and file-transfer / firmware update. That’s where the python tools explained here can be valuable.

Analysis using pyshark

My goal was to provide some quick command-line tools that would analyze one or more BLE capture files and summarize information (including performance) from them. Furthermore, a way to run specific “tests” would be ideal as the system I’m working on implements a fairly complex protocol on top of BLE which has asynchronous command/response type semantics and handles file transfer, OTA update and the like.

Digging around on the internet I found a few possible solutions to automating log analysis. These included scapy and pyshark. I chose to look at pyshark because there are quite a few articles about using it in a simple fashion (e.g. Optimizing the Bluetooth Low Energy Service Discovery Process and pbctf 2021 Writeups) and that gave me a good starting point.

There are two alternatives when using pyshark “EK-mode” (which converts all packet information into python objects) and “original-mode” which leaves them as XML objects dumped out by the tshark program which pyshark uses to parse the capture file. I found “EK-mode” much easier to use and it is enabled by simply including the parameter “use_ek=True” when reading in a capture file. Installation of pyshark is covered in the (rather sparse) documentation

Some basic information on using pyshark is at the end of this post in the “Getting Started with pyshark” section.

Getting the BLE analysis tools

The tools described here are available in a GitHub repository. You can clone the repo with something like:

cd <to-a-folder-to-put-the-files>
git clone https://github.com/robdobsn/BLELogAnalysis

To use these tools you will need to install the required packages. To do this:

cd BLELogAnalysis
pip install -r requirements.txt

It is generally a good idea to use a python virtual environment to avoid cluttering up your main python installation with a lot of packages. There is a good explanation of doing this here.

You may need to use “python3 -m pip” instead of just “pip” in the above depending on your platform.

Basic BLE Capture Analysis

The first tool I will discuss is the BLELogAnalyzer.py program. This can be run from the command line using the following syntax:

python BLELogAnalyzer.py <capture-file-name>

Where <capture-file-name> is the name of a pcapng file or a folder containing pcapng files (in which case all capture files in the folder will be processed)

In addition you can include the following arguments:

  • –verbose … a lot of additional output will be produced including the contents of every data packet transferred
  • –config … allows an alternate JSON config file (there is one called config.json in the main folder and this will be used if an alternate is not specified) to be specified. The config JSON file contains the following sections:
    • uuids … a list of UUID values for services and characteristics along with a “friendly name” which will replace the UUID when it is found

On some platforms you will need to use python3 instead of python.

Example output from the BLELogAnalyzer is:

INFO: -------------- Asus C232N ricjs dash 1ms Rev5 v1.2.46 + 4th Attempt.pcapng --------------
INFO: IMPORTANT FEATURES DLE:YES 2M:NO CODED:NO 
INFO: DLE (Data Length Extension) TxMax 251 TxTime 2120 RxMax 251 RxTime 2120
INFO: RX MTU 512
INFO: CONNECTION Interval 6 (7.5ms) Latency 0 Timeout 1000
INFO: PHY PHY 1m CODED:NO
INFO: APPROX MAX THROUGHPUT 100.40 kBytes/s (3.0 packets per interval)
INFO: "Service Changed" WRITE_REQ Packets 1 Bytes 2
INFO: "RIC2_RSP" VALUE_IND Packets 665 Bytes 77879
INFO: "RIC2_CMD" WRITE_REQ Packets 200 Bytes 98100

The summary produced for each file includes the negotiated values for DLE, MTU, PHY and connection interval. A good description of what these terms mean can be found in this article on BLE throughput and this one. In addition the total number of packets (and bytes) transmitted and received using each of the BLE mechanisms is provided:

  • VALUE_IND … packets sent to the central using INDICATE semantics
  • VALUE_NOTIFY … packets sent to the central using NOTIFY semantics
  • WRITE_REQ … packets received from the central using REQUEST semantics
  • WRITE_CMD … packets received from the central using COMMAND semantics

An attempt is made to calculate the maximum throughput that should be obtainable on the link – using the calculations in the above referenced BLE throughput documents. However, these should be used cautiously as the calculation may be inaccurate due to:

  • an assumption that a maximum of 6 frames can be sent in a connection interval – this is implied to be true for Android but may no longer be valid – and it probably isn’t valid for iOS or other operating systems
  • an assumption that 2M PHY is around 1.7x faster than 1M PHY (see calculations in the above documents) – this might not be valid
  • other aspects that may affect throughput may be relevant but not included
  • my calculations may be wrong!

When the –verbose flag is used a much more detailed output is produced, for instance see the output below. In this view the advertising periods are shown (along with approximate advertising interval calculation). Furthermore all relevant PDU, LL and ATT message contents are shown included data values.

INFO: -------------- Asus C232N WebApp Rev5 v1.2.46 + 1st Attempt with extra 1s delay before upgrade .pcapng --------------
DEBUG: BLE device address: b8:d6:1a:bc:6e:96
DEBUG: 0.0 1-514 Advertising Interval 28ms ADV_IND 292 SCAN_REQ 119 SCAN_RESP 101 CONNECT_IND 1 ADV_SCAN_IND 1 ADV_EXT_IND 1 
DEBUG: 8.046 515 CONNECT_IND
DEBUG: 8.050 516 LL_FEATURE_REQ ENC CPRP EXTREJ SLVFEAT PING DLE PRIV SCANFILT (2M:NO) (CODED:NO)
DEBUG: 8.070 517 LL_FEATURE_REQ ENC CPRP EXTREJ SLVFEAT PING DLE PRIV SCANFILT (2M:NO) (CODED:NO)
DEBUG: 8.090 518 LL_FEATURE_REQ ENC CPRP EXTREJ SLVFEAT PING DLE PRIV SCANFILT (2M:NO) (CODED:NO)
DEBUG: 8.110 521 LL_FEATURE_RSP ENC CPRP EXTREJ SLVFEAT PING DLE PRIV SCANFILT (2M:NO) (CODED:NO)
DEBUG: 8.130 523 LL_FEATURE_RSP ENC CPRP EXTREJ SLVFEAT PING DLE PRIV SCANFILT (2M:NO) (CODED:NO)
DEBUG: 8.150 524 ATT_MTU_REQ CLIENT RX MTU 517
DEBUG: 8.170 527 ATT_MTU_RSP SERVER RX MTU 512
DEBUG: 8.190 528 ATT_READ_BY_TYPE_REQ Handle 1 - 65535
DEBUG: 8.210 531 ATT_READ_BY_TYPE_REQ Handle 1
DEBUG: 8.230 532 ATT_READ_BY_GROUP_TYPE_REQ Handle 1 - 65535
DEBUG: 8.250 535 ATT_READ_BY_GROUP_TYPE_RSP Service "Generic Access" Attribute "Primary Service"
DEBUG: 8.290 536 ATT_READ_BY_GROUP_TYPE_REQ Handle 10 - 65535
DEBUG: 8.310 539 ATT_READ_BY_GROUP_TYPE_RSP Service "Generic Attribute" Attribute "RIC2_SVC"(REVERSED)
DEBUG: 8.330 540 ATT_READ_BY_GROUP_TYPE_REQ Handle 1 - 65535
DEBUG: 8.350 543 ATT_READ_BY_GROUP_TYPE_REQ Handle 1
DEBUG: 8.370 544 ATT_READ_BY_TYPE_REQ Handle 1 - 65535
DEBUG: 8.390 547 ATT_READ_BY_TYPE_REQ Handle 1
DEBUG: 8.410 548 ATT_READ_BY_TYPE_REQ Handle 1 - 65535
DEBUG: 8.430 551 ATT_READ_BY_TYPE_RSP Service None Attribute None
DEBUG: 8.450 552 ATT_READ_BY_TYPE_REQ Handle 8 - 65535
DEBUG: 8.470 557 ATT_READ_BY_TYPE_RSP Service "RIC2_SVC" "RIC2_SVC" "RIC2_SVC" "RIC2_SVC"  Attribute "RIC2_CMD" "RIC2_CMD"
DEBUG: 8.490 558 ATT_READ_BY_TYPE_REQ Handle 14 - 65535
DEBUG: 8.510 561 ATT_READ_BY_TYPE_REQ Handle 14
DEBUG: 8.530 562 ATT_FIND_INFO_REQ Handle 15 - 65535
DEBUG: 8.550 565 ATT_FIND_INFO_RSP Handle 15
DEBUG: 8.570 566 ATT_FIND_INFO_REQ Handle 16 - 65535
DEBUG: 8.590 569 ATT_FIND_INFO_REQ Handle 16
DEBUG: 8.650 574 ATT_WRITE_REQ Handle 9 Service "Generic Attribute" Characteristic "Service Changed" Length 2 Data 0200
DEBUG: 8.670 577 ATT_WRITE_RSP Handle 9
DEBUG: 8.690 578 ATT_READ_REQ Handle 3
DEBUG: 8.710 581 ATT_READ_RSP Handle 3 Service "Generic Access" Characteristic "Device Name" No data
DEBUG: 8.730 582 ATT_READ_REQ Handle 5
DEBUG: 8.750 585 ATT_READ_RSP Handle 5 Service "Generic Access" Characteristic "Appearance" No data
DEBUG: 8.770 586 ATT_WRITE_REQ Handle 15 Service "RIC2_SVC" Characteristic "RIC2_RSP" No data
DEBUG: 8.790 589 ATT_WRITE_RSP Handle 15
DEBUG: 8.813 601 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042380000c23c0000447480001300c3fffe1a00e57c00000000017b0c0000d134000040010000000000002002020700cac0d3cae7
DEBUG: 8.851 608 ATT_WRITE_REQ Handle 12 Service "RIC2_SVC" Characteristic "RIC2_CMD" Length 48 Data e747020068777374617475732f737472737461743f66696c7465724279547970653d536d617274536572766f00c449e7
DEBUG: 8.901 647 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 450 Data e74742017b22726571223a2268777374617475732f737472737461743f66696c7465724279547970653d536d617274536572766f222c226877223a5b7b2261223a224c6566744869707c536d617274536572766f7c307c4c4869704d6f746f727c3130307c666666666666666666666666666666667c302e302e307c31227d2c7b2261223a224c65667454776973747c536d617274536572766f7c317c7c66666666666666667c7c302e302e307c30227d2c7b2261223a224c6566744b6e65657c536d617274536572766f7c327c7c66666666666666667c7c302e302e307c30227d2c7b2261223a2252696768744869707c536d617274536572766f7c337c7c66666666666666667c7c302e302e307c30227d2c7b2261223a22526967687454776973747c536d617274536572766f7c347c7c66666666666666667c7c302e302e307c30227d2c7b2261223a2252696768744b6e65657c536d617274536572766f7c357c7c66666666666666667c7c302e302e307c30227d2c7b2261223a224c65667441726d7c536d617274536572766f7c367c7c66666666666666667c7c302e302e307c30227d2c7b2261223a22526967687441726d7c536d617274536572766f
DEBUG: 8.904 655 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 86 Data 7c377c7c66666666666666667c7c302e302e307c30227d2c7b2261223a22457965737c536d617274536572766f7c387c7c66666666666666667c7c302e302e307c30227d5d2c2272736c74223a226f6b227d003090e7
DEBUG: 8.910 668 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042440000c2300000447480001300c3fffe1a00e57c000000000177480000d134000040010000000000002002020c00ca8308dfe7
DEBUG: 8.970 675 ATT_WRITE_REQ Handle 12 Service "RIC2_SVC" Characteristic "RIC2_CMD" Length 45 Data e748020068777374617475732f737472737461743f66696c7465724279547970653d52534164644f6e007be2e7
DEBUG: 9.012 686 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 75 Data e74842017b22726571223a2268777374617475732f737472737461743f66696c7465724279547970653d52534164644f6e222c226877223a5b5d2c2272736c74223a226f6b227d0071f1e7
DEBUG: 9.016 698 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042480000c21c00004475c000130092fffe1a00e57c000000000177480000d134000040010000000000002002020c00ca83371ae7
DEBUG: 9.070 704 LL_CONNECTION_PARAM_REQ Interval Min 6 (7.5ms) Max 6 (7.5ms) Latency 0 Timeout 1000
DEBUG: 9.070 705 ATT_WRITE_REQ Handle 12 Service "RIC2_SVC" Characteristic "RIC2_CMD" Length 47 Data e749020068777374617475732f737472737461743f66696c7465724279547970653d427573506978656c7300d3f0e7
DEBUG: 9.090 707 LL_CONNECTION_UPDATE_IND Interval 6 (7.5ms) Latency 0 Timeout 1000
DEBUG: 9.116 730 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 250 Data e74942017b22726571223a2268777374617475732f737472737461743f66696c7465724279547970653d427573506978656c73222c226877223a5b7b2261223a22427573506978656c73307c427573506978656c737c33397c42757350697831397c31303032303031337c7c302e302e307c31227d2c7b2261223a224c6566744c45446579657c427573506978656c737c33387c4c45446579657c31303032303031617c7c302e302e307c31227d2c7b2261223a2252696768744c45446579657c427573506978656c737c33377c4c45446579657c66666666666666667c7c302e302e307c31227d5d2c2272736c74223a226f6b227d003774e7
DEBUG: 9.120 742 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042300000c22000004476c0001300a5fffe1a00e57c000000000177480000d134000040010000000000002002020c00ca838f6ce7
DEBUG: 9.171 751 ATT_WRITE_REQ Handle 12 Service "RIC2_SVC" Characteristic "RIC2_CMD" Length 67 Data e74a020068777374617475732f737472737461743f66696c7465724279547970653d21536d617274536572766f2c52534164644f6e2c427573506978656c73006532e7
DEBUG: 9.218 780 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 346 Data e74a42017b22726571223a2268777374617475732f737472737461743f66696c7465724279547970653d21536d617274536572766f2c52534164644f6e2c427573506978656c73222c226877223a5b7b2261223a22494d55307c494d557c31397c4b58544a337c31303031313035377c7c302e302e307c31227d2c7b2261223a22417564696f4f75747c4932534f75747c34307c7c66666666666666667c7c302e302e307c31227d2c7b2261223a22526963427574746f6e307c4750494f7c33367c4750494f357c31303034303030357c7c302e302e307c31227d2c7b2261223a224675656c4761756765307c4675656c47617567657c33357c7c66666666666666667c7c302e302e307c30227d2c7b2261223a22506f7765724374726c7c506f7765724374726c7c33347c524943506f7765727c31303033303030307c7c302e302e307c31227d5d2c2272736c74223a226f6b227d0072c8e7
DEBUG: 9.222 792 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042300000c2440000447480001300c3fffe1a00e57c000000000177080000d134000040010000000000002002020c00cac345d0e7
DEBUG: 9.316 826 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042340000c2500000447480001300b3fffe1a00e57c000000000177080000d134000040010000000000002002020c00cac39500e7
DEBUG: 9.421 864 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f17900422c0000c238000044764000130011fffe1a00e57c000000000177080000d134000040010000000000002002020c00cac393efe7
DEBUG: 9.518 896 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042400000c224000044764000130011fffe1a00e57c000000000177080000d134000040010000000000002002020c00cac3b1f5e7
DEBUG: 9.627 934 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042480000c2280000447580001300c6fffe1a00e57c000000000177080000d134000040010000000000002002020c00cac30d4be7
DEBUG: 9.728 970 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042440000c2340000447540001300fefffe1a00e57c000000000177080000d134000040010000000000002002020c00cac3ee3ee7
DEBUG: 9.826 1006 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f1790042440000c2380000447580001300bafffe1a00e57c000000000177080000d134000040010000000000002002020c00cac370dbe7
DEBUG: 9.923 1042 ATT_HANDLE_VALUE_INDICATION Handle 14 Service "RIC2_SVC" Characteristic "RIC2_RSP" Length 124 Data e70080fffe3600c97800000000000080010000000000020000000000030000000000040000000000050000000000060000000000070000000000080000000000e3fffe0e00f17900423c0000c23000004475000013004afffe1a00e57c0

Getting started with pyshark

A simple example of using pyshark is the following program which dumps all packets in a file:

import pyshark
with pyshark.FileCapture("example.pcapng", use_ek=True) as cap:
    for pkt in cap:
        pkt.show()

The first packet output from this (with a BLE file) is:

Layer NORDIC_BLE
:       address: 
                resolved: False
        packet: 
                time: 320
                id: 2
                counter: 52920
        crcok: True
        flag: 
                reserved2: 0
                reserved7: 0
                reserved1: 0
        len: 10
        phy: 0
        board: 
                id: 22
        protover: 3
        flags: 1
        event: 
                counter: 0
        time: 3415185080
        plen: 49
        rssi: -26
        header: None
        channel: 39
Layer BTLE
:       access: 
                address: 2391391958
        crc: 6261915
        advertising: 
                address: b8:d6:1a:bc:6e:96
                header: 7680
                        ch: 
                                sel: False
                        rfu: 
                                4: 0
                                1: 0
                        pdu: 
                                type: 0
                        length: 30
                        randomized: 
                                tx: False
        length: 30

Getting started with nRF Sniffer

Getting the firmware installed isn’t too difficult but the Wireshark plugin can be a bit annoying as there is some older documentation and guides out there which suggest installation options that didn’t work for me. But with a bit of persistence it isn’t too hard to get running.

One thing that I’m used to when using Wireshark on an IP connection is filtering at the point of packet collection rather than in the UI. I generally do this by specifying the “host” IP address to be the address of the device I’m trying to debug. I would have expected the equivalent in BLE to be a specification of MAC address and it would certainly be convenient to reduce the volume of logged data in this way – but this doesn’t seem to be an option at the moment. So you just need to log everything the sniffer sniffs and then filter it later.

Filtering out devices other than the one you want in Wireshark also seems a bit odd. It seems you need to select a device to filter at the point when it is advertising. Which can be a pain if the device connects automatically or you want to investigate a session that is already connected. There’s probably a way to do this easily but I haven’t found it.