Timing tool traces (ARMmbed#2401)

* Added FHSS timing tool traces

* Fixed TX done trace

* timing tool: use TIMING_TOOL_TRACES flag for traces

Author: Jarkko Paso

source/MAC/IEEE802_15_4/mac_pd_sap.c

@@ -36,6 +36,9 @@
 #include "MAC/IEEE802_15_4/mac_mcps_sap.h"
 #include "MAC/IEEE802_15_4/mac_cca_threshold.h"
 #include "MAC/rf_driver_storage.h"
+#include "ns_trace.h"
+
+#define TRACE_GROUP "mPDs"
 
 /* Define TX Timeot Period */
 // Hardcoded to 1200ms. Should be changed dynamic: (FHSS) channel retries needs longer timeout
@@ -373,6 +376,9 @@ static void  mac_sap_cca_fail_cb(protocol_interface_rf_mac_setup_s *rf_ptr, uint
 
 static void mac_sap_no_ack_cb(protocol_interface_rf_mac_setup_s *rf_ptr)
 {
+#ifdef TIMING_TOOL_TRACES
+    tr_info("%u no_ack", mac_mcps_sap_get_phy_timestamp(rf_ptr));
+#endif
     rf_ptr->macRfRadioTxActive = false;
     if (rf_ptr->mac_tx_retry < rf_ptr->mac_mlme_retry_max) {
         rf_ptr->mac_cca_retry = 0;
@@ -438,6 +444,9 @@ static int8_t mac_data_interface_tx_done_cb(protocol_interface_rf_mac_setup_s *r
         if (rf_ptr->mac_ack_tx_active) {
             //Accept direct non crypted acks and crypted only if neighbor is at list
             if (rf_ptr->ack_tx_possible) {
+#ifdef TIMING_TOOL_TRACES
+                tr_info("%u TX_start %u", mac_mcps_sap_get_phy_timestamp(rf_ptr), rf_ptr->mac_channel);
+#endif
                 return PHY_TX_ALLOWED;
             }
 
@@ -454,6 +463,9 @@ static int8_t mac_data_interface_tx_done_cb(protocol_interface_rf_mac_setup_s *r
         }
 
         if (mac_data_asynch_channel_switch(rf_ptr, rf_ptr->active_pd_data_request)) {
+#ifdef TIMING_TOOL_TRACES
+            tr_info("%u TX_start %u", mac_mcps_sap_get_phy_timestamp(rf_ptr), rf_ptr->mac_channel);
+#endif
             rf_ptr->active_pd_data_request->initial_tx_channel = rf_ptr->mac_channel;
             int8_t channel_cca_threshold = mac_cca_thr_get_dbm(rf_ptr, rf_ptr->mac_channel);
             if (CCA_FAILED_DBM != channel_cca_threshold) {
@@ -501,12 +513,17 @@ static int8_t mac_data_interface_tx_done_cb(protocol_interface_rf_mac_setup_s *r
                 return PHY_RESTART_CSMA;
             }
         }
-
+#ifdef TIMING_TOOL_TRACES
+        tr_info("%u TX_start %u", mac_mcps_sap_get_phy_timestamp(rf_ptr), rf_ptr->mac_channel);
+#endif
         return 0;
     }
 
     if (rf_ptr->mac_ack_tx_active) {
         mac_data_ack_tx_finish(rf_ptr);
+#ifdef TIMING_TOOL_TRACES
+        tr_info("%u TX_done", mac_mcps_sap_get_phy_timestamp(rf_ptr));
+#endif
         return 0;
     } else {
 
@@ -531,6 +548,11 @@ static int8_t mac_data_interface_tx_done_cb(protocol_interface_rf_mac_setup_s *r
              * PHY_LINK_TX_FAIL either happened during transmission or when waiting Ack -> we must use the CCA count given by PHY.
              */
             if ((cca_retry == 0) && (status != PHY_LINK_TX_FAIL)) {
+#ifdef TIMING_TOOL_TRACES
+                if (status != PHY_LINK_CCA_FAIL) {
+                    tr_info("%u TX_done", mac_mcps_sap_get_phy_timestamp(rf_ptr));
+                }
+#endif
                 cca_retry = 1;
             }
             rf_ptr->mac_tx_status.cca_cnt += cca_retry;
@@ -970,6 +992,10 @@ int8_t mac_pd_sap_data_cb(void *identifier, arm_phy_sap_msg_t *message)
         if (pd_data_ind->data_len < 3) {
             return -1;
         }
+#ifdef TIMING_TOOL_TRACES
+        tr_info("%u RX_start", mac_pd_sap_get_phy_rx_time(rf_ptr));
+        tr_info("%u RX_done", mac_mcps_sap_get_phy_timestamp(rf_ptr));
+#endif
         mac_cca_threshold_event_send(rf_ptr, rf_ptr->mac_channel, pd_data_ind->dbm);
         mac_fcf_sequence_t fcf_read;
         const uint8_t *ptr = mac_header_parse_fcf_dsn(&fcf_read, pd_data_ind->data_ptr);

source/Service_Libs/fhss/fhss_ws.c

@@ -343,13 +343,23 @@ static void fhss_broadcast_handler(const fhss_api_t *fhss_api, uint16_t delay)
 #ifdef FHSS_CHANNEL_DEBUG
         tr_info("%"PRIu32" UC %u", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api), fhss_structure->rx_channel);
 #endif /*FHSS_CHANNEL_DEBUG*/
+#ifdef TIMING_TOOL_TRACES
+        tr_info("%u UC_change %u", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api), next_channel);
+#endif
     }
     fhss_structure->callbacks.change_channel(fhss_structure->fhss_api, next_channel);
 #ifdef FHSS_CHANNEL_DEBUG_CBS
     if (fhss_bc_switch) {
         fhss_bc_switch();
     }
 #endif /*FHSS_CHANNEL_DEBUG_CBS*/
+#ifdef TIMING_TOOL_TRACES
+    if (fhss_structure->ws->is_on_bc_channel == true) {
+        tr_info("%u BC_start %u", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api), next_channel);
+    } else {
+        tr_info("%u BC_done", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api));
+    }
+#endif
 }
 
 static int own_floor(float value)
@@ -392,6 +402,9 @@ static void fhss_event_timer_cb(int8_t timer_id, uint16_t slots)
     }
     if (queue_size) {
         fhss_structure->callbacks.tx_poll(fhss_structure->fhss_api);
+#ifdef TIMING_TOOL_TRACES
+        tr_info("%u TX_poll", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api));
+#endif
     }
 }
 
@@ -517,6 +530,9 @@ static void fhss_ws_update_uc_channel_callback(fhss_structure_t *fhss_structure)
 #ifdef FHSS_CHANNEL_DEBUG
     tr_info("%"PRIu32" UC %u %u", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api), next_channel, fhss_structure->ws->uc_slot);
 #endif /*FHSS_CHANNEL_DEBUG*/
+#ifdef TIMING_TOOL_TRACES
+    tr_info("%u UC_change %u", fhss_structure->callbacks.read_timestamp(fhss_structure->fhss_api), next_channel);
+#endif
     fhss_structure->callbacks.change_channel(fhss_structure->fhss_api, next_channel);
 #ifdef FHSS_CHANNEL_DEBUG_CBS
     if (fhss_uc_switch) {