Re: high cpu load with tcpdump

[Manuel Bouyer]

On Tue, Aug 30, 2016 at 04:12:02PM +0200, Rhialto wrote:
> Meanwhile, in 7.0.1, tcpdump still seems to cause (close to) 100% cpu
> load.  (Tested with "tcpdump -i re1 -vvv icmp6" on an almost idle link)
> 
> Has this been fixed in -current? Will it be in 7.0.2 (or 7.1?) soon?

I'm not sure it has been fixed. I'm seeing such issues with arpwatch
or ndpwatch (which uses bpf too).

-- 
Manuel Bouyer 
 NetBSD: 26 ans d'experience feront toujours la difference
--

Re: high cpu load with tcpdump

[Rhialto]

On Sun 06 Mar 2016 at 18:59:57 +0100, Manuel Bouyer wrote:
> On Fri, Mar 04, 2016 at 12:31:07PM +, Patrick Welche wrote:
> > Was there ever a conclusion to the "pipe read returning EAGAIN" thread?
> > 
> >   https://mail-index.netbsd.org/current-users/2016/02/07/msg028841.html
> 
> The conclusion was that it's a programming error in the application,
> but there's still something messy with poll (it says there's one descriptor
> ready for read but there are two descriptors in the fileset).

Meanwhile, in 7.0.1, tcpdump still seems to cause (close to) 100% cpu
load.  (Tested with "tcpdump -i re1 -vvv icmp6" on an almost idle link)

Has this been fixed in -current? Will it be in 7.0.2 (or 7.1?) soon?

-Olaf.
-- 
___ Olaf 'Rhialto' Seibert  -- Wayland: Those who don't understand X
\X/ rhialto/at/xs4all.nl-- are condemned to reinvent it. Poorly.


signature.asc
Description: PGP signature

Re: high cpu load with tcpdump

[Manuel Bouyer]

On Fri, Mar 04, 2016 at 12:31:07PM +, Patrick Welche wrote:
> Was there ever a conclusion to the "pipe read returning EAGAIN" thread?
> 
>   https://mail-index.netbsd.org/current-users/2016/02/07/msg028841.html

The conclusion was that it's a programming error in the application,
but there's still something messy with poll (it says there's one descriptor
ready for read but there are two descriptors in the fileset).

-- 
Manuel Bouyer 
 NetBSD: 26 ans d'experience feront toujours la difference
--

Re: high cpu load with tcpdump

[Patrick Welche]

Was there ever a conclusion to the "pipe read returning EAGAIN" thread?

  https://mail-index.netbsd.org/current-users/2016/02/07/msg028841.html

Cheers,

Patrick

Re: high cpu load with tcpdump

[Patrick Welche]

On Mon, Feb 29, 2016 at 09:11:44PM +0100, 6b...@6bone.informatik.uni-leipzig.de 
wrote:
>   2362  9 named1456773617.648034355 CALL  
> setsockopt(0x262,0x,0x800,0x7f7ff09f8484,4)

SOL_SOCKET SO_NOSIGPIPE

>   2362  6 named1456773618.151732844 CALL  
> setsockopt(0x260,0x,0x2000,0x7f7ff15fb484,4)

SOL_SOCKET SO_TIMESTAMP

On the citrix receiver front setsockopt is called with

SOL_SOCKET SO_SNDBUF

and dansguardian oddly does

IPPROTO_TCP TCP_NODELAY
SOL_SOCKET SO_REUSEADDR

so another dead end...

Cheers,

Patrick

Re: high cpu load with tcpdump

[6bone]

On Mon, 29 Feb 2016, Christos Zoulas wrote:



This tcpdump ktrace is when bind is running, right?
What happens if you stop it? How does the ktrace look then?
Or once you start bind, tcpdump goes nuts and stays that way?


You're right. When tcpdump is started after the bind, tcpdump caused 
problems.



