ipset kernel oops

ipset kernel oops

[Mr Dash Four]

During loading of a (rather) large set (consisting of about 30k members) 
I am getting the following kernel error:

Apr 22 22:14:41 test1 kernel: BUG: soft lockup - CPU#0 stuck for 61s! 
[ipset:1568]
Apr 22 22:14:41 test1 kernel: Pid: 1568, comm: ipset Not tainted 
2.6.34.8-68.fc13.i686 #1        /      
Apr 22 22:14:41 test1 kernel: EIP: 0060:[<d3b8c1ea>] EFLAGS: 00000283 CPU: 0
Apr 22 22:14:41 test1 kernel: EIP is at 
iptreemap_list_members_size+0x7a/0xcd [ip_set_iptreemap]
Apr 22 22:14:41 test1 kernel: EAX: 00000252 EBX: 000000f2 ECX: cca59de0 
EDX: 00000001
Apr 22 22:14:41 test1 kernel: ESI: 00000046 EDI: ffffffff EBP: cc3a7e88 
ESP: cc3a7e64
Apr 22 22:14:41 test1 kernel: DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
Apr 22 22:14:41 test1 kernel: Process ipset (pid: 1568, ti=cc3a6000 
task=d0868000 task.ti=cc3a6000)
Apr 22 22:14:41 test1 kernel: Stack:
Apr 22 22:14:41 test1 kernel: 000000ce d07ca000 c19dc000 c1890400 
cca59de0 000000ba d3b8d350 d3bc1000
Apr 22 22:14:41 test1 kernel: <0> 00000005 cc3a7ebc d36c2f10 00000014 
08050590 d3b8d350 000230d8 000001a4
Apr 22 22:14:41 test1 kernel: <0> 00000004 00000380 c09b1838 d36c3f64 
d36c3f98 00000053 cc3a7ee4 c071e82d
Apr 22 22:14:41 test1 kernel: Call Trace:
Apr 22 22:14:41 test1 kernel: [<d36c2f10>] ? 
ip_set_sockfn_get+0x402/0x7e7 [ip_set]
Apr 22 22:14:41 test1 kernel: [<c071e82d>] ? nf_sockopt+0xf1/0x118
Apr 22 22:14:41 test1 kernel: [<c071e86c>] ? nf_getsockopt+0x18/0x1a
Apr 22 22:14:41 test1 kernel: [<c072f822>] ? ip_getsockopt+0x6c/0x99
Apr 22 22:14:41 test1 kernel: [<c07466e0>] ? raw_getsockopt+0x20/0x95
Apr 22 22:14:41 test1 kernel: [<c06f8f18>] ? 
sock_common_getsockopt+0x18/0x1d
Apr 22 22:14:41 test1 kernel: [<c06f70b4>] ? sys_getsockopt+0x64/0x7f
Apr 22 22:14:41 test1 kernel: [<c06f886c>] ? sys_socketcall+0x157/0x1aa
Apr 22 22:14:41 test1 kernel: [<c07908bc>] ? syscall_call+0x7/0xb
Apr 22 22:14:41 test1 kernel: Code: d2 74 51 40 31 d2 eb 4c 8b 75 e8 8b 
34 9e 89 75 ec 31 f6 83 7d ec 00 75 09 85 d2 74 2e 40 31 d2 eb 29 89 4d 
dc 8b 4d ec 0f a3 31 <19> ff 85 ff 74 07 ba 01 00 00 00 eb 07 85 d2 74 
03 40 31 d2 46
Apr 22 22:14:41 test1 kernel: Call Trace:
Apr 22 22:14:41 test1 kernel: [<d36c2f10>] ip_set_sockfn_get+0x402/0x7e7 
[ip_set]
Apr 22 22:14:41 test1 kernel: [<c071e82d>] nf_sockopt+0xf1/0x118
Apr 22 22:14:41 test1 kernel: [<c071e86c>] nf_getsockopt+0x18/0x1a
Apr 22 22:14:41 test1 kernel: [<c072f822>] ip_getsockopt+0x6c/0x99
Apr 22 22:14:41 test1 kernel: [<c07466e0>] raw_getsockopt+0x20/0x95
Apr 22 22:14:41 test1 kernel: [<c06f8f18>] sock_common_getsockopt+0x18/0x1d
Apr 22 22:14:41 test1 kernel: [<c06f70b4>] sys_getsockopt+0x64/0x7f
Apr 22 22:14:41 test1 kernel: [<c06f886c>] sys_socketcall+0x157/0x1aa
Apr 22 22:14:41 test1 kernel: [<c07908bc>] syscall_call+0x7/0xb

The machine on which this executes is not particularly powerful pentium2 
box, so I suspect ipset hogs it and doesn't give the watchdog any 
room/response. Is there anything which could be done about this? The 
ipset version in question is 4.5

Re: ipset kernel oops

[Jozsef Kadlecsik]

On Fri, 22 Apr 2011, Mr Dash Four wrote:

> During loading of a (rather) large set (consisting of about 30k members) I am
> getting the following kernel error:
> 
> Apr 22 22:14:41 test1 kernel: BUG: soft lockup - CPU#0 stuck for 61s!
> [ipset:1568]
> Apr 22 22:14:41 test1 kernel: Pid: 1568, comm: ipset Not tainted
> 2.6.34.8-68.fc13.i686 #1        /      Apr 22 22:14:41 test1 kernel: EIP:
> 0060:[<d3b8c1ea>] EFLAGS: 00000283 CPU: 0
> Apr 22 22:14:41 test1 kernel: EIP is at iptreemap_list_members_size+0x7a/0xcd
> [ip_set_iptreemap]
> Apr 22 22:14:41 test1 kernel: EAX: 00000252 EBX: 000000f2 ECX: cca59de0 EDX:
> 00000001
> Apr 22 22:14:41 test1 kernel: ESI: 00000046 EDI: ffffffff EBP: cc3a7e88 ESP:
> cc3a7e64
> Apr 22 22:14:41 test1 kernel: DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068
> Apr 22 22:14:41 test1 kernel: Process ipset (pid: 1568, ti=cc3a6000
> task=d0868000 task.ti=cc3a6000)
> Apr 22 22:14:41 test1 kernel: Stack:
> Apr 22 22:14:41 test1 kernel: 000000ce d07ca000 c19dc000 c1890400 cca59de0
> 000000ba d3b8d350 d3bc1000
> Apr 22 22:14:41 test1 kernel: <0> 00000005 cc3a7ebc d36c2f10 00000014 08050590
> d3b8d350 000230d8 000001a4
> Apr 22 22:14:41 test1 kernel: <0> 00000004 00000380 c09b1838 d36c3f64 d36c3f98
> 00000053 cc3a7ee4 c071e82d
> Apr 22 22:14:41 test1 kernel: Call Trace:
> Apr 22 22:14:41 test1 kernel: [<d36c2f10>] ? ip_set_sockfn_get+0x402/0x7e7
> [ip_set]
> Apr 22 22:14:41 test1 kernel: [<c071e82d>] ? nf_sockopt+0xf1/0x118
> Apr 22 22:14:41 test1 kernel: [<c071e86c>] ? nf_getsockopt+0x18/0x1a
> Apr 22 22:14:41 test1 kernel: [<c072f822>] ? ip_getsockopt+0x6c/0x99
> Apr 22 22:14:41 test1 kernel: [<c07466e0>] ? raw_getsockopt+0x20/0x95
> Apr 22 22:14:41 test1 kernel: [<c06f8f18>] ? sock_common_getsockopt+0x18/0x1d
> Apr 22 22:14:41 test1 kernel: [<c06f70b4>] ? sys_getsockopt+0x64/0x7f
> Apr 22 22:14:41 test1 kernel: [<c06f886c>] ? sys_socketcall+0x157/0x1aa
> Apr 22 22:14:41 test1 kernel: [<c07908bc>] ? syscall_call+0x7/0xb
> Apr 22 22:14:41 test1 kernel: Code: d2 74 51 40 31 d2 eb 4c 8b 75 e8 8b 34 9e
> 89 75 ec 31 f6 83 7d ec 00 75 09 85 d2 74 2e 40 31 d2 eb 29 89 4d dc 8b 4d ec
> 0f a3 31 <19> ff 85 ff 74 07 ba 01 00 00 00 eb 07 85 d2 74 03 40 31 d2 46
> Apr 22 22:14:41 test1 kernel: Call Trace:
> Apr 22 22:14:41 test1 kernel: [<d36c2f10>] ip_set_sockfn_get+0x402/0x7e7
> [ip_set]
> Apr 22 22:14:41 test1 kernel: [<c071e82d>] nf_sockopt+0xf1/0x118
> Apr 22 22:14:41 test1 kernel: [<c071e86c>] nf_getsockopt+0x18/0x1a
> Apr 22 22:14:41 test1 kernel: [<c072f822>] ip_getsockopt+0x6c/0x99
> Apr 22 22:14:41 test1 kernel: [<c07466e0>] raw_getsockopt+0x20/0x95
> Apr 22 22:14:41 test1 kernel: [<c06f8f18>] sock_common_getsockopt+0x18/0x1d
> Apr 22 22:14:41 test1 kernel: [<c06f70b4>] sys_getsockopt+0x64/0x7f
> Apr 22 22:14:41 test1 kernel: [<c06f886c>] sys_socketcall+0x157/0x1aa
> Apr 22 22:14:41 test1 kernel: [<c07908bc>] syscall_call+0x7/0xb
> 
> The machine on which this executes is not particularly powerful pentium2 box,
> so I suspect ipset hogs it and doesn't give the watchdog any room/response. Is
> there anything which could be done about this? The ipset version in question
> is 4.5

