Every morning we experience a CPU load increase on all our portasip servers [b2p1] [b2p2] [b2p3]. Numerous customers constantly complain about call problems occurring around 9h in the morning. The problem was spotted with CPU charts [82a1] [a6h1] [a6h2] [a6h3] a long time ago. The apparent reason is an activity scheduled on the master-billing server for the midnight in the Pacific Time zone corresponding to CET 9h (except the first one-two days of the month).

Irresponsiveness of the radius server

Our initial hypothesis was that the radius service becomes affected during these periods with its responsiveness being seriously degraded. The analysis of the radius log confirmed that during the period in question the response time of the radius server is increasing noticeably [b2p1] [b2p2] [b2p3]. We launched a project (being run by Yannick Vaucher) aiming at a development of an autonomous routing module for astrad servers that is temporarily activated in case of timed out radius answers. If the hypothesis of radius irresponsiveness were correct, the problem must appear on two types of sip servers as both rely on the call authentication via radius. Even though the CPU load of astrad servers does not change in the same way as it is seen on the portasip servers, the astrad servers [b1q1] had to be affected as much as the portasip servers are. By design, as long as the module of the autonomous mode is not developed, the lack of radius answers must disable calls on an astrad server as much as it does on portasip servers. Section Analysis of CDR files of all astrad servers analyses the CDR files of all astrad servers and, despite our initial hypothesis, proves that astrad servers do not undergo any noticeable abnormality during the morning period. It therefore rejects the theory of irresponsiveness of the radius server.

Irresponsiveness of the database

A different research comparing the hourly intensity of calls for portasip and astrad servers confirms that only portasip servers are affected by the morning problem (see Hourly traffic charts). The following chart shows the hourly traffic pattern of all portasip servers in comparison with the global pattern of all astrad servers. The curves are aligned such that their average levels match. While the both curves match well everywhere (reflecting the natural traffic pattern of our average clientele), between 9h to 10h we see an exceptional gap. We can clearly identify that portasip servers are passing significantly less traffic than the astrad servers.

Origin of the problem

Our new conclusion is that portasip servers become crazy during 9h to 10h morning period not because of the irresponsiveness of the radius but rather because of the irresponsiveness of the mysql accesses that are carried out by portasip servers uniquely for the update of the central location database. The analysis of the log of radius server [b2p1] [b2p2] [b2p3] showed that during the morning hours the processing of AAA requests is taking longer time and that the increase in the processing time is due uniquely of mysql while the rest of processing takes the same resource. This partially confirms our new assumption. Apparently portasip is designed in a way that it reacts too badly on mysql delays. In contrast to portasip, for astrad servers the irresponsiveness of mysql does not have any blocking effect. The updates of the central location database are processed by an independent process, connected to the asterisk via a socket of the asterisk manager. In the worst case, the irresponsiveness of mysql can temporarily block only the independent listener on the astrad server without affecting the core functionality of astrad. Furthermore, the registrations are processed by astrad locally and irrespectively of the connection with the master.

Comparison of database call records for two types of servers

Before comparing the call records of portasip and astrad servers, we carried out a deep analysis of CDR files of astrad servers only. Our objective was to spot the morning problem on astrad servers as we expected that they suffer similarly to portasip. The next section Analysis of CDR files of all astrad servers presents the details of this analysis and we show that astrad servers are in fact not suffering from the morning problem. To validate this conclusion, in this section, we expanded our research over both types of servers, including now also portasip servers.

SQL query generating the CDR file

By Yannick Vaucher

An SQL query retrieves all call records by associating to each record the current location (domain / sip server) of the customer’s account (CLI). This requests counts on a weak or no migration of customers across the servers over the concerned period.

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# mysql -uroot -p******

Welcome to the MySQL monitor. Commands end with ; or \g.

Your MySQL connection id is 22120

Server version: 5.0.51a-24+lenny4-log (Debian)

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> SELECT

-> cdr.*,loc.domain, loc.last_modified

-> FROM

-> ( SELECT domain as lastDom, username

-> FROM `porta-sip`.location

-> GROUP BY `porta-sip`.location.username

-> ORDER BY `porta-sip`.location.last_modified DESC )

-> as b

-> INNER JOIN

-> `porta-sip`.location loc ON loc.domain = b.lastDom AND loc.username = b.username

-> INNER JOIN

-> `porta-billing`.CDR_Accounts cdr ON loc.username = cdr.account_id

-> WHERE

-> cdr.connect_time > "2011-02-07"

-> into outfile 'out1.csv'

-> fields terminated by ',' optionally enclosed by '"' lines terminated by '\n';

Query OK, 381534 rows affected (21 min 57.41 sec)

mysql>

mysql> quit

Bye

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# date -d "11-02-07 +36 days" +%y-%m-%d

11-03-15

db2:~/folders/110315-db-cdr# mv /var/lib/mysql/out1.csv 110207+36,cdr1.csv

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# ls -l

total 99624

-rw-rw-rw- 1 mysql mysql 101985088 2011-03-15 19:34 110207+36,cdr1.csv

-rw-rw-rw- 1 mysql mysql 26782 2011-03-15 18:51 out1.csv

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# tail 110207+36,cdr1.csv | cut -d, -f4-9,11,14,16-17,20,26-27

"41215501639","41215340465",24,"2011-03-15 18:48:21","2011-03-15 18:54:52",16,391,"41215501639",391,0.00000,0.03784,"91.121.147.45","2011-03-15 18:13:01"

"41225500418","442079221900",14,"2011-03-15 18:53:41","2011-03-15 18:55:29",16,108,"41225500418",108,0.00000,0.00504,"91.121.143.56","2011-03-06 17:03:52"

...

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# head 110207+36,cdr1.csv | cut -d, -f4-9,11,14,16-17,20,26-27

