Radius is running away with the CPU
I have been using freeradius for several years but in the last few months have seen a problem with the cpu usage. TOP almost always shows radius with
100% CPU much of the time it is at 300%. The load average runs up to 32 at times as well. This corresponds with the max_servers. I am using a mysql database on the same box and it looks to be behaving and queries to it are fast. The box is dual 2.8 xeon with 2 GB ram. Anyone have a idea what would cause this?
David top - 14:33:51 up 82 days, 3:50, 1 user, load average: 2.83, 4.85, 4.30 Tasks: 100 total, 2 running, 98 sleeping, 0 stopped, 0 zombie Cpu(s): 10.3% us, 64.9% sy, 0.0% ni, 24.6% id, 0.2% wa, 0.0% hi, 0.0% si Mem: 1034396k total, 859184k used, 175212k free, 32808k buffers Swap: 2032212k total, 47388k used, 1984824k free, 712524k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 12550 radiusd 16 0 96576 5312 816 S 300 0.5 22064:15 radiusd
David wrote:
I have been using freeradius for several years but in the last few months have seen a problem with the cpu usage. TOP almost always shows radius with
100% CPU much of the time it is at 300%. The load average runs up to 32 at times as well. This corresponds with the max_servers. I am using a mysql database on the same box and it looks to be behaving and queries to it are fast. The box is dual 2.8 xeon with 2 GB ram. Anyone have a idea what would cause this?
You're likely HUP'ing the server. Don't. HUP doesn't work. Alan DeKok.
I am not intentionally/manually HUP'ing the server. The problem happens pretty much as soon as I start the server. David
-----Original Message----- From: freeradius-users-bounces+david=speedyquick.net@lists.freeradiu s.org [mailto:freeradius-users-bounces+david=speedyquick.net@lists.f reeradius.org] On Behalf Of Alan DeKok Sent: Tuesday, August 14, 2007 10:50 AM To: FreeRadius users mailing list Subject: Re: Radius is running away with the CPU
David wrote:
I have been using freeradius for several years but in the last few months have seen a problem with the cpu usage. TOP almost always shows radius with
100% CPU much of the time it is at 300%. The load average runs up to 32 at times as well. This corresponds with the max_servers. I am using a mysql database on the same box and it looks to be behaving and queries to it are fast. The box is dual 2.8 xeon with 2 GB ram. Anyone have a idea what would cause this?
You're likely HUP'ing the server. Don't. HUP doesn't work.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
David wrote:
I am not intentionally/manually HUP'ing the server. The problem happens pretty much as soon as I start the server.
Well, something changed. It worked before, didn't it? Find out what changed. Run the server in debugging mode. Use 'strace' to see what it's doing. Alan DeKok.
I found that when running radius -x to the console I see lines like the following WARNING: Unresponsive child (id 3074419616) for request 8978 I don't know what they mean. I see lines like Dropping conflicting packet from client Bogus:2377 - ID: 195 due to unfinished request 8978 above the Warning line but don't see where the original request is and don't know if it matter? I am not sure how to use strace I ran it on the pid of the radius server but don't know what to make of its output. Below is a small excerpt of the output Process 26228 attached - interrupt to quit select(6, [3 4 5], NULL, NULL, {0, 980000}) = 1 (in [4], left {0, 760000}) time(NULL) = 1187123924 recvfrom(4, "\4\16\0\277w\7d\273\17\vh\0\371\311By\203\16#\30\6\6\0"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(3602), sin_addr=inet_addr("192.168.1.45")}, [16]) = 191 write(1, "rad_recv: Accounting-Request pac"..., 86) = 86 time(NULL) = 1187123924 futex(0xfb7990, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {1, 0}) = 0 (Timeout) time(NULL) = 1187123925 select(6, [3 4 5], NULL, NULL, {1, 0}) = 0 (Timeout) time(NULL) = 1187123926 select(6, [3 4 5], NULL, NULL, {4, 0}) = 0 (Timeout) time(NULL) = 1187123930 time(NULL) = 1187123930 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [3], left {1, 48000}) time(NULL) = 1187123934 recvfrom(3, "\1\32\0\225k\341\30\241T\335\330s\355Y\356%\372\222\330"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1460), sin_addr=inet_addr("192.168.1.10")}, [16]) = 149 write(1, "rad_recv: Access-Request packet "..., 81) = 81 time(NULL) = 1187123934 futex(0xfb7990, FUTEX_WAKE, 1) = 1 time(NULL) = 1187123934 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 futex(0x7c37c8, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [4], left {4, 968000}) time(NULL) = 1187123934 recvfrom(4, "\4\33\0\222{G\204B\333\200x\226\265\35\3428yZ\371\21\6"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1460), sin_addr=inet_addr("192.168.1.10")}, [16]) = 146 write(1, "rad_recv: Accounting-Request pac"..., 85) = 85 time(NULL) = 1187123934 futex(0xfb7990, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [4], left {3, 995000}) time(NULL) = 1187123935 recvfrom(4, "\4\33\0\222%\265\374M|\220;\255\0\251\215)\24\\\341J\6"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1460), sin_addr=inet_addr("192.168.1.10")}, [16]) = 146 write(1, "rad_recv: Accounting-Request pac"..., 85) = 85 time(NULL) = 1187123935 write(1, "Dropping conflicting packet from"..., 94) = 94 time(NULL) = 1187123935 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [4], left {3, 991000}) time(NULL) = 1187123936 recvfrom(4, "\4\33\0\222P%\10\27\nB\4\20I\227\263\33V\210\17M\6\6\0"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1460), sin_addr=inet_addr("192.168.1.10")}, [16]) = 146 write(1, "rad_recv: Accounting-Request pac"..., 85) = 85 time(NULL) = 1187123936 write(1, "Dropping conflicting packet from"..., 94) = 94 select(6, [3 4 5], NULL, NULL, {4, 0}) = 1 (in [4], left {1, 131000}) time(NULL) = 1187123939 recvfrom(4, "\4+\0\305\301\t\16\332\256\0\214\363\302]\0\332z\325\1"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1750), sin_addr=inet_addr("192.168.1.30")}, [16]) = 197 write(1, "rad_recv: Accounting-Request pac"..., 86) = 86 time(NULL) = 1187123939 futex(0xfb7990, FUTEX_WAKE, 1) = 1 time(NULL) = 1187123939 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 select(6, [3 4 5], NULL, NULL, {1, 0}) = 0 (Timeout) time(NULL) = 1187123940 time(NULL) = 1187123940 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [4], left {4, 83000}) time(NULL) = 1187123941 recvfrom(4, "\4,\0\302P\205\334\356\251w\202w\266\357\37\265\260\4\372"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1750), sin_addr=inet_addr("192.168.1.30")}, [16]) = 194 write(1, "rad_recv: Accounting-Request pac"..., 86) = 86 time(NULL) = 1187123941 futex(0xfb7990, FUTEX_WAKE, 1) = 1 time(NULL) = 1187123941 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 time(NULL) = 1187123941 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 select(6, [3 4 5], NULL, NULL, {4, 0}) = 0 (Timeout) time(NULL) = 1187123945 futex(0xfb7990, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {2, 0}) = 1 (in [4], left {1, 758000}) time(NULL) = 1187123946 recvfrom(4, "\4\17\0\304\337#\372#\245=\347F\\\220|\0045\321\221*\6"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(3602), sin_addr=inet_addr("192.168.1.45")}, [16]) = 196 write(1, "rad_recv: Accounting-Request pac"..., 86) = 86 time(NULL) = 1187123946 futex(0xfb7990, FUTEX_WAKE, 1) = 1 time(NULL) = 1187123946 write(1, "WARNING: Unresponsive child (id "..., 61) = 61 futex(0xfb7990, FUTEX_WAKE, 2) = 2 select(6, [3 4 5], NULL, NULL, {1, 0}) = 0 (Timeout) time(NULL) = 1187123947 futex(0xfb7990, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {5, 0}) = 1 (in [3], left {4, 742000}) time(NULL) = 1187123947 recvfrom(3, "\1 \0\304\260%\241\17\315i\373q\206\360\346\247\214@TC"..., 4096, 0, {sa_family=AF_INET, sin_port=htons(1109), sin_addr=inet_addr("192.168.1.43")}, [16]) = 196 write(1, "rad_recv: Access-Request packet "..., 81) = 81 time(NULL) = 1187123947 futex(0xfb7990, FUTEX_WAKE, 1) = 1 select(6, [3 4 5], NULL, NULL, {5, 0} <unfinished ...> David
-----Original Message----- From: freeradius-users-bounces+david=speedyquick.net@lists.freeradiu s.org [mailto:freeradius-users-bounces+david=speedyquick.net@lists.f reeradius.org] On Behalf Of Alan DeKok Sent: Tuesday, August 14, 2007 11:20 AM To: FreeRadius users mailing list Subject: Re: Radius is running away with the CPU
David wrote:
I am not intentionally/manually HUP'ing the server. The problem happens pretty much as soon as I start the server.
Well, something changed. It worked before, didn't it?
Find out what changed. Run the server in debugging mode. Use 'strace' to see what it's doing.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
David wrote:
I found that when running radius -x to the console I see lines like the following WARNING: Unresponsive child (id 3074419616) for request 8978
Ah. The database you're using isn't responding to the RADIUS server. So the server is blocked from getting anything done.
I am not sure how to use strace I ran it on the pid of the radius server but don't know what to make of its output.
OR run the server in debugging mode, as suggested in the FAQ, README, INSTALL, etc. Alan DeKok.
I have verified that the database can run all of the queries quickly. I was having trouble running radiusd -X (it was slow ) but radiusd -x was better but the thread count and load average would run up. At you suggest I ran in debugging mode -X again and this time notice that it was pausing for a while before out put the lines. So I am guessing that problem lies somewhere in the accounting module radutmp. I commented out the line radutmp in the accounting section of the radiusd.conf. Now things seem to be running smoothly. I looked at the radutmp file and noticed it is 450 MB. I thought the size of it could be an issue. So I deleted it and restart radiusd with the radutmp commented back in. Things look for the moment to be going smoothly but once that file grows in size again it may be a problem. So what would cause that file to get so big? I notice in the radiusd.conf it mentions in the session section that "The rlm_sql module is *much* faster" the default configuration uses radutmp. If I change it to sql then I could leave the radutmp commented out of the accounting section and still be able to do simultaneous checking, right? David modcall[accounting]: module "radutmp" returns ok for request 4 modcall: group accounting returns ok for request 4 Sending Accounting-Response of id 13 to 192.168.0.10:2789 Finished request 4
-----Original Message----- From: freeradius-users-bounces+david=speedyquick.net@lists.freeradiu s.org [mailto:freeradius-users-bounces+david=speedyquick.net@lists.f reeradius.org] On Behalf Of Alan DeKok Sent: Tuesday, August 14, 2007 5:23 PM To: FreeRadius users mailing list Subject: Re: Radius is running away with the CPU
David wrote:
I found that when running radius -x to the console I see lines like the following WARNING: Unresponsive child (id 3074419616) for request 8978
Ah. The database you're using isn't responding to the RADIUS server. So the server is blocked from getting anything done.
I am not sure how to use strace I ran it on the pid of the radius server but don't know what to make of its output.
OR run the server in debugging mode, as suggested in the FAQ, README, INSTALL, etc.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Oops I wrote that a little out of order. It should have gone like this: I have verified that the database can run all of the queries quickly. I was having trouble running radiusd -X (it was slow ) but radiusd -x was better but the thread count and load average would run up. At you suggest I ran in debugging mode -X again and this time notice that it was pausing for a while before output the lines: modcall[accounting]: module "radutmp" returns ok for request 4 modcall: group accounting returns ok for request 4 Sending Accounting-Response of id 13 to 204.228.198.132:2789 Finished request 4 So I am guessing that problem lies somewhere in the accounting module radutmp. I commented out the line radutmp in the accounting section of the radiusd.conf. Now things seem to be running smoothly. I looked at the radutmp file and noticed it is 450 MB. I thought the size of it could be an issue. So I deleted it and restart radiusd with the radutmp commented back in. Things look for the moment to be going smoothly but once that file grows in size again it may be a problem. So what would cause that file to get so big? I notice in the radiusd.conf it mentions in the session section that "The rlm_sql module is *much* faster" the default configuration uses radutmp. If I change it to sql then I could leave the radutmp commented out of the accounting section and still be able to do simultaneous checking, right? David
-----Original Message----- From: freeradius-users-bounces+david=speedyquick.net@lists.freeradiu s.org [mailto:freeradius-users-bounces+david=speedyquick.net@lists.f reeradius.org] On Behalf Of David Sent: Tuesday, August 14, 2007 9:34 PM To: 'FreeRadius users mailing list' Subject: RE: Radius is running away with the CPU
I have verified that the database can run all of the queries quickly. I was having trouble running radiusd -X (it was slow ) but radiusd -x was better but the thread count and load average would run up. At you suggest I ran in debugging mode -X again and this time notice that it was pausing for a while before out put the lines. So I am guessing that problem lies somewhere in the accounting module radutmp. I commented out the line radutmp in the accounting section of the radiusd.conf. Now things seem to be running smoothly. I looked at the radutmp file and noticed it is 450 MB. I thought the size of it could be an issue. So I deleted it and restart radiusd with the radutmp commented back in. Things look for the moment to be going smoothly but once that file grows in size again it may be a problem. So what would cause that file to get so big? I notice in the radiusd.conf it mentions in the session section that "The rlm_sql module is *much* faster" the default configuration uses radutmp. If I change it to sql then I could leave the radutmp commented out of the accounting section and still be able to do simultaneous checking, right?
David
modcall[accounting]: module "radutmp" returns ok for request 4 modcall: group accounting returns ok for request 4 Sending Accounting-Response of id 13 to 192.168.0.10:2789 Finished request 4
-----Original Message----- From: freeradius-users-bounces+david=speedyquick.net@lists.freeradiu s.org [mailto:freeradius-users-bounces+david=speedyquick.net@lists.f reeradius.org] On Behalf Of Alan DeKok Sent: Tuesday, August 14, 2007 5:23 PM To: FreeRadius users mailing list Subject: Re: Radius is running away with the CPU
David wrote:
I found that when running radius -x to the console I see lines like the following WARNING: Unresponsive child (id 3074419616) for request 8978
Ah. The database you're using isn't responding to the RADIUS server. So the server is blocked from getting anything done.
I am not sure how to use strace I ran it on the pid of the radius server but don't know what to make of its output.
OR run the server in debugging mode, as suggested in the FAQ, README, INSTALL, etc.
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
David wrote:
... So what would cause that file to get so big? I notice in the radiusd.conf it mentions in the session section that "The rlm_sql module is *much* faster" the default configuration uses radutmp. If I change it to sql then I could leave the radutmp commented out of the accounting section and still be able to do simultaneous checking, right?
Exactly, yes. Alan DeKok.
On Wed 15 Aug 2007, David wrote:
I have verified that the database can run all of the queries quickly. I was having trouble running radiusd -X (it was slow ) but radiusd -x was better but the thread count and load average would run up. At you suggest I ran in debugging mode -X again and this time notice that it was pausing for a while before out put the lines. So I am guessing that problem lies somewhere in the accounting module radutmp. I commented out the line radutmp in the accounting section of the radiusd.conf. Now things seem to be running smoothly. I looked at the radutmp file and noticed it is 450 MB. I thought the size of it could be an issue. So I deleted it and restart radiusd with the radutmp commented back in. Things look for the moment to be going smoothly but once that file grows in size again it may be a problem. So what would cause that file to get so big? I notice in the radiusd.conf it mentions in the session section that "The rlm_sql module is *much* faster" the default configuration uses radutmp. If I change it to sql then I could leave the radutmp commented out of the accounting section and still be able to do simultaneous checking, right?
Generally speaking the dbm based modules have issues when they get large... Use the SQL based versions.. -- Peter Nixon http://peternixon.net/
participants (3)
-
Alan DeKok -
David -
Peter Nixon