Processing time statistics of invite authentication and authorization requests of the AAA radius server

Emin Gabrielyan

Created or modified: on 2011-02-25 by Emin

The following test shows that all logged invite authentication requests are accompanied by a processing time record.

fraud-control:/home/var/log/radius#

fraud-control:/home/var/log/radius# cat 110223,090042,201808,0,rotated,radius.log | perl -ne 'if(/^$/ && $a=~/^nas-ip-address.*^h323-conf-id.*method.*invite.*/ism){print $a if($a!~/Done Authorize.INVITE in/)} $a="" if(/^$/); $a.=$_'

fraud-control:/home/var/log/radius#

The following chart shows the average time spent by the radius server for 5 min intervals.

[zip]

All cases of invite requests processed in more than 1 second can be found in the daily log by the following command line:

fraud-control:/home/folders/110225-invites#

fraud-control:/home/folders/110225-invites# cat /home/var/log/radius/110224,090046,201790,0,rotated,radius.log | perl -ne 'if(/^([^ ]+ +[0-9]+) +([0-9:]+): \.\.\.Done Authorize\/INVITE in ([0-9.]+) seconds, ([0-9.]+) spent in SQL queries\.$/){$date=$1; $time=$2; $total=$3; $sql=$4; print if($total > 1)}'

Feb 24 00:12:15: ...Done Authorize/INVITE in 1.253967 seconds, 1.221725 spent in SQL queries.

Feb 24 00:12:23: ...Done Authorize/INVITE in 2.785065 seconds, 2.768906 spent in SQL queries.

Feb 24 00:13:13: ...Done Authorize/INVITE in 1.600808 seconds, 1.566315 spent in SQL queries.

Feb 24 00:14:27: ...Done Authorize/INVITE in 1.550839 seconds, 1.519080 spent in SQL queries.

Feb 24 00:14:50: ...Done Authorize/INVITE in 1.953423 seconds, 1.911623 spent in SQL queries.

Feb 24 00:15:11: ...Done Authorize/INVITE in 1.146464 seconds, 1.112943 spent in SQL queries.

Feb 24 00:15:52: ...Done Authorize/INVITE in 8.425980 seconds, 8.409533 spent in SQL queries.

Feb 24 00:16:04: ...Done Authorize/INVITE in 4.615599 seconds, 4.599381 spent in SQL queries.

Feb 24 00:16:46: ...Done Authorize/INVITE in 1.138968 seconds, 1.122514 spent in SQL queries.

Feb 24 00:18:03: ...Done Authorize/INVITE in 1.515901 seconds, 1.478320 spent in SQL queries.

Feb 24 00:19:19: ...Done Authorize/INVITE in 2.760451 seconds, 2.730553 spent in SQL queries.

Feb 24 00:21:27: ...Done Authorize/INVITE in 1.047024 seconds, 1.030418 spent in SQL queries.

Feb 24 00:22:30: ...Done Authorize/INVITE in 1.083549 seconds, 1.049626 spent in SQL queries.

Feb 24 00:23:02: ...Done Authorize/INVITE in 2.237400 seconds, 2.204385 spent in SQL queries.

Feb 24 00:23:33: ...Done Authorize/INVITE in 1.710871 seconds, 1.667733 spent in SQL queries.

Feb 24 00:24:59: ...Done Authorize/INVITE in 1.008390 seconds, 0.967440 spent in SQL queries.

Feb 24 00:28:19: ...Done Authorize/INVITE in 1.080803 seconds, 1.045036 spent in SQL queries.

Feb 24 00:28:53: ...Done Authorize/INVITE in 1.105748 seconds, 1.067983 spent in SQL queries.

Feb 24 00:28:55: ...Done Authorize/INVITE in 1.040234 seconds, 1.010318 spent in SQL queries.

Feb 24 00:31:19: ...Done Authorize/INVITE in 3.415789 seconds, 3.398617 spent in SQL queries.

Feb 24 00:31:34: ...Done Authorize/INVITE in 1.797655 seconds, 1.748269 spent in SQL queries.

Feb 24 00:32:29: ...Done Authorize/INVITE in 1.280192 seconds, 1.247773 spent in SQL queries.

Feb 24 00:32:44: ...Done Authorize/INVITE in 8.806046 seconds, 8.786301 spent in SQL queries.

Feb 24 00:32:48: ...Done Authorize/INVITE in 1.956632 seconds, 1.926202 spent in SQL queries.

Feb 24 00:32:58: ...Done Authorize/INVITE in 2.251668 seconds, 2.241752 spent in SQL queries.

Feb 24 00:33:03: ...Done Authorize/INVITE in 3.341902 seconds, 3.324453 spent in SQL queries.

Feb 24 00:33:22: ...Done Authorize/INVITE in 2.986150 seconds, 2.969194 spent in SQL queries.

Feb 24 00:33:25: ...Done Authorize/INVITE in 1.726571 seconds, 1.713303 spent in SQL queries.

Feb 24 00:36:13: ...Done Authorize/INVITE in 1.084789 seconds, 1.050269 spent in SQL queries.

