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

[Kenneth Marshall]

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 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
> >>
> >
> 
> -
> List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
>