From: Frank Kardel Date: Thu, 25 May 2006 07:55:42 +0000 (+0000) Subject: monopt.html: X-Git-Tag: NTP_4_2_3P2~5^2~4 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=cadbd08391d899f493e4bf0dc089a4e3591fa725;p=thirdparty%2Fntp.git monopt.html: document timingstats (only available when daemon is compiled with DEBUG) ntpd.h, ntpd.c, ntp_util.c: support collection of timing data ntp_io.c: implement SO_TIMESTAMP for systems that have it support collection of timing data fix io signal blocking in refclock io handling functions ntp_crypto.c: return OK when interface is not bound bk: 447562fewFIRfiYAnOOu13_hYPb6Mw --- diff --git a/html/monopt.html b/html/monopt.html index 4f32996bb..3e3b2d989 100644 --- a/html/monopt.html +++ b/html/monopt.html @@ -70,6 +70,10 @@
Rate exceeded 147
Number of packets discarded due to rate limitation. +
timingstats +
ONLY available when the deamon is compiled with debugging support. Enables recording of ntpd processing time information for various selected code paths: +
53876 36.920 10.0.3.5 1 0.000014592 input processing delay +
The first two fields show the date (Modified Julian Day) and time (seconds and fraction past UTC midnight). The next field is a potential peer address, - or -REFCLOCK- depending on the associated io source. Then an event count for the number of processed events in the code path follows. The fifth field is the total time spend for the events. The rest of the line denotes the code path description (see source for more information).
statsdir directory_path
Indicates the full path of a directory where statistics files should be created (see below). This keyword allows the (otherwise constant) filegen filename prefix to be modified for file generation sets, which is useful for handling statistics logs.
filegen name [file filename] [type typename] [link | nolink] [enable | disable] @@ -125,4 +129,4 @@ - \ No newline at end of file + diff --git a/include/ntpd.h b/include/ntpd.h index b2f8025d5..8d93f17ba 100644 --- a/include/ntpd.h +++ b/include/ntpd.h @@ -92,6 +92,9 @@ extern void io_multicast_add P((struct sockaddr_storage)); extern void io_multicast_del P((struct sockaddr_storage)); extern void kill_asyncio P((int)); extern void sendpkt P((struct sockaddr_storage *, struct interface *, int, struct pkt *, int)); +#ifdef DEBUG +extern void collect_timing P((struct recvbuf *, const char *, int, l_fp *)); +#endif #ifdef HAVE_SIGNALED_IO extern void wait_for_signal P((void)); extern void unblock_io_and_alarm P((void)); @@ -234,6 +237,9 @@ extern void record_clock_stats P((struct sockaddr_storage *, const char *)); extern void record_raw_stats P((struct sockaddr_storage *, struct sockaddr_storage *, l_fp *, l_fp *, l_fp *, l_fp *)); extern void record_sys_stats P((void)); extern void record_crypto_stats P((struct sockaddr_storage *, const char *)); +#ifdef DEBUG +extern void record_timing_stats P((const char *)); +#endif extern int sock_hash P((struct sockaddr_storage *)); extern double old_drift; diff --git a/ntpd/ntp_crypto.c b/ntpd/ntp_crypto.c index e720f7eea..84adbdda1 100644 --- a/ntpd/ntp_crypto.c +++ b/ntpd/ntp_crypto.c @@ -270,7 +270,7 @@ make_keylist( int i; if (!dstadr) - return; + return XEVNT_OK; /* * Allocate the key list if necessary. diff --git a/ntpd/ntp_io.c b/ntpd/ntp_io.c index a120a9b0c..f01a506af 100644 --- a/ntpd/ntp_io.c +++ b/ntpd/ntp_io.c @@ -15,6 +15,7 @@ #include "ntp_stdlib.h" #include "ntp_request.h" #include "ntp.h" +#include "ntp_unixtime.h" /* Don't include ISC's version of IPv6 variables and structures */ #define ISC_IPV6_H 1 @@ -309,7 +310,27 @@ static int move_fd(int fd) } #endif +#ifdef DEBUG +/* + * collect timing information for various processing + * paths. currently we only pass then on to the file + * for later processing. this could also do histogram + * based analysis in other to reduce the load (and skew) + * dur to the file output + */ +void +collect_timing(struct recvbuf *rb, const char *tag, int count, l_fp *dts) +{ + char buf[2048]; + snprintf(buf, sizeof(buf), "%s %d %s %s", + (rb != NULL) ? + ((rb->dstadr) ? stoa(&rb->recv_srcadr) : "-REFCLOCK-") : "-", + count, lfptoa(dts, 9), tag); + record_timing_stats(buf); +} +#endif + /* * About dynamic interfaces, sockets, reception and more... * @@ -337,12 +358,12 @@ static int move_fd(int fd) * the code here currently allocates a separate interface entry for those * multicast addresses * iff it is able to bind to a *new* socket with the multicast address (flags |= MCASTIF) - * in case of failure the multicast address of bound to an existing interface. + * in case of failure the multicast address is bound to an existing interface. * - on some systems it is perfectly legal to assign the same address to * multiple interfaces. Therefore this code does not really keep a list of interfaces * but a list of interfaces that represent a unique address as determined by the kernel * by the procedure in findlocalinterface. Thus it is perfectly legal to see only - * one representavive of a group of real interfaces if they share the same address. + * one representative of a group of real interfaces if they share the same address. * * Frank Kardel 20050910 */ @@ -1034,7 +1055,7 @@ update_interfaces( * this is new or refreshing failed - add to our interface list * if refreshing failed we will delete the interface structure in * phase 2 as the interface was not marked current. We can bind to - * the address as the refresh code already closed to offending socket + * the address as the refresh code already closed the offending socket */ iface = create_interface(port, &interface); @@ -2124,6 +2145,24 @@ open_socket( return (INVALID_SOCKET); } + +#if defined(SO_TIMESTAMP) && defined(SCM_TIMESTAMP) + { + if (setsockopt(fd, SOL_SOCKET, SO_TIMESTAMP, + (char*)&on, sizeof(on))) + { + netsyslog(LOG_DEBUG, + "setsockopt SO_TIMESTAMP on fails on address %s: %m", + stoa(addr)); + } +#ifdef DEBUG + else + { + DPRINTF(1, ("setsockopt SO_TIMESTAMP enabled on fd %d address %s\n", fd, stoa(addr))); + } +#endif + } +#endif DPRINTF(1, ("bind() fd %d, family %d, port %d, addr %s, flags=0x%x\n", fd, addr->ss_family, @@ -2156,7 +2195,7 @@ open_socket( } #if !defined(SYS_WINNT) && !defined(VMS) - DPRINTF(1, ("flags for fd %d: 0%o\n", fd, + DPRINTF(1, ("flags for fd %d: 0x%x\n", fd, fcntl(fd, F_GETFL, 0))); #endif /* SYS_WINNT || VMS */ @@ -2449,7 +2488,6 @@ read_refclock_packet(SOCKET fd, struct refclockio *rp, l_fp ts) return (buflen); } - i = (rp->datalen == 0 || rp->datalen > sizeof(rb->recv_space)) ? sizeof(rb->recv_space) : rp->datalen; @@ -2463,6 +2501,7 @@ read_refclock_packet(SOCKET fd, struct refclockio *rp, l_fp ts) freerecvbuf(rb); return (buflen); } + /* * Got one. Mark how and when it got here, * put it on the full list and do bookkeeping. @@ -2508,6 +2547,12 @@ read_network_packet(SOCKET fd, struct interface *itf, l_fp ts) int fromlen; int buflen; register struct recvbuf *rb; +#if defined(SO_TIMESTAMP) && defined(SCM_TIMESTAMP) + struct msghdr msghdr; + struct iovec iovec; + char control[5120]; /* pick up control messages */ + struct cmsghdr *cmsghdr; +#endif /* * Get a buffer and read the frame. If we @@ -2540,11 +2585,26 @@ read_network_packet(SOCKET fd, struct interface *itf, l_fp ts) } fromlen = sizeof(struct sockaddr_storage); + +#if !defined(SO_TIMESTAMP) || !defined(SCM_TIMESTAMP) rb->recv_length = recvfrom(fd, (char *)&rb->recv_space, sizeof(rb->recv_space), 0, (struct sockaddr *)&rb->recv_srcadr, &fromlen); +#else + iovec.iov_base = (void *)&rb->recv_space; + iovec.iov_len = sizeof(rb->recv_space); + msghdr.msg_name = (void *)&rb->recv_srcadr; + msghdr.msg_namelen = sizeof(rb->recv_space); + msghdr.msg_iov = &iovec; + msghdr.msg_iovlen = 1; + msghdr.msg_control = (void *)&control; + msghdr.msg_controllen = sizeof(control); + msghdr.msg_flags = 0; + rb->recv_length = recvmsg(fd, &msghdr, 0); +#endif + if (rb->recv_length == 0|| (rb->recv_length == -1 && (errno==EWOULDBLOCK #ifdef EAGAIN @@ -2562,6 +2622,43 @@ read_network_packet(SOCKET fd, struct interface *itf, l_fp ts) freerecvbuf(rb); return (rb->recv_length); } +#if defined(SO_TIMESTAMP) && defined(SCM_TIMESTAMP) + cmsghdr = CMSG_FIRSTHDR(&msghdr); + while (cmsghdr != NULL) { + switch (cmsghdr->cmsg_type) + { + case SCM_TIMESTAMP: + { + struct timeval *tvp = (struct timeval *)CMSG_DATA(cmsghdr); + double dtemp; + l_fp nts; + DPRINTF(2, ("input_handler: system network time stamp: %ld.%06ld\n", tvp->tv_sec, tvp->tv_usec)); + nts.l_i = tvp->tv_sec + JAN_1970; + dtemp = tvp->tv_usec / 1e6; + /* fuzz lower bits not covered by precision */ + if (sys_precision != 0) + dtemp += (ntp_random() / FRAC - .5) / (1 << + -sys_precision); + nts.l_uf = (u_int32)(dtemp*FRAC); +#ifdef DEBUG + { + l_fp dts = ts; + L_SUB(&dts, &nts); + rb->dstadr = itf; + collect_timing(rb, "input processing delay", 1, &dts); + DPRINTF(2, ("input_handler: timestamp delta: %s (incl. prec fuzz)\n", lfptoa(&dts, 9))); + } +#endif + ts = nts; /* replace loop timestamp by network time stamp */ + break; + } + default: + DPRINTF(1, ("input_handler: skipping control message %d\n", cmsghdr->cmsg_type)); + break; + } + cmsghdr = CMSG_NXTHDR(&msghdr, cmsghdr); + } +#endif #ifdef DEBUG if (debug > 2) { if(rb->recv_srcadr.ss_family == AF_INET) @@ -2761,6 +2858,7 @@ input_handler( * it. */ L_SUB(&ts_e, &ts); + collect_timing(NULL, "input handler", 1, &ts_e); if (debug > 3) netsyslog(LOG_INFO, "input_handler: Processed a gob of fd's in %s msec", lfptoms(&ts_e, 6)); #endif @@ -2800,6 +2898,16 @@ findinterface( /* * findlocalinterface - find local interface index corresponding to address + * + * This code attempts to find the local sending address for an outgoing + * address by connecting a new socket to destinationaddress:NTP_PORT + * and reading the sockname of the resulting connect. + * the complicated sequence simulates the routing table lookup + * for to first hop without duplicating any of the routing logic into + * ntpd. preferably we would have used an API call - but its not there - + * so this is the best we can do here short of duplicating to entire routing + * logic in ntpd which would be a silly and really unportable thing to do. + * */ struct interface * findlocalinterface( @@ -2815,12 +2923,6 @@ findlocalinterface( DPRINTF(2, ("Finding interface for addr %s in list of addresses\n", stoa(addr));) - /* - * This is considerably hoke. We open a socket, connect to it - * and slap a getsockname() on it. If anything breaks, as it - * probably will in some j-random knockoff, we just return the - * NULL - */ memset(&saddr, 0, sizeof(saddr)); saddr.ss_family = addr->ss_family; if(addr->ss_family == AF_INET) { @@ -3144,6 +3246,7 @@ io_closeclock( struct refclockio *rio ) { + BLOCKIO(); /* * Remove structure from the list */ @@ -3162,14 +3265,17 @@ io_closeclock( break; } - if (rp == NULL) + if (rp == NULL) { + UNBLOCKIO(); return; + } } /* * Close the descriptor. */ close_and_delete_fd_from_list(rio->fd); + UNBLOCKIO(); } #endif /* REFCLOCK */ @@ -3201,6 +3307,7 @@ kill_asyncio(int startfd) lsock = next; } + UNBLOCKIO(); } /* diff --git a/ntpd/ntp_util.c b/ntpd/ntp_util.c index aba30b77c..7c100e622 100644 --- a/ntpd/ntp_util.c +++ b/ntpd/ntp_util.c @@ -79,6 +79,9 @@ static FILEGEN loopstats; static FILEGEN clockstats; static FILEGEN rawstats; static FILEGEN sysstats; +#ifdef DEBUG +static FILEGEN timingstats; +#endif #ifdef OPENSSL static FILEGEN cryptostats; #endif /* OPENSSL */ @@ -118,6 +121,9 @@ init_util(void) filegen_register(&statsdir[0], "cryptostats", &cryptostats); #endif /* OPENSSL */ +#ifdef DEBUG + filegen_register(&statsdir[0], "timingstats", &timingstats); +#endif } @@ -457,6 +463,7 @@ record_peer_stats( fflush(peerstats.fp); } } + /* * record_loop_stats - write loop filter statistics to file * @@ -647,7 +654,39 @@ record_crypto_stats( } #endif /* OPENSSL */ +#ifdef DEBUG +/* + * record_crypto_stats - write crypto statistics to file + * + * file format: + * day (mjd) + * time (s past midnight) + * text message + */ +void +record_timing_stats( + const char *text + ) +{ + static unsigned int flshcnt; + l_fp now; + u_long day; + + if (!stats_control) + return; + get_systime(&now); + filegen_setup(&timingstats, now.l_ui); + day = now.l_ui / 86400 + MJD_1900; + now.l_ui %= 86400; + if (timingstats.fp != NULL) { + fprintf(timingstats.fp, "%lu %s %s\n", + day, lfptoa(&now, 3), text); + if (++flshcnt % 100 == 0) + fflush(timingstats.fp); + } +} +#endif /* * getauthkeys - read the authentication keys from the specified file */ diff --git a/ntpd/ntpd.c b/ntpd/ntpd.c index 43497ed44..a8ad81e7e 100644 --- a/ntpd/ntpd.c +++ b/ntpd/ntpd.c @@ -958,29 +958,55 @@ getgroup: #endif /* HAVE_IO_COMPLETION_PORT */ - rbuf = get_full_recv_buffer(); - while (rbuf != NULL) +#ifdef DEBUG { + l_fp pts; + l_fp tsa, tsb; + int bufcount = 0; + + get_systime(&pts); + tsa = pts; +#endif + rbuf = get_full_recv_buffer(); + while (rbuf != NULL) + { # ifdef HAVE_SIGNALED_IO - unblock_io_and_alarm(); + unblock_io_and_alarm(); # endif /* HAVE_SIGNALED_IO */ - /* - * Call the data procedure to handle each received - * packet. - */ - if (rbuf->receiver != NULL) /* This should always be true */ - { - (rbuf->receiver)(rbuf); - } else { - msyslog(LOG_ERR, "receive buffer corruption - receiver found to be NULL - ABORTING"); - abort(); - } + /* + * Call the data procedure to handle each received + * packet. + */ + if (rbuf->receiver != NULL) /* This should always be true */ + { +#ifdef DEBUG + l_fp dts = pts; + + L_SUB(&dts, &rbuf->recv_time); + DPRINTF(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, "receive buffer corruption - receiver found to be NULL - ABORTING"); + abort(); + } # ifdef HAVE_SIGNALED_IO - block_io_and_alarm(); + block_io_and_alarm(); # endif /* HAVE_SIGNALED_IO */ - freerecvbuf(rbuf); - rbuf = get_full_recv_buffer(); + freerecvbuf(rbuf); + rbuf = get_full_recv_buffer(); + } +#ifdef DEBUG + get_systime(&tsb); + L_SUB(&tsb, &tsa); + if (bufcount) { + collect_timing(NULL, "processing", bufcount, &tsb); + DPRINTF(2, ("processing time for %d buffers %s\n", bufcount, lfptoa(&tsb, 9))); + } } +#endif /* * Go around again