summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorJérémy Dufour2011-01-06 16:42:28 +0100
committerJérémy Dufour2011-01-17 14:25:31 +0100
commit05588cb2a5611a82640a8880d7feb1f05e19948a (patch)
treef6d9c7b4e3440df7e3faa55143e11c6cf0b8bf42
parent70e1c9bdb36a44caec27bce3fee72e104007a6a8 (diff)
cesar/ce/rx: improve trace of ce rx, closes #2199
This commit includes: - rewrite of some traces for better understanding, - support of timestamps, - new traces to detect the reason for making the ce restart.
-rw-r--r--cesar/ce/rx/bitloading/fsm/src/fsm.c5
-rw-r--r--cesar/ce/rx/bitloading/src/common.c39
-rw-r--r--cesar/ce/rx/bitloading/src/transition.c14
-rw-r--r--cesar/ce/rx/inc/trace.h15
-rw-r--r--cesar/ce/rx/src/measure.c4
-rw-r--r--cesar/ce/rx/src/trace.c55
6 files changed, 83 insertions, 49 deletions
diff --git a/cesar/ce/rx/bitloading/fsm/src/fsm.c b/cesar/ce/rx/bitloading/fsm/src/fsm.c
index ae24d369d2..169e411d49 100644
--- a/cesar/ce/rx/bitloading/fsm/src/fsm.c
+++ b/cesar/ce/rx/bitloading/fsm/src/fsm.c
@@ -29,8 +29,6 @@ ce_rx_bl_fsm_handle_event (ce_rx_t *ce_rx, sta_t *sta, ce_rx_bl_fsm_event_type_t
dbg_assert (fsm < CE_RX_BL_FSM_STATE_NB);
dbg_assert (e < CE_RX_BL_FSM_EVENT_TYPE_NB);
- CE_RX_TRACE_VERBOSE (FSM_HANDLING_EVENT, fsm, e);
-
/* Get transition. */
ce_rx_bl_fsm_transition_t tr = ce_rx_bl_fsm_transition_table[fsm][e];
/* A non managed event is an error. */
@@ -41,7 +39,8 @@ ce_rx_bl_fsm_handle_event (ce_rx_t *ce_rx, sta_t *sta, ce_rx_bl_fsm_event_type_t
dbg_assert (((br >> 8) & 0xff) == e);
sta->ce_rx_bt.fsm = br & 0xff;
- CE_RX_TRACE_VERBOSE (FSM_FROM_TO, fsm, e, sta->ce_rx_bt.fsm);
+ if (fsm != sta->ce_rx_bt.fsm)
+ CE_RX_TRACE (FSM_FROM_TO, sta->tei, fsm, e, sta->ce_rx_bt.fsm);
ce_debug_gpio_event
(CE_DEBUG_GPIO_EVENT_CE_RX_BL_FSM_IDLE + sta->ce_rx_bt.fsm, true);
ce_debug_gpio_event
diff --git a/cesar/ce/rx/bitloading/src/common.c b/cesar/ce/rx/bitloading/src/common.c
index 1a6fef5816..0b9c933b63 100644
--- a/cesar/ce/rx/bitloading/src/common.c
+++ b/cesar/ce/rx/bitloading/src/common.c
@@ -32,27 +32,37 @@ ce_rx_bl_start_bl (ce_rx_t *ce_rx, sta_t *sta, tonemask_info_t *ts)
/* Not using ts directly. */
/* Not using ce_rx directly. */
- CE_RX_TRACE (BL_INITIAL);
+ CE_RX_TRACE (BL_INITIAL, sta->tei);
ce_debug_gpio_event (CE_DEBUG_GPIO_EVENT_CE_RX_BL_WORKING, true);
/* Compute initial tone map. */
tonemap_t *initial_tm = ce_rx_bl_initial (ts, &sta->ce_rx_bt);
- uint i;
-#if CONFIG_TRACE
/* Dump tone map in trace. */
- if (initial_tm != NULL)
- for (i = 0; i < PHY_CARRIER_NB - 8; i += 8)
+ if (CONFIG_TRACE)
+ {
+ dbg_assert (ts);
+#define OFFSET 2
+ int mod_count[OFFSET + CE_MOD_COUNT];
+ uint m;
+ /* Initialize. */
+ mod_count[0] = phy_date ();
+ mod_count[1] = sta->tei;
+ for (m = OFFSET; m < COUNT (mod_count); m++)
+ mod_count[m] = 0;
+ /* Count. */
+ if (initial_tm)
{
- u32 tm_words[4];
- uint j = 0;
- for (j = 0; j < 4; j++)
- tm_words[j] =
- *tonemap_get_tone_word (initial_tm, i + j * 2);
- CE_RX_TRACE_VERBOSE (TONEMAP_INITIAL, tm_words[0], tm_words[1],
- tm_words[2], tm_words[3]);
+ TONEMAP_READ_BEGIN (initial_tm, ts->tonemask, m)
+ {
+ mod_count[m + OFFSET]++;
+ }
+ TONEMAP_READ_END;
}
-#endif
+ /* Trace result. */
+ CE_RX_TRACE_N (TONEMAP, mod_count, COUNT (mod_count));
+#undef OFFSET
+ }
u8 tmi;
/* Compare with ROBO. */
@@ -78,12 +88,13 @@ ce_rx_bl_start_bl (ce_rx_t *ce_rx, sta_t *sta, tonemask_info_t *ts)
ce_rx_bl_ber_sliding_mean_update
(&sta->ce_rx_bt, ce_rx_bl_ber_pt_robo (ts->carrier_nb));
/* Trace it. */
- CE_RX_TRACE (INITIAL_WORSE_THAN_ROBO);
+ CE_RX_TRACE (INITIAL_WORSE_THAN_ROBO, sta->tei);
}
sta->rx_tonemaps->default_tmi = tmi;
ce_rx_cp_send_mme_new_tone_map
(ce_rx, sta, TONEMAP_INDEX_IS_NEGOTIATED (tmi) ? tmi : 0, 0, true);
/* Store next time the CE can restart. */
+ uint i;
for (i = 0; i < COUNT (ce_rx_bl_min_time_between_ce_restart_ms); i++)
sta->ce_rx_bt.next_date_min_for_restart_rtc_date[i]
= cyg_current_time ()
diff --git a/cesar/ce/rx/bitloading/src/transition.c b/cesar/ce/rx/bitloading/src/transition.c
index e7a9b5de06..05c3260243 100644
--- a/cesar/ce/rx/bitloading/src/transition.c
+++ b/cesar/ce/rx/bitloading/src/transition.c
@@ -99,8 +99,6 @@ ce_rx_bl__common__restart_ce_rx (ce_rx_t *ce_rx, sta_t *sta)
sta->ce_rx_bt.high_pb_error_rate_frame_counter = 0;
/* Reset BER sliding means. */
ce_rx_bl_ber_sliding_mean_reset (&sta->ce_rx_bt);
-
- CE_RX_TRACE (RESTART_CE, sta->tei);
}
/**
@@ -230,6 +228,7 @@ ce_rx_bl__TRACKING__measure_received (ce_rx_t *ce_rx, sta_t *sta,
ce_debug_gpio_event
(CE_DEBUG_GPIO_EVENT_CE_RX_BL_MEASURE_SOUND, true);
/* Restart CE in RX. */
+ CE_RX_TRACE (RESTART_FORCED, sta->tei);
ce_rx_bl__common__restart_ce_rx (ce_rx, sta);
/* Initialize sum of NSR. */
ce_rx_bl_nsr_sum_init (&sta->ce_rx_bt, measure->chan_data,
@@ -264,9 +263,11 @@ ce_rx_bl__TRACKING__measure_received (ce_rx_t *ce_rx, sta_t *sta,
{
/* Increase frame counter. */
sta->ce_rx_bt.high_pb_error_rate_frame_counter++;
- CE_RX_TRACE (PB_ERR_RATE_HIGH, sta->tei,
- measure->false_pb_count, measure->total_pb_count,
- sta->ce_rx_bt.high_pb_error_rate_frame_counter);
+ CE_RX_TRACE_VERBOSE
+ (PB_ERR_RATE_HIGH, sta->tei,
+ measure->rx_params.tmi_av, measure->false_pb_count,
+ measure->total_pb_count,
+ sta->ce_rx_bt.high_pb_error_rate_frame_counter);
/* Enough frame in this case and not too soon? */
if ((sta->ce_rx_bt.high_pb_error_rate_frame_counter
>= ce_rx_bl_min_frame_with_high_pb_err_rate_)
@@ -276,6 +277,8 @@ ce_rx_bl__TRACKING__measure_received (ce_rx_t *ce_rx, sta_t *sta,
{
ce_debug_gpio_event
(CE_DEBUG_GPIO_EVENT_CE_RX_BL_MEASURE_DATA_HIGH_PB_ERROR_RATE, true);
+ CE_RX_TRACE (RESTART_PB_ERR, sta->tei,
+ sta->ce_rx_bt.high_pb_error_rate_frame_counter);
/* Restart CE. */
ce_rx_bl__common__restart_ce (ce_rx, sta);
@@ -329,6 +332,7 @@ ce_rx_bl__TRACKING__measure_received (ce_rx_t *ce_rx, sta_t *sta,
{
ce_debug_gpio_event
(CE_DEBUG_GPIO_EVENT_CE_RX_BL_MEASURE_DATA_BER_LOW, true);
+ CE_RX_TRACE (RESTART_BER, sta->tei);
/* Restart CE. */
ce_rx_bl__common__restart_ce (ce_rx, sta);
return ce_rx_bl_fsm_next_branch (TRACKING,
diff --git a/cesar/ce/rx/inc/trace.h b/cesar/ce/rx/inc/trace.h
index 484ca2feaf..d418596b9c 100644
--- a/cesar/ce/rx/inc/trace.h
+++ b/cesar/ce/rx/inc/trace.h
@@ -20,10 +20,14 @@
* Shortcut for tracing inside CE RX.
*/
#define CE_RX_TRACE(id, args...) \
- TRACE_SHORT (CE_RX_TRACE_, &ce_rx->trace, id, ## args)
+ TRACE_SHORT (CE_RX_TRACE_, &ce_rx->trace, id, phy_date (), ## args)
+
+#define CE_RX_TRACE_N(id, args, nb_args) \
+ TRACE_N_SHORT (CE_RX_TRACE_, &ce_rx->trace, id, args, nb_args)
#define CE_RX_TRACE_VERBOSE(id, args...) \
- TRACE_FAST_SHORT (CE_RX_TRACE_, &ce_rx->trace_verbose, id, ## args)
+ TRACE_FAST_SHORT (CE_RX_TRACE_, &ce_rx->trace_verbose, id, phy_date (), \
+ ## args)
#if CONFIG_TRACE
@@ -37,11 +41,12 @@ enum
CE_RX_TRACE_SEND_TONEMAP,
CE_RX_TRACE_SEND_TONEMAP_REFRESH,
CE_RX_TRACE_FSM_FROM_TO,
- CE_RX_TRACE_FSM_HANDLING_EVENT,
- CE_RX_TRACE_TONEMAP_INITIAL,
+ CE_RX_TRACE_TONEMAP,
CE_RX_TRACE_INITIAL_WORSE_THAN_ROBO,
- CE_RX_TRACE_RESTART_CE,
+ CE_RX_TRACE_RESTART_FORCED,
CE_RX_TRACE_PB_ERR_RATE_HIGH,
+ CE_RX_TRACE_RESTART_PB_ERR,
+ CE_RX_TRACE_RESTART_BER,
};
BEGIN_DECLS
diff --git a/cesar/ce/rx/src/measure.c b/cesar/ce/rx/src/measure.c
index 3bca62ac35..d960a3c6de 100644
--- a/cesar/ce/rx/src/measure.c
+++ b/cesar/ce/rx/src/measure.c
@@ -64,7 +64,9 @@ ce_rx_measure_sar_cb (void *data, pbproc_rx_params_t *rx_params,
< CE_RX_MEASURE_MBOX_MAX_SIZE))
{
/* Trace it. */
- CE_RX_TRACE_VERBOSE (SAR_CB, rx_params->tei, chan_data_count, total_pb_count);
+ CE_RX_TRACE_VERBOSE (SAR_CB, rx_params->tei, rx_params->tmi_av,
+ chan_data_count, total_pb_count,
+ rx_params->sound, rx_params->sound_complete);
/* Allocate a measure. */
ce_rx_measure_mbox_t *measure = slab_alloc (&ce_rx->measure_cache);
diff --git a/cesar/ce/rx/src/trace.c b/cesar/ce/rx/src/trace.c
index 148e782239..a8ffa94f48 100644
--- a/cesar/ce/rx/src/trace.c
+++ b/cesar/ce/rx/src/trace.c
@@ -68,27 +68,40 @@ ce_rx_trace_init (ce_rx_t *ctx)
static const trace_event_id_t event_ids[] =
{
TRACE_EVENT (CE_RX_TRACE_INIT, "init"),
- TRACE_EVENT (CE_RX_TRACE_UNINIT, "uninit"),
- TRACE_EVENT (CE_RX_TRACE_MEASURE_HANDLING, "Handling measure for "
- "TEI %d on TMI %d: CD = %d & PBs = %d (Si = %d, "
- "SC = %d)"),
- TRACE_EVENT (CE_RX_TRACE_SAR_CB, "Callback from SAR for TEI %d: "
- "CD = %d & PBM = %d"),
- TRACE_EVENT (CE_RX_TRACE_BL_INITIAL, "Starting initial bit-loading"),
- TRACE_EVENT (CE_RX_TRACE_SEND_TONEMAP, "Sending tone map to TEI %d "
- "(TMI: new %d - old %d, initial_ce : %d)"),
- TRACE_EVENT (CE_RX_TRACE_SEND_TONEMAP_REFRESH,
- "Sending tone map refresh list to TEI %d"),
- TRACE_EVENT (CE_RX_TRACE_FSM_FROM_TO,
- "FSM: %S == %E ==> %S"),
- TRACE_EVENT (CE_RX_TRACE_FSM_HANDLING_EVENT,
- "FSM: %S == %E ==..."),
- TRACE_EVENT (CE_RX_TRACE_TONEMAP_INITIAL, "Tone map initial : %x %x %x %x"),
- TRACE_EVENT (CE_RX_TRACE_INITIAL_WORSE_THAN_ROBO, "Using ROBO rather "
- "than CE generated tone map"),
- TRACE_EVENT (CE_RX_TRACE_RESTART_CE, "Restart CE for TEI %d"),
- TRACE_EVENT (CE_RX_TRACE_PB_ERR_RATE_HIGH, "PB Error Rate high (for "
- "%d, %d / %d since %d frames)"),
+ TRACE_EVENT (CE_RX_TRACE_UNINIT, "uninit", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_MEASURE_HANDLING, "tei %d: "
+ "handling measure: tmi=%d, channel_data=%d, "
+ "pb_count=%d, sound=%d, sound_complete=%d",
+ TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_SAR_CB, "tei %d: "
+ "[sar] enqueue measure: tmi=%d, channel_data=%d, "
+ "pb_count=%d, sound=%d, sound_complete=%d",
+ TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_BL_INITIAL, "tei %d: "
+ "initial bit-loading", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_SEND_TONEMAP, "tei %d: "
+ "send tm: new_tmi=%d, old_tmi=%d, initial_ce=%d",
+ TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_SEND_TONEMAP_REFRESH, "tei %d: "
+ "send tm refresh", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_FSM_FROM_TO, "tei %d: "
+ "[fsm] %S == %E ==> %S", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_TONEMAP, "tei %d: "
+ "tone map generated: %dx0, %dx1, %dx2, %dx3 "
+ "%dx4, %dx5, %dx6, %dx7", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_INITIAL_WORSE_THAN_ROBO, "tei %d: "
+ "ROBO is better", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_RESTART_FORCED, "tei %d: "
+ "forced restart of ce rx - sound received",
+ TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_PB_ERR_RATE_HIGH, "tei %d: "
+ "PBErrRate high: on tmi %d, %d false on %d total "
+ "since %d frames)", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_RESTART_PB_ERR, "tei %d: "
+ "restart PB error rate too high "
+ "(since %d frames)", TIMESTAMP),
+ TRACE_EVENT (CE_RX_TRACE_RESTART_BER, "tei %d: "
+ "restart BER low", TIMESTAMP),
};
dbg_assert (ctx);
trace_namespace_init (&namespace, event_ids, COUNT (event_ids));