asterisk users - Dec 2009 - Realtime mysql extensions mutiple queries for each priority?

Hi All,

I'm testing some realtime extension apps with Asterisk 1.4.28 and
addons 1.4.10 using res_mysql.  Localhost database is 5.0.32 with
Debian Etch.  The apps are working fine all syntax is proper, using
Set with (REALTIME) function, Set with (CUT) function, calling a Macro
with s extensions, and using a few pattern matching extensions as
well.  I can certainly detail all database rows if needed, but it is
all pretty standard dialplan stuff, nothing too fancy.  I built apps
in extensions.conf first to ensure they all work, then migrated them
to the database, they work there as well.

I turned on console debug to see the actual mysql queries and to my
surprise and concern, I see every query for an extension priority
repeated 3 or more times prior to dialplan execution.  For instance my
first dialplan activity is all extracted from the database:

context		exten	pri	app	appdata
dpdefault14	_991X	1	NoOp	INBOUND CALL FROM SIPP
dpdefault14	_991X	2	NoOp	TRUNK-${EXTEN:0:2} DID-${EXTEN:2}
dpdefault14	_991X	3	Set	CALLERID(number)=600
dpdefault14	_991X	4	Answer	
dpdefault14	_991X	5	Goto	${EXTEN:2}|1

Each priority is queried several times before executing.  Here is a
sample of the first 2 priorities on a pastebin:

http://pastebin.com/m54c9c41e

I would not think this is normal activity as I can query the database
directly once and get a valid response.  I don't have any realtime
mysql connections issues that I can see, no errors in the logs and
console status is:

test1-6*CLI> realtime mysql status
Connected to astclust at 127.0.0.1, port 3306 with username root for 1
hours, 7 minutes, 28 seconds.
[Dec 28 18:06:50] DEBUG[8664]: res_config_mysql.c:657 mysql_reconnect:
MySQL RealTime: Everything is fine.
test1-6*CLI>

Any guidance on trouble shooting this will be appreciated.

Thanks.

JR
-- 
JR Richardson
Engineering for the Masses

On Monday 28 December 2009 18:09:15 JR Richardson wrote:
> I turned on console debug to see the actual mysql queries and to my
> surprise and concern, I see every query for an extension priority
> repeated 3 or more times prior to dialplan execution.  For instance my
> first dialplan activity is all extracted from the database:
>
> context		exten	pri	app	appdata
> dpdefault14	_991X	1	NoOp	INBOUND CALL FROM SIPP
> dpdefault14	_991X	2	NoOp	TRUNK-${EXTEN:0:2} DID-${EXTEN:2}
> dpdefault14	_991X	3	Set	CALLERID(number)=600
> dpdefault14	_991X	4	Answer
> dpdefault14	_991X	5	Goto	${EXTEN:2}|1
>
> Each priority is queried several times before executing.  Here is a
> sample of the first 2 priorities on a pastebin:
>
> http://pastebin.com/m54c9c41e
>
> I would not think this is normal activity as I can query the database
> directly once and get a valid response.  I don't have any realtime
> mysql connections issues that I can see, no errors in the logs and
> console status is:
No, that's normal.  The order of queries done is 1) check if the extension
exists, 2) on spawn, retrieve the extension to populate information about
the application into the channel structure, and 3) actually execute the
application.  There are 3 queries done for each extension actually executed
in order of priorities and a few more when the extension changes (or
originates).  It's not optimal, but it's the way that it works.

At some point, a slight optimization could certainly be done to narrow this
down to a single query from the database, followed by a fairly short caching
period (1 second would be plenty), but that optimization has never been
done.

-- 
Tilghman Lesher
Digium, Inc. | Senior Software Developer
twitter: Corydon76 | IRC: Corydon76-dig (Freenode)
Check us out at: www.digium.com & www.asterisk.org

> On Monday 28 December 2009 23:49:13 Tilghman Lesher wrote:
>> On Monday 28 December 2009 18:09:15 JR Richardson wrote:
>> > I turned on console debug to see the actual mysql queries and to
my
>> > surprise and concern, I see every query for an extension priority
>> > repeated 3 or more times prior to dialplan execution. ?For
instance my
>> > first dialplan activity is all extracted from the database:
>> >
>> > context ? ? ? ? ? ? exten ? pri ? ? app ? ? appdata
>> > dpdefault14 _991X ? 1 ? ? ? NoOp ? ?INBOUND CALL FROM SIPP
>> > dpdefault14 _991X ? 2 ? ? ? NoOp ? ?TRUNK-${EXTEN:0:2}
DID-${EXTEN:2}
>> > dpdefault14 _991X ? 3 ? ? ? Set ? ? CALLERID(number)=600
>> > dpdefault14 _991X ? 4 ? ? ? Answer
>> > dpdefault14 _991X ? 5 ? ? ? Goto ? ?${EXTEN:2}|1
>> >
>> > Each priority is queried several times before executing. ?Here is
a
>> > sample of the first 2 priorities on a pastebin:
>> >
>> > http://pastebin.com/m54c9c41e
>> >
>> > I would not think this is normal activity as I can query the
database
>> > directly once and get a valid response. ?I don't have any
realtime
>> > mysql connections issues that I can see, no errors in the logs and
>> > console status is:
>>
>> No, that's normal. ?The order of queries done is 1) check if the
extension
>> exists, 2) on spawn, retrieve the extension to populate information
about
>> the application into the channel structure, and 3) actually execute the
>> application. ?There are 3 queries done for each extension actually
executed
>> in order of priorities and a few more when the extension changes (or
>> originates). ?It's not optimal, but it's the way that it works.
>>
>> At some point, a slight optimization could certainly be done to narrow
this
>> down to a single query from the database, followed by a fairly short
>> caching period (1 second would be plenty), but that optimization has
never
>> been done.
>
> https://issues.asterisk.org/view.php?id=16521
>
> Needs testing.
>
> --
> Tilghman Lesher
Tilghman,

Saying I?m a bit excited right now is an understatement. First of all,
the patch seems to work fine applied to 1.4.28 stable release. The
performance of this patch is extraordinary. Before migrating my static
dialplan to the database I could push 380 calls at 15 to 20 CPS. After
migrating to the database, I could only push a little more than 100
calls and no more than 6 to 9 CPS. With this patch applied, I am
pushing reliably 300 calls at 15 CPS. 7500+ calls without a hiccup.
Not quite as good as a static dialplan, but that is expected. MySQLd
has also decreased utilization, as expected, from 6 to 12, now 1 to 6.
This has got to be an overall performance increase by 50% or more.

I will be patching on my new 1.4 systems going forward. The sooner
this patch gets applied to Asterisk, the better.

Thanks.

JR
-- 
JR Richardson
Engineering for the Masses