"41215504724","4922198744793",28,"2011-02-07 00:20:19","2011-02-07 00:20:23",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

"41215504724","4922198744793",28,"2011-02-07 00:39:10","2011-02-07 00:39:14",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

...

db2:~/folders/110315-db-cdr#

db2:~/folders/110315-db-cdr# cat 110207+36,cdr1.csv | cut -d, -f4-9,11,14,16-17,20,26-27 > 110207+36,cdr2,fields13.csv

db2:~/folders/110315-db-cdr# wc -l 110207+36,cdr*

381534 110207+36,cdr1.csv

381534 110207+36,cdr2,fields13.csv

763068 total

db2:~/folders/110315-db-cdr# wc -c 110207+36,cdr*

101985088 110207+36,cdr1.csv

58243062 110207+36,cdr2,fields13.csv

160228150 total

db2:~/folders/110315-db-cdr#

data1\a4\log1.zip

data1\a4\Book1.xls (headers)

This query is executed on the db2 development server replicating the master’s database.

CDR file limited by PDD, duration, and server type (portasip/astrad)

In the previous section, we show the generation of a CDR file containing the following 13 fields: CLI, CLD, setup_time, connect_time, disconnect_time, disconnect_cause, duration, account_id, charged_time, charged_amount, cost, domain, and last_modified (data1\a4\Book1.xls). In this subsection, we obtain an output file with six fields, which are sufficient for obtaining the quality stats: setup_time, connect_time, disconnect_time, duration, domain, server_type. The last field (server_type) is a function of the previous field (IP address of the domain/registrar).

Here is an overview of the 13-field input file:

$ scp root@db2.switzernet.com:/root/folders/110315-db-cdr/110207+36,cdr3,fields13.csv.gz .

root@db2.switzernet.com's password:

110207+36,cdr3,fields13.csv.gz 100% 11MB 30.1KB/s 06:23

$ cp 110207+36,cdr3,fields13.csv.gz cdr3.csv.gz

$ gzip -d cdr3.csv.gz

$ wc -l cdr3.csv

381534 cdr3.csv

$ tail -4 cdr3.csv

"41215506215","41216469114",18,"2011-03-15 18:50:43","2011-03-15 19:01:28",16,645,"41215506215",645,0.00000,0.05943,"91.121.143.56","2011-03-15 18:43:04"

"41225500769","33676899837",19,"2011-03-15 19:01:31","2011-03-15 19:01:32",16,1,"41225500769",1,0.01000,0.00077,"91.121.143.56","2011-03-15 18:27:49"

"41615041550","41764083329",9,"2011-03-15 19:00:42","2011-03-15 19:01:35",16,53,"41615041550",53,0.13000,0.09956,"91.121.138.5","2011-03-15 18:36:33"

"41325042668","41329680883",14,"2011-03-15 19:04:49","2011-03-15 19:05:27",16,38,"41325042668",38,0.00000,0.00949,"91.121.142.9","2011-03-15 18:36:27"

$ cat headers.txt

cdr.CLI,

cdr.CLD,

cdr.setup_time,

cdr.connect_time,

cdr.disconnect_time,

cdr.disconnect_cause,

cdr.duration,

cdr.account_id,

cdr.charged_time,

cdr.charged_amount,

cdr.cost,

loc.domain,

loc.last_modified

data1\a4\log2.zip

Here is the list of all IP addresses encountered under the domain field of the input CDR file:

$ cut -d, -f12 cdr3.csv | sort | uniq -c | sort -n

56 "94.23.225.212"

253 "91.121.205.108"

496 "66.234.138.73"

655 "213.251.169.218"

6746 "91.121.147.45"

13306 "91.121.16.79"

14840 "91.121.178.108"

15644 "94.23.50.74"

16309 "91.121.142.9"

16560 "91.121.143.56"

22400 "91.121.99.16"

23822 "91.121.121.115"

26802 "91.121.167.75"

29766 "91.121.101.126"

30165 "82.103.128.3"

35032 "91.121.70.119"

39572 "213.251.174.129"

40526 "91.121.138.5"

48584 "91.121.75.124"

data1\a4\log2.zip

Here are justifications for getting rid of the charged_time field (which is not always equal to the actual duration).

$ head -2 cdr3.csv

"41215504724","4922198744793",28,"2011-02-07 00:20:19","2011-02-07 00:20:23",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

"41215504724","4922198744793",28,"2011-02-07 00:39:10","2011-02-07 00:39:14",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

$ cat ../../a4/cdr3.csv | awk -F, '{t1+=$7; t2+=$9} END{printf "t1=%d t2=%d\n",t1,t2}'

t1=147981407 t2=148181413

$ cat cdr3.csv | awk -F, '$7 != $9 {print}' | head -4

"41215502610","41327101112",10,"2011-02-07 08:14:56","2011-02-07 08:15:24",16,28,"41215502610",60,0.04000,0.00532,"82.103.128.3","2011-03-15 19:07:06"

"41215502610","41327101112",9,"2011-02-07 08:18:55","2011-02-07 08:19:03",16,8,"41215502610",60,0.04000,0.00152,"82.103.128.3","2011-03-15 19:07:06"

"41215502610","41327203171",8,"2011-02-07 08:22:13","2011-02-07 08:22:35",16,22,"41215502610",60,0.04000,0.00418,"82.103.128.3","2011-03-15 19:07:06"

"41215502610","41327101112",10,"2011-02-07 08:39:39","2011-02-07 08:40:15",16,36,"41215502610",60,0.04000,0.00684,"82.103.128.3","2011-03-15 19:07:06"

$ # As shown above the duration and the charged time are not obligatorily the same. The charged time can be rounded to 1m (for prepaid customers).

data1\a4\log2.zip

