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

[Vincent Laborie]

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
>