How much RAM have you got in that machine? Are the 30k addresses 
pseudo-random, i.e. don't come from several netblocks?

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlec@mail.kfki.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : KFKI Research Institute for Particle and Nuclear Physics
          H-1525 Budapest 114, POB. 49, Hungary

Re: ipset kernel oops

[Mr Dash Four]

> How much RAM have you got in that machine?
283248k physical RAM, 128MB swap file.

>  Are the 30k addresses 
> pseudo-random, i.e. don't come from several netblocks?
>   
99.8% from all addresses/subnets come my geoip database (IP addresses 
compiled from various countries I banned from my networks as they have 
no business accessing it) - the rest consists of pseudo-random 
(selected) subnets. It is also worth mentioning that:

1. When ipset loads these addresses during boot no such error takes 
place (though it takes about 10+ minutes for these to load as the 
machine on which this run is not very powerful);
2. The error happens when I try to load these ipsets from the command 
line (i.e. do exactly the same thing from the shell as in 1 above);
3. At no point during 1 or 2 the swap file is used, which leads me to 
believe that this error does not happen because of insufficient memory;

On a separate note, is it normal for my ipsets to take absolute *ages* 
to load (about 5 minutes on a P4 machine as well)? I am loading these 
exact sets on a Core2 machine and even though it takes much less time 
(about 20 seconds or so) I am still a bit bemused why does it take that 
long, comparing to other ipset operations? I can't complain about the 
run-time performance of ipset though - it is simply unmatched by 
anything else I used (or attempted to use)!

Re: ipset kernel oops

[Jozsef Kadlecsik]

On Sun, 24 Apr 2011, Mr Dash Four wrote:

> > How much RAM have you got in that machine?
> 283248k physical RAM, 128MB swap file.

That 30k addresses alone need roughly 30MB non-swappable memory, ~10% of 
all of the physical RAM. Depending on what else's running on that machine, 
the required memory can be significant.
 
> >  Are the 30k addresses pseudo-random, i.e. don't come from several
> > netblocks?
> >   
> 99.8% from all addresses/subnets come my geoip database (IP addresses compiled
> from various countries I banned from my networks as they have no business
> accessing it) - the rest consists of pseudo-random (selected) subnets. It is
> also worth mentioning that:
> 
> 1. When ipset loads these addresses during boot no such error takes place
> (though it takes about 10+ minutes for these to load as the machine on which
> this run is not very powerful);
> 2. The error happens when I try to load these ipsets from the command line
> (i.e. do exactly the same thing from the shell as in 1 above);

At boot time the memory is not fragmented. Later on maybe it's harder to 
find for the kernel the required continuous memory spaces.

> 3. At no point during 1 or 2 the swap file is used, which leads me to believe
> that this error does not happen because of insufficient memory;
> 
> On a separate note, is it normal for my ipsets to take absolute *ages* to load
> (about 5 minutes on a P4 machine as well)? I am loading these exact sets on a
> Core2 machine and even though it takes much less time (about 20 seconds or so)
> I am still a bit bemused why does it take that long, comparing to other ipset
> operations? I can't complain about the run-time performance of ipset though -
> it is simply unmatched by anything else I used (or attempted to use)!

I have never tested iptree(map) with so many elements, so it's surprising 
for me that it takes so many time. But if the 30k addresses are quite 
different then the iptreemap has to build up a four-level tree with 30k 
branches from the second level down.

Best regards,
Jozsef
-
E-mail  : kadlec@blackhole.kfki.hu, kadlec@mail.kfki.hu
PGP key : http://www.kfki.hu/~kadlec/pgp_public_key.txt
Address : KFKI Research Institute for Particle and Nuclear Physics
          H-1525 Budapest 114, POB. 49, Hungary

Re: ipset kernel oops

[Mr Dash Four]

> That 30k addresses alone need roughly 30MB non-swappable memory, ~10% of 
> all of the physical RAM. Depending on what else's running on that machine, 
> the required memory can be significant.
>   
The system, when it boots, has more than 150MiB of RAM available (that 
excludes about 80MiB of "cached" memory), so RAM is clearly not an issue 
I don't think. I forgot to mention that I executed the whole sequence 
(which triggered the bug) as soon as I booted up, so no other 
applications were loaded (yet).

> I have never tested iptree(map) with so many elements, so it's surprising 
> for me that it takes so many time.
It is the single most frustrating issue I've always had with ipset - I 
am more than pleased with everything else, apart from the initial 
loading, which, as I already pointed out even on a fast machine with 
lots of RAM (Core2 with 4GiB RAM) takes about 20 or so seconds for these 
ipsets to load. That goes to about 5 minutes on less-powerful, but 
equally well-equipped P4 (3.3MHz) with 1GiB RAM.

>  But if the 30k addresses are quite 
> different then the iptreemap has to build up a four-level tree with 30k 
> branches from the second level down.
>   
So, do you have an idea what is causing this bug and how could it be 
avoided/fixed?

I have tried the new version of ipset, but didn't have luck with it 
either - see my other post on this list with regards to that particular 
set of problems.