According to the first command shown below, the disconnection code apparently is not going to provide us any valuable information. The second command shows us the dial- and speak- times in minutes.

$ cat cdr3.csv | cut -d, -f6 | sort | uniq -c | sort -n

4 0

5 40

381525 16

$ # stats of disconnect causes

$ cat cdr3.csv | awk -F, '{pdd+=$3; dur+=$7} END{printf "pdd=%-20.1f dur=%-20.1f speak/dial=%-10.3f\n",pdd/60,dur/60,dur/pdd}'

pdd=89319.1 dur=2466356.8 speak/dial=27.613

data1\a4\log2.zip

Based on the previous observations, we finally limit ourselves with six output fields, which are: (1) call setup duration, (2) connect time, (3) disconnect time, (4) call duration, (5) domain IP, and (6) server type.

$ for i in 4 5 6 7 8; do h=astrad$i; echo -n "[$h] "; ping $h.switzernet.com 100 2 | grep from | cut -d" " -f1-4 | uniq -c; done

[astrad4] 2 108 bytes from 91.121.16.79:

[astrad5] 1 108 bytes from 91.121.178.108:

[astrad6] 1 108 bytes from 91.121.142.9:

[astrad7] 2 108 bytes from 91.121.147.45:

[astrad8] 2 108 bytes from 91.121.143.56:

$ head -2 cdr3.csv

"41215504724","4922198744793",28,"2011-02-07 00:20:19","2011-02-07 00:20:23",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

"41215504724","4922198744793",28,"2011-02-07 00:39:10","2011-02-07 00:39:14",16,4,"41215504724",4,0.01000,0.00051,"91.121.99.16","2011-03-15 19:06:52"

$ head -2 cdr3.csv | cut -d, -f3-5,7,12

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16"

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16"

$ head -2 cdr3.csv | cut -d, -f3-5,7,12 | perl -ne '$serv=/,"(?:91.121.16.79|91.121.178.108|91.121.142.9|91.121.147.45|91.121.143.56)"$/?"astrad":"portasip"; print "$1,$serv\n" if(/(.*)$/)'

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16",portasip

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16",portasip

$ cat cdr3.csv | cut -d, -f3-5,7,12 | perl -ne '$serv=/,"(?:91.121.16.79|91.121.178.108|91.121.142.9|91.121.147.45|91.121.143.56)"$/?"astrad":"portasip"; print "$1,$serv\n" if(/(.*)$/)' > cdr4.csv

$ wc -l cdr3.csv cdr4.csv

381534 cdr3.csv

381534 cdr4.csv

763068 total

data1\a4\log2.zip

data1\a4\cdr4.zip

Validations

The output CDR file is validated by re-computing and comparing the totals per IP and type.

$ head -2 cdr4.csv

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16",portasip

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16",portasip

$ # fields of cdr4.csv

$ # cdr.setup_time,cdr.connect_time,cdr.disconnect_time,cdr.duration,loc.domain,server

$ cut -d, -f5 cdr4.csv | sort | uniq -c | sort -n

56 "94.23.225.212"

253 "91.121.205.108"

496 "66.234.138.73"

655 "213.251.169.218"

6746 "91.121.147.45"

13306 "91.121.16.79"

14840 "91.121.178.108"

15644 "94.23.50.74"

16309 "91.121.142.9"

16560 "91.121.143.56"

22400 "91.121.99.16"

23822 "91.121.121.115"

26802 "91.121.167.75"

29766 "91.121.101.126"

30165 "82.103.128.3"

35032 "91.121.70.119"

39572 "213.251.174.129"

40526 "91.121.138.5"

48584 "91.121.75.124"

$ cut -d, -f6 cdr4.csv | sort | uniq -c | sort -n

67761 astrad

313773 portasip

$ expr 13306 + 14840 + 16309 + 6746 + 16560

67761

$ #The numbers match

$ wc -l cdr4.csv

381534 cdr4.csv

$ expr 381534 - 67761

313773

$ #The numbers match

data1\a4\log2.zip

Speak/dial ratio per server type

Below we see the distribution of the number of calls, duration, and PDD over portasip and astrad server types.

$ # now computing the speak/dial ratio for both types of servers

$ cat cdr4.csv | awk -F, '$6=="portasip" {n1++;pdd1+=$1;dur1+=$4} $6=="astrad" {n2++;;pdd2+=$1;dur2+=$4} END{printf "%20s %20s %20s %20s %20s\n","server","num","pdd","dur","speak/dial"; printf "%20s %20d %20.1f %20.1f %20.3f\n","portasip",n1,pdd1/60,dur1/60,dur1/pdd1; printf "%20s %20d %20.1f %20.1f %20.3f\n","astrad",n2,pdd2/60,dur2/60,dur2/pdd2; }'

server num pdd dur speak/dial

portasip 313773 73044.0 1999886.9 27.379

astrad 67761 16275.0 466469.8 28.662

$ #the ratio is insignificantly better for astrad

$ cat cdr4.csv | cut -d, -f4 | egrep "^0$" | wc -l

$ # no call found above with 0 duration

data1\a4\log2.zip

Generation of 10-min interval stats for the both server types

Now we are recording for each 10-min interval of a day and for two types of servers (portasip/astrad) the following three values, (1) the number of calls, (2) the total PDD, and (3) the total duration.

$ # cdr.setup_time,cdr.connect_time,cdr.disconnect_time,cdr.duration,loc.domain,server

$ head -2 cdr4.csv

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16",portasip

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16",portasip

$ head -2 cdr4.csv | perl -ne 'if(/^([0-9]+),".* ([0-9]{2}:[0-9]).*",".*",([0-9]+),".*",([a-z]+)$/){($pdd,$conn,$dur,$serv)=($1,$2,$3,$4);$conn.=0; printf "%d,%s,%d,%s\n",$pdd,$conn,$dur,$serv}'

