Skip to content
Commits on Source (7)
......@@ -64,7 +64,6 @@ LIBRESSL_VERSION_NUMBER
# Things WAF sets that don't get #undefs if they're not set
ENABLE_EARLY_DROPROOT
ENABLE_LEAP_SMEAR
ENABLE_DEBUG_TIMING
ENABLE_LOCKCLOCK
ENABLE_MSSNTP
ENABLE_LEAP_TESTING
......
......@@ -223,24 +223,6 @@ names from the rusage struct. See +man getrusage+ for details.
(The NetBSD and FreeBSD man pages have more details.)
The maxrss column is the high water mark since the process was started.
The remaining fields show the values used since the last report.
+
+timingstats+;;
(Only available when the daemon is compiled with process time
debugging support (+--enable-debug-timing+ - costs performance). Record
processing time statistics for various selected code paths.
+
+53876 36.920 10.0.3.5 1 0.000014592 input processing delay+
+
[width="100%",cols="<34%,<33%,<33%",]
|====================================
|Item |Units |Description
|+53876+ |MJD |date
|+36.920+ |s |time past midnight
|+10.0.3.5+ |IP |server address
|+1+ |# |event count
|+0.000014592+|s |total time
|_message_ |text |code path description (see source)
|====================================
// End of super-long series of statistics directives
......
......@@ -95,9 +95,6 @@ extern void init_io (void);
extern void io_open_sockets (void);
extern void io_clr_stats (void);
extern void sendpkt (sockaddr_u *, endpt *, void *, int);
#ifdef ENABLE_DEBUG_TIMING
extern void collect_timing (struct recvbuf *, const char *, int, l_fp);
#endif
extern const char * latoa(endpt *);
/* ntp_loopfilter.c */
......@@ -193,13 +190,10 @@ extern void record_raw_stats (struct peer *,
double root_dispersion, uint32_t refid,
unsigned int outcount);
extern void check_leap_file (bool is_daily_check, time_t systime);
#ifdef ENABLE_DEBUG_TIMING
extern void record_timing_stats (const char *);
#endif
/* packetstamp.c */
extern void enable_packetstamps(int, sockaddr_u *);
extern l_fp fetch_packetstamp(struct recvbuf *, struct msghdr *, l_fp);
extern l_fp fetch_packetstamp(struct msghdr *);
/*
* Signals we catch for debugging.
......
......@@ -39,7 +39,6 @@ struct recvbuf {
struct netendpt * dstadr; /* address pkt arrived on */
SOCKET fd; /* fd on which it was received */
l_fp recv_time; /* time of arrival */
void (*receiver)(struct recvbuf *); /* callback */
size_t recv_length; /* number of octets received */
union {
struct pkt X_recv_pkt;
......@@ -74,30 +73,10 @@ extern void freerecvbuf(struct recvbuf *);
/* signal safe - no malloc */
extern struct recvbuf *get_free_recv_buffer(void);
/* Add a buffer to the full list
*/
extern void add_full_recv_buffer(struct recvbuf *);
/* number of recvbufs on freelist */
extern unsigned long free_recvbuffs(void); /* not really pure */
extern unsigned long full_recvbuffs(void); /* not really pure */
extern unsigned long total_recvbuffs(void); /* not really pure */
extern unsigned long lowater_additions(void); /* not really pure */
/* Returns the next buffer in the full list.
*
*/
extern struct recvbuf *get_full_recv_buffer(void);
/*
* purge_recv_buffers_for_fd() - purges any previously-received input
* from a given file descriptor.
*/
extern void purge_recv_buffers_for_fd(SOCKET);
/*
* Checks to see if there are buffers to process
*/
extern bool has_full_recv_buffer(void); /* not really pure */
#endif /* GUARD_RECVBUFF_H */
......@@ -97,7 +97,6 @@ struct key_tok ntp_keywords[] = {
{ "protostats", T_Protostats, FOLLBY_TOKEN },
{ "rawstats", T_Rawstats, FOLLBY_TOKEN },
{ "sysstats", T_Sysstats, FOLLBY_TOKEN },
{ "timingstats", T_Timingstats, FOLLBY_TOKEN },
{ "usestats", T_Usestats, FOLLBY_TOKEN },
/* filegen_option */
{ "file", T_File, FOLLBY_STRING },
......
......@@ -1983,7 +1983,8 @@ ctl_putsys(
break;
case CS_USED_RBUF:
ctl_putuint(sys_var[varid].text, full_recvbuffs());
// FIXME: nuke this slot
ctl_putuint(sys_var[varid].text, 0);
break;
case CS_RBUF_LOWATER:
......@@ -2624,9 +2625,12 @@ ctl_getitem(
NLOG(NLOG_SYSEVENT)
if (quiet_until <= current_time) {
quiet_until = current_time + 300;
/* The cast on SRCPORT is required to supress a warning on NetBSD 8.0
* http://gnats.netbsd.org/cgi-bin/query-pr-single.pl?number=53618
*/
msyslog(LOG_WARNING,
"Possible 'ntpdx' exploit from %s#%" PRIu16 " (possibly spoofed)",
socktoa(rmt_addr), SRCPORT(rmt_addr));
socktoa(rmt_addr), (unsigned)SRCPORT(rmt_addr));
}
reqpt = reqend; /* never again for this packet! */
return NULL;
......
......@@ -257,10 +257,10 @@ static void maintain_activefds(int fd, bool closing);
/*
* Routines to read the ntp packets
*/
static int read_network_packet (SOCKET, endpt *, l_fp);
static void input_handler (fd_set *, l_fp *);
static int read_network_packet (SOCKET, endpt *);
static void input_handler (fd_set *);
#ifdef REFCLOCK
static int read_refclock_packet (SOCKET, struct refclockio *, l_fp);
static int read_refclock_packet (SOCKET, struct refclockio *);
#endif
/*
......@@ -306,30 +306,6 @@ maintain_activefds(
}
#ifdef ENABLE_DEBUG_TIMING
/*
* collect timing information for various processing
* paths. currently we only pass them on to the file
* for later processing. this could also do histogram
* based analysis in order to reduce the load (and skew)
* due to the file output
*/
void
collect_timing(struct recvbuf *rb, const char *tag, int count, l_fp dts)
{
char buf[256];
snprintf(buf, sizeof(buf), "%s %d %s %s",
(rb != NULL)
? ((rb->dstadr != NULL)
? socktoa(&rb->recv_srcadr)
: "-REFCLOCK-")
: "-",
count, lfptoa(dts, 9), tag);
record_timing_stats(buf);
}
#endif
/*
* About dynamic interfaces, sockets, reception and more...
*
......@@ -2084,8 +2060,7 @@ sendpkt(
static int
read_refclock_packet(
SOCKET fd,
struct refclockio * rp,
l_fp ts
struct refclockio * rp
)
{
size_t i;
......@@ -2093,6 +2068,13 @@ read_refclock_packet(
int saved_errno;
int consumed;
struct recvbuf * rb;
l_fp ts;
/* Could read earlier in normal case,
* but too early gets wrong time if data arrives
* while we are busy processing other packets.
*/
get_systime(&ts);
rb = get_free_recv_buffer();
......@@ -2131,12 +2113,12 @@ read_refclock_packet(
rb->dstadr = 0;
rb->fd = fd;
rb->recv_time = ts;
rb->receiver = rp->clock_recv;
rb->network_packet = false;
consumed = indicate_refclock_packet(rp, rb);
if (!consumed) {
rp->recvcount++;
// FIXME: should have separate slot for refclock packets
pkt_count.packets_received++;
}
......@@ -2152,8 +2134,7 @@ read_refclock_packet(
static int
read_network_packet(
SOCKET fd,
endpt * itf,
l_fp ts
endpt * itf
)
{
socklen_t fromlen;
......@@ -2262,14 +2243,13 @@ read_network_packet(
*/
rb->dstadr = itf;
rb->fd = fd;
ts = fetch_packetstamp(rb, &msghdr, ts);
rb->recv_time = ts;
rb->receiver = receive;
rb->recv_time = fetch_packetstamp(&msghdr);
#ifdef REFCLOCK
rb->network_packet = true;
#endif /* REFCLOCK */
add_full_recv_buffer(rb);
receive(rb);
freerecvbuf(rb);
itf->received++;
pkt_count.packets_received++;
......@@ -2305,11 +2285,7 @@ io_handler(void)
pthread_sigmask(SIG_SETMASK, &runMask, NULL);
if (nfound > 0) {
l_fp ts;
get_systime(&ts);
input_handler(&rdfdes, &ts);
input_handler(&rdfdes);
} else if (nfound == -1 && errno != EINTR) {
msyslog(LOG_ERR, "IO: select() error: %m");
}
......@@ -2327,16 +2303,11 @@ io_handler(void)
*/
static void
input_handler(
fd_set * fds,
l_fp * cts
fd_set * fds
)
{
int buflen;
SOCKET fd;
l_fp ts; /* Timestamp at BOselect() gob */
#ifdef ENABLE_DEBUG_TIMING
l_fp ts_e; /* Timestamp at EOselect() gob */
#endif
size_t select_count;
endpt * ep;
#ifdef REFCLOCK
......@@ -2356,7 +2327,6 @@ input_handler(
* If we have something to do, freeze a timestamp.
* See below for the other cases (nothing left to do or error)
*/
ts = *cts;
++pkt_count.handler_pkts;
......@@ -2372,7 +2342,7 @@ input_handler(
if (!FD_ISSET(fd, fds))
continue;
++select_count;
buflen = read_refclock_packet(fd, rp, ts);
buflen = read_refclock_packet(fd, rp);
/*
* The first read must succeed after select()
* indicates readability, or we've reached
......@@ -2395,7 +2365,7 @@ input_handler(
} else {
/* drain any remaining refclock input */
do {
buflen = read_refclock_packet(fd, rp, ts);
buflen = read_refclock_packet(fd, rp);
} while (buflen > 0);
}
}
......@@ -2410,7 +2380,7 @@ input_handler(
if (FD_ISSET(fd, fds))
do {
++select_count;
buflen = read_network_packet(fd, ep, ts);
buflen = read_network_packet(fd, ep);
} while (buflen > 0);
}
......@@ -2444,19 +2414,6 @@ input_handler(
return;
}
/* We've done our work */
#ifdef ENABLE_DEBUG_TIMING
get_systime(&ts_e);
/*
* (ts_e - ts) is the amount of time we spent processing this
* gob of file descriptors. Log it.
*/
ts_e -= ts;
collect_timing(NULL, "input handler", 1, ts_e);
if (debug > 3) /* SPECIAL DEBUG */
msyslog(LOG_DEBUG,
"IO: input_handler: Processed a gob of fd's in %s msec",
lfptoms(ts_e, 6));
#endif /* ENABLE_DEBUG_TIMING */
/* We're done... */
return;
}
......@@ -2859,7 +2816,6 @@ io_closeclock(
rio->active = false;
UNLINK_SLIST(unlinked, refio, rio, next, struct refclockio);
if (NULL != unlinked) {
purge_recv_buffers_for_fd(rio->fd);
/*
* Close the descriptor.
*/
......
......@@ -82,9 +82,7 @@ enable_packetstamps(
*/
l_fp
fetch_packetstamp(
struct recvbuf * rb,
struct msghdr * msghdr,
l_fp ts
struct msghdr * msghdr
)
{
struct cmsghdr * cmsghdr;
......@@ -97,21 +95,12 @@ fetch_packetstamp(
double fuzz;
l_fp lfpfuzz;
l_fp nts = 0; /* network time stamp */
#ifdef ENABLE_DEBUG_TIMING
l_fp dts;
#endif
#ifndef ENABLE_DEBUG_TIMING
UNUSED_ARG(rb);
#endif
/* There should be only one cmsg. */
cmsghdr = CMSG_FIRSTHDR(msghdr);
if (NULL == cmsghdr) {
DPRINT(4, ("fetch_timestamp: can't find timestamp\n"));
msyslog(LOG_ERR,
"ERR: fetch_timestamp: no msghdrs, %s",
socktoa(&rb->recv_srcadr));
msyslog(LOG_ERR, "ERR: fetch_timestamp: no msghdrs");
exit(2);
/* return ts; ** Kludge to use time from select. */
}
......@@ -159,16 +148,8 @@ fetch_packetstamp(
fuzz = ntp_random() * 2. / FRAC * sys_fuzz;
lfpfuzz = dtolfp(fuzz);
nts += lfpfuzz;
#ifdef ENABLE_DEBUG_TIMING
dts = ts;
dts -= nts;
collect_timing(rb, "input processing delay", 1, dts);
DPRINT(4, ("fetch_timestamp: timestamp delta: %s (incl. fuzz)\n",
lfptoa(dts, 9)));
#endif /* ENABLE_DEBUG_TIMING */
ts = nts;
return ts;
return nts;
}
// end
......@@ -12,13 +12,11 @@
/*
* Memory allocation.
*/
static unsigned long full_recvbufs; /* recvbufs on full_recv_fifo */
static unsigned long free_recvbufs; /* recvbufs on free_recv_list */
static unsigned long total_recvbufs; /* total recvbufs currently in use */
static unsigned long lowater_adds; /* # of times we have added memory */
static unsigned long buffer_shortfall; /* # of missed free receive buffers
between replenishments */
static DECL_FIFO_ANCHOR(recvbuf_t) full_recv_fifo;
static recvbuf_t * free_recv_list;
#ifdef DEBUG
......@@ -32,12 +30,6 @@ free_recvbuffs (void)
return free_recvbufs;
}
unsigned long
full_recvbuffs (void)
{
return full_recvbufs;
}
unsigned long
total_recvbuffs (void)
{
......@@ -94,8 +86,7 @@ init_recvbuff(unsigned int nbufs)
/*
* Init buffer free list and stat counters
*/
free_recvbufs = total_recvbufs = 0;
full_recvbufs = lowater_adds = 0;
free_recvbufs = total_recvbufs = lowater_adds = 0;
create_buffers(nbufs);
......@@ -111,13 +102,6 @@ uninit_recvbuff(void)
{
recvbuf_t *rbunlinked;
for (;;) {
UNLINK_FIFO(rbunlinked, full_recv_fifo, link);
if (rbunlinked == NULL)
break;
free(rbunlinked);
}
for (;;) {
UNLINK_HEAD_SLIST(rbunlinked, free_recv_list, link);
if (rbunlinked == NULL)
......@@ -128,6 +112,23 @@ uninit_recvbuff(void)
#endif /* DEBUG */
recvbuf_t *
get_free_recv_buffer(void)
{
recvbuf_t *buffer;
UNLINK_HEAD_SLIST(buffer, free_recv_list, link);
if (buffer != NULL) {
free_recvbufs--;
initialise_buffer(buffer);
buffer->used++;
} else {
buffer_shortfall++;
}
return buffer;
}
/*
* freerecvbuf - make a single recvbuf available for reuse
*/
......@@ -147,91 +148,6 @@ freerecvbuf(recvbuf_t *rb)
}
void
add_full_recv_buffer(recvbuf_t *rb)
{
if (rb == NULL) {
msyslog(LOG_ERR, "ERR: add_full_recv_buffer received NULL buffer");
return;
}
LINK_FIFO(full_recv_fifo, rb, link);
full_recvbufs++;
}
recvbuf_t *
get_free_recv_buffer(void)
{
recvbuf_t *buffer;
UNLINK_HEAD_SLIST(buffer, free_recv_list, link);
if (buffer != NULL) {
free_recvbufs--;
initialise_buffer(buffer);
buffer->used++;
} else {
buffer_shortfall++;
}
return buffer;
}
recvbuf_t *
get_full_recv_buffer(void)
{
recvbuf_t * rbuf;
/*
* try to grab a full buffer
*/
UNLINK_FIFO(rbuf, full_recv_fifo, link);
if (rbuf != NULL)
full_recvbufs--;
return rbuf;
}
/*
* purge_recv_buffers_for_fd() - purges any previously-received input
* from a given file descriptor.
*/
void
purge_recv_buffers_for_fd(
SOCKET fd
)
{
recvbuf_t *rbufp;
recvbuf_t *next;
recvbuf_t *punlinked;
for (rbufp = HEAD_FIFO(full_recv_fifo);
rbufp != NULL;
rbufp = next) {
next = rbufp->link;
if (rbufp->fd == fd) {
UNLINK_MID_FIFO(punlinked, full_recv_fifo,
rbufp, link, recvbuf_t);
INSIST(punlinked == rbufp);
full_recvbufs--;
freerecvbuf(rbufp);
}
}
}
/*
* Checks to see if there are buffers to process
*/
bool has_full_recv_buffer(void)
{
if (HEAD_FIFO(full_recv_fifo) != NULL)
return (true);
else
return (false);
}
#ifdef NTP_DEBUG_LISTS
void
......
......@@ -667,7 +667,8 @@ indicate_refclock_packet(
return true;
}
add_full_recv_buffer(rb);
(rio->clock_recv)(rb);
freerecvbuf(rb);
return false;
}
......
......@@ -62,7 +62,6 @@ static FILEGEN peerstats;
static FILEGEN protostats;
static FILEGEN rawstats;
static FILEGEN sysstats;
static FILEGEN timingstats;
static FILEGEN usestats;
/*
......@@ -112,7 +111,6 @@ uninit_util(void)
filegen_unregister("sysstats");
filegen_unregister("peerstats");
filegen_unregister("protostats");
filegen_unregister("timingstats");
filegen_unregister("usestats");
}
#endif /* DEBUG */
......@@ -130,7 +128,6 @@ init_util(void)
filegen_register(statsdir, "sysstats", &sysstats);
filegen_register(statsdir, "peerstats", &peerstats);
filegen_register(statsdir, "protostats", &protostats);
filegen_register(statsdir, "timingstats", &timingstats);
filegen_register(statsdir, "usestats", &usestats);
/*
......@@ -685,36 +682,6 @@ record_proto_stats(
}
}
#ifdef ENABLE_DEBUG_TIMING
/*
* record_timing_stats - write timing statistics to file
*
* file format:
* day (mjd)
* time (s past midnight)
* text message
*/
void
record_timing_stats(
const char *text /* text message */
)
{
static unsigned int flshcnt;
struct timespec now;
if (!stats_control)
return;
clock_gettime(CLOCK_REALTIME, &now);
filegen_setup(&timingstats, now.tv_sec);
if (timingstats.fp != NULL) {
fprintf(timingstats.fp, "%s %s\n",
timespec_to_MJDtime(&now), text);
if (++flshcnt % 100 == 0)
fflush(timingstats.fp);
}
}
#endif
/*
......
......@@ -917,15 +917,14 @@ ntpdmain(
*/
static void mainloop(void)
{
struct recvbuf *rbuf;
init_timer();
for (;;) {
if (sig_flags.sawQuit)
finish_safe(signo);
if (!sig_flags.sawALRM && !has_full_recv_buffer()) {
if (!sig_flags.sawALRM) {
// FIXME: Check other flags
/*
* Nothing to do. Wait for something.
*/
......@@ -948,56 +947,6 @@ static void mainloop(void)
}
#endif
# ifdef ENABLE_DEBUG_TIMING
{
l_fp pts;
l_fp tsa, tsb;
int bufcount = 0;
get_systime(&pts);
tsa = pts;
# endif
rbuf = get_full_recv_buffer();
while (rbuf != NULL) {
if (sig_flags.sawALRM) {
/* avoid timer starvation during lengthy I/O handling */
timer();
sig_flags.sawALRM = false;
}
/*
* Call the data procedure to handle each received
* packet.
*/
if (rbuf->receiver != NULL) {
# ifdef ENABLE_DEBUG_TIMING
l_fp dts = pts;
dts -= rbuf->recv_time;
DPRINT(2, ("processing timestamp delta %s (with prec. fuzz)\n", lfptoa(dts, 9)));
collect_timing(rbuf, "buffer processing delay", 1, dts);
bufcount++;
# endif
(*rbuf->receiver)(rbuf);
} else {
msyslog(LOG_ERR, "ERR: fatal: receive buffer callback NULL");
abort();
}
freerecvbuf(rbuf);
rbuf = get_full_recv_buffer();
}
# ifdef ENABLE_DEBUG_TIMING
get_systime(&tsb);
tsb -= tsa;
if (bufcount) {
collect_timing(NULL, "processing", bufcount, tsb);
DPRINT(2, ("processing time for %d buffers %s\n", bufcount, lfptoa(tsb, 9)));
}
}
# endif
/*
* Check files
*/
......
......@@ -1889,6 +1889,11 @@ local_input(
}
if (count)
{ /* simulate receive */
// FIXME - this copy is no longer needed
// This code is the result of a simple fix for SINGLEBUFFER
// The copy used to go to add_full_recv_buffer, but that's not needed any more
// I'm not sure the local_receive below is correct
// Hal, 2018-Sep-21
buf = get_free_recv_buffer();
if (buf != NULL) {
memmove((void *)buf->recv_buffer,
......@@ -1898,12 +1903,12 @@ local_input(
buf->recv_time = rbufp->recv_time;
buf->srcadr = rbufp->srcadr;
buf->dstadr = rbufp->dstadr;
buf->receiver = rbufp->receiver;
buf->fd = rbufp->fd;
buf->recv_peer = rbufp->recv_peer;
parse->generic->io.recvcount++;
pkt_count.packets_received++;
add_full_recv_buffer(buf);
local_receive(buf);
freerecvbuf(buf);
}
parse_iodone(&parse->parseio);
}
......
......@@ -17,9 +17,6 @@ TEST_TEAR_DOWN(recvbuff) {}
TEST(recvbuff, Initialization) {
TEST_ASSERT_EQUAL(RECV_INIT, free_recvbuffs());
TEST_ASSERT_EQUAL(0, full_recvbuffs());
TEST_ASSERT_FALSE(has_full_recv_buffer());
TEST_ASSERT_NULL(get_full_recv_buffer());
}
TEST(recvbuff, GetAndFree) {
......@@ -31,19 +28,7 @@ TEST(recvbuff, GetAndFree) {
TEST_ASSERT_EQUAL(initial, free_recvbuffs());
}
TEST(recvbuff, GetAndFill) {
recvbuf_t* buf = get_free_recv_buffer();
recvbuf_t* buf1;
add_full_recv_buffer(buf);
TEST_ASSERT_EQUAL(1, full_recvbuffs());
TEST_ASSERT_TRUE(has_full_recv_buffer());
buf1 = get_full_recv_buffer();
TEST_ASSERT_POINTERS_EQUAL(buf, buf1);
}
TEST_GROUP_RUNNER(recvbuff) {
RUN_TEST_CASE(recvbuff, Initialization);
RUN_TEST_CASE(recvbuff, GetAndFree);
RUN_TEST_CASE(recvbuff, GetAndFill);
}
......@@ -840,11 +840,6 @@ int main(int argc, char **argv) {
else:
ctx.undefine("ENABLE_CLASSIC_MODE")
if ctx.options.enable_debug_timing:
ctx.define("ENABLE_DEBUG_TIMING", 1)
else:
ctx.undefine("ENABLE_DEBUG_TIMING")
# Ugly hack to examine config symbols
for sym in ctx.env.DEFINES:
if sym.startswith("NTP_SIZEOF_TIME_T="):
......