Performance or locking issue with rlm_detail

[Aleš Rygl]

Hello.

 I would like to kindly ask for help with freeradius server
processing Accounting req. I am running freeradius 3.0.11 on Debian
stable, kernel 3.16.0-4-amd64. Server is DL380 G9, CPU E5-2680 v3 @
2.50GHz, 256GB RAM, very fast HP SSD RAID5 2.5 TB. The kernel can see 48
CPU.

 Radius is processing ~ 3kqps of Accounting (Telco environment).
The daemon receives Acct. req. and using module rml_detail it writes it
into a detail file(s) - there are 32 file queues based on modulo of
Calling-Station-Id.

 detail detail.mobile {
 Queue-Number = "%{expr:
%{Calling-Station-Id} %% 32 }"
 filename =
${radacctdir}/detail.mobile_v3/queue-${Queue-Number}/detail-%Y%m%d%H

locking = yes
 }

 Then there are detail file loaders into DB:

 server
buffered-sql-0 {
 listen {
 type = detail
 filename =
"${radacctdir}/detail.mobile_v3/queue-0/detail-*"
 load_factor = 95

track = yes
 poll_interval = 1
 retry_interval = 60

 }
 preacct {

 }


accounting {
 sql_instance_mobile
 if (noop) {
 ok
 }

 }
 }

 Some
server params:

 max_request_time = 10
 cleanup_delay = 5
 max_requests
= 20000
 hostname_lookups = no
 max_servers = 1500

 min_spare_servers =
100
 max_spare_servers = 300

 Everything works fine, there is ~15
connections to DB while processing ~2-3 kqps. Freeradius utilize about 3
CPU. This setup can load gigs of logs into DB without slowing down
Radius responses. 

The issue is that freeradius randomly starts to use
too much CPU (60-70% of whole server). There are following lines
appearing in the log: 

Wed Mar 29 09:17:43 2017 : WARNING: (44056176)
WARNING: Module rlm_detail became unblocked for request 44056176
Wed Mar
29 09:17:43 2017 : WARNING: (44056177) WARNING: Module rlm_detail became
unblocked for request 44056177
Wed Mar 29 09:17:43 2017 : WARNING:
(44056178) WARNING: Module rlm_detail became unblocked for request
44056178
Wed Mar 29 09:17:43 2017 : WARNING: (44056179) WARNING: Module
rlm_detail became unblocked for request 44056179
Wed Mar 29 09:17:43
2017 : WARNING: (44056180) WARNING: Module rlm_detail became unblocked
for request 44056180 

It seems to be related to high spikes in the
incoming radius traffic that occurs every hour - the issue become worse
after DST change when certain amount of terminal were restarted in the
same moment and their sessions produce Radius Accounting synchronously.
But not every time. 

I have an old server doing the same thing running
Freeradius 3.0.8., the kernel can see 24 CPU, and it really never
happened here while on the new box it is on daily basis. The
configuration of Radius is identical. 

Thanks 

Regards 

Ales