Feb 24 00:39:28: ...Done Authorize/INVITE in 1.212377 seconds, 1.174518 spent in SQL queries.

Feb 24 01:04:53: ...Done Authorize/INVITE in 1.993001 seconds, 1.976845 spent in SQL queries.

Feb 24 01:06:09: ...Done Authorize/INVITE in 62.381848 seconds, 62.336549 spent in SQL queries.

Feb 24 01:07:49: ...Done Authorize/INVITE in 94.122503 seconds, 94.061494 spent in SQL queries.

Feb 24 01:09:24: ...Done Authorize/INVITE in 73.886387 seconds, 73.864097 spent in SQL queries.

Feb 24 01:09:38: ...Done Authorize/INVITE in 2.222394 seconds, 2.181515 spent in SQL queries.

Feb 24 01:09:41: ...Done Authorize/INVITE in 1.814260 seconds, 1.761632 spent in SQL queries.

Feb 24 01:09:50: ...Done Authorize/INVITE in 3.803457 seconds, 3.786934 spent in SQL queries.

Feb 24 01:10:00: ...Done Authorize/INVITE in 4.162497 seconds, 4.120542 spent in SQL queries.

Feb 24 01:10:05: ...Done Authorize/INVITE in 4.818195 seconds, 4.800860 spent in SQL queries.

Feb 24 01:10:09: ...Done Authorize/INVITE in 2.958490 seconds, 2.945278 spent in SQL queries.

Feb 24 01:10:12: ...Done Authorize/INVITE in 2.290532 seconds, 2.266177 spent in SQL queries.

Feb 24 01:10:16: ...Done Authorize/INVITE in 2.481977 seconds, 2.468695 spent in SQL queries.

Feb 24 01:10:22: ...Done Authorize/INVITE in 4.754724 seconds, 4.741225 spent in SQL queries.

Feb 24 01:10:28: ...Done Authorize/INVITE in 4.851553 seconds, 4.835030 spent in SQL queries.

Feb 24 01:10:36: ...Done Authorize/INVITE in 5.608283 seconds, 5.594937 spent in SQL queries.

Feb 24 01:10:50: ...Done Authorize/INVITE in 5.596401 seconds, 5.580081 spent in SQL queries.

Feb 24 01:10:54: ...Done Authorize/INVITE in 3.993838 seconds, 3.977432 spent in SQL queries.

Feb 24 01:11:02: ...Done Authorize/INVITE in 6.931499 seconds, 6.900159 spent in SQL queries.

Feb 24 01:11:18: ...Done Authorize/INVITE in 1.628830 seconds, 1.592562 spent in SQL queries.

Feb 24 01:11:26: ...Done Authorize/INVITE in 1.279309 seconds, 1.248036 spent in SQL queries.

Feb 24 01:12:44: ...Done Authorize/INVITE in 1.068600 seconds, 0.980695 spent in SQL queries.

Feb 24 01:16:02: ...Done Authorize/INVITE in 1.010367 seconds, 0.963615 spent in SQL queries.

Feb 24 01:17:44: ...Done Authorize/INVITE in 1.509664 seconds, 1.468229 spent in SQL queries.

Feb 24 01:26:07: ...Done Authorize/INVITE in 1.883488 seconds, 1.640538 spent in SQL queries.

Feb 24 01:30:04: ...Done Authorize/INVITE in 1.078043 seconds, 1.045644 spent in SQL queries.

Feb 24 01:39:05: ...Done Authorize/INVITE in 2.329061 seconds, 2.293553 spent in SQL queries.

Feb 24 02:33:19: ...Done Authorize/INVITE in 1.079715 seconds, 1.037711 spent in SQL queries.

Feb 24 03:16:02: ...Done Authorize/INVITE in 1.063701 seconds, 1.022343 spent in SQL queries.

Feb 24 03:58:19: ...Done Authorize/INVITE in 1.398892 seconds, 1.357403 spent in SQL queries.

Feb 24 05:07:29: ...Done Authorize/INVITE in 1.049232 seconds, 1.010388 spent in SQL queries.

Feb 24 05:43:24: ...Done Authorize/INVITE in 1.014165 seconds, 0.973242 spent in SQL queries.

Feb 24 14:08:33: ...Done Authorize/INVITE in 1.908850 seconds, 1.877987 spent in SQL queries.

Feb 24 22:33:50: ...Done Authorize/INVITE in 1.552998 seconds, 1.528639 spent in SQL queries.

Feb 24 23:25:30: ...Done Authorize/INVITE in 1.019601 seconds, 0.968896 spent in SQL queries.

Feb 24 23:57:19: ...Done Authorize/INVITE in 3.290312 seconds, 3.260030 spent in SQL queries.

fraud-control:/home/folders/110225-invites#

[log]

Note that the time in the log is in the US Pacific Time Zone while the time in the Excel chart is converted into CET Swiss time.

The morning peaks are systematic. During these peaks, the SIP nodes are processing the calls with serious delays with many calls dropped. At the same time the CPU load on SIP servers increases significantly, which is a known problem.