28,00:20,4,portasip

28,00:30,4,portasip

$ head -5 cdr4.csv

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16",portasip

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16",portasip

23,"2011-02-07 02:08:43","2011-02-07 02:08:48",5,"91.121.121.115",portasip

15,"2011-02-07 02:13:16","2011-02-07 02:13:24",8,"91.121.75.124",portasip

5,"2011-02-07 00:56:36","2011-02-07 02:55:59",7163,"91.121.101.126",portasip

$ cat cdr4.csv | perl -e 'while(<>){if(/^([0-9]+),".* ([0-9]{2}:[0-9]).*",".*",([0-9]+),".*",([a-z]+)$/){($pdd,$conn,$dur,$serv)=($1,$2,$3,$4);$conn.=0;$N{$conn}++;$i="$conn,$serv";$n{$i}++;$pdd{$i}+=$pdd;$dur{$i}+=$dur}} for $conn (keys %N){print $conn; for $serv ("portasip","astrad"){$i="$conn,$serv"; printf ",%d,%d,%d",$n{$i},$pdd{$i},$dur{$i} } printf ",%d\n",$N{$conn}}' | sort

00:00,615,9221,342709,93,1212,64925,708

00:10,559,8188,335210,75,902,62482,634

00:20,481,6957,360523,83,1017,100868,564

00:30,416,5915,290795,79,1077,63601,495

00:40,342,4821,227066,74,890,37601,416

00:50,331,4713,189275,59,890,33993,390

01:00,244,3640,180283,55,761,53800,299

01:10,187,2545,102281,43,693,44413,230

01:20,187,2427,140746,40,567,26557,227

01:30,193,2828,112292,47,681,28284,240

01:40,140,2008,109359,37,539,17246,177

01:50,140,1967,120441,27,474,12289,167

02:00,120,1591,93876,22,380,3141,142

02:10,114,1645,80024,24,411,32947,138

02:20,113,1401,68211,12,185,8599,125

02:30,153,1915,54425,32,519,9410,185

02:40,130,1642,39882,41,680,7994,171

02:50,70,938,31113,35,624,16260,105

03:00,70,943,24752,22,360,1352,92

03:10,70,968,43294,11,199,13382,81

03:20,71,875,57669,13,168,2167,84

03:30,55,777,31114,15,260,8142,70

03:40,70,1163,45964,14,232,7903,84

03:50,57,871,33235,17,288,258,74

04:00,52,795,31044,11,132,2846,63

04:10,46,649,25738,7,102,2663,53

04:20,76,1082,30774,2,41,52,78

04:30,72,951,30315,6,142,4038,78

04:40,90,914,25212,3,21,257,93

04:50,60,874,33632,7,72,2751,67

05:00,141,1269,32320,9,223,3533,150

05:10,57,836,16266,14,167,3168,71

05:20,68,927,18161,9,114,3044,77

05:30,123,1104,20745,6,111,8062,129

05:40,65,1010,35574,11,205,1395,76

05:50,95,1391,25924,21,335,7974,116

06:00,102,1465,21350,20,296,8885,122

06:10,84,1267,28683,14,164,2312,98

06:20,101,1478,28277,25,352,13478,126

06:30,276,2131,63947,41,640,7938,317

06:40,191,2395,43952,39,683,10752,230

06:50,201,2908,61641,52,619,9474,253

07:00,295,4371,85057,73,1120,15706,368

07:10,382,5243,109148,108,1549,34516,490

07:20,467,6852,114105,113,1605,28946,580

07:30,674,9217,176236,173,2391,46706,847

07:40,741,10218,194063,166,2263,40388,907

07:50,854,11856,243426,259,3504,76703,1113

08:00,1218,15974,328080,309,3974,81878,1527

08:10,1232,16493,364688,351,4874,116706,1583

08:20,1430,19251,459535,368,4965,101820,1798

08:30,1776,23735,528870,468,6169,157055,2244

08:40,1866,24394,523034,502,7566,163065,2368

08:50,2083,27194,532910,601,8401,220376,2684

09:00,2526,32943,539169,659,8568,193523,3185

09:10,2733,36768,508716,729,10336,241048,3462

09:20,2981,38727,726049,721,9941,263444,3702

09:30,3081,40680,905272,747,10137,225217,3828

09:40,3321,44947,1002363,781,10448,306780,4102

09:50,3332,45195,960266,847,11590,296551,4179

10:00,3056,41662,930161,757,10259,269437,3813

10:10,3165,42492,1028613,827,11418,293172,3992

10:20,3370,45046,1120612,848,12511,314528,4218

10:30,3766,49665,1232128,800,10605,297400,4566

10:40,3923,53557,1226325,868,11676,290187,4791

10:50,4080,55149,1225976,835,11688,318211,4915

11:00,3984,54182,1194621,853,11795,255657,4837

11:10,3925,53129,1192571,816,11274,272677,4741

11:20,3837,51503,1197056,849,11613,302577,4686

11:30,3992,54912,1161176,846,11483,255234,4838

11:40,4037,55078,1170278,822,11258,223505,4859

11:50,3773,50946,1021774,844,11809,241288,4617

12:00,3185,43649,928767,713,9868,264141,3898

12:10,3137,43354,1003982,672,9816,247190,3809

12:20,3023,42037,1007369,696,10133,234031,3719

12:30,2983,42260,1042096,661,9612,195020,3644

12:40,3068,43863,1092913,658,9369,230559,3726

12:50,3116,44394,1107620,610,8916,210995,3726

13:00,3368,46841,1179232,651,10163,237612,4019

13:10,3405,48479,1073020,692,9814,295454,4097

