Add more entries to tracking log

Add number of combined sources, remaining offset correction from
previous update and estimated stddev of the combined offset.
This commit is contained in:
Miroslav Lichvar 2013-06-17 18:16:52 +02:00
parent 9c78ad708b
commit 6fa11a853a
5 changed files with 55 additions and 23 deletions

View file

@ -2074,7 +2074,8 @@ An example line (which actually appears as a single line in the file)
from the tracking log file is shown below. from the tracking log file is shown below.
@example @example
2012-02-23 05:40:50 158.152.1.76 3 340.529 1.606 1.046e-03 N 2012-02-23 05:40:50 158.152.1.76 3 340.529 1.606 1.046e-03 N \
4 6.849e-03 -4.670e-04
@end example @end example
The columns are as follows (the quantities in square brackets are the The columns are as follows (the quantities in square brackets are the
@ -2104,6 +2105,14 @@ system is fast of UTC). [1.046e-3]
Leap status (@code{N} means normal, @code{+} means that the last minute Leap status (@code{N} means normal, @code{+} means that the last minute
of this month has 61 seconds, @code{-} means that the last minute of the month of this month has 61 seconds, @code{-} means that the last minute of the month
has 59 seconds, @code{?} means the clock is not currently synchronised.) [N] has 59 seconds, @code{?} means the clock is not currently synchronised.) [N]
@item
The number of combined sources. [4]
@item
The estimated standard deviation of the combined offset (in seconds).
[6.849e-03]
@item
The remaining offset correction from the previous update (in seconds, positive
means the system clock is slow of UTC). [-4.670e-04]
@end enumerate @end enumerate
A banner is periodically written to the log file to indicate the A banner is periodically written to the log file to indicate the

View file

@ -196,7 +196,7 @@ REF_Initialise(void)
} }
logfileid = CNF_GetLogTracking() ? LOG_FileOpen("tracking", logfileid = CNF_GetLogTracking() ? LOG_FileOpen("tracking",
" Date (UTC) Time IP Address St Freq ppm Skew ppm Offset L") " Date (UTC) Time IP Address St Freq ppm Skew ppm Offset L Co Offset sd Rem. corr.")
: -1; : -1;
max_update_skew = fabs(CNF_GetMaxUpdateSkew()) * 1.0e-6; max_update_skew = fabs(CNF_GetMaxUpdateSkew()) * 1.0e-6;
@ -646,12 +646,16 @@ update_leap_status(NTP_Leap leap, time_t now)
/* ================================================== */ /* ================================================== */
static void static void
write_log(struct timeval *ref_time, char *ref, int stratum, NTP_Leap leap, double freq, double skew, double offset) write_log(struct timeval *ref_time, char *ref, int stratum, NTP_Leap leap,
double freq, double skew, double offset, int combined_sources,
double offset_sd, double uncorrected_offset)
{ {
const char leap_codes[4] = {'N', '+', '-', '?'}; const char leap_codes[4] = {'N', '+', '-', '?'};
if (logfileid != -1) { if (logfileid != -1) {
LOG_FileWrite(logfileid, "%s %-15s %2d %10.3f %10.3f %10.3e %1c", LOG_FileWrite(logfileid, "%s %-15s %2d %10.3f %10.3f %10.3e %1c %2d %10.3e %10.3e",
UTI_TimeToLogForm(ref_time->tv_sec), ref, stratum, freq, skew, offset, leap_codes[leap]); UTI_TimeToLogForm(ref_time->tv_sec), ref, stratum, freq, skew,
offset, leap_codes[leap], combined_sources, offset_sd,
uncorrected_offset);
} }
} }
@ -660,6 +664,7 @@ write_log(struct timeval *ref_time, char *ref, int stratum, NTP_Leap leap, doubl
void void
REF_SetReference(int stratum, REF_SetReference(int stratum,
NTP_Leap leap, NTP_Leap leap,
int combined_sources,
uint32_t ref_id, uint32_t ref_id,
IPAddr *ref_ip, IPAddr *ref_ip,
struct timeval *ref_time, struct timeval *ref_time,
@ -682,6 +687,7 @@ REF_SetReference(int stratum,
double update_interval; double update_interval;
double elapsed; double elapsed;
double correction_rate; double correction_rate;
double uncorrected_offset;
struct timeval now, raw_now, ev_now, ev_raw_now; struct timeval now, raw_now, ev_now, ev_raw_now;
assert(initialised); assert(initialised);
@ -712,7 +718,8 @@ REF_SetReference(int stratum,
/* This is cheaper than calling LCL_CookTime */ /* This is cheaper than calling LCL_CookTime */
SCH_GetLastEventTime(&ev_now, NULL, &ev_raw_now); SCH_GetLastEventTime(&ev_now, NULL, &ev_raw_now);
UTI_AddDiffToTimeval(&ev_now, &ev_raw_now, &raw_now, &now); UTI_DiffTimevalsToDouble(&uncorrected_offset, &ev_now, &ev_raw_now);
UTI_AddDoubleToTimeval(&raw_now, uncorrected_offset, &now);
UTI_DiffTimevalsToDouble(&elapsed, &now, ref_time); UTI_DiffTimevalsToDouble(&elapsed, &now, ref_time);
our_offset = offset + elapsed * frequency; our_offset = offset + elapsed * frequency;
@ -813,7 +820,10 @@ REF_SetReference(int stratum,
our_leap_status, our_leap_status,
abs_freq_ppm, abs_freq_ppm,
1.0e6*our_skew, 1.0e6*our_skew,
our_offset); our_offset,
combined_sources,
offset_sd,
uncorrected_offset);
if (drift_file) { if (drift_file) {
/* Update drift file at most once per hour */ /* Update drift file at most once per hour */
@ -858,7 +868,7 @@ REF_SetManualReference
/* We are not synchronised to an external source, as such. This is /* We are not synchronised to an external source, as such. This is
only supposed to be used with the local source option, really only supposed to be used with the local source option, really
... */ ... */
REF_SetReference(0, LEAP_Unsynchronised, manual_refid, NULL, REF_SetReference(0, LEAP_Unsynchronised, 1, manual_refid, NULL,
ref_time, offset, 0.0, frequency, skew, 0.0, 0.0); ref_time, offset, 0.0, frequency, skew, 0.0, 0.0);
} }
@ -868,11 +878,14 @@ void
REF_SetUnsynchronised(void) REF_SetUnsynchronised(void)
{ {
/* Variables required for logging to statistics log */ /* Variables required for logging to statistics log */
struct timeval now; struct timeval now, now_raw;
double uncorrected_offset;
assert(initialised); assert(initialised);
LCL_ReadCookedTime(&now, NULL); /* This is cheaper than calling LCL_CookTime */
SCH_GetLastEventTime(&now, NULL, &now_raw);
UTI_DiffTimevalsToDouble(&uncorrected_offset, &now, &now_raw);
if (fb_drifts) { if (fb_drifts) {
schedule_fb_drift(&now); schedule_fb_drift(&now);
@ -887,7 +900,10 @@ REF_SetUnsynchronised(void)
our_leap_status, our_leap_status,
LCL_ReadAbsoluteFrequency(), LCL_ReadAbsoluteFrequency(),
1.0e6*our_skew, 1.0e6*our_skew,
0.0); 0.0,
0,
0.0,
uncorrected_offset);
} }
/* ================================================== */ /* ================================================== */

View file

@ -105,6 +105,7 @@ extern void REF_SetReference
( (
int stratum, int stratum,
NTP_Leap leap, NTP_Leap leap,
int combined_sources,
uint32_t ref_id, uint32_t ref_id,
IPAddr *ref_ip, IPAddr *ref_ip,
struct timeval *ref_time, struct timeval *ref_time,

View file

@ -131,8 +131,6 @@ handle_slew(struct timeval *raw,
void void
SCH_Initialise(void) SCH_Initialise(void)
{ {
struct timeval tv;
FD_ZERO(&read_fds); FD_ZERO(&read_fds);
n_read_fds = 0; n_read_fds = 0;
@ -146,8 +144,10 @@ SCH_Initialise(void)
LCL_AddParameterChangeHandler(handle_slew, NULL); LCL_AddParameterChangeHandler(handle_slew, NULL);
LCL_ReadRawTime(&tv); LCL_ReadRawTime(&last_select_ts_raw);
srandom(tv.tv_sec << 16 ^ tv.tv_usec); last_select_ts = last_select_ts_raw;
srandom(last_select_ts.tv_sec << 16 ^ last_select_ts.tv_usec);
initialised = 1; initialised = 1;
} }

View file

@ -426,7 +426,7 @@ source_to_string(SRC_Instance inst)
/* ================================================== */ /* ================================================== */
static void static int
combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset, combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
double *offset_sd, double *frequency, double *skew) double *offset_sd, double *frequency, double *skew)
{ {
@ -434,11 +434,14 @@ combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
double src_offset, src_offset_sd, src_frequency, src_skew; double src_offset, src_offset_sd, src_frequency, src_skew;
double src_root_delay, src_root_dispersion, elapsed; double src_root_delay, src_root_dispersion, elapsed;
double weight, sum_weight, sum_offset, sum2_offset_sd, sum_frequency, sum_skew; double weight, sum_weight, sum_offset, sum2_offset_sd, sum_frequency, sum_skew;
int i, index; int i, index, combined;
if (n_sel_sources == 1)
return 1;
sum_weight = sum_offset = sum2_offset_sd = sum_frequency = sum_skew = 0.0; sum_weight = sum_offset = sum2_offset_sd = sum_frequency = sum_skew = 0.0;
for (i = 0; i < n_sel_sources; i++) { for (i = combined = 0; i < n_sel_sources; i++) {
index = sel_sources[i]; index = sel_sources[i];
SST_GetTrackingData(sources[index]->stats, &src_ref_time, SST_GetTrackingData(sources[index]->stats, &src_ref_time,
&src_offset, &src_offset_sd, &src_offset, &src_offset_sd,
@ -477,6 +480,8 @@ combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
(src_offset - *offset) * (src_offset - *offset)); (src_offset - *offset) * (src_offset - *offset));
sum_frequency += weight * src_frequency; sum_frequency += weight * src_frequency;
sum_skew += weight * src_skew; sum_skew += weight * src_skew;
combined++;
} }
assert(sum_weight > 0.0); assert(sum_weight > 0.0);
@ -489,6 +494,8 @@ combine_sources(int n_sel_sources, struct timeval *ref_time, double *offset,
LOG(LOGS_INFO, LOGF_Sources, "combined result offset=%e sd=%e freq=%e skew=%e", LOG(LOGS_INFO, LOGF_Sources, "combined result offset=%e sd=%e freq=%e skew=%e",
*offset, *offset_sd, *frequency, *skew); *offset, *offset_sd, *frequency, *skew);
#endif #endif
return combined;
} }
/* ================================================== */ /* ================================================== */
@ -508,7 +515,7 @@ SRC_SelectSource(uint32_t match_refid)
int n_endpoints, j1, j2; int n_endpoints, j1, j2;
double best_lo, best_hi; double best_lo, best_hi;
int depth, best_depth; int depth, best_depth;
int n_sel_sources; int n_sel_sources, combined;
double distance, sel_src_distance; double distance, sel_src_distance;
int stratum, min_stratum; int stratum, min_stratum;
struct SelectInfo *si; struct SelectInfo *si;
@ -927,13 +934,12 @@ SRC_SelectSource(uint32_t match_refid)
&src_frequency, &src_skew, &src_frequency, &src_skew,
&src_root_delay, &src_root_dispersion); &src_root_delay, &src_root_dispersion);
if (n_sel_sources > 1) { combined = combine_sources(n_sel_sources, &ref_time, &src_offset,
combine_sources(n_sel_sources, &ref_time, &src_offset, &src_offset_sd, &src_frequency, &src_skew);
&src_offset_sd, &src_frequency, &src_skew);
}
REF_SetReference(sources[selected_source_index]->sel_info.stratum, REF_SetReference(sources[selected_source_index]->sel_info.stratum,
leap_status, leap_status,
combined,
sources[selected_source_index]->ref_id, sources[selected_source_index]->ref_id,
sources[selected_source_index]->ip_addr, sources[selected_source_index]->ip_addr,
&ref_time, &ref_time,