While debugging a problem of my ppp connection I noticed that ppp was apparently doing a protocol lookup (with a file open, read, close sequence) for every packet it read. This is an excerpt from the strace log, one of my favourite debugging tools.
open("/etc/protocols", O_RDONLY) = 1
fstat(1, {st_mode=S_IFREG|0644, st_size=5752, ...}) = 0
read(1, "#\n# Internet protocols\n#\n# $Free"..., 8192) = 5752
close(1) = 0
System calls, are about two orders of magnitude more expensive than
simple function calls;
in measurements I did for a chapter of the
Code Reading
companion volume I am writing I measured that on my platform
a function call took 1.2ns, whereas a FreeBSD 4.9 system call tool 651ns.
int
FilterCheck(const unsigned char *packet, u_int32_t family,
const struct filter *filter, unsigned *psecs)
{
char [...] prototxt[16];
[...]
if ((pe = getprotobynumber(cproto)) == NULL)
snprintf(prototxt, sizeof prototxt, "%d", cproto);
else
snprintf(prototxt, sizeof prototxt, "%s", pe->p_name);
The getprotobynumber call was causing all the inefficient lookups.
It turned out that the prototxt value calculated by the above call
was only used under some very specific conditions.
if (log_IsKept(LogDEBUG)) {
[...]
log_Printf(LogDEBUG, " Filter: proto = %s, %s\n", prototxt, dbuff);
[...]
if (log_IsKept(LogFILTER)) {
snprintf(dstip, sizeof dstip, "%s", ncpaddr_ntoa(&dstaddr));
log_Printf(LogFILTER, "%sbound rule = %d accept %s "
"src = %s:%d dst = %s:%d\n", filter->name, n, prototxt,
ncpaddr_ntoa(&srcaddr), sport, dstip, dport);
[...]
if (log_IsKept(LogFILTER)) {
snprintf(dstip, sizeof dstip, "%s", ncpaddr_ntoa(&dstaddr));
log_Printf(LogFILTER,
"%sbound rule = %d deny %s src = %s/%d dst = %s/%d\n",
filter->name, n, prototxt,
ncpaddr_ntoa(&srcaddr), sport, dstip, dport);
... and so on.
if (log_IsKept(LogDEBUG) || log_IsKept(LogFILTER)) {
if ((pe = getprotobynumber(cproto)) == NULL)
snprintf(prototxt, sizeof prototxt, "%d", cproto);
else
snprintf(prototxt, sizeof prototxt, "%s", pe->p_name);
Then I thought: "what if the logging conditionals within the 279-line function
body someday change?"
So I modified the sequence to create a dummy prototxt value that would
alert the maintainer that something was amiss.
char *prototxt, protobuff[16];
[...]
if (log_IsKept(LogDEBUG) || log_IsKept(LogFILTER)) {
if ((pe = getprotobynumber(cproto)) == NULL)
snprintf(protobuff, sizeof protobuff, "%d", cproto);
else
snprintf(protobuff, sizeof protobuff, "%s", pe->p_name);
prototxt = protobuff;
} else
prototxt = "[Logging conditionals have changed."
"Fix the conditional where this string appears.]";
/*
* Return a text string representing the cproto protocol number.
*
* The purpose of this routine is calculate this result, for
* the many times it is needed in FilterCheck, only on demand
* (i.e. when the corresponding logging functions are invoked).
*
* This optimization saves, over the previous implementation, which
* calculated prototxt at the beginning of FilterCheck, an
* open/read/close system call sequence per packet.
*
* The caching performed here is just a side effect.
*/
static const char *
prototxt(int cproto)
{
static int oproto = 6;
static char protobuff[16] = "tcp";
struct protoent *pe;
if (cproto == oproto)
return protobuff;
if ((pe = getprotobynumber(cproto)) == NULL)
snprintf(protobuff, sizeof protobuff, "%d", cproto);
else
snprintf(protobuff, sizeof protobuff, "%s", pe->p_name);
oproto = cproto;
return (protobuff);
}
static int oproto = -1;
static char protobuff[16] = "-1";
dds 2004/05/13 02:03:00 PDT FreeBSD src repository Modified files: usr.sbin/ppp ip.c Log: Make getprotobynumber() calls in FilterCheck conditional on the log levels by which they are used. On a typical production setting (no debug or filter logging) this will save an open/read/close system call sequence per packet, approximately halving the system overhead and reducing the overall overhead by 38%. dd bs=1k count=512 if=/usr/share/dict/web2 | ssh ppp-linked-host dd of=/dev/null # time original-ppp -nat -foreground connection Working in foreground mode Using interface: tun0 2.822u 2.404s 2:00.31 4.3% 392+496k 8+18io 3pf+0w # time new-ppp -nat -foreground connection Working in foreground mode Using interface: tun0 2.082u 1.173s 1:26.06 3.7% 379+450k 0+18io 0pf+0w MFC after: 3 weeks Revision Changes Path 1.101 +43 -13 src/usr.sbin/ppp/ip.c
Last modified: Sunday, May 16, 2004 1:09 pm
Unless otherwise expressly stated, all original material on this page created by Diomidis Spinellis is licensed under a Creative Commons Attribution-NonCommercial 4.0 International License.