Commit f89fba91 authored by Aurelio Colosimo's avatar Aurelio Colosimo

diagnostic messages cleanup and fix

parent c2320d6a
...@@ -227,6 +227,12 @@ int minic_rx_frame(uint8_t *hdr, uint8_t *payload, uint32_t buf_size, struct hw_ ...@@ -227,6 +227,12 @@ int minic_rx_frame(uint8_t *hdr, uint8_t *payload, uint32_t buf_size, struct hw_
hwts->nsec = counter_r * 8; hwts->nsec = counter_r * 8;
hwts->valid = (dhdr & RXOOB_TS_INCORRECT) ? 0 : 1; hwts->valid = (dhdr & RXOOB_TS_INCORRECT) ? 0 : 1;
if (!hwts->valid) {
int k;
PP_VPRINTF("Warning: rx timestamp invalid - dhdr: ");
for (k = 0; k < 2; k++) PP_VPRINTF("%02x ", ((char*)&dhdr)[k]);
PP_VPRINTF("\n");
}
} }
n_recvd = (buf_size < payload_size ? buf_size : payload_size); n_recvd = (buf_size < payload_size ? buf_size : payload_size);
...@@ -321,6 +327,9 @@ int minic_tx_frame(uint8_t *hdr, uint8_t *payload, uint32_t size, struct hw_time ...@@ -321,6 +327,9 @@ int minic_tx_frame(uint8_t *hdr, uint8_t *payload, uint32_t size, struct hw_time
hwts->ahead = 0; hwts->ahead = 0;
hwts->nsec = counter_r * 8; hwts->nsec = counter_r * 8;
if (!ts_valid) {
PP_PRINTF("Warning: tx timestamp invalid\n");
}
// TRACE_DEV("minic_tx_frame [%d bytes] TS: %d.%d valid %d\n", size, hwts->utc, hwts->nsec, hwts->valid); // TRACE_DEV("minic_tx_frame [%d bytes] TS: %d.%d valid %d\n", size, hwts->utc, hwts->nsec, hwts->valid);
minic.tx_count++; minic.tx_count++;
......
...@@ -38,7 +38,6 @@ void pps_gen_init() ...@@ -38,7 +38,6 @@ void pps_gen_init()
void pps_gen_set(int32_t sec, int32_t nsec) void pps_gen_set(int32_t sec, int32_t nsec)
{ {
TRACE_DEV("ADJ: sec %d nsec %d\n", sec, nsec);
PPSG->ADJ_UTCLO = sec; PPSG->ADJ_UTCLO = sec;
PPSG->ADJ_UTCHI = 0; PPSG->ADJ_UTCHI = 0;
...@@ -46,11 +45,11 @@ void pps_gen_set(int32_t sec, int32_t nsec) ...@@ -46,11 +45,11 @@ void pps_gen_set(int32_t sec, int32_t nsec)
PPSG->CR = PPSG_CR_CNT_EN | PPSG_CR_PWIDTH_W(PPS_PULSE_WIDTH) | PPSG->CR = PPSG_CR_CNT_EN | PPSG_CR_PWIDTH_W(PPS_PULSE_WIDTH) |
PPSG_CR_CNT_SET; PPSG_CR_CNT_SET;
PP_PRINTF("UTC set %d.%d\n", sec, nsec);
} }
void pps_gen_adjust_nsec(int32_t how_much) void pps_gen_adjust_nsec(int32_t how_much)
{ {
TRACE_DEV("ADJ: nsec %d nanoseconds\n", how_much);
#if 1 #if 1
PPSG->ADJ_UTCLO = 0; PPSG->ADJ_UTCLO = 0;
PPSG->ADJ_UTCHI = 0; PPSG->ADJ_UTCHI = 0;
...@@ -66,7 +65,6 @@ void pps_gen_adjust_utc(int32_t how_much) ...@@ -66,7 +65,6 @@ void pps_gen_adjust_utc(int32_t how_much)
{ {
#if 1 #if 1
TRACE_DEV("ADJ: utc %d seconds\n", how_much);
PPSG->ADJ_UTCLO = how_much; PPSG->ADJ_UTCLO = how_much;
PPSG->ADJ_UTCHI = 0; PPSG->ADJ_UTCHI = 0;
PPSG->ADJ_NSEC = 0; PPSG->ADJ_NSEC = 0;
......
...@@ -12,12 +12,12 @@ void pp_diag_fsm(struct pp_instance *ppi, char *name, int sequence, int plen) ...@@ -12,12 +12,12 @@ void pp_diag_fsm(struct pp_instance *ppi, char *name, int sequence, int plen)
{ {
if (sequence == STATE_ENTER) { if (sequence == STATE_ENTER) {
/* enter with or without a packet len */ /* enter with or without a packet len */
pp_printf("fsm for %p: ENTER %3i (%s), packet len %i\n", pp_timed_printf("fsm for %p: ENTER %3i (%s), packet len %i\n",
ppi, ppi->state, name, plen); ppi, ppi->state, name, plen);
return; return;
} }
/* leave has one \n more, so different states are separate */ /* leave has one \n more, so different states are separate */
pp_printf("fsm for %p: LEAVE %3i (%s) (next: %3i in %i ms)\n\n", pp_timed_printf("fsm for %p: LEAVE %3i (%s) (next: %3i in %i ms)\n\n",
ppi, ppi->state, name, ppi->next_state, ppi->next_delay); ppi, ppi->state, name, ppi->next_state, ppi->next_delay);
} }
......
...@@ -17,7 +17,12 @@ int pp_state_machine(struct pp_instance *ppi, uint8_t *packet, int plen) ...@@ -17,7 +17,12 @@ int pp_state_machine(struct pp_instance *ppi, uint8_t *packet, int plen)
{ {
struct pp_state_table_item *ip; struct pp_state_table_item *ip;
int state, err; int state, err;
#ifdef PPSI_MASTER__
if ((plen > 0))
pp_printf("RECV %02d %d.%d %s\n", plen,
ppi->last_rcv_time.seconds,
ppi->last_rcv_time.nanoseconds,pp_msg_names[packet[0] & 0x0f]);
#endif
if (packet) if (packet)
msg_unpack_header(ppi, packet); msg_unpack_header(ppi, packet);
...@@ -30,13 +35,15 @@ int pp_state_machine(struct pp_instance *ppi, uint8_t *packet, int plen) ...@@ -30,13 +35,15 @@ int pp_state_machine(struct pp_instance *ppi, uint8_t *packet, int plen)
/* found: handle this state */ /* found: handle this state */
ppi->next_state = state; ppi->next_state = state;
ppi->next_delay = 0; ppi->next_delay = 0;
pp_diag_fsm(ppi, ip->name, STATE_ENTER, plen); if ((pp_diag_verbosity) || (ppi->is_new_state))
pp_diag_fsm(ppi, ip->name, STATE_ENTER, plen);
err = ip->f1(ppi, packet, plen); err = ip->f1(ppi, packet, plen);
if (!err && ip->f2) if (!err && ip->f2)
err = ip->f2(ppi, packet, plen); err = ip->f2(ppi, packet, plen);
if (err) if (err)
pp_diag_error(ppi, err); pp_diag_error(ppi, err);
pp_diag_fsm(ppi, ip->name, STATE_LEAVE, 0 /* unused */); if (pp_diag_verbosity)
pp_diag_fsm(ppi, ip->name, STATE_LEAVE, 0 /* unused */);
ppi->is_new_state = 0; ppi->is_new_state = 0;
......
...@@ -272,6 +272,8 @@ enum pp_std_messages { ...@@ -272,6 +272,8 @@ enum pp_std_messages {
PPM_MANAGEMENT, PPM_MANAGEMENT,
}; };
extern const char const * pp_msg_names[];
/* Enumeration Domain Number (table 2, page 41) */ /* Enumeration Domain Number (table 2, page 41) */
enum ENDomainNumber { enum ENDomainNumber {
DFLT_DOMAIN_NUMBER = 0, DFLT_DOMAIN_NUMBER = 0,
......
...@@ -341,7 +341,7 @@ extern void div2_TimeInternal(TimeInternal *r); ...@@ -341,7 +341,7 @@ extern void div2_TimeInternal(TimeInternal *r);
/* Get and Set system timestamp */ /* Get and Set system timestamp */
extern void pp_get_tstamp(TimeInternal *t); extern void pp_get_tstamp(TimeInternal *t);
extern int32_t pp_set_tstamp(TimeInternal *t); extern int32_t pp_set_tstamp(TimeInternal *t);
extern const char *pp_get_tstamp_str();
/* Virtualization of Linux adjtimex (or BSD adjtime) system clock time /* Virtualization of Linux adjtimex (or BSD adjtime) system clock time
* adjustment. Boolean: returns 1 in case of success and 0 if failure */ * adjustment. Boolean: returns 1 in case of success and 0 if failure */
......
...@@ -108,5 +108,7 @@ void set_TimeInternal(TimeInternal *t, Integer32 s, Integer32 ns) ...@@ -108,5 +108,7 @@ void set_TimeInternal(TimeInternal *t, Integer32 s, Integer32 ns)
void display_TimeInternal(const char *label, TimeInternal *t) void display_TimeInternal(const char *label, TimeInternal *t)
{ {
PP_VPRINTF("%s: %d.%d \n", label, t->seconds, t->nanoseconds); PP_VPRINTF("%s: %s%d.%09d \n", label,
(t->seconds < 0 || (t->seconds == 0 && t->nanoseconds < 0)) ? "-" : " ",
abs(t->seconds), abs(t->nanoseconds));
} }
...@@ -571,7 +571,7 @@ void msg_unpack_pdelay_resp_followup(void *buf, ...@@ -571,7 +571,7 @@ void msg_unpack_pdelay_resp_followup(void *buf,
PP_VPRINTF("\n"); PP_VPRINTF("\n");
} }
static const char const * pp_msg_names[] = { const char const * pp_msg_names[] = {
"sync", "sync",
"delay_req", "delay_req",
"pdelay_req", "pdelay_req",
...@@ -585,6 +585,7 @@ static const char const * pp_msg_names[] = { ...@@ -585,6 +585,7 @@ static const char const * pp_msg_names[] = {
"management" "management"
}; };
#ifdef PPSI_SLAVE
#define MSG_SEND_AND_RET(x,y,z)\ #define MSG_SEND_AND_RET(x,y,z)\
if (pp_send_packet(ppi, ppi->buf_out, PP_## x ##_LENGTH,\ if (pp_send_packet(ppi, ppi->buf_out, PP_## x ##_LENGTH,\
&ppi->last_snt_time, PP_NP_##y , z) < PP_## x ##_LENGTH) {\ &ppi->last_snt_time, PP_NP_##y , z) < PP_## x ##_LENGTH) {\
...@@ -592,9 +593,20 @@ static const char const * pp_msg_names[] = { ...@@ -592,9 +593,20 @@ static const char const * pp_msg_names[] = {
pp_msg_names[PPM_##x], PPM_##x);\ pp_msg_names[PPM_##x], PPM_##x);\
return -1;\ return -1;\
}\ }\
PP_VPRINTF("%s(%d) Message sent\n", pp_msg_names[PPM_##x], PPM_##x);\
ppi->sent_seq_id[PPM_## x]++;\ ppi->sent_seq_id[PPM_## x]++;\
return 0; return 0;
#else
#define MSG_SEND_AND_RET(x,y,z)\
if (pp_send_packet(ppi, ppi->buf_out, PP_## x ##_LENGTH,\
&ppi->last_snt_time, PP_NP_##y , z) < PP_## x ##_LENGTH) {\
PP_PRINTF("%s(%d) Message can't be sent -> FAULTY state!\n",\
pp_msg_names[PPM_##x], PPM_##x);\
return -1;\
}\
ppi->sent_seq_id[PPM_## x]++;\
//PP_PRINTF("SENT %02d %d.%d %s \n", PP_## x ##_LENGTH, ppi->last_snt_time.seconds, ppi->last_snt_time.nanoseconds,pp_msg_names[PPM_##x]);\
return 0;
#endif
/* Pack and send on general multicast ip adress an Announce message */ /* Pack and send on general multicast ip adress an Announce message */
int msg_issue_announce(struct pp_instance *ppi) int msg_issue_announce(struct pp_instance *ppi)
......
...@@ -33,13 +33,13 @@ void pp_update_delay(struct pp_instance *ppi, TimeInternal *correction_field) ...@@ -33,13 +33,13 @@ void pp_update_delay(struct pp_instance *ppi, TimeInternal *correction_field)
if (OPTS(ppi)->max_dly) { /* If max_delay is 0 then it's OFF */ if (OPTS(ppi)->max_dly) { /* If max_delay is 0 then it's OFF */
if (s_to_m_dly.seconds) { if (s_to_m_dly.seconds) {
PP_PRINTF("updateDelay aborted, delay greater than 1" PP_VPRINTF("pp_update_delay aborted, delay greater than 1"
" second."); " second\n");
return; return;
} }
if (s_to_m_dly.nanoseconds > OPTS(ppi)->max_dly) { if (s_to_m_dly.nanoseconds > OPTS(ppi)->max_dly) {
PP_PRINTF("updateDelay aborted, delay %d greater than " PP_VPRINTF("pp_update_delay aborted, delay %d greater than "
"administratively set maximum %d\n", "administratively set maximum %d\n",
s_to_m_dly.nanoseconds, s_to_m_dly.nanoseconds,
OPTS(ppi)->max_dly); OPTS(ppi)->max_dly);
...@@ -254,13 +254,13 @@ void pp_update_clock(struct pp_instance *ppi) ...@@ -254,13 +254,13 @@ void pp_update_clock(struct pp_instance *ppi)
if (OPTS(ppi)->max_rst) { /* If max_rst is 0 then it's OFF */ if (OPTS(ppi)->max_rst) { /* If max_rst is 0 then it's OFF */
if (DSCUR(ppi)->offsetFromMaster.seconds) { if (DSCUR(ppi)->offsetFromMaster.seconds) {
PP_PRINTF("pp_update_clock aborted, offset greater " PP_PRINTF("pp_update_clock aborted, offset greater "
"than 1 second."); "than 1 second\n");
goto display; goto display;
} }
if (DSCUR(ppi)->offsetFromMaster.nanoseconds > if (DSCUR(ppi)->offsetFromMaster.nanoseconds >
OPTS(ppi)->max_rst) { OPTS(ppi)->max_rst) {
PP_PRINTF("updateClock aborted, offset %d greater than " PP_VPRINTF("pp_update_clock aborted, offset %d greater than "
"administratively set maximum %d\n", "administratively set maximum %d\n",
DSCUR(ppi)->offsetFromMaster.nanoseconds, DSCUR(ppi)->offsetFromMaster.nanoseconds,
OPTS(ppi)->max_rst); OPTS(ppi)->max_rst);
...@@ -285,6 +285,7 @@ void pp_update_clock(struct pp_instance *ppi) ...@@ -285,6 +285,7 @@ void pp_update_clock(struct pp_instance *ppi)
} }
} }
} else { } else {
static int dc = 0;
/* the PI controller */ /* the PI controller */
/* no negative or zero attenuation */ /* no negative or zero attenuation */
...@@ -310,6 +311,16 @@ void pp_update_clock(struct pp_instance *ppi) ...@@ -310,6 +311,16 @@ void pp_update_clock(struct pp_instance *ppi)
/* apply controller output as a clock tick rate adjustment */ /* apply controller output as a clock tick rate adjustment */
if (!OPTS(ppi)->no_adjust) if (!OPTS(ppi)->no_adjust)
pp_adj_freq(-adj); pp_adj_freq(-adj);
dc++;
if (dc % 8 == 0) { /* Prints statistics every 8s */
PP_PRINTF("ofst %d, raw ofst %d, mean-dly %d, adj %d\n",
DSCUR(ppi)->offsetFromMaster.nanoseconds,
SRV(ppi)->m_to_s_dly.nanoseconds,
DSCUR(ppi)->meanPathDelay.nanoseconds,
adj);
}
} }
display: display:
...@@ -319,26 +330,26 @@ display: ...@@ -319,26 +330,26 @@ display:
*/ */
PP_PRINTF("\n--Offset Correction-- \n"); PP_VPRINTF("\n--Offset Correction-- \n");
PP_PRINTF("Raw offset from master: %10ds %11dns\n", PP_VPRINTF("Raw offset from master: %10ds %11dns\n",
SRV(ppi)->m_to_s_dly.seconds, SRV(ppi)->m_to_s_dly.seconds,
SRV(ppi)->m_to_s_dly.nanoseconds); SRV(ppi)->m_to_s_dly.nanoseconds);
PP_PRINTF("\n--Offset and Delay filtered-- \n"); PP_VPRINTF("\n--Offset and Delay filtered-- \n");
if (!OPTS(ppi)->e2e_mode) { if (!OPTS(ppi)->e2e_mode) {
PP_PRINTF("one-way delay averaged (P2P): %10ds %11dns\n", PP_VPRINTF("one-way delay averaged (P2P): %10ds %11dns\n",
DSPOR(ppi)->peerMeanPathDelay.seconds, DSPOR(ppi)->peerMeanPathDelay.seconds,
DSPOR(ppi)->peerMeanPathDelay.nanoseconds); DSPOR(ppi)->peerMeanPathDelay.nanoseconds);
} else { } else {
PP_PRINTF("one-way delay averaged (E2E): %10ds %11dns\n", PP_VPRINTF("one-way delay averaged (E2E): %10ds %11dns\n",
DSCUR(ppi)->meanPathDelay.seconds, DSCUR(ppi)->meanPathDelay.seconds,
DSCUR(ppi)->meanPathDelay.nanoseconds); DSCUR(ppi)->meanPathDelay.nanoseconds);
} }
PP_PRINTF("offset from master: %10ds %11dns\n", PP_VPRINTF("offset from master: %10ds %11dns\n",
DSCUR(ppi)->offsetFromMaster.seconds, DSCUR(ppi)->offsetFromMaster.seconds,
DSCUR(ppi)->offsetFromMaster.nanoseconds); DSCUR(ppi)->offsetFromMaster.nanoseconds);
PP_PRINTF("observed drift: %10d\n", SRV(ppi)->obs_drift); PP_VPRINTF("observed drift: %10d\n", SRV(ppi)->obs_drift);
} }
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment