FreeRadius is 3 time quicker when running in full debug mode ( -X option)

[Vincent Laborie]

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 at 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 at 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
>>
>