AST_VDADstats.php long execution time / Database lockup
Posted: Fri Feb 14, 2014 2:59 am
After a svn upgrade of our system strange things stared to happen.
A small hiccup when the system didn't respond and agents where complaining, the asterisk log showed this:
[Feb 13 11:09:17] WARNING[3332] chan_sip.c: Autodestruct on dialog '7ea53ead72a71b883ca7675c45100b09@<<Server IP>>:5060' with owner SIP/carrier_1-0000092f in place (Method: BYE). Rescheduling destruction for 10000 ms
aha, I've seen that before I though http://www.vicidial.org/VICIDIALforum/v ... =4&t=30297 but it was not exactly the same:
WARNING[2626]: chan_sip.c:4214 __sip_autodestruct: Autodestruct on dialog '0d42b9247c928cc90702775372e13c01@<<Server IP>>:5060' with owner SIP/ in place (Method: BYE). Rescheduling destruction for 10000 ms
the second time it happen it was a longer delay so I started investigate it more and found this in my /var/run/mysql/mysqld-slow.log (slow query logging):
(second time the problem occur the query took 231 seconds!!)
I knew I had run some report when it happen and the logs confirmed it:
123.123.123.2 - 6666 [13/Feb/2014:11:08:54 +0100] "GET /vicidial/AST_VDADstats.php HTTP/1.1" 200 24379 "http://123.123.123.123/vicidial/admin.php?ADD=999999" "Mozilla/5.0"
I tried that slow query and just removed ,vicidial_list
and voila:
1012 times faster
and apparently this is how the query looked like before the change 2013-02-08 (140208-2033 - Added List select option)
now I noticed this text in the report page: "Lists: (optional, possibly slow)" no shit
if you look at the result from the query its very far off too!
So I did some tests:
build 140208-2033
list selection: --ALL--
list selection: 997, 998
no selected list selection
build 140108-0730
no list selection because this was before that option
as you can see that the list selection queries is all wrong (look at the Productivity Rating value),
it will join with vicidial_list so only the number of leads will show and thus the productivity rating will be skyrocketing or the opposite when lists: --ALL-- is selected.
the query should left join instead to be able to grab all the data from vicidial_agent_log:
I made a patch that changes the queries to left join and I posted it to the issue tracker: http://www.vicidial.org/VICIDIALmantis/view.php?id=741
With the patch the numbers are correct and the queries is fast, win win!
A small hiccup when the system didn't respond and agents where complaining, the asterisk log showed this:
[Feb 13 11:09:17] WARNING[3332] chan_sip.c: Autodestruct on dialog '7ea53ead72a71b883ca7675c45100b09@<<Server IP>>:5060' with owner SIP/carrier_1-0000092f in place (Method: BYE). Rescheduling destruction for 10000 ms
aha, I've seen that before I though http://www.vicidial.org/VICIDIALforum/v ... =4&t=30297 but it was not exactly the same:
WARNING[2626]: chan_sip.c:4214 __sip_autodestruct: Autodestruct on dialog '0d42b9247c928cc90702775372e13c01@<<Server IP>>:5060' with owner SIP/ in place (Method: BYE). Rescheduling destruction for 10000 ms
the second time it happen it was a longer delay so I started investigate it more and found this in my /var/run/mysql/mysqld-slow.log (slow query logging):
- Code: Select all
# Time: 140213 11:09:17
# User@Host: cron[cron] @ [123.123.123.123]
# Query_time: 11.792559 Lock_time: 0.000187 Rows_sent: 1 Rows_examined: 431
use asterisk;
SET timestamp=1392286157;
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
# Time: 140213 11:09:31
# User@Host: cron[cron] @ [123.123.123.123]
# Query_time: 13.376370 Lock_time: 0.628954 Rows_sent: 1 Rows_examined: 433
SET timestamp=1392286171;
SELECT sum(pause_sec + wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and campaign_id IN('98') and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000;
# Time: 140213 11:09:41
# User@Host: cron[cron] @ [123.123.123.123]
# Query_time: 10.593508 Lock_time: 0.142008 Rows_sent: 1 Rows_examined: 435
SET timestamp=1392286181;
select avg(wait_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
(second time the problem occur the query took 231 seconds!!)
I knew I had run some report when it happen and the logs confirmed it:
123.123.123.2 - 6666 [13/Feb/2014:11:08:54 +0100] "GET /vicidial/AST_VDADstats.php HTTP/1.1" 200 24379 "http://123.123.123.123/vicidial/admin.php?ADD=999999" "Mozilla/5.0"
I tried that slow query and just removed ,vicidial_list
and voila:
- Code: Select all
mysql> SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
+--------------------------------------+
| sum(wait_sec + talk_sec + dispo_sec) |
+--------------------------------------+
| 1084 |
+--------------------------------------+
1 row in set (0.02 sec)
mysql> SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
+--------------------------------------+
| sum(wait_sec + talk_sec + dispo_sec) |
+--------------------------------------+
| 799945388 |
+--------------------------------------+
1 row in set (20.24 sec)
1012 times faster
and apparently this is how the query looked like before the change 2013-02-08 (140208-2033 - Added List select option)
now I noticed this text in the report page: "Lists: (optional, possibly slow)" no shit
if you look at the result from the query its very far off too!
So I did some tests:
build 140208-2033
list selection: --ALL--
- Code: Select all
/vicidial/AST_VDADstats.php.orig1?agent_hours=&DB=1&outbound_rate=&costformat=&print_calls=&query_date=2014-02-13&end_date=2014-02-14&group%5B%5D=98&list_ids%5B%5D=--ALL--&include_rollover=NO&bottom_graph=NO&carrier_stats=NO&report_display_type=TEXT&shift=ALL&SUBMIT=SUBMIT
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-14 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98') ;
Productivity Rating: 0
list selection: 997, 998
- Code: Select all
/vicidial/AST_VDADstats.php.orig1?agent_hours=&DB=1&outbound_rate=&costformat=&print_calls=&query_date=2014-02-13&end_date=2014-02-14&group%5B%5D=98&list_ids%5B%5D=997&list_ids%5B%5D=998&include_rollover=NO&bottom_graph=NO&carrier_stats=NO&report_display_type=TEXT&shift=ALL&SUBMIT=SUBMIT
select count(*) from vicidial_closer_log where call_date >= '2014-02-13 00:00:00' and call_date <= '2014-02-14 23:59:59' and campaign_id IN('') and list_id IN('997','998') and status NOT IN('DROP','XDROP','HXFER','QVMAIL','HOLDTO','LIVE','QUEUE');
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-14 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98') and vicidial_agent_log.lead_id=vicidial_list.lead_id and vicidial_list.list_id IN('997','998');
Productivity Rating: 1.9
no selected list selection
- Code: Select all
/vicidial/AST_VDADstats.php.orig1?agent_hours=&DB=1&outbound_rate=&costformat=&print_calls=&query_date=2014-02-13&end_date=2014-02-14&group%5B%5D=98&include_rollover=NO&bottom_graph=NO&carrier_stats=NO&report_display_type=TEXT&shift=ALL&SUBMIT=SUBMIT
select count(*) from vicidial_closer_log where call_date >= '2014-02-13 00:00:00' and call_date <= '2014-02-14 23:59:59' and campaign_id IN('') and status NOT IN('DROP','XDROP','HXFER','QVMAIL','HOLDTO','LIVE','QUEUE');
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-14 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98') ;
Productivity Rating: 0.11
build 140108-0730
no list selection because this was before that option
- Code: Select all
/vicidial/AST_VDADstats_r2067.php?agent_hours=&DB=1&outbound_rate=&costformat=&print_calls=&query_date=2014-02-13&end_date=2014-02-14&group%5B%5D=98&include_rollover=NO&bottom_graph=NO&carrier_stats=NO&report_display_type=TEXT&shift=ALL&SUBMIT=SUBMIT
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-14 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
Productivity Rating: 0.11
as you can see that the list selection queries is all wrong (look at the Productivity Rating value),
it will join with vicidial_list so only the number of leads will show and thus the productivity rating will be skyrocketing or the opposite when lists: --ALL-- is selected.
the query should left join instead to be able to grab all the data from vicidial_agent_log:
query without list selection:
SELECT * from vicidial_agent_log where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
-- 1084
bad query with list selection --ALL--
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
-- 799945388
bad query with list selection 997, 998:
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log,vicidial_list where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98') and vicidial_agent_log.lead_id=vicidial_list.lead_id and vicidial_list.list_id IN('997','998');
-- 63
good query with list selection:
SELECT sum(wait_sec + talk_sec + dispo_sec) from vicidial_agent_log
left join vicidial_list on vicidial_list.lead_id=vicidial_agent_log.lead_id
and list_id IN('997','998')
where event_time >= '2014-02-13 00:00:00' and event_time <= '2014-02-13 23:59:59' and pause_sec<65000 and wait_sec<65000 and talk_sec<65000 and dispo_sec<65000 and campaign_id IN('98');
-- 1084
I made a patch that changes the queries to left join and I posted it to the issue tracker: http://www.vicidial.org/VICIDIALmantis/view.php?id=741
With the patch the numbers are correct and the queries is fast, win win!