Long wait time - AST_VDauto_dial 'stuck'

[rajeevpn]

Agents experience a long wait time between calls intermittently. Happens twice or three times in a day but the wait time is sometimes as high as 5 minutes in those instances - it's usually around 30 sec. with the kind of pacing and setup that we have. Interestingly, we have noticed this only the last few weeks - been running perfectly fine for over 6 months!

Our specs:

3 servers - 2 running asterisk and 1 with MySQL and Web
E1 PRI lines (2 PRIs in one and 1 in the other)
Load average < 2
No recording
Astguiclient Version 2.0.3
Asterisk 1.2.17

We've tried a whole bunch of things and here's the dump:

there seems to be enough space in the hard disk
ntpdate runs fine - it's in the cron
PRI lines are ok - no red alarms
load average normal <2
Happened even if there are no agents - when we do auto message playing
Connectivity between servers seem fine - no error messages in the root mailbox

The following log is the only clue that we seem to have:

This is a dump of vdautodial.2008-01-02

Code: Select all

2008-01-02 15:41:57||     logindate UPDATED 2|'RELAV','SPL'||
2008-01-02 15:46:44|LIVE AGENTS LOGGED IN: 27   ACTIVE CALLS: 4|
2008-01-02 15:46:44|OLD TRUNK SHORTS CLEARED: 1 |'','RELAV','SPL'||
2008-01-02 15:46:44|RELAV 192.168.1.10: agents: 14     dial_level: 1.7|


Notice a 5 minute gap in the VDauto_dial.pl log between 15:41 and 15:46.

We noticed that if we manually kill the autodial process if we see it not doing anything (when we use screen), it resumes at the time of the keepalive execution at the next minute and things seem fine

So am guessing, there's something fishy that's making this script 'hang'!

Any help appreciated and have a great year ahead!
thanks
rajeev

[mflorell]

Asterisk CLI output?

have you attached to the ASTVDauto screen to see what is going on with it?

[rajeevpn]

Well: the last two times it happened:

* asterisk CLI (using screen) - no activity - just status on current calls

* If I attach to ASTVDauto screen, nothing seems to be happening. That's when if we kill the process, it seems to resume and all is well. Many times, even without the kill, it seems to resume activity after a certain amount of time (random at each occurrence but some where between 4 and 5 minutes)

[rajeevpn]

Sorry to bother y'all but any clues?

[mflorell]

output of "mysqladmin processlist"?

[rajeevpn]

Ah - there's a whole bunch of entries - a few of them over 100 seconds long. But we notice similar number of entries even when there are no issues with the dialing.

Quick qn: I noticed the query looks for '2008-01-02 24:15:00' - will mysql complain if we use hour >23?

We do have over a million records in the DB - do you think that could be the issue?

Loadavg on the server looks ok though - around 3. This is a dual core with hyperthreading with 4 GB RAM so am thinking a loadavg of up to 4 is ok

Code: Select all