13:20,3501,49942,1190904,760,10562,342231,4261

13:30,3618,50357,1149498,784,11028,310324,4402

13:40,3494,48721,1130534,729,10261,287381,4223

13:50,3584,49275,1125817,756,10185,254635,4340

14:00,3746,52474,1132655,793,13613,295615,4539

14:10,3650,50802,1172090,800,10720,302828,4450

14:20,3589,50202,1131759,768,10599,286245,4357

14:30,3428,45686,1101155,727,10479,231326,4155

14:40,3406,46942,1121888,763,10949,267429,4169

14:50,3644,49183,1178127,757,9861,267046,4401

15:00,3594,50650,1110798,805,11411,315969,4399

15:10,3607,50351,1118480,756,10735,244152,4363

15:20,3413,47656,1032919,764,10417,252783,4177

15:30,3596,48778,1038806,769,10762,257776,4365

15:40,3570,49003,1129672,734,10607,278486,4304

15:50,3580,48758,1007891,725,10257,276104,4305

16:00,3486,47828,1124701,725,10328,252697,4211

16:10,3476,48656,1150924,763,11467,265519,4239

16:20,3812,52624,1138789,762,10373,311480,4574

16:30,3854,53822,1148017,807,11123,264160,4661

16:40,3864,54182,1226211,769,10634,323150,4633

16:50,3862,54738,1253856,745,10538,253457,4607

17:00,3953,55819,1267749,894,12779,348800,4847

17:10,3990,58191,1310568,824,12319,319548,4814

17:20,3963,56636,1354819,841,12874,329416,4804

17:30,3748,52909,1388953,885,13060,330283,4633

17:40,3926,55944,1460958,949,14459,409263,4875

17:50,3943,57246,1441291,879,13074,341557,4822

18:00,4020,58213,1522518,864,12977,342160,4884

18:10,4023,59424,1557098,837,12618,327036,4860

18:20,3847,56079,1405090,861,12885,337899,4708

18:30,3984,57915,1566994,885,13518,351037,4869

18:40,4212,61100,1673182,938,14236,363822,5150

18:50,4242,62184,1762222,934,13902,363782,5176

19:00,3963,57040,1702545,895,13260,373370,4858

19:10,4074,59589,1758829,904,13364,391071,4978

19:20,3894,55737,1748785,911,14209,376397,4805

19:30,3657,52757,1623105,748,11045,325747,4405

19:40,3701,52595,1733610,820,12016,419964,4521

19:50,3832,54538,1904191,817,12716,379241,4649

20:00,3872,55634,1953572,828,12049,417161,4700

20:10,3841,53915,1972165,777,11385,449740,4618

20:20,3632,52168,1773605,738,11114,427286,4370

20:30,3844,54608,1985262,859,15016,550751,4703

20:40,3562,49930,2201016,775,11486,444844,4337

20:50,3304,47250,1905251,710,10421,393179,4014

21:00,3302,46700,2093888,673,10406,445649,3975

21:10,3182,45423,1854440,614,9618,453450,3796

21:20,2934,41722,1849393,531,7954,373352,3465

21:30,2779,39788,1678043,500,7360,337493,3279

21:40,2668,38268,1642665,479,7185,305617,3147

21:50,2375,34050,1561740,419,6027,311997,2794

22:00,2107,29274,1426554,401,6000,222144,2508

22:10,2009,28595,1252935,353,4789,258598,2362

22:20,1940,26312,1236493,294,4220,195533,2234

22:30,1696,24409,1104330,303,4308,205118,1999

22:40,1582,22408,996939,243,3563,140701,1825

22:50,1303,18135,823357,256,3720,189370,1559

23:00,1208,17442,710565,247,3656,178236,1455

23:10,1195,17627,764943,216,3137,129438,1411

23:20,914,13013,585471,147,2143,123405,1061

23:30,790,11345,495364,153,2272,101042,943

23:40,718,10590,439408,125,1888,83235,843

23:50,657,9828,462449,113,1657,70126,770

data1\a4\log2.zip

data1\a4\cdr5,stat.zip

data1\a4\cdr5,stat.xls

For the validation of the output, the total number of calls, PDD time, and call duration of the output file are compared with their counterparts obtained from the input file.

$ head -2 cdr4.csv

28,"2011-02-07 00:20:19","2011-02-07 00:20:23",4,"91.121.99.16",portasip

28,"2011-02-07 00:39:10","2011-02-07 00:39:14",4,"91.121.99.16",portasip

$ cat cdr4.csv | awk -F, '{n++; pdd+=$1; dur+=$4} END{print n,pdd,dur}'

381534 5359144 147981407

$ head -2 cdr5,stat.csv

00:00,615,9221,342709,93,1212,64925,708

00:10,559,8188,335210,75,902,62482,634

$ cat cdr5,stat.csv | awk -F, '{n+=$2+$5; pdd+=$3+$6; dur+=$4+$7; nn+=$8} END{print n,pdd,dur,nn}'

381534 5359144 147981407 381534

$ #The numbers are matching PDD=5359144 sec DUR=147981407 sec

data1\a4\log2.zip

The results are the same, showing that we can trust the output file.

Hourly traffic charts

For each server type, the hourly distribution of the traffic is displayed. For each of the two types of servers, the metric is scaled to align the mean level of the traffic for the given server type to 100%. At the peak time, the hourly intensity of the traffic is above the mean and at the off-peak or nighttime, the traffic drops below the mean level. Irrespectively of the ratio of absolute volumes passing via astrad and portasip servers, in such a self-adjusted metric, both charts (for portasip and astrad) become aligned quite well.

The astrad curve (in green) is more nervous than the portasip curve, as there is less volume, and therefore less stats for astrad. Both curves follow the natural pattern of calls of the clientele.