Here the ktrace (tcpdump before bind)

  3451  1 tcpdump  1456839639.234979724 RET   read 0
  3451  1 tcpdump  1456839639.234983565 CALL  read(3,0x7f7ff7b16000,0x8)
  3451  1 tcpdump  1456839640.235319234 GIO   fd 3 read 0 bytes  ""
  3451  1 tcpdump  1456839640.235322516 RET   read 0
  3451  1 tcpdump  1456839640.235328872 CALL  read(3,0x7f7ff7b16000,0x8)
  3451  1 tcpdump  1456839641.235662445 GIO   fd 3 read 0 bytes  ""
  3451  1 tcpdump  1456839641.235665868 RET   read 0
  3451  1 tcpdump  1456839641.235670128 CALL  read(3,0x7f7ff7b16000,0x8)
  3451  1 tcpdump  1456839642.236012990 GIO   fd 3 read 0 bytes  ""
  3451  1 tcpdump  1456839642.236017460 RET   read 0
  3451  1 tcpdump  1456839642.236021371 CALL  read(3,0x7f7ff7b16000,0x8)
  3451  1 tcpdump  1456839643.236348030 GIO   fd 3 read 0 bytes  ""


In this case all works fine. There is also no change in the bind ktrace.


Regards
Uwe

Re: high cpu load with tcpdump

[Christos Zoulas]

On Feb 29,  9:11pm, 6b...@6bone.informatik.uni-leipzig.de 
(6b...@6bone.informatik.uni-leipzig.de) wrote:
-- Subject: Re: high cpu load with tcpdump

| On Mon, 29 Feb 2016, Christos Zoulas wrote:
| 
| > | Hello,
| > |
| > | the problem occurs only on one of my servers. I tried to find the
| > | difference. It is the bind9 (bind-9.10.3pl3). If I stop the bind9, tcpdump
| > | works without problems. When I restart the bind9, the CPU load goes back
| > | to 100%.
| > |
| > | Is it a problem of the kernel, tcpdump or bind9?
| >
| > Can you ktrace the bind? Perhaps it is waking up tcpdump spuriously.
| > That would indicate a kernel problem.
| 
| ktrace tcpdump starting at timestamp 1456773618

This tcpdump ktrace is when bind is running, right?
What happens if you stop it? How does the ktrace look then?
Or once you start bind, tcpdump goes nuts and stays that way?

christos

Re: high cpu load with tcpdump

[6bone]

On Mon, 29 Feb 2016, Christos Zoulas wrote:


| Hello,
|
| the problem occurs only on one of my servers. I tried to find the
| difference. It is the bind9 (bind-9.10.3pl3). If I stop the bind9, tcpdump
| works without problems. When I restart the bind9, the CPU load goes back
| to 100%.
|
| Is it a problem of the kernel, tcpdump or bind9?

Can you ktrace the bind? Perhaps it is waking up tcpdump spuriously.
That would indicate a kernel problem.


ktrace tcpdump starting at timestamp 1456773618

  1847  1 tcpdump  1456773617.99648 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.01813 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.03699 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.06213 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.08029 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.10333 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.12289 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.15641 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.17667 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.20111 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.22206 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.24860 RET   read -1 errno 35 Resource 
temporarily unavailable
  1847  1 tcpdump  1456773618.26746 CALL  read(3,0x7f7ff7b16000,0x8)
  1847  1 tcpdump  1456773618.28981 RET   read -1 errno 35 Resource 
temporarily unavailable
...


ktrace named starting at timestamp 1456773618

  2362  9 named1456773617.648034355 CALL  
setsockopt(0x262,0x,0x800,0x7f7ff09f8484,4)
  2362  6 named1456773618.151726698 RET   setsockopt 0
  2362  6 named1456773618.151732844 CALL  
setsockopt(0x260,0x,0x2000,0x7f7ff15fb484,4)
  2362  3 named1456773618.151748627 RET   setsockopt 0
  2362  6 named1456773618.151749815 RET   setsockopt 0
  2362  3 named1456773618.151760291 CALL  
getsockopt(0x261,0x,0x1002,0x7f7ff21fe43c,0x7f7ff21fe438)
  2362  6 named1456773618.151763224 CALL  
getsockopt(0x260,0x,0x1002,0x7f7ff15fb48c,0x7f7ff15fb488)
  2362  9 named1456773618.151783617 RET   setsockopt 0
  2362  3 named1456773618.151790601 RET   getsockopt 0
  2362  6 named1456773618.151792696 RET   getsockopt 0
  2362  5 named1456773618.151793395 RET   __socket30 14/0xe
  2362  3 named1456773618.151807642 CALL  
bind(0x261,0x7f7ff21fe630,0x10)
  2362  5 named1456773618.151812601 CALL  fcntl(0xe,0,0x200)
  2362  9 named1456773618.151791509 CALL  
setsockopt(0x262,0x,0x2000,0x7f7ff09f8484,4)
  2362  3 named1456773618.151817071 MISC  mbsoname: [0.0.0.0]
  2362  6 named1456773618.151803941 CALL  