Enter password:
+--------+------+--------------------+----------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+
| Id     | User | Host               | db       | Command | Time | State                | Info                                                                                                 |
+--------+------+--------------------+----------+---------+------+----------------------+------------------------------------------------------------------------------------------------------+
| 69     | cron | 192.168.1.12:40186 | asterisk | Sleep   | 0    |                      |                                                                                                      |
| 70     | cron | 192.168.1.12:40187 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 71     | cron | 192.168.1.10:45111 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 72     | cron | 192.168.1.12:40189 | asterisk | Sleep   | 36   |                      |                                                                                                      |
| 73     | cron | 192.168.1.10:45112 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 74     | cron | 192.168.1.12:40190 | asterisk | Query   | 136  | Locked               | UPDATE vicidial_list set status='NA' where lead_id='2483668'                                         |
| 75     | cron | 192.168.1.12:40192 | asterisk | Sleep   | 2    |                      |                                                                                                      |
| 76     | cron | 192.168.1.10:45114 | asterisk | Sleep   | 16   |                      |                                                                                                      |
| 77     | cron | 192.168.1.10:45115 | asterisk | Query   | 151  | Updating             | UPDATE vicidial_list set status='NA' where lead_id=''                                                |
| 78     | cron | 192.168.1.10:45117 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 79     | cron | 192.168.1.10:45118 | asterisk | Sleep   | 2    |                      |                                                                                                      |
| 80     | cron | 192.168.1.10:45119 | asterisk | Sleep   | 2    |                      |                                                                                                      |
| 230893 | cron | localhost          | asterisk | Query   | 25   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:45:00' and call_date <= '2008-01 |
| 231373 | cron | localhost          | asterisk | Query   | 13   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231390 | cron | localhost          | asterisk | Query   | 10   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231404 | cron | localhost          | asterisk | Query   | 33   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231418 | cron | localhost          | asterisk | Query   | 13   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231433 | cron | localhost          | asterisk | Query   | 12   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231442 | cron | localhost          | asterisk | Query   | 13   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231452 | cron | localhost          | asterisk | Query   | 26   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231468 | cron | localhost          | asterisk | Query   | 3    | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:30:00' and call_date <= '2008-01 |
| 231484 | cron | localhost          | asterisk | Query   | 1    | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231501 | cron | localhost          | asterisk | Query   | 13   | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 231516 | cron | localhost          | asterisk | Query   | 3    | Sending data         | select count(*) from vicidial_log where call_date >= '2008-01-12 24:15:00' and call_date <= '2008-01 |
| 237033 | cron | 192.168.1.10:45261 | asterisk | Query   | 140  | Locked               | UPDATE vicidial_list set vendor_lead_code='', title='', first_name='DINESHKUMARDUBEY', middle_initia |
| 237104 | cron | localhost          | asterisk | Query   | 139  | Locked               | UPDATE vicidial_list set vendor_lead_code='', title='', first_name='SAYATHSALEEM', middle_initial='' |
| 237298 | cron | localhost          | asterisk | Query   | 136  | Locked               | select vicidial_list.security_phrase, vicidial_list.first_name, vicidial_list.last_name, vicidial_li |
| 237375 | cron | 192.168.1.10:45281 | asterisk | Query   | 135  | Locked               | SELECT count(*) FROM vicidial_list where called_since_last_reset='N' and status IN('HU','N','CPNA',' |
| 238047 | cron | localhost          | asterisk | Query   | 124  | Locked               | UPDATE vicidial_list set status='SA', user='vasugi' where lead_id='2459614'                          |
| 238049 | cron | 192.168.1.10:45311 | asterisk | Query   | 124  | Locked               | UPDATE vicidial_list set status='SA', user='johnsi' where lead_id='2459598'                          |
| 238269 | cron | localhost          | asterisk | Query   | 118  | Locked               | select vicidial_list.security_phrase, vicidial_list.first_name, vicidial_list.last_name, vicidial_li |
| 240645 | cron | localhost          | asterisk | Query   | 82   | Locked               | UPDATE vicidial_list set status='N', user='' where status IN('QUEUE','INCALL') and user ='shah'      |
| 241063 | cron | 192.168.1.10:45418 | asterisk | Query   | 75   | Locked               | SELECT count(*) FROM vicidial_list where called_since_last_reset='N' and status IN('HU','N','CPNA',' |
| 241488 | cron | localhost          | asterisk | Query   | 5    | Copying to tmp table | select count(*),status from vicidial_agent_log where event_time <= '2008-01-12 23:59:59' and event_t |
| 244753 | cron | 192.168.1.10:45563 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 244764 | cron | 192.168.1.10:45566 | asterisk | Query   | 15   | Locked               | SELECT count(*) FROM vicidial_list where called_since_last_reset='N' and status IN('HU','N','CPNA',' |
| 244785 | cron | 192.168.1.12:38001 | asterisk | Sleep   | 1    |                      |                                                                                                      |
| 245441 | cron | localhost          | asterisk | Query   | 4    | Locked               | UPDATE vicidial_agent_log set pause_sec='250',pause_epoch='1200129312' where agent_log_id='1025425'  |
| 245491 | cron | localhost          | asterisk | Query   | 3    | Locked               | select pause_epoch,pause_sec from vicidial_agent_log where agent_log_id='1025425'                    |
| 245681 | cron | localhost          |          | Query   | 0    |                      | show processlist                                                                                     |


[mflorell]

Any idea what wcript is sending those queries with hour > 23?

The DB activity is probably causing your problems.

On a dedicated DB server, 1,000,000 records in vicidial_log is no problem

[enjay]

not by chance getting your vicidial_auto_calls table filled up with stale leads? as a result making your dialer, dial slow?

[rajeevpn]

Don't see any stale leads.

Looks like a DB related issue - the agents are now complaining that the WEBFORM takes longer than usual to download.
The script that has query where it looks for dates like '2007-01-14 24:00:00' seem to be the following:

Code: Select all

rajeevpn@kaivalya:~/Software/asterisk/vici/v204$ grep "<= 96" */*/*

www/vicidial/AST_CLOSERstats.php:while ($i <= 96)
www/vicidial/AST_inboundEXTstats.php:   while ($i <= 96)
www/vicidial/AST_parkstats.php:while ($i <= 96)
www/vicidial/AST_VDADstats.php:while ($i <= 96)


So the value of i and h start at zero and increment 4 times and once respectively each time the loop is traversed. The first time the loop is done the value of i will be 4 and h will be 1, the second time, i=8 and h=2 and so on until i=96 and h=24. Since the loop check for i<=96 and not i<96, it executes for this value of i when the query will look for hour = 24.

I noticed that the vicidial_log has 5 million + records and not 1 million as I had originally posted! Doing an archive to see if that will help.

Another query optimization suggestion: Do you think modifying queries where we do a count to do a count(indexed_column) rather than count(*)?

thanks
rajeev

[mflorell]

I am sure there are a lot of database optimizations that could be done to improve performance, I just haven't had any time to focus on that. I would suggest trying it and getting back to us.