Alan, Many thanks for your answer, I had a look to syslog and it seems that my server is already using rsyslog: ps -elf | grep syslog 5 S root 1963 1 0 80 0 - 7041 - Mar20 ? 00:01:56 /usr/sbin/rsyslogd -c3 I also try to print directly on stdout : destination = stdout Or in files And this doesn't realy change anything. I also tried to reduce logging as much as possible for example by commenting : #auth_log but it doesn't realy help too. Looking forward to any clue that will help me to reduce this response time, Thanks, Vincent On Mon, Sep 7, 2009 at 12:59 PM, Alan DeKok<aland@deployingradius.com> wrote:

Vincent Laborie wrote:

...

I am surprised by the fact that freeRadius (Version 2.0.4) is 3 time quicker when running in full debug mode ( -X option).

 You are logging to syslog.

 Use a syslog server that doesn't kill performance, like rsyslog.

 Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Alan and other list member, It seems that the difference of performance is due to multi thread feature. When running freeradius with -s option ( single mode ) I have similar performance than in debug mode. That make sense as -X is equivalent to -sfxx -l stdout. So new questions are: How can I take benefits of freeradius multi thread option and keeping good response time ? According to the man page "Some systems have issues with threading" is there any system configuration that can help ? And finally if I decide to stick to single mode how can I modify the /et/init.d/freeradius to use the -s option ? Many thanks in advance for your support. Vincent On Mon, Sep 7, 2009 at 10:30 PM, Alan DeKok<aland@deployingradius.com> wrote:

Vincent Laborie wrote:

...

Many thanks for your answer, I had a look to syslog and it seems that my server is already using rsyslog:

 <shrug>  There isn't anything in the server that says "run faster in debug mode".  Usually it's the other way around, because of all the extrea output that debug mode has.

...

I also try to print directly on stdout : destination = stdout Or in files And this doesn't realy change anything.

 Then the problem is elsewhere.

...

I also tried to reduce logging as much as possible for example by commenting : #auth_log but it doesn't realy help too.

Looking forward to any clue that will help me to reduce this response time,

 What have you changed from the default configuration?  Start looking there.

 Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

We are using debian lenny that I guess has a reasonable threading implementation. with the standard free-radius package ( version 2.0.4) is any body aware of this kind of issue with Lenny and this version of Freeradius? The fact that free radius man page contain the following sentence : "The server normally runs with multiple threads and/or processes, which can lower its response time to requests." Seems to indicate that this is a know fact on some system Is any body has this kind of issue ? Any way I will continue to investigate. Looking forward to your valuable feedback, Thanks Vincent On Wed, Sep 9, 2009 at 10:23 AM, Alan DeKok<aland@deployingradius.com> wrote:

Vincent Laborie wrote:

...

It seems that the difference of performance is due to multi thread feature. When running freeradius with -s option ( single mode ) I have similar performance than in debug mode.

 That's just bizarre.

...

So new questions are: How can I take benefits of  freeradius multi thread option and keeping good response time ?

 Use an OS that has a reasonable threading implementation.

...

According to the man page "Some systems have issues with threading" is there any system configuration that can help ?

 Perhaps you could tell us what OS you're using.

...

And finally if I decide to stick to single mode how can I modify the /et/init.d/freeradius to use the -s option ?

 Use a text editor?

 Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Thanks for all your replies So after additional investigation it seems that the issue is due to external program call via exec-program-wait exec check1{ wait = yes program = "/tool/check1" … } That is taking much more time in multithreaded mode than in single mode Does it ring any bell? Explanation on how I reach this conclusion is available below. I am now investigating options to call this external program, but I would like to avoid (for now) building a new module. Any advice will be appreciated thanks. Here is what I did to reach this conclusion: I went back to basis I took the default configuration file radiusd.conf And I made minimal change: # Forcing Site enable to include only one site (to avoid loading other site) $INCLUDE sites-enabled/default Then I launched freeradius in debug mode. And I used a remote client to perform an access request: Here is the debug output : rad_recv: Access-Request packet from host 82.127.63.184 port 28527, id=231, length=66 User-Name = "vincent" User-Password = "Bicente65" Called-Station-Id = "00-50-E8-02-70-5E" +- entering group authorize ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop rlm_realm: No '@' in User-Name = "vincent", looking up realm NULL rlm_realm: No such realm "NULL" ++[suffix] returns noop rlm_eap: No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns updated users: Matched entry DEFAULT at line 217 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated rad_check_password: Found Auth-Type auth: type "PAP" +- entering group PAP rlm_pap: login attempt with password "Bicente65" rlm_pap: Using CRYPT encryption. rlm_pap: User authenticated successfully ++[pap] returns ok Login OK: [vincent/Bicente65] (from client trustivehotspot port 0) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 231 to 82.127.63.184 port 28527 Acct-Interim-Interval = 600 Idle-Timeout = 900 Session-Timeout = 7200 Finished request 0. Going to the next request Waking up in 4.9 seconds. According to my Radius client this request took between 62 and 78 ms (I did it many time and result are identical). Launching the server with –s option is equivalent Then launching the server in multi threaded mode. The same Radius request from the same client took the same amount of time between 62 and 78 ms. So so far so good .... Now starting to add my configuration in radiusd.conf : # adding one wait exec script as I have to do in my real system # As an example this sh script just do echo "Auth-Type := Accept" ; exec checkreject { wait = yes program = "/bin/sh /tool/checkreject.sh" input_pairs = request output_pairs = config packet_type = Access-Request } Adding call to checkreject in the authorize section from sites-enabled/default authorize { …. checkreject } Then I launched freeradius in debug mode. And I used a remote client to perform an access request: Here is the debug output : rad_recv: Access-Request packet from host 82.127.63.184 port 22437, id=206, length=66 User-Name = "vincent" User-Password = "Bicente65" Called-Station-Id = "00-50-E8-02-70-5E" +- entering group authorize ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop rlm_realm: No '@' in User-Name = "vincent", looking up realm NULL rlm_realm: No such realm "NULL" ++[suffix] returns noop rlm_eap: No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns updated users: Matched entry DEFAULT at line 217 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Exec-Program output: Auth-Type := Accept Exec-Program-Wait: value-pairs: Auth-Type := Accept Exec-Program: returned: 0 ++[checkreject] returns ok rad_check_password: Found Auth-Type Accept rad_check_password: Auth-Type = Accept, accepting the user Login OK: [vincent/Bicente65] (from client myhotspot port 0) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 206 to 82.127.63.184 port 22437 Acct-Interim-Interval = 600 Idle-Timeout = 900 Session-Timeout = 7200 Finished request 2. Going to the next request Waking up in 4.9 seconds. According to my Radius client this request took around 78 ms (I did it many time and result are identical). Launching the server with –s option is equivalent Then launching the server in multi threaded mode. The same Radius request from the same client mow takes around 178 ms. So the difference in executing this script in single or multi threaded mode is around 100ms…. On Wed, Sep 9, 2009 at 11:07 AM, Phil Mayers<p.mayers@imperial.ac.uk> wrote:

Vincent Laborie wrote:

...

We are using debian lenny that I guess has a reasonable threading implementation. with the standard free-radius package ( version 2.0.4) is any body aware of this kind of issue with Lenny and this version of Freeradius?

The fact that free radius man page contain the following sentence : "The  server  normally  runs with multiple threads and/or processes, which can lower its response time to requests." Seems to indicate that this is a know fact on some system Is any body has this kind of issue ?

No, you've mis-read that. It "lowers the time" i.e. makes it faster.

This is all very bizarre, debian is normal OS, and FreeRadius should *not* be running slower in threaded mode.

How are you measuring this performance?

What configuration changes have you made from the default (please don't send all your config files - just a brief description of which modules you've got enabled)

Could you send the debug output (i.e. "radiusd -X") for a *SINGLE* one of the performance-test requests? - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Vincent, I think the difference you are seeing is a result of needing to dispatch the program to run the shell script in the multi- threaded case. The 100ms delay is more than likely your scheduler granularity. The single-threaded program does not have this because it runs the program itself. You can probably reduce this delay by adjusting your kernel tick rate. I think using the perl version is much cleaner and will scale better. Regards, Ken On Thu, Sep 10, 2009 at 04:33:51PM +0200, Vincent Laborie wrote:

Some aditional information to add to the previous tests, I tried this:

A simple perl file based on example.pl , that only returns RLM_MODULE_OK:

use strict; use vars qw(%RAD_REQUEST %RAD_REPLY %RAD_CHECK); use Data::Dumper;

use constant RLM_MODULE_REJECT=> 0;# /* immediately reject the request */ use constant RLM_MODULE_FAIL=> 1;# /* module failed, don't reply */ use constant RLM_MODULE_OK=> 2;# /* the module is OK, continue */ use constant RLM_MODULE_HANDLED=> 3;# /* the module handled the request, so stop. */ use constant RLM_MODULE_INVALID=> 4;# /* the module considers the request invalid. */ use constant RLM_MODULE_USERLOCK=> 5;# /* reject the request (user is locked out) */ use constant RLM_MODULE_NOTFOUND=> 6;# /* user not found */ use constant RLM_MODULE_NOOP=> 7;# /* module succeeded without doing anything */ use constant RLM_MODULE_UPDATED=> 8;# /* OK (pairs modified) */ use constant RLM_MODULE_NUMCODES=> 9;# /* How many return codes there are */

sub authorize { return RLM_MODULE_OK; }

Using this authorization module instead of the shell script (or exec-program-wait), no difference in the response time was seen at all between the single threaded version (with -X or -s ) and the multi threaded version (standard or with -f).

Should it be considered "normal" to have this 100ms hit when using anything else than rml_perl on a multi thread version?

Any advice will be greatly appreciated Thanks amd regards, Vincent

On Wed, Sep 9, 2009 at 5:39 PM, Vincent Laborie <vlaborie@gmail.com> wrote:

...

Thanks for all your replies

So after additional investigation it seems that the issue is due to external program call via exec-program-wait exec ?check1{ wait = yes program = "/tool/check1" ? } That is taking much more time in multithreaded mode than in single mode Does it ring any bell? Explanation on how I reach this conclusion is available below. I am now investigating options to call this external program, but I would like to avoid (for now) building a new module. Any advice will be appreciated thanks.

Here is what I did to reach this conclusion: I went back to basis I took the default configuration file radiusd.conf And I made minimal change:

# Forcing Site enable to include only one site (to avoid loading other site) $INCLUDE sites-enabled/default

Then I launched freeradius in debug mode. And I used a remote client to perform an access request: Here is the debug output :

rad_recv: Access-Request packet from host 82.127.63.184 port 28527, id=231, length=66 ? ? ? ?User-Name = "vincent" ? ? ? ?User-Password = "Bicente65" ? ? ? ?Called-Station-Id = "00-50-E8-02-70-5E" +- entering group authorize ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop ? ?rlm_realm: No '@' in User-Name = "vincent", looking up realm NULL ? ?rlm_realm: No such realm "NULL" ++[suffix] returns noop ?rlm_eap: No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns updated ? ?users: Matched entry DEFAULT at line 217 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated ?rad_check_password: ?Found Auth-Type auth: type "PAP" +- entering group PAP rlm_pap: login attempt with password "Bicente65" rlm_pap: Using CRYPT encryption. rlm_pap: User authenticated successfully ++[pap] returns ok Login OK: [vincent/Bicente65] (from client trustivehotspot port 0) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 231 to 82.127.63.184 port 28527 ? ? ? ?Acct-Interim-Interval = 600 ? ? ? ?Idle-Timeout = 900 ? ? ? ?Session-Timeout = 7200 Finished request 0. Going to the next request Waking up in 4.9 seconds.

According to my Radius client this request took between 62 and 78 ms (I did it many time and result are identical). Launching the server with ?s option is equivalent

Then launching the server in multi threaded mode. The same Radius request from the same client took the same amount of time between 62 and 78 ms. So so far so good ....

Now starting to add my configuration in radiusd.conf :

# adding one wait exec script as I have to do in my real system # As an example this sh script just do echo "Auth-Type := Accept" ;

exec ?checkreject { wait = yes program = "/bin/sh /tool/checkreject.sh" input_pairs = request output_pairs = config packet_type = Access-Request }

Adding call to checkreject ?in the authorize section from sites-enabled/default authorize { ? ? ? ??. ? ?checkreject }

Then I launched freeradius in debug mode. And I used a remote client to perform an access request: Here is the debug output :

rad_recv: Access-Request packet from host 82.127.63.184 port 22437, id=206, length=66 ? ? ? ?User-Name = "vincent" ? ? ? ?User-Password = "Bicente65" ? ? ? ?Called-Station-Id = "00-50-E8-02-70-5E" +- entering group authorize ++[preprocess] returns ok ++[chap] returns noop ++[mschap] returns noop ? ?rlm_realm: No '@' in User-Name = "vincent", looking up realm NULL ? ?rlm_realm: No such realm "NULL" ++[suffix] returns noop ?rlm_eap: No EAP-Message, not doing EAP ++[eap] returns noop ++[unix] returns updated ? ?users: Matched entry DEFAULT at line 217 ++[files] returns ok ++[expiration] returns noop ++[logintime] returns noop ++[pap] returns updated Exec-Program output: Auth-Type := Accept Exec-Program-Wait: value-pairs: Auth-Type := Accept Exec-Program: returned: 0 ++[checkreject] returns ok ?rad_check_password: ?Found Auth-Type Accept ?rad_check_password: Auth-Type = Accept, accepting the user Login OK: [vincent/Bicente65] (from client myhotspot port 0) +- entering group post-auth ++[exec] returns noop Sending Access-Accept of id 206 to 82.127.63.184 port 22437 ? ? ? ?Acct-Interim-Interval = 600 ? ? ? ?Idle-Timeout = 900 ? ? ? ?Session-Timeout = 7200 Finished request 2. Going to the next request Waking up in 4.9 seconds.

According to my Radius client this request took around 78 ms (I did it many time and result are identical). Launching the server with ?s option is equivalent

Then launching the server in multi threaded mode. The same Radius request from the same client mow takes around 178 ms. So the difference in executing this script in single or multi threaded mode is around 100ms?.

On Wed, Sep 9, 2009 at 11:07 AM, Phil Mayers<p.mayers@imperial.ac.uk> wrote:

...

Vincent Laborie wrote:

...

We are using debian lenny that I guess has a reasonable threading implementation. with the standard free-radius package ( version 2.0.4) is any body aware of this kind of issue with Lenny and this version of Freeradius?

The fact that free radius man page contain the following sentence : "The ?server ?normally ?runs with multiple threads and/or processes, which can lower its response time to requests." Seems to indicate that this is a know fact on some system Is any body has this kind of issue ?

No, you've mis-read that. It "lowers the time" i.e. makes it faster.

This is all very bizarre, debian is normal OS, and FreeRadius should *not* be running slower in threaded mode.

How are you measuring this performance?

What configuration changes have you made from the default (please don't send all your config files - just a brief description of which modules you've got enabled)

Could you send the debug output (i.e. "radiusd -X") for a *SINGLE* one of the performance-test requests? - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

Alan DeKok <aland@deployingradius.com> wrote:

Vincent Laborie wrote:

...

It seems that the difference of performance is due to multi thread feature. When running freeradius with -s option ( single mode ) I have similar performance than in debug mode.

That's just bizarre.

Hyperthreading? If you are using wimpy x86 (Intel) chips rather than real hardware you might see this. Cheers -- Alexander Clouter .sigmonster says: Visit beautiful Vergas, Minnesota.