bind(0x260,0x7f7ff15fb680,0x10)
  2362  6 named1456773618.151832016 MISC  mbsoname: [0.0.0.0]
  2362  3 named1456773618.151861768 RET   bind 0
  2362  5 named1456773618.151883279 RET   fcntl 611/0x263
  2362  3 named1456773618.151884815 CALL  
recvmsg(0x261,0x7f7ff21fe320,0)
  2362  5 named1456773618.151889844 CALL  close(0xe)
  2362  3 named1456773618.151893545 MISC  msghdr: [name=0x7f7fef511088, 
namelen=128, iov=0x7f7ff21fe350, iovlen=1, control=0x7f7ff39a6fa0, 
controllen=96, flags=400]
  2362  5 named1456773618.151908980 RET   close 0
  2362  5 named1456773618.151913729 CALL  fcntl(0x263,3,0)
  2362  5 named1456773618.151916732 RET   fcntl 2
  2362  5 named1456773618.151920992 CALL  fcntl(0x263,4,6)
  2362  9 named1456773618.151922808 RET   setsockopt 0
  2362  9 named1456773618.151943900 CALL  
getsockopt(0x262,0x,0x1002,0x7f7ff09f848c,0x7f7ff09f8488)
  2362  9 named1456773618.151980705 RET   getsockopt 0
  2362  9 named1456773618.151992299 CALL  
bind(0x262,0x7f7ff09f8680,0x10)
  2362  9 named1456773618.15251 MISC  mbsoname: [0.0.0.0]
  2362 11 named1456773618.152002845 RET   close 0
  2362 11 named1456773618.152016184 CALL  read(5,0x7f7ff01f6f10,8)
  2362  9 named1456773618.152018768 RET   bind 0
  2362  6 named1456773618.152018140 RET   bind 0
  2362  3 named1456773618.152029244 RET   recvmsg -1 errno 35 Resource 
temporarily unavailable
  2362 11 named1456773618.152035390 GIO   fd 5 read 8 bytes 
",\^B\0\0\M-{\M^?\M^?\M^?"
  2362 11 named1456773618.152041396 RET   read 8
  2362  6 named1456773618.152040698 CALL  
recvmsg(0x260,0x7f7ff15fb370,0)
  2362  9 named1456773618.152033854 CALL  
recvmsg(0x262,0x7f7ff09f8370,0)
  2362 11 named1456773618.152050266 CALL  

Re: high cpu load with tcpdump

[Christos Zoulas]

On Feb 29,  2:48pm, 6b...@6bone.informatik.uni-leipzig.de 
(6b...@6bone.informatik.uni-leipzig.de) wrote:
-- Subject: Re: high cpu load with tcpdump

| On Sat, 27 Feb 2016, 6b...@6bone.informatik.uni-leipzig.de wrote:
| 
| > Date: Sat, 27 Feb 2016 23:52:24 +0100 (CET)
| > From: 6b...@6bone.informatik.uni-leipzig.de
| > To: Joerg Sonnenberger <jo...@britannica.bec.de>
| > Cc: current-users@netbsd.org
| > Subject: Re: high cpu load with tcpdump
| > 
| > On Sat, 27 Feb 2016, Joerg Sonnenberger wrote:
| >
| >> fstat should tell you what the file descriptor is, I just want to
| >> identify what device seems to have the trouble.
| 
| Hello,
| 
| the problem occurs only on one of my servers. I tried to find the 
| difference. It is the bind9 (bind-9.10.3pl3). If I stop the bind9, tcpdump 
| works without problems. When I restart the bind9, the CPU load goes back 
| to 100%.
| 
| Is it a problem of the kernel, tcpdump or bind9?

Can you ktrace the bind? Perhaps it is waking up tcpdump spuriously.
That would indicate a kernel problem.

christos

Re: high cpu load with tcpdump

[6bone]

On Sat, 27 Feb 2016, 6b...@6bone.informatik.uni-leipzig.de wrote:


Date: Sat, 27 Feb 2016 23:52:24 +0100 (CET)
From: 6b...@6bone.informatik.uni-leipzig.de
To: Joerg Sonnenberger <jo...@britannica.bec.de>
Cc: current-users@netbsd.org
Subject: Re: high cpu load with tcpdump

On Sat, 27 Feb 2016, Joerg Sonnenberger wrote:


fstat should tell you what the file descriptor is, I just want to
identify what device seems to have the trouble.


Hello,

the problem occurs only on one of my servers. I tried to find the 
difference. It is the bind9 (bind-9.10.3pl3). If I stop the bind9, tcpdump 
works without problems. When I restart the bind9, the CPU load goes back 
to 100%.


Is it a problem of the kernel, tcpdump or bind9?


Thank you for your efforts


Regards
Uwe

Re: high cpu load with tcpdump

[6bone]

On Sat, 27 Feb 2016, Joerg Sonnenberger wrote:


fstat should tell you what the file descriptor is, I just want to
identify what device seems to have the trouble.



You're right.

USER CMD  PID   FD MOUNT   INUM MODE SZ|DV R/W
_tcpdump tcpdump  823 root /14249633 drwxr-xr-x 512 r
_tcpdump tcpdump  823   wd /14249633 drwxr-xr-x 512 r
_tcpdump tcpdump  8230 /dev/pts   5 crw--w--w-   pts/1 rw
_tcpdump tcpdump  8231 /dev/pts   5 crw--w--w-   pts/1 rw
_tcpdump tcpdump  8232 /dev/pts   5 crw--w--w-   pts/1 rw
_tcpdump tcpdump  8233* bpf rec=0, dr=0, cap=0, pid=823, seesent, idle
_tcpdump tcpdump  8234 /9157214 -rw-r--r--   25628 r
_tcpdump tcpdump  8235* kqueue pending 0
_tcpdump tcpdump  8236 /9157439 -rw-r--r--  71 r



Regards
Uwe

Re: high cpu load with tcpdump

[Joerg Sonnenberger]

On Sat, Feb 27, 2016 at 10:28:43PM +0100, 6b...@6bone.informatik.uni-leipzig.de 
wrote:
> On Sat, 27 Feb 2016, Joerg Sonnenberger wrote:
> 
> >Date: Sat, 27 Feb 2016 20:38:37 +0100
> >From: Joerg Sonnenberger <jo...@britannica.bec.de>
> >To: current-users@netbsd.org
> >Subject: Re: high cpu load with tcpdump
> >
> >On Sat, Feb 27, 2016 at 08:18:41PM +0100, 
> >6b...@6bone.informatik.uni-leipzig.de wrote:
> >>  5015  1 tcpdump  1456559035.621583576 CALL  
> >> read(3,0x7f7ff7b16000,0x8)
> >
> >FD 3 is a BPF instance?
> >
> >Joerg
> >
> 
> I don't know what FD 3 is used for, perhaps it could be a BPF descriptor.

fstat should tell you what the file descriptor is, I just want to
identify what device seems to have the trouble.

Joerg

Re: high cpu load with tcpdump

[6bone]

On Sat, 27 Feb 2016, Joerg Sonnenberger wrote:


Date: Sat, 27 Feb 2016 20:38:37 +0100
From: Joerg Sonnenberger <jo...@britannica.bec.de>
To: current-users@netbsd.org
Subject: Re: high cpu load with tcpdump

On Sat, Feb 27, 2016 at 08:18:41PM +0100, 6b...@6bone.informatik.uni-leipzig.de 
wrote:

  5015  1 tcpdump  1456559035.621583576 CALL  read(3,0x7f7ff7b16000,0x8)


FD 3 is a BPF instance?

Joerg



I don't know what FD 3 is used for, perhaps it could be a BPF descriptor.

modstat | grep bpf
bpf  driver builtin7 0--
if_athn_usb  driver builtin0 0-bpf
if_axe   driver builtin0 0-bpf
if_axen  driver builtin0 0-bpf
if_rum   driver builtin0 0-bpf
if_run   driver builtin0 0-bpf
if_urtw  driver builtin0 0-bpf
if_urtwn driver builtin0 0-bpf

But I think this is the default of all kernels based at the GENERIC 
configuration. The system has some ipfilter rules but no npf 
configuration. Stopping ipfilter has no impact to the tcpdump problem.



Regards
Uwe

Re: high cpu load with tcpdump

[Joerg Sonnenberger]

On Sat, Feb 27, 2016 at 08:18:41PM +0100, 6b...@6bone.informatik.uni-leipzig.de 
wrote:
>   5015  1 tcpdump  1456559035.621583576 CALL  
> read(3,0x7f7ff7b16000,0x8)

FD 3 is a BPF instance?

