[Kamailio-Devel] [ openser-Bugs-2094925 ] benchmark timer wraps and get negative

[SourceForge.net]

Bugs item #2094925, was opened at 2008-09-05 14:42
Message generated for change (Comment added) made by tramjoe
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=2094925&group_id=139143

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: ver 1.3.x
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Henning Westerholt (henningw)
Assigned to: Nobody/Anonymous (nobody)
Summary: benchmark timer wraps and get negative

Initial Comment:
During some tests i noticed that the variables used from the benchmark module could wrap and get negative.

Sep  5 14:24:58 voiptest0 openser[23209]: benchmark (timer test [0]): 168 [ msgs/total/min/max/avg - LR: 100/-958731/140/-975189/-9587.310000 | GB: 3000/-270929/135/-975189/-90.309667]
Sep  5 14:25:03 voiptest0 openser[23213]: benchmark (timer test [0]): 169 [ msgs/total/min/max/avg - LR: 100/28287/139/10253/282.870000 | GB: 3100/-242642/135/-975189/-78.271613]

Having a negative average value makes not that much sense in my opinion. I observed this in 1.3.X, but i think the problems is also present in the trunk.

Perhaps the internal variables should be changed to unsigned long long, and the logging to %llu?

Henning

----------------------------------------------------------------------

Comment By: Jerome Martin (tramjoe)
Date: 2008-10-14 16:21

Message:
I was about to report this for 1.4.1+ but noticed it is a long lasting
issue.
Typical example in 1.4 looks like this :

[Oct 14 16:14:53][27165] [2-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 290432 microseconds to execute 
[Oct 14 16:14:53][27118] [5-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 396020 microseconds to execute 
[Oct 14 16:14:54][27168] [25--360][INVITE/1] aaroute: BENCHMARK: DB call
db_aaroute took 18446744073709246500 microseconds to execute 
[Oct 14 16:14:54][27142] [6-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 18446744073708815827 microseconds to execute 
[Oct 14 16:14:55][27149] [9-1-360][200->INVITE/1] reply: BENCHMARK: DB
call db_stoproute took 18446744073709208713 microseconds to execute 
[Oct 14 16:14:55][27163] [6-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 127169 microseconds to execute 
[Oct 14 16:14:55][27122] [5-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 449968 microseconds to execute 
[Oct 14 16:14:56][27146] [3-1-360][BYE/2] request: BENCHMARK: DB call
db_stopcall took 18446744073709167471 microseconds to execute 
[Oct 14 16:14:56][27136] [18--360][200->INVITE/1] reply: BENCHMARK: DB
call db_stoproute took 326607 microseconds to execute

I think you'll notice the wrapped counters easily here :-)
But I do not understand how/why this happens. Maybe a way to reset the
benchmark timers would ease this ?

Jerome - tramjoe.merin at gmail dot com


----------------------------------------------------------------------

Comment By: Henning Westerholt (henningw)
Date: 2008-09-12 11:23

Message:
Well, if the variable goes negative one could at least easily spot that it
not valid anymore. It seems that there is also an issue with concurent
access to this variables (which are in shared memory), this needs further
investigation.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=743020&aid=2094925&group_id=139143