[OpenSIPS-Devel] potential timer shifting

[Vlad Paiu]

Hi Edwin,

So it seems that even though a single query doesn't take very long, 
there are many queries ran one after another, and their sum equals to 
14+ seconds, so the timer warning is correct.

For a prepared statement, there are two steps. First preparing the 
statement, which is done only once, and then executing the actual 
prepared statement, which is done every time you run the query. It's 
this second step ( that's executed everytime ) that the OpenSIPS mysql 
threshold is complaining about.

For the next 1.10 release, we are planning some improvements to the 
usrloc module, for optimising the DB access, in the sense of combining 
multiple insert & delete queries.

Still, how big is your current location table ? Is it MyISAM or InnoDB ? 
First thing I'd try is to optimise your DB engine.

Regards,

Vlad Paiu
OpenSIPS Developer
http://www.opensips-solutions.com


On 03/29/2013 12:23 PM, Edwin wrote:
> Bogdan
>
> I moved usrloc.so aside and used the patched usrloc.so. With sipsak i pushed
> 438 Registrations (120sec).
>
> This is part of the output from my logfiles (beginning and end, i skipped +-
> 400 lines):
>
>
> Mar 29 10:27:13 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 76208 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> Mar 29 10:27:13 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 25010 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> Mar 29 10:27:13 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 50051 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> ... 400 more rules ...
> Mar 29 10:27:27 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 25424 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> Mar 29 10:27:27 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 24749 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> Mar 29 10:27:27 opensips /usr/sbin/opensips[6180]:
> WARNING:db_mysql:log_expiry: threshold exceeded : mysql prep stmt took too
> long - 25061 us.Source : delete from location where username=? AND contact=?
> AND callid=?
> Mar 29 10:27:27 opensips /usr/sbin/opensips[6180]: CRITICAL:usrloc:timer:
> ul_timer from 1364549233 to 1364549247 (in sec)
> Mar 29 10:27:27 opensips /usr/sbin/opensips[6180]:
> CRITICAL:core:timer_ticker: timer handler<ul-timer>  lasted (13380000 us)
> for more than timer tick (1000000 us) ->  potential timer shifting
>
> Here we can see the action took +-14 seconds. Strange thing is I see the
> 'mysql prep stmt' 400 + times repeated. This is strange for a mysql prepared
> statement or not? I would expect this rule once...
>
> Gr.
>
> Edwin
>
>
>
> --
> View this message in context: http://opensips-open-sip-server.1449251.n2.nabble.com/potential-timer-shifting-tp7585511p7585549.html
> Sent from the OpenSIPS - Devel mailing list archive at Nabble.com.
>
> _______________________________________________
> Devel mailing list
> Devel at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/devel