[RADIATOR] Slow response from Radiator
Heikki Vatiainen
hvn at open.com.au
Tue Mar 12 07:29:20 CDT 2013
On 03/12/2013 02:00 PM, Arya, Manish Kumar wrote:
> Hi I tried to run Radius in foreground with trace level 4, this shows
> that the
>
> time taken from LDAP connection to return attr is about 4 sec and then
> radius further takes 3 sec to confirm accept
Can you add LogMicrseconds (a global parameter), as Hugh mentioned, in
the configuration too. This would allow to see subsecond time stamps.
However, the steps taken from 11:55:19 to 11:55:21 are internal to
Radiator requiring no external connections that might wait. Normally I
would expect to see these happen within few milliseconds, not 2-3 seconds.
It looks like the whole processing done by Radiator is slowed down, not
just e.g., external connections to LDAP server. I have seen slow LDAP
connections, but so far nothing that slows down the whole Radiator
instance like this.
What is the system load? What does e.g., uptime say about the load average?
Thanks,
Heikki
> *** Received from 10.174.2.2 port 50841 ....
> Code: Access-Request
> Identifier: 68
> Authentic: 4<151>#hPhj<187>I<16><26>F<25><169>\<4>
> Attributes:
> User-Name = "mlavende at alu"
> User-Password = "xxxxxxxxxxxxxxxxxx"
> NAS-IP-Address = 10.174.2.2
> Calling-Station-Id = "10.5.1.196"
> NAS-Port-Type = Virtual
>
> Tue Mar 12 11:55:19 2013: DEBUG: Handling request with Handler 'Realm =
> alu,NAS-IP-Address=/10\.174\..*/', Identifier ''
> Tue Mar 12 11:55:20 2013: DEBUG: Rewrote user name to mlavende
> Tue Mar 12 11:55:20 2013: DEBUG: Deleting session for mlavende at alu,
> 10.174.2.2,
> Tue Mar 12 11:55:21 2013: DEBUG: Handling with Radius::AuthLDAP2:
> alu_msp_user_auth-7750
> Tue Mar 12 11:55:21 2013: INFO: Connecting to 127.0.0.1:389
> Tue Mar 12 11:55:22 2013: INFO: Attempting to bind to LDAP server
> 127.0.0.1:389
> Tue Mar 12 11:55:23 2013: DEBUG: LDAP got result for
> uid=mlavende,ou=people,o=COLT,ou=customers,dc=colt,dc=net
> Tue Mar 12 11:55:23 2013: DEBUG: LDAP got userPassword: {crypt}0AZ8zj5xYpLak
> Tue Mar 12 11:55:24 2013: DEBUG: LDAP got radius-sam-sec-grp-name:
> TAC_SUPPORT2
> Tue Mar 12 11:55:24 2013: DEBUG: LDAP got radius-7750-Timetra-Access: 3
> Tue Mar 12 11:55:25 2013: DEBUG: LDAP got radius-7750-Timetra-Profile:
> administrative
> Tue Mar 12 11:55:25 2013: DEBUG: LDAP got
> radius-7750-Timetra-Default-Action: 1
> Tue Mar 12 11:55:26 2013: DEBUG: Radius::AuthLDAP2 looks for match with
> mlavende [mlavende at alu]
> Tue Mar 12 11:55:26 2013: DEBUG: Radius::AuthLDAP2 ACCEPT: : mlavende
> [mlavende at alu]
> Tue Mar 12 11:55:27 2013: DEBUG: AuthBy LDAP2 result: ACCEPT,
> Tue Mar 12 11:55:27 2013: DEBUG: Access accepted for mlavende
> Tue Mar 12 11:55:28 2013: DEBUG: Packet dump:
> *** Sending to 10.174.2.2 port 50841 ....
> Code: Access-Accept
> Identifier: 68
> Authentic: Y<207><170><28><139><18>j<244><193><159><179>r$<142><207><202>
> Attributes:
> Sam-security-group-name = "TAC_SUPPORT2"
> Timetra-Access = 3
> Timetra-Profile = "administrative"
> Timetra-Default-Action = 1
> Service-Type = Login-User
>
>
> Regards,
> -Manish
>
>
> ------------------------------------------------------------------------
> *From:* Hugh Irvine <hugh at open.com.au>
> *To:* "Arya, Manish Kumar" <m.arya at yahoo.com>
> *Cc:* Radiator <radiator at open.com.au>
> *Sent:* Monday, March 11, 2013 3:00 PM
> *Subject:* Re: [RADIATOR] Slow response from Radiator
>
>
> Hello Manish -
>
> I suggest you add "LogMicroseconds" (requires Time-Hires from CPAN) to
> your Radiator global configuration options, and "Debug 255" to your
> AuthBy LDAP 2 clause.
>
> Then you should run radiusd by hand from the command line like this so
> you can see the LDAP debug messages (using your local Radiator directory):
>
>
> cd /your/Radiator/distribution/directory
>
> perl radiusd -foreground -log_stdout -trace 4 -config_file
> /your/Radiator/configuration/file
>
>
> From the debug you show below it looks like your LDAP server response is
> very slow.
>
> BTW - the most recent version is Radiator-4.11.
>
> regards
>
> Hugh
>
>
> On 11 Mar 2013, at 19:16, "Arya, Manish Kumar" <m.arya at yahoo.com
> <mailto:m.arya at yahoo.com>> wrote:
>
>> Hi,
>>
>> Can anyone help please. I am using Radiator version 4.9 on Solaris 10
>>
>> [xxxx at rxxxxx:/var/log/radiator]$ cat /etc/release
>> Solaris 10 11/06 s10s_u3wos_10 SPARC
>> Copyright 2006 Sun Microsystems, Inc. All Rights Reserved.
>> Use is subject to license terms.
>> Assembled 14 November 2006
>>
>>
>> Regards,
>> -Manish
>>
>> From: "Arya, Manish Kumar" <m.arya at yahoo.com <mailto:m.arya at yahoo.com>>
>> To: Radiator <radiator at open.com.au <mailto:radiator at open.com.au>>;
> "manishkumar.arya at colt.net <mailto:manishkumar.arya at colt.net>"
> <manishkumar.arya at colt.net <mailto:manishkumar.arya at colt.net>>
>> Sent: Friday, March 8, 2013 2:59 PM
>> Subject: Slow response from Radiator
>>
>> Hi,
>>
>> Radius server takes approx 7-10 seconds to handle one request, there
> not much load on this radius server.
>>
>> Radius Packet dump
>>
>> *** Received from 127.0.0.1 port 32812 ....
>> Code: Access-Request
>> Identifier: 102
>>
>> Fri Mar 8 09:08:11 2013: DEBUG: Rewrote user name to xxxxxx
>> Fri Mar 8 09:08:12 2013: DEBUG: Deleting session for xxxxxxx at alu,
> 10.174.2.2,
>> Fri Mar 8 09:08:12 2013: DEBUG: Handling with Radius::AuthLDAP2:
> alu_msp_user_auth-7750
>> Fri Mar 8 09:08:13 2013: INFO: Connecting to 127.0.0.1:389
>> Fri Mar 8 09:08:13 2013: INFO: Attempting to bind to LDAP server
> 127.0.0.1:389
>> Fri Mar 8 09:08:14 2013: DEBUG: LDAP got result for
> uid=xxxxx,ou=people,o=COLT,ou=customers,dc=colt,dc=net
>> Fri Mar 8 09:08:14 2013: DEBUG: LDAP got userPassword: xxxxxx
>> Fri Mar 8 09:08:15 2013: DEBUG: LDAP got radius-sam-sec-grp-name:
> TAC_SUPPORT2
>> Fri Mar 8 09:08:15 2013: DEBUG: LDAP got radius-7750-Timetra-Access: 3
>> Fri Mar 8 09:08:16 2013: DEBUG: LDAP got radius-7750-Timetra-Profile:
> administrative
>> Fri Mar 8 09:08:16 2013: DEBUG: LDAP got
> radius-7750-Timetra-Default-Action: 1
>> Fri Mar 8 09:08:17 2013: DEBUG: Radius::AuthLDAP2 looks for match
> with xxxxxx [xxxxxx at alu]
>> Fri Mar 8 09:08:17 2013: DEBUG: Radius::AuthLDAP2 ACCEPT: : xxxxxx
> [xxxxxx at alu]
>> Fri Mar 8 09:08:18 2013: DEBUG: AuthBy LDAP2 result: ACCEPT,
>> Fri Mar 8 09:08:18 2013: DEBUG: Access accepted for xxxxxx
>> Fri Mar 8 09:08:19 2013: DEBUG: Packet dump:
>> *** Sending to 10.174.2.2 port 50838 ....
>> Code: Access-Accept
>> Identifier: 167
>> Authentic: <245><217>Un<184>Ge<144>.<213>QE<1>u4.
>> Attributes:
>> Sam-security-group-name = "TAC_SUPPORT2"
>> Timetra-Access = 3
>> Timetra-Profile = "administrative"
>> Timetra-Default-Action = 1
>> Service-Type = Login-User
>>
>>
>> ldapsearch for uid with above attributes is also very quick, no
> complaints of indexes too
>>
>> real 0m0.020s
>> user 0m0.006s
>> sys 0m0.010s
>>
>> hardware config
>>
>> [root at rad-lon1:/var/log/radiator]# prtdiag
>> System Configuration: Sun Microsystems sun4u Sun Fire V245
>> System clock frequency: 188 MHZ
>> Memory size: 4GB
>>
>> ==================================== CPUs
> ====================================
>> E$ CPU CPU
>> CPU Freq Size Implementation Mask Status
> Location
>> --- -------- ---------- --------------------- ----- ------
> --------
>> 0 1504 MHz 1MB SUNW,UltraSPARC-IIIi 3.4 on-line MB/P0
>> 1 1504 MHz 1MB SUNW,UltraSPARC-IIIi 3.4 on-line MB/P1
>>
>>
>> CPU usage (uptime)
>>
>> [root at rad-lon1:/var/log/radiator]# uptime
>> 9:21am up 262 day(s), 20:18, 5 users, load average: 0.04, 0.04, 0.04
>>
>>
>> CPU/Memory usage with top states no processes are using very minimal
> CPU and memory.
>>
>> last pid: 11066; load avg: 0.04, 0.04, 0.04; up 262+20:19:30
> 09:22:51
>> 68 processes: 67 sleeping, 1 on cpu
>> CPU states: 98.7% idle, 0.6% user, 0.7% kernel, 0.0% iowait, 0.0% swap
>> Memory: 4096M phys mem, 1718M free mem, 8005M total swap, 8005M free swap
>>
>> PID USERNAME LWP PRI NICE SIZE RES STATE TIME CPU COMMAND
>> 22797 dsadmin 41 59 0 297M 261M sleep 468:00 0.44% ns-slapd
>> 23543 root 1 59 0 355M 353M sleep 174:26 0.29% perl
>> 10858 root 1 59 0 2888K 1784K cpu/0 0:00 0.09% top
>> 23137 root 41 59 0 196M 162M sleep 329:16 0.05% ns-slapd
>> 22899 root 30 59 0 134M 92M sleep 167:34 0.02% java
>> 691 noaccess 25 59 0 177M 96M sleep 231:51 0.02% java
>> 10823 root 1 59 0 3008K 2488K sleep 0:00 0.02% bash
>> 10821 root 1 59 0 8304K 2728K sleep 0:00 0.01% sshd
>> 26407 daemon 4 59 0 620M 559M sleep 19:44 0.01% nfsmapid
>> 331 root 1 100 -20 2312K 1512K sleep 31:05 0.01% xntpd
>> 5013 root 25 59 0 6544K 4576K sleep 1:01 0.01% nscd
>> 114 root 6 59 0 4128K 3248K sleep 341:09 0.01% picld
>> 7312 root 1 59 0 1984K 1576K sleep 0:00 0.00% tail
>> 1148 root 1 59 0 9000K 3352K sleep 0:00 0.00% sshd
>> 7 root 13 59 0 9784K 7728K sleep 4:47 0.00% svc.startd
>>
>> Regards,
>> -Manish
>>
>>
>> _______________________________________________
>> radiator mailing list
>> radiator at open.com.au <mailto:radiator at open.com.au>
>> http://www.open.com.au/mailman/listinfo/radiator
>
>
> --
>
> Hugh Irvine
> hugh at open.com.au <mailto:hugh at open.com.au>
>
> Radiator: the most portable, flexible and configurable RADIUS server
> anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
> Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
> TTLS, PEAP, TNC, WiMAX, RSA, Vasco, Yubikey, MOTP, HOTP, TOTP,
> DIAMETER etc.
> Full source on Unix, Windows, MacOSX, Solaris, VMS, NetWare etc.
>
>
>
>
>
> _______________________________________________
> radiator mailing list
> radiator at open.com.au
> http://www.open.com.au/mailman/listinfo/radiator
>
--
Heikki Vatiainen <hvn at open.com.au>
Radiator: the most portable, flexible and configurable RADIUS server
anywhere. SQL, proxy, DBM, files, LDAP, NIS+, password, NT, Emerald,
Platypus, Freeside, TACACS+, PAM, external, Active Directory, EAP, TLS,
TTLS, PEAP, TNC, WiMAX, RSA, Vasco, Yubikey, MOTP, HOTP, TOTP,
DIAMETER etc. Full source on Unix, Windows, MacOSX, Solaris, VMS,
NetWare etc.
More information about the radiator
mailing list