Note an easily observable discrepancy during the morning period between 9h and 10h. There is less traffic passing via portasip servers during the time in question. This chart proves the conclusions (Conclusions) obtained while analyzing the CDR files of astrad servers uniquely: the astrad servers do not suffer from the problem of 9h to 10h.

data1\a4\cdr5,stat.xls

For the clarity, the collapsed long command line generating the hourly stats for the portasip and astrad servers used in this section (see Generation of 10-min interval stats for the both server types) can be expanded into a more readable layout:

$ cat cdr4.csv | perl -e '

while(<>)

{

if(/^([0-9]+),".* ([0-9]{2}:[0-9]).*",".*",([0-9]+),".*",([a-z]+)$/)

{

($pdd,$conn,$dur,$serv)=($1,$2,$3,$4);

$conn.=0;

$N{$conn}++;

$i="$conn,$serv";

$n{$i}++;

$pdd{$i}+=$pdd;

$dur{$i}+=$dur;

}

for $conn (keys %N)

{

print $conn;

for $serv ("portasip","astrad")

{

$i="$conn,$serv";

printf ",%d,%d,%d",$n{$i},$pdd{$i},$dur{$i}

}

printf ",%d\n",$N{$conn}

}

' | sort > cdr5,stat2.csv; diff cdr5,stat.csv cdr5,stat2.csv

Given that you have the input file in the proper format, it is sufficient to copy-paste this command into a Cygwin window to generate new stats.

Traffic ratio of astrad over portasip

The following chart highlights differently the way the 9h problem affects the astrad and portasip servers. The black horizontal line shows the average ratio of the traffic passing via astrad servers over the traffic passing via portasip servers. In average, the traffic of astrad servers represents only the 23.3% of the overall traffic of portasip servers. The red curve shows the average of the astrad/portasip ratio for a floating interval of 4h10m. We see that around 9h, the ratio is much higher than the global 24h average. That means that astrad servers during this period pass a lot more traffic compared to portasip servers. The real reason is that portasip servers are passing a less traffic during the morning problem. The peak of 9h is better highlighted for an average over a (shorter) floating interval of 50m (see the light yellowish curve).

data1\a4\cdr5,stat.xls

The values of the time (horizontal) axis do not represent the simple middle of the floating interval. The time point is computed as a weighted middle of the interval taking into account to the traffic distribution within the interval. This gives a better accuracy for the (horizontal) location of the curve. Below we show an example of a computation of the weighted average point for the time axis.

[M48]=MOD((SUMPRODUCT(OFFSET(OFFSET($D48,-M$44,0),0,0,2*M$44+1),OFFSET(OFFSET($A48,-M$44,0),0,0,2*M$44+1))+SUMPRODUCT(OFFSET(OFFSET($G48,-M$44,0),0,0,2*M$44+1),OFFSET(OFFSET($A48,-M$44,0),0,0,2*M$44+1)))/SUM(OFFSET(OFFSET($D48,-M$44,0),0,0,2*M$44+1),OFFSET(OFFSET($G48,-M$44,0),0,0,2*M$44+1))+TIME(0,5,0),1)

data1\a4\cdr5,stat.xls

Analysis of CDR files of all astrad servers

All CDR files of all astrad servers are downloaded via the following command:

$ for i in 4 5 6 7 8; do scp root@astrad$i.switzernet.com:/var/log/asterisk/cdr-csv-old/Master.csv-*.gz $i; done

data1\a3\log4.zip

data1\a2\log3.zip

Concurrent calls

The following script shows the creation of a CSV file aiming at the visualization of the number of concurrent calls as a function of the hour of the day. We divide the daily timescale into 120-second intervals and we compute the total number of simultaneous calls passing via all astrad servers registered during each individual interval. For each call, we go through the intervals that are under the footprint of that call, and we increment the time (in seconds) contributed into the individual interval by the call in question. Thus, there are two embedded loops, one for all calls, and the other one for the intervals covered by the call.

$ cat ?/Master.csv-* | cut -d, -f5-6,8 | grep ANSWERED | cut -d, -f1,2 | perl -e '$d=120; while(<>){if(/^".* ([0-9]{2}):([0-9]{2}):([0-9]{2})","([0-9]+)"$/){$stop=7*24*3600+$1*3600+$2*60+$3; $dur=$4;$start=$stop-$dur; for(my $i=int($start/$d)*$d;$i<$stop;$i+=$d){$k=$d; $k-=$start-$i if($start>$i); $k-=$i+$d-$stop if($stop<$i+$d); $load{$i%(3600*24)}+=$k}}} for my $i (keys %load){print "$i,$load{$i}\n"}' | sort -n > out7.csv

$ head out7.csv

0,23889

120,24315

240,23919

360,23300

480,22638

600,22081

720,21988

840,20791

960,20342

1080,20586

$ cat ?/Master.csv-* | head | cut -d, -f2-8

cat: write error: No space left on device

"0041215500329","s","","2011-01-31 18:50:25","0","2011-01-31 18:50:18","NO ANSWER"

"0041215500329","0788822702","","2011-01-31 18:50:25","0","2011-01-31 18:50:17","NO ANSWER"

"41215509849","0215500327","2011-01-31 20:12:10","2011-01-31 21:08:53","3403","2011-01-31 20:12:07","ANSWERED"

"41215509849","s","","2011-02-01 12:01:56","0","2011-02-01 12:01:46","NO ANSWER"

"41215509849","0215500327","","2011-02-01 12:01:56","0","2011-02-01 12:01:45","NO ANSWER"

"41215509849","s","","2011-02-01 12:02:44","0","2011-02-01 12:02:40","NO ANSWER"

"41215509849","0215500329","","2011-02-01 12:02:44","0","2011-02-01 12:02:40","NO ANSWER"

"0041215509849","s","","2011-02-01 12:03:09","0","2011-02-01 12:03:03","NO ANSWER"

"0041215509849","0788822702","","2011-02-01 12:03:09","0","2011-02-01 12:03:02","NO ANSWER"

"0041215509849","s","","2011-02-01 12:05:15","0","2011-02-01 12:05:11","NO ANSWER"

$ cat ?/Master.csv-* | cut -d, -f6 | head | perl -ne 'while(<>){$t+=$1 if(/"(.*)"/)} print $t'

3403

$ cat ?/Master.csv-* | cut -d, -f6 | perl -ne 'while(<>){$t+=$1 if(/"(.*)"/)} print $t'

35023834

$ cat out7.csv | awk -F, '{t+=$2} END{print t}'

35023834

$ #The total seconds are computed correctly (the file out7.csv gives the same total as the concatenation of all CDR files)

data1\a3\log5.zip

data1\a3\out7.zip

The following chart shows the overall number of concurrent calls passing via all astrad servers.

data1\a3\out7.xls

Thanks to the way the computation is implemented, the number of concurrent calls is obtained accurately. We restore the real number of simultaneous calls per interval, and not simply a value that is proportional to the sum of durations of calls started within the interval (which is a simpler technique often used for obtaining a quick idea on the load).

Call setup

We extend the script in order to count also the concurrent SIP channels that are in the call setup phase. Our input is limited by three fields, (1) the stop time, (2) call duration, and (3) the dial- or invite- time. The subroutine of breaking down of a time segment (characterized by its start and stop points on the timescale) into intervals is defined within a procedure “breakdown”, which is used for breaking both the PDD periods and answered call segments.

$ cat ?/Master.csv-* | cut -d, -f5-7 | head

"2011-01-31 18:50:25","0","2011-01-31 18:50:18"

"2011-01-31 18:50:25","0","2011-01-31 18:50:17"

"2011-01-31 21:08:53","3403","2011-01-31 20:12:07"

"2011-02-01 12:01:56","0","2011-02-01 12:01:46"

"2011-02-01 12:01:56","0","2011-02-01 12:01:45"

"2011-02-01 12:02:44","0","2011-02-01 12:02:40"

"2011-02-01 12:03:09","0","2011-02-01 12:03:03"

"2011-02-01 12:03:09","0","2011-02-01 12:03:02"

"2011-02-01 12:05:15","0","2011-02-01 12:05:11"

$ #In the above output, the first field is the stop time, the 2nd field is the duration, and the 3rd field is the invite time

$ cat ?/Master.csv-* | cut -d, -f5-7 | perl -e '$d=120; sub breakdown{my ($A,$B,$slot)=@_; for(my $i=int($A/$d)*$d;$i<$B;$i+=$d){my $k=$d; $k-=$A-$i if($A>$i); $k-=$i+$d-$B if($B<$i+$d); $load{$slot*24*3600+$i%(24*3600)}+=$k}} while(<>){if(/^"([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})","([0-9]+)","([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})"$/){$stop=2*24*3600+$2*3600+$3*60+$4;$dur=$5;$start=$stop-$dur;$setup=($6 lt $1?1:2)*24*3600+$7*3600+$8*60+$9; &breakdown($start,$stop,0); &breakdown($setup,$start,1)}} for my $i (keys %load){if($i<24*3600){$speak{$i}=$load{$i}}else{$dial{$i%(24*3600)}=$load{$i}} $session{$i%(24*3600)}+=$load{$i}} for my $i (keys %session){print "$i,$speak{$i}\n"}' | sort -n > out8.csv

$ diff out7.csv out8.csv

$ cat ?/Master.csv-* | cut -d, -f5-7 | perl -e '$d=480; sub breakdown{my ($A,$B,$slot)=@_; for(my $i=int($A/$d)*$d;$i<$B;$i+=$d){my $k=$d; $k-=$A-$i if($A>$i); $k-=$i+$d-$B if($B<$i+$d); $load{$slot*24*3600+$i%(24*3600)}+=$k}} while(<>){if(/^"([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})","([0-9]+)","([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})"$/){$stop=2*24*3600+$2*3600+$3*60+$4;$dur=$5;$start=$stop-$dur;$setup=($6 lt $1?1:2)*24*3600+$7*3600+$8*60+$9; &breakdown($start,$stop,0); &breakdown($setup,$start,1)}} for my $i (keys %load){if($i<24*3600){$speak{$i}=$load{$i}}else{$dial{$i%(24*3600)}=$load{$i}} $session{$i%(24*3600)}+=$load{$i}} for my $i (keys %session){print "$i,$dial{$i},$speak{$i},$session{$i}\n"}' | sort -n > out10.csv

data1\a3\log5.zip

For the clarity, the last collapsed command line of the above printout is rewritten below into a more readable expanded layout.

$ cat ../../a3/?/Master.csv-* | cut -d, -f5-7 | perl -e '

$d=480;

sub breakdown

{

my ($A,$B,$slot)=@_;

for(my $i=int($A/$d)*$d;$i<$B;$i+=$d)

{

my $k=$d;

$k-=$A-$i if($A>$i);

$k-=$i+$d-$B if($B<$i+$d);

$load{$slot*24*3600+$i%(24*3600)}+=$k

}

while(<>)

{

if(/^"([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})","([0-9]+)","([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})"$/)

{

$stop=2*24*3600+$2*3600+$3*60+$4;

$dur=$5;

$start=$stop-$dur;

$setup=($6 lt $1?1:2)*24*3600+$7*3600+$8*60+$9;

&breakdown($start,$stop,0);

&breakdown($setup,$start,1)

}

for my $i (keys %load)

{

if($i<24*3600)

{

$speak{$i}=$load{$i}

}

else

{

$dial{$i%(24*3600)}=$load{$i}

}

$session{$i%(24*3600)}+=$load{$i}

}

for my $i (keys %session)

{

print "$i,$dial{$i},$speak{$i},$session{$i}\n"

}

' | sort -n > out10a.csv

$ diff out10.csv out10a.csv

$ rm out10a.csv

The following chart, built from the output of the above script shows the number of “speaking” channels in green and the number of “dialing” channels (not yet answered calls) in red. The numbers represent the total over five astrad servers. No anomaly is spotted within the 9h – 10h period in the morning.

data1\a3\out10.xls

data1\a3\out10.doc

data1\a3\out10.htm

Speak/dial time-ratio

No problem is revealed at 9h – 10h also by the chart of the speak/dial ratio. The chart is constructed by showing a floating average over a cyclic tail. The tail, over which the average is computed, has a variable length. The tail length is longer for the hours with weak traffic and is shorter for intensive traffic. The length is chosen to provide a minimal volume of minutes.

data1\a3\out10-var-tail-avg.xls

Ratio of answers over the dial-time

Neither an abnormality is revealed by the ratio of the answered calls (multiplied by ACD) over the dial (call setup) time.

data1\a3\out11.xls

The following printout shows the command line generating the data of the above chart. The printout also validates the data by comparing it with the previous outputs.

$ cat ?/Master.csv-* | cut -d, -f5-7 | perl -e '$d=480; while(<>){if(/^"([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})","([0-9]+)","([0-9-]+) ([0-9]{2}):([0-9]{2}):([0-9]{2})"$/){$stop=2*24*3600+$2*3600+$3*60+$4;$dur=$5;$start=$stop-$dur;$setup=($6 lt $1?1:2)*24*3600+$7*3600+$8*60+$9; my $i=(int($setup/$d)*$d)%(24*3600); $dial{$i}+=$start-$setup; $answ{$i}+=$dur?1:0; $count{$i}++; $dur{$i}+=$dur}} for my $i (keys %count){print "$i,$dial{$i},$answ{$i},$count{$i},$dur{$i}\n"}' | sort -n > out11.csv

$ head out11.csv

162240,14,1,1,16178

163200,10,1,1,10828

163680,18,1,1,10297

164640,15,1,1,18091

165120,26,2,2,30591

165600,13,1,1,7329

166080,34,2,2,19200

166560,16,1,1,8878

167040,19,2,2,16705

167520,44,4,4,26707

$ cat out11.csv | awk -F, '{t+=$5} END{print t}'

35023834

$ head out10.csv

0,4016,95423,99439

480,3861,87498,91359

960,3779,83432,87211

1440,3772,81699,85471

1920,3392,70392,73784

2400,3053,66528,69581

2880,3314,62840,66154

3360,2636,59263,61899

3840,1949,56537,58486

4320,2136,55499,57635

$ cat out10.csv | awk -F, '{t+=$3} END{print t}'

35023834

$ #The seconds are the same in both files

data1\a3\log6.zip

Disconnection causes

Though the disconnection cause “8” appears only during the morning hours of our interest, its quantity is so weak that no serious problems must be expected in relation to this code.

$ cat ?/Master.csv-* | awk -F, '{print $9}' | sort | uniq -c

55597 ""

69638 "0"

349 "12"

58972 "13"

17 "2"

549 "3"

8 "5"

25 "7"

21 "8"

178 "9"

$ cat ?/Master.csv-* | awk -F, '{print $10}' | sort | uniq -c

53766 ""

26831 "PeerAuth"

104757 "SipAuth"

$ cat ?/Master.csv-* | cut -d, -f6-9 | head

"0","2011-01-31 18:50:18","NO ANSWER",""

"0","2011-01-31 18:50:17","NO ANSWER","0"

"3403","2011-01-31 20:12:07","ANSWERED","13"

"0","2011-02-01 12:01:46","NO ANSWER",""

"0","2011-02-01 12:01:45","NO ANSWER","13"

"0","2011-02-01 12:02:40","NO ANSWER",""

"0","2011-02-01 12:02:40","NO ANSWER","13"

"0","2011-02-01 12:03:03","NO ANSWER",""

"0","2011-02-01 12:03:02","NO ANSWER","0"

"0","2011-02-01 12:05:11","NO ANSWER",""

$ cat ?/Master.csv-* | head | cut -d, -f6,7,8,9 | perl -e 'while(<>){if(/^".*",".* ([0-9]{2}):.*",".*","(.*)"$/){$code=$2; $hh=$1; $codes{$code}++; $hh{$hh}++; $hourly{"$hh,$code"}++}} for $c (sort keys %codes){print ",$c"} print "\n"; for $h (keys %hh){print $h; for $c (sort keys %codes){print ",".$hourly{"$h,$c"}} print "\n"}'

cat: write error: No space left on device

,,0,13

18,1,1,

12,4,1,2

20,,,1

$ cat ?/Master.csv-* | cut -d, -f6,7,8,9 | perl -e 'while(<>){if(/^".*",".* ([0-9]{2}):.*",".*","(.*)"$/){$code=$2; $hh=$1; $codes{$code}++; $hh{$hh}++; $hourly{"$hh,$code"}++}} for $c (sort keys %codes){print ",$c"} print "\n"; for $h (keys %hh){print $h; for $c (sort keys %codes){print ",".$hourly{"$h,$c"}} print "\n"}' > out12.csv

data1\a3\log6.zip

data1\a3\out12.xls

Conclusions

The astrad servers are not affected in any serious way by the morning problem. However, the astrad project aiming at the capability to bypass the radius irresponsiveness remains fully valid. We expect that the bizarre (but not critical) disconnection cause (see Disconnection causes) may disappear after such an upgrade.