From owner-freebsd-net@FreeBSD.ORG Tue Jul 1 06:06:49 2008 Return-Path: Delivered-To: freebsd-net@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id B002F106567B; Tue, 1 Jul 2008 06:06:49 +0000 (UTC) (envelope-from mike@sentex.net) Received: from smarthost1.sentex.ca (smarthost1.sentex.ca [64.7.153.18]) by mx1.freebsd.org (Postfix) with ESMTP id 847668FC1D; Tue, 1 Jul 2008 06:06:49 +0000 (UTC) (envelope-from mike@sentex.net) Received: from lava.sentex.ca (pyroxene.sentex.ca [199.212.134.18]) by smarthost1.sentex.ca (8.14.2/8.14.2) with ESMTP id m6166k6i062688; Tue, 1 Jul 2008 02:06:46 -0400 (EDT) (envelope-from mike@sentex.net) Received: from mdt-xp.sentex.net (simeon.sentex.ca [192.168.43.27]) by lava.sentex.ca (8.13.8/8.13.3) with ESMTP id m6166jFe084204 (version=TLSv1/SSLv3 cipher=DHE-RSA-AES256-SHA bits=256 verify=NO); Tue, 1 Jul 2008 02:06:46 -0400 (EDT) (envelope-from mike@sentex.net) Message-Id: <200807010606.m6166jFe084204@lava.sentex.ca> X-Mailer: QUALCOMM Windows Eudora Version 7.1.0.9 Date: Tue, 01 Jul 2008 02:06:53 -0400 To: "Bruce M. Simpson" From: Mike Tancsa In-Reply-To: References: <4852E23E.2040505@gtcomm.net> <4854EBF1.7020708@FreeBSD.org> Mime-Version: 1.0 Content-Type: text/plain; charset="us-ascii"; format=flowed X-Scanned-By: MIMEDefang 2.64 on 64.7.153.18 Cc: freebsd-net@freebsd.org, bz@freebsd.org, Paul Subject: Re: Route messages X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 01 Jul 2008 06:06:49 -0000 At 10:34 PM 6/27/2008, mike@sentex.net wrote: >On Sun, 15 Jun 2008 11:16:17 +0100, in sentex.lists.freebsd.net you >wrote: > > >Paul wrote: > >> Get these with GRE tunnel on > >> FreeBSD 7.0-STABLE FreeBSD 7.0-STABLE #5: Sun May 11 19:00:57 EDT > >> 2008 :/usr/obj/usr/src/sys/ROUTER amd64 > >> But do not get them with 7.0-RELEASE > >> > >> Any ideas what changed? :) Wish there was some sort of changelog.. > >> # of messages per second seems consistent with packets per second on > >> GRE interface.. > >> No impact in routing, but definitely impact in cpu usage for all > >> processes monitoring the route messages. > > > >RTM_MISS is actually fairly common when you don't have a default route. > > > >Hi, > I am seeing this issue as well on a pair of recently deployed >boxes, one running MPD and one acting as an area router in front of >it. The MPD box has a default route and only has 400 routes or so. > >A steady stream of those messages, upwards of 500 per second. > >got message of size 96 on Fri Jun 27 22:25:42 2008 >RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno >0, flags: >locks: inits: >sockaddrs: > default > >got message of size 96 on Fri Jun 27 22:25:42 2008 >RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno >0, flags: >locks: inits: >sockaddrs: > default > >Is there a way to try and track down what is generating those messages >? Its eating up a fair bit of cpu with quagga (the zebra process >specifically) I narrowed down where the change to RELENG_7 happened. It looks like a commit around April 22nd caused the behaviour to change. When a box acting as a router has a packet transit it, an RTM_MISS is generated for *each packet*... Given a setup of H1 ---- R1 ----- H2 where H1 is 10.10.1.2/24 H2 is 10.20.1.2/24 and R1 has 2 interfaces, 10.10.1.1/24 and 10.20.1.1/24 Pinging H2 from H1 makes R1 generate a RTM_MISS for each packet! For routing daemons such as zebra, this eats up a *lot* of CPU. Turning on ip_fast_forwarding stops this behaviour on R1. However, if the interface routing the packet is an netgraph interface (e.g. mpd) fast_forwarding doesnt seem to have an effect and the RTM_MISS messages are generated again for each packet. The ping packet below is a valid icmp echo request and reply. e.g 0[releng7]# ping -c 2 -S 10.20.1.2 10.10.1.2 PING 10.10.1.2 (10.10.1.2) from 10.20.1.2: 56 data bytes 64 bytes from 10.10.1.2: icmp_seq=0 ttl=63 time=0.302 ms 64 bytes from 10.10.1.2: icmp_seq=1 ttl=63 time=0.337 ms --- 10.10.1.2 ping statistics --- 2 packets transmitted, 2 packets received, 0.0% packet loss round-trip min/avg/max/stddev = 0.302/0.320/0.337/0.018 ms 0[releng7]# generates 4 messages on the router [r7-router]# route -n monitor got message of size 96 on Tue Jul 1 00:42:35 2008 RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno 0, flags: locks: inits: sockaddrs: default got message of size 96 on Tue Jul 1 00:42:35 2008 RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno 0, flags: locks: inits: sockaddrs: default got message of size 96 on Tue Jul 1 00:42:36 2008 RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno 0, flags: locks: inits: sockaddrs: default got message of size 96 on Tue Jul 1 00:42:36 2008 RTM_MISS: Lookup failed on this address: len 96, pid: 0, seq 0, errno 0, flags: locks: inits: sockaddrs: default I am thinking http://lists.freebsd.org/pipermail/cvs-src/2008-April/090303.html is the commit ? If I revert to the prev version, the issue goes away. kernel is just 0[r7-router]% diff router GENERIC 24,27c24 < ident router < < makeoptions MODULES_OVERRIDE="ipfw acpi" < --- > ident GENERIC 37,38c34,35 < #options INET6 # IPv6 communications protocols < #options SCTP # Stream Control Transmission Protocol --- > options INET6 # IPv6 communications protocols > options SCTP # Stream Control Transmission Protocol 47c44 < #options NFSLOCKD # Network Lock Manager --- > options NFSLOCKD # Network Lock Manager 61c58 < #options STACK # stack(9) support --- > options STACK # stack(9) support 303c300 < #device uslcom # SI Labs CP2101/CP2102 serial adapters --- > device uslcom # SI Labs CP2101/CP2102 serial adapters ---Mike