In my previous post, we saw how to setup two CE devices and run a Bluetooth performance test. In this one, we'll see how to process and analyze the log file generated on the DUT device. I will use Excel to perform some calculations on the data and to display a graph.

The first step is to use pparse.exe (available in CETK) to convert the log file to a comma delimited format:

D:\temp>pparse -c perf_bluetooth_NOPLAT_ARMV4I_VER5_1_204.LOG
Logging to csv files...
Creating output file perf_bluetooth_ARMV4I_SmartPhone_VER5.1.204.csv
done!

Now open the .csv file in Excel. You will see this (I edited a bit to make shorter lines):

Bluetooth RFCOMM Connection Setup : (ms)              523     153
BT Data Xfer: Send BufSize = 16 bytes : (ms)        20003   18207
BT Data Xfer: Recv BufSize = 16 bytes : (ms)        54480   43345
BT Data Xfer: Send BufSize = 512 bytes : (ms)        4479    4725
BT Data Xfer: Recv BufSize = 512 bytes : (ms)        2848    2836
BT Data Xfer: Send BufSize = 1024 bytes : (ms)       4044    4318
BT Data Xfer: Recv BufSize = 1024 bytes : (ms)       2668    2806
BT Data Xfer: Send BufSize = 2048 bytes : (ms)       4168    4357
BT Data Xfer: Recv BufSize = 2048 bytes : (ms)       3055    4970
BT Data Xfer: Send BufSize = RANDOM bytes : (ms)     4195    4318
BT Data Xfer: Recv BufSize = RANDOM bytes : (ms)     2988    3004
Bluetooth RFCOMM Connection Teardown : (ms)            30       4

There is one row per basic operation. Each row contains multiple numeric values (one per iteration) where each numeric value is basically “the number of milliseconds it took to perform the operation in this iteration”. In this particular example, I ran 2 iterations, so we see 2 numeric columns in the log.

We can ignore the RFCOMM setup/teardown measurements for now because they are not relevant for throughput measurements.

How can we obtain results in kbps from this table? Let’s analyze the measurement for the first transfer operation, in the first iteration: “20003”. This number is telling us  the following: “it took 20003 milliseconds to perform the operation of sending 163480 bytes in chunks of 16 bytes”. We can now type the following formula in another cell:

throughput = (163840 *8 /1000)/(C2/1000) = 66 kbits / sec

Where:
(163840*8/1000) = total number of transferred kbits
C2 = Excel cell where “20003” is located (it may be different in your spreadsheet)
(C2/1000)= (20003 / 10000) = 20.003 = elapsed time in seconds

At this point you can use your favorite mechanism in Excel to copy this formula over and over until you generate another table where measurements will be in kbps. Here it is  (I also changed the operation names  for convenience):

SND_16     66   72
RCV_16     24   30
SND_512   293  277
RCV_512   460  462
SND_1024  324  304
RCV_1024  491  467
SND_2048  314  301
RCV_2048  429  264
SND_RND   312  304
RCV_RND   439  436

And to better see what’s going on, we can use the data from the table to create a graph:

The operations are on the horizontal axis, and each line in the graph (called “series” here) correspond to a column in the source table. We can observe the following things:

- Throughput on both send and receive is very low when a 16 byte buffer is used. Bad choice of packet size is actually a very common reason for low performance in networking components.
- Average throughput for normal cases is around 400kbps, as can be expected for a non-EDR Bluetooth module such as the one I used.
- In general, receive throughput appears to be higher than send. This is because in this case the DUT was the slave in the asymmetrical link, and forward rate is typically higher than reverse rate.
- The two iterations report very different measurements for RCV_2048. This may be a transient glitch caused by RF conditions, CPU usage, etc. As we run more iterations I expect all lines to be comparable.

The other interesting measurement in the Excel sheet is the connection setup/teardown time.  We can see that connection time for the first iteration is around 500 msec. and < 200 msec. for subsequent iterations. This  is because the first connection requires a baseband page and ACL link establishment, but the following ones reuse the established link. This data point is mostly informational for a transport driver developer, because nothing can be done at this level to improve it.

As a last comment, it’s worth mentioning that we can use the same data in Excel to calculate other performance metrics such as average throughput, standard deviation, etc.