2.2.0 & dhcp: regression
Hi! We have been running FreeRADIUS 2.1.12/dhcp module with success for long time with FreeBSD 8. Our DHCP perl script opens two file descriptors (per thread): one for database connection TCP socket and one for syslog (/var/run/log unix domain socket). With pool size consisting of 1000 threads, this worked just fine with 2.1.12 Now, as we upgraded to 2.2.0, this schema stopped to work. It works if I decrease maximum pool size so that total amount of radiusd's open file descriptors does not exceed 1023, this corresponds to 501 threads in the pool. If I use 502 threads or more, it initially works until the process creates enough threads to open 1024th file descriptor, then it starts to write to its log: Fri Jul 12 17:09:13 2013 : Info: WARNING: Child is hung for request 727 in component post-auth module perl. Fri Jul 12 17:09:14 2013 : Info: WARNING: Child is hung for request 765 in component post-auth module perl. I've tried to recompile freeradius with CFLAGS including -DFD_SIZE=4096, that changed nothing. If I disable syslog usage in my perl script thus decreasing open files from 2 per thread to only one, then 2.2.0 runs with 1000 threads just fine. Again, increase of thread pool size breaks after open of 1024th file descriptor. Please help. We need at least 1000 concurrent threads to deal with the load here. Our hardware has enough raw power and we do not like to create useless queueing delays. Eugene Grosbein
On 12/07/13 11:17, Eugene Grosbein wrote:
Please help. We need at least 1000 concurrent threads to deal with the load here.
1000 threads is a crazy number. Can you explain why you think you need that many? Are you doing very slow logic/lookups or something? Anyway, the problem is almost certainly system ulimits. I don't know why it's different under 2.2 to 2.1, but I would look into ulimit.
On 12.07.2013 17:38, Phil Mayers wrote:
On 12/07/13 11:17, Eugene Grosbein wrote:
Please help. We need at least 1000 concurrent threads to deal with the load here.
1000 threads is a crazy number. Can you explain why you think you need that many? Are you doing very slow logic/lookups or something?
Our database is powerful enough to deal with so many requests. We may easily get that many requests and want to be able to process them in parallel without needless queueing.
Anyway, the problem is almost certainly system ulimits. I don't know why it's different under 2.2 to 2.1, but I would look into ulimit.
ulimit for files is over 11000 here. And radiusd successfully opens more than 1024 files. It just breaks afterwards.
On 12/07/13 11:55, Eugene Grosbein wrote:
On 12.07.2013 17:38, Phil Mayers wrote:
On 12/07/13 11:17, Eugene Grosbein wrote:
Please help. We need at least 1000 concurrent threads to deal with the load here.
1000 threads is a crazy number. Can you explain why you think you need that many? Are you doing very slow logic/lookups or something?
Our database is powerful enough to deal with so many requests. We may easily get that many requests and want to be able to process them in parallel without needless queueing.
With respect, this is a pretty basic logic. The figure of merit here is offered load in terms of request/sec, and the average/max processing time per-request. If you have 1000 request/sec and each request takes 1 millisecond to process, a single thread is sufficient. If you have 100,000 request/sec and each request takes 10 milliseconds, then you need 100 threads. If your database is "so powerful" it shouldn't be taking too long, so unless you have a truly enormous number of request/sec, you don't need 1000 threads. If you really do have that many request/sec, you probably should look at some form of load balancing, rather than having enormous thread pool. The thread pool performance will not scale linearly - various server internal data structures are locked, and you will probably run into lock contention at high thread counts. I assert that 1000 (posix, shared-memory) threads is always the wrong answer to pretty much *any* problem ;o)
Anyway, the problem is almost certainly system ulimits. I don't know why it's different under 2.2 to 2.1, but I would look into ulimit.
ulimit for files is over 11000 here. And radiusd successfully opens more than 1024 files. It just breaks afterwards.
It could be the use of select() then. If rlm_perl opens FDs 5-1023, then the radius server needs to open some sockets, it will get FD #1024, which might cause select to complain. Try running the server under "strace" and see if you can see where it goes wrong, and what it calls just before it does.
On 12.07.2013 18:39, Phil Mayers wrote:
Our database is powerful enough to deal with so many requests. We may easily get that many requests and want to be able to process them in parallel without needless queueing.
With respect, this is a pretty basic logic.
The figure of merit here is offered load in terms of request/sec, and the average/max processing time per-request.
If you have 1000 request/sec and each request takes 1 millisecond to process, a single thread is sufficient.
If you have 100,000 request/sec and each request takes 10 milliseconds, then you need 100 threads.
If your database is "so powerful" it shouldn't be taking too long, so unless you have a truly enormous number of request/sec, you don't need 1000 threads.
Yes, we may have large number of request/sec and need to be able to process them instantly.
If you really do have that many request/sec, you probably should look at some form of load balancing, rather than having enormous thread pool. The thread pool performance will not scale linearly - various server internal data structures are locked, and you will probably run into lock contention at high thread counts.
We performed extensive testing and found no noticeable contention while using 2.1.12. With lesser pool size we have unneeded queueing delays. Anyway, that's another topic. The regression in 2.2.0 is what I wanted to discuss here.
Anyway, the problem is almost certainly system ulimits. I don't know why it's different under 2.2 to 2.1, but I would look into ulimit.
ulimit for files is over 11000 here. And radiusd successfully opens more than 1024 files. It just breaks afterwards.
It could be the use of select() then. If rlm_perl opens FDs 5-1023, then the radius server needs to open some sockets, it will get FD #1024, which might cause select to complain.
I rebuilt freeradius-2.2.0 with CFLAGS containing -DFD_SETSIZE=4096, that changed nothing.
Try running the server under "strace" and see if you can see where it goes wrong, and what it calls just before it does.
I'll try, thanks.
On 12.07.2013 17:17, Eugene Grosbein wrote:
Hi!
We have been running FreeRADIUS 2.1.12/dhcp module with success for long time with FreeBSD 8.
Our DHCP perl script opens two file descriptors (per thread): one for database connection TCP socket and one for syslog (/var/run/log unix domain socket). With pool size consisting of 1000 threads, this worked just fine with 2.1.12
Now, as we upgraded to 2.2.0, this schema stopped to work. It works if I decrease maximum pool size so that total amount of radiusd's open file descriptors does not exceed 1023, this corresponds to 501 threads in the pool. If I use 502 threads or more, it initially works until the process creates enough threads to open 1024th file descriptor, then it starts to write to its log:
Fri Jul 12 17:09:13 2013 : Info: WARNING: Child is hung for request 727 in component post-auth module perl. Fri Jul 12 17:09:14 2013 : Info: WARNING: Child is hung for request 765 in component post-auth module perl.
I've tried to recompile freeradius with CFLAGS including -DFD_SIZE=4096, that changed nothing.
If I disable syslog usage in my perl script thus decreasing open files from 2 per thread to only one, then 2.2.0 runs with 1000 threads just fine. Again, increase of thread pool size breaks after open of 1024th file descriptor.
Please help. We need at least 1000 concurrent threads to deal with the load here. Our hardware has enough raw power and we do not like to create useless queueing delays.
Forgot to mention that operating system's open files limit for freeradius is over 11000. And file descriptors are numbered starting from zero, so descriptor 1024 is really 1025th. radiusd works fine until it has descriptors 0-1023 only and breaks with creation of descriptor 1024: it stops calling perl routing post_auth and thus, processing of DHCP requests ceases.
Eugene Grosbein wrote:
Forgot to mention that operating system's open files limit for freeradius is over 11000. And file descriptors are numbered starting from zero, so descriptor 1024 is really 1025th.
radiusd works fine until it has descriptors 0-1023 only and breaks with creation of descriptor 1024: it stops calling perl routing post_auth and thus, processing of DHCP requests ceases.
The server has no limits on the number of sockets it can use. That is all enforced by the OS. Or, maybe there's an issue with Perl. I would also check why you need 1000 threads. That's a lot. Maybe it's that your Perl script is slow. Or, your database is slow. I'd also suggest skipping syslog in Perl. The server has a "linelog" module, which can do logging to syslog. Just put the log messages into an attribute, and let the linelog module handle it. Alan DeKok.
On 12.07.2013 18:10, Alan DeKok wrote:
Eugene Grosbein wrote:
Forgot to mention that operating system's open files limit for freeradius is over 11000. And file descriptors are numbered starting from zero, so descriptor 1024 is really 1025th.
radiusd works fine until it has descriptors 0-1023 only and breaks with creation of descriptor 1024: it stops calling perl routing post_auth and thus, processing of DHCP requests ceases.
The server has no limits on the number of sockets it can use. That is all enforced by the OS.
Extra sockets got opened just fine, I see that with lsof/fstat here.
Or, maybe there's an issue with Perl.
2.1.12 has not this issue with same Perl.
I would also check why you need 1000 threads. That's a lot. Maybe it's that your Perl script is slow. Or, your database is slow.
Yes, that's a lot. That reflects high load we may have. We do not want to queue requests that may be processed in parallel.
I'd also suggest skipping syslog in Perl. The server has a "linelog" module, which can do logging to syslog. Just put the log messages into an attribute, and let the linelog module handle it.
We use syslogd's facility to send logs to remote log collectors using traditional syslog protocol (udp/514). Can "linelog" module do that? Eugene Grosbein
Eugene Grosbein wrote:
Extra sockets got opened just fine, I see that with lsof/fstat here.
OK. But I'm not aware of any change in any code which will limit the number of sockets.
2.1.12 has not this issue with same Perl.
OK. The rlm_perl module changed. It added some locks to avoid issues with Perl Clone and threads. Maybe you're running into lock contention. i.e. it worked in 2.1.12 by magic, because thread-specific structures were not locked properly. Adding locks makes it *correct*, but at the price of performance.
Yes, that's a lot. That reflects high load we may have. We do not want to queue requests that may be processed in parallel.
Queuing requests for a short time shouldn't hurt anything. DHCP clients will wait ~8 seconds for a response. Is your load really that high? i.e. how many packets/s does the server receive? How long does it take to process one packet?
We use syslogd's facility to send logs to remote log collectors using traditional syslog protocol (udp/514). Can "linelog" module do that?
Yes. Alan DeKok.
On 12.07.2013 19:07, Alan DeKok wrote:
Eugene Grosbein wrote:
Extra sockets got opened just fine, I see that with lsof/fstat here.
OK. But I'm not aware of any change in any code which will limit the number of sockets.
2.1.12 has not this issue with same Perl.
OK. The rlm_perl module changed. It added some locks to avoid issues with Perl Clone and threads. Maybe you're running into lock contention.
The problem is always reproducible and have obvious "hard limit" correlating or consisting with number of open files.
i.e. it worked in 2.1.12 by magic, because thread-specific structures were not locked properly. Adding locks makes it *correct*, but at the price of performance.
I understand. With one exception - we have not performance problem, we have full lockup of all threads and after that not one request is served.
Yes, that's a lot. That reflects high load we may have. We do not want to queue requests that may be processed in parallel.
Queuing requests for a short time shouldn't hurt anything. DHCP clients will wait ~8 seconds for a response.
Is your load really that high? i.e. how many packets/s does the server receive? How long does it take to process one packet?
That's another topic. I'd like not to turn to deep discussion of our load. In short, there may be bursts of thousands of DHCP requests per second lasting several minutes and we have enough horsepower to process them in parallel if we have at least one thousand of threads in the pool.
We use syslogd's facility to send logs to remote log collectors using traditional syslog protocol (udp/514). Can "linelog" module do that?
Yes.
Thanks, I'll take a look.
On 12.07.2013 19:07, Alan DeKok wrote:
OK. But I'm not aware of any change in any code which will limit the number of sockets.
2.1.12 has not this issue with same Perl.
OK. The rlm_perl module changed. It added some locks to avoid issues with Perl Clone and threads. Maybe you're running into lock contention.
i.e. it worked in 2.1.12 by magic, because thread-specific structures were not locked properly. Adding locks makes it *correct*, but at the price of performance.
I've realized that my perl code is not supposed to open distinct syslog connection for each thread, as syslog() function is thread-safe per POSIX. The code connects to syslog in CLONE_SKIP() in hope it should be called only once per whole radiusd process life time. I've added more debug to CLONE_SKIP and see it's called hundreds times in my case. I've modified my code to call openlog() only once using private flag and solved my problem - every thread uses creates only one file descriptor (persistent DB connection) and I do not hit "the limit of 1024". Basically, I solved our problem but one question persists: why is CLONE_SKIP called many times at radiusd start time? Eugene Grosbein
participants (3)
-
Alan DeKok -
Eugene Grosbein -
Phil Mayers