Joerg

Re: high cpu load with tcpdump

[6bone]

On Fri, 26 Feb 2016, Christos Zoulas wrote:


Date: Fri, 26 Feb 2016 14:52:46 + (UTC)
From: Christos Zoulas <chris...@astron.com>
To: current-users@netbsd.org
Subject: Re: high cpu load with tcpdump

In article <pine.neb.4.64.1602261452000.28...@6bone.informatik.uni-leipzig.de>,
<6b...@6bone.informatik.uni-leipzig.de> wrote:

Hello,

On my router tcpdump uses always 100% CPU.

  PID USERNAME PRI NICE   SIZE   RES STATE  TIME   WCPUCPU COMMAND
 3403 _tcpdump  38019M 3016K RUN/6  0:24 98.08% 70.02% tcpdump
0 root   00 0K 1182M CPU/7 49:35  0.00%  3.76% [system]

The problem also occurs when tcpdump is listening on an interface
with no network traffic. Therefore, it can not be a load problem.

The problem does not occur on all interfaces.

ixg(0|1), bnx(0|1) and tap(0|1) are affected.

lo0, stf0 and vlan* are not affected.


System is: NetBSD 7.0_STABLE

Any idea what could be the problem?


Thank you for your efforts.


ktrace please?

christos


...
  5015  1 tcpdump  1456559035.621583576 CALL  read(3,0x7f7ff7b16000,0x8)
  5015  1 tcpdump  1456559035.621593842 RET   read -1 errno 35 Resource 
temporarily unavailable
  5015  1 tcpdump  1456559035.621595938 CALL  read(3,0x7f7ff7b16000,0x8)
  5015  1 tcpdump  1456559035.621598033 RET   read -1 errno 35 Resource 
temporarily unavailable
  5015  1 tcpdump  1456559035.621599849 CALL  read(3,0x7f7ff7b16000,0x8)
  5015  1 tcpdump  1456559035.621601944 RET   read -1 errno 35 Resource 
temporarily unavailable
  5015  1 tcpdump  1456559035.621603690 CALL  read(3,0x7f7ff7b16000,0x8)
  5015  1 tcpdump  1456559035.621605785 RET   read -1 errno 35 Resource 
temporarily unavailable
  5015  1 tcpdump  1456559035.621607601 CALL  read(3,0x7f7ff7b16000,0x8)
  5015  1 tcpdump  1456559035.621609626 RET   read -1 errno 35 Resource 
temporarily unavailable
...

There are more than 150,000 read operations per second.
When a data packet is sent or received by the interface, the data packet 
is displayed correctly.



Regards
Uwe

Re: high cpu load with tcpdump

[Christos Zoulas]

In article ,
 <6b...@6bone.informatik.uni-leipzig.de> wrote:
>Hello,
>
>On my router tcpdump uses always 100% CPU.
>
>   PID USERNAME PRI NICE   SIZE   RES STATE  TIME   WCPUCPU COMMAND
>  3403 _tcpdump  38019M 3016K RUN/6  0:24 98.08% 70.02% tcpdump
> 0 root   00 0K 1182M CPU/7 49:35  0.00%  3.76% [system]
>
>The problem also occurs when tcpdump is listening on an interface 
>with no network traffic. Therefore, it can not be a load problem.
>
>The problem does not occur on all interfaces.
>
>ixg(0|1), bnx(0|1) and tap(0|1) are affected.
>
>lo0, stf0 and vlan* are not affected.
>
>
>System is: NetBSD 7.0_STABLE
>
>Any idea what could be the problem?
>
>
>Thank you for your efforts.

ktrace please?

christos

high cpu load with tcpdump

[6bone]

Hello,

On my router tcpdump uses always 100% CPU.

  PID USERNAME PRI NICE   SIZE   RES STATE  TIME   WCPUCPU COMMAND
 3403 _tcpdump  38019M 3016K RUN/6  0:24 98.08% 70.02% tcpdump
0 root   00 0K 1182M CPU/7 49:35  0.00%  3.76% [system]

The problem also occurs when tcpdump is listening on an interface 
with no network traffic. Therefore, it can not be a load problem.


The problem does not occur on all interfaces.

ixg(0|1), bnx(0|1) and tap(0|1) are affected.

lo0, stf0 and vlan* are not affected.


System is: NetBSD 7.0_STABLE

Any idea what could be the problem?


Thank you for your efforts.


Regards
Uwe