WARP Project Forums - Wireless Open-Access Research Platform

Filtered Log Index:
         1 of Type NODE_INFO
    15,352 of Type RX_OFDM
         1 of Type TIME_INFO
       934 of Type TX_HIGH
     3,518 of Type TX_LOW
--------------------------
    19,806 total entries

Node Info:
  Node Type    : (AP/DCF)
  MAC Address  : 40:d8:55:04:23:8a
  Serial Number: W3-a-00422
  WLAN Exp Ver : 1.7.4

Experiment Started at: Mon May 14 16:22:17 2018


Example 1: Tx Information per Rate:
               Rate                            # Tx Pkts
                                                       CPU Low        Re-trans
6.0 Mbps (NONHT BPSK 1/2)                 213             180
9.0 Mbps (NONHT BPSK 3/4)                   0               0
12.0 Mbps (NONHT QPSK 1/2)                   0               0
18.0 Mbps (NONHT QPSK 3/4)                   0               0
24.0 Mbps (NONHT 16-QAM 1/2)                 0               0
36.0 Mbps (NONHT 16-QAM 3/4)                 0               0
48.0 Mbps (NONHT 64-QAM 2/3)                 0               0
54.0 Mbps (NONHT 64-QAM 3/4)                 0               0
6.5 Mbps (HTMF BPSK 1/2)                    0               0
13.0 Mbps (HTMF QPSK 1/2)                    0               0
19.5 Mbps (HTMF QPSK 3/4)                    0               0
26.0 Mbps (HTMF 16-QAM 1/2)                  0               0
39.0 Mbps (HTMF 16-QAM 3/4)                  0               0
52.0 Mbps (HTMF 64-QAM 2/3)                  0               0
58.5 Mbps (HTMF 64-QAM 3/4)                  0               0
65.0 Mbps (HTMF 64-QAM 5/6)                  0               0

Total Retransmissions: 2011
---------------------------------------------

The filter I use in my code is the same as the log_process_summarize.py, which is
log_index = log_util.filter_log_index(raw_log_index,
                                        include_only=['NODE_INFO', 'TIME_INFO', 'RX_OFDM', 'TX_HIGH', 'TX_LOW'],
                                        merge={'RX_OFDM': ['RX_OFDM', 'RX_OFDM_LTG'],                                             
                                                'TX_HIGH' : ['TX_HIGH', 'TX_HIGH_LTG'],
                                                'TX_LOW' : ['TX_LOW', 'TX_LOW_LTG']})

The above is the log_process_summarize.py result of the LTG sender's log file. The number of TX_LOW events is the same as my code output, and my output shows that it only contains the RTS and PROBE_RESP frames. While the TX_HIGH events do show that it had transmitted DATA frames.

And the Example 1 result seems weird, since the Total Retransmissions is not equal to the sum of the list.

I've got a simple fix. There were actually two problems in the DCF causing the behavior you were seeing. You can fix both with a single line of C code change. Change this line in wlan_mac_dcf.c from

// Send IPC message containing the details about this low-level transmission
wlan_mac_low_send_low_tx_details(pkt_buf, &low_tx_details);

to

// Set tx_has_started control variable back to 0 so low_tx_details can be
// re-evaluated with MPDU Tx information
tx_has_started = 0;

The reasons for this change aren't obvious at first glance and depend pretty heavily on the way CPU_HIGH and CPU_LOW work together to log TX_LOW events. CPU_HIGH expects to receive IPC messages from CPU_LOW on each transmission "attempt." When RTS/CTS isn't used, an "attempt" is simply a TX_LOW event of an MPDU. When RTS/CTS is used, an attempt can either be an RTS by itself (if no CTS is received) or an RTS+MPDU transmission (if a CTS is received). When CPU_HIGH receives an IPC message indicating than an attempt consisted of both an RTS and an MPDU, it creates the log entires for both TX_LOW events in the same context. The formal way to describe an "attempt" is that it is the sum of the SRC and LRC. See this page for details.

The error in the code previously was twofold:

1) The DCF was calling wlan_mac_low_send_low_tx_details() prematurely after sending an RTS while an ongoing MPDU transmission was active. This simply shouldn't have been there. If the DCF is sending an MPDU, the intent was to let CPU_HIGH know about the combination RTS+MPDU after the MPDU was done.
2) An internal variable, tx_has_started, prevented the DCF from updating the IPC message to CPU_HIGH from a RTS-only message type to an RTS+MPDU message type.

The end result is that an RTS+MPDU attempt actually resulted in 2 IPC messages both of which indicated RTS-only. That's why there were way too many RTS TX_LOW log entries and no MPDU TX_LOW log entries. The above one-liner will fix it and we will incorporate the fix into the next release. Thanks for letting us know.

Also, as a brief aside, the "log_process_summarize.py" example script is very confusing when applied to a log that contains RTS transmissions. Specifically, "Example 1" was written in such a way that an "attempt" was just an MPDU transmission. I think it even predated when we added the RTS/CTS functionality to the design. Because an RTS/MPDU "attempt" actually spans multiple MCS/PHY modes (i.e. one for the RTS and one for the MPDU), that table doesn't make any sense. I'd just ignore that example and do your own processing.

FYI, we just incorporated this fix (and only this fix) into a new 1.7.7 release. To anyone reading this thread, you can download the release here