[OpenSIPS-Users] WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed
Aqs Younas
aqsyounas at gmail.com
Fri Jan 22 18:37:59 CET 2016
On the start of test. Using top
13265 root 20 0 136m 11m 10m R 57 0.0 0:02.12 opensips
13258 root 20 0 136m 11m 10m S 53 0.0 0:02.03 opensips
13262 root 20 0 136m 11m 10m R 6 0.0 0:00.74 opensips
13254 root 20 0 136m 1604 184 S 0 0.0 0:00.43 opensips
13256 root 20 0 136m 11m 9.9m S 0 0.0 0:00.28 opensips
13259 root 20 0 136m 11m 10m S 0 0.0 0:00.75 opensips
13260 root 20 0 136m 11m 10m S 0 0.0 0:00.47 opensips
13264 root 20 0 136m 11m 10m S 0 0.0 0:00.75 opensips
13267 root 20 0 136m 8300 6840 S 0 0.0 0:00.13 opensips
13271 root 20 0 136m 6732 5272 S 0 0.0 0:00.15 opensips
13274 root 20 0 136m 6136 4676 S 0 0.0 0:00.16 opensips
13262 root 20 0 136m 11m 10m R 97 0.0 0:00.92 opensips
13265 root 20 0 136m 11m 10m R 97 0.0 0:02.30 opensips
13259 root 20 0 136m 11m 10m R 70 0.0 0:00.88 opensips
13259 root 20 0 136m 11m 10m R 106 0.0 0:01.05 opensips
13262 root 20 0 136m 11m 10m R 100 0.0 0:01.08 opensips
13265 root 20 0 136m 11m 10m S 69 0.0 0:02.41 opensips
13257 root 20 0 136m 11m 10m R 38 0.0 0:00.44 opensips
13261 root 20 0 136m 11m 10m R 38 0.0 0:00.66 opensips
13257 root 20 0 136m 11m 10m R 101 0.0 0:00.61 opensips
13259 root 20 0 136m 11m 10m R 101 0.0 0:01.22 opensips
13261 root 20 0 136m 11m 10m R 101 0.0 0:00.83 opensips
13262 root 20 0 136m 11m 10m R 101 0.0 0:01.25 opensips
After sometime.
13262 root 20 0 136m 13m 12m S 7 0.0 0:02.46 opensips
13256 root 20 0 136m 13m 12m S 5 0.0 0:00.97 opensips
13258 root 20 0 136m 13m 11m S 5 0.0 0:02.20 opensips
13263 root 20 0 136m 13m 11m S 3 0.0 0:00.91 opensips
13257 root 20 0 136m 13m 12m S 1 0.0 0:02.68 opensips
13255 root 20 0 136m 1604 184 S 0 0.0 0:00.20 opensips
13265 root 20 0 136m 13m 12m R 29 0.0 0:04.50 opensips
13258 root 20 0 136m 13m 12m R 22 0.0 0:02.86 opensips
13263 root 20 0 136m 13m 12m S 21 0.0 0:01.55 opensips
13261 root 20 0 136m 13m 12m R 19 0.0 0:02.30 opensips
13264 root 20 0 136m 13m 12m S 9 0.0 0:01.99 opensips
13257 root 20 0 136m 13m 12m S 5 0.0 0:02.82 opensips
13262 root 20 0 136m 13m 12m S 4 0.0 0:02.58 opensips
13259 root 20 0 136m 13m 12m S 2 0.0 0:03.79 opensips
13260 root 20 0 136m 13m 12m S 2 0.0 0:00.87 opensips
13256 root 20 0 136m 13m 12m S 1 0.0 0:00.99 opensips
13268 root 20 0 136m 9592 8132 S 0 0.0 0:00.14 opensips
13271 root 20 0 136m 10m 9588 S 0 0.0 0:00.16 opensips
13265 root 20 0 136m 13m 12m S 87 0.0 0:07.13 opensips
13261 root 20 0 136m 13m 12m S 51 0.0 0:03.83 opensips
13258 root 20 0 136m 13m 12m S 50 0.0 0:04.36 opensips
13256 root 20 0 136m 13m 12m S 37 0.0 0:02.10 opensips
13257 root 20 0 136m 13m 12m R 12 0.0 0:03.18 opensips
13259 root 20 0 136m 13m 12m S 11 0.0 0:04.11 opensips
13260 root 20 0 136m 13m 12m S 4 0.0 0:00.98 opensips
13263 root 20 0 136m 13m 12m S 1 0.0 0:01.57 opensips
13264 root 20 0 136m 14m 12m S 1 0.0 0:02.01 opensips
13254 root 20 0 136m 1604 184 S 0 0.0 0:00.45 opensips
13280 root 20 0 136m 6672 5212 S 0 0.0 0:00.17 opensips
13284 root 20 0 136m 9056 7596 S 0 0.0 0:00.16 opensips
When sipps stop originating new calls..
13280 root 20 0 136m 13m 12m S 0 0.0 0:00.22 opensips
13284 root 20 0 136m 16m 14m S 0 0.0 0:00.21 opensips
13287 root 20 0 136m 14m 12m S 0 0.0 0:00.19 opensips
13264 root 20 0 136m 21m 19m S 0 0.0 0:08.75 opensips
13271 root 20 0 136m 16m 14m S 0 0.0 0:00.21 opensips
13274 root 20 0 136m 12m 11m S 0 0.0 0:00.22 opensips
13254 root 20 0 136m 1604 184 S 0 0.0 0:00.61 opensips
13279 root 20 0 136m 11m 10m S 0 0.0 0:00.23 opensips
13268 root 20 0 136m 15m 14m S 0 0.0 0:00.19 opensips
13254 root 20 0 136m 1604 184 S 0 0.0 0:00.62 opensips
13255 root 20 0 136m 1604 184 S 0 0.0 0:00.27 opensips
13258 root 20 0 136m 21m 19m S 0 0.0 0:08.25 opensips
13266 root 20 0 136m 16m 14m S 0 0.0 0:00.17 opensips
13280 root 20 0 136m 13m 12m S 0 0.0 0:00.23 opensips
13284 root 20 0 136m 16m 14m S 0 0.0 0:00.22 opensips
13267 root 20 0 136m 13m 11m S 6 0.0 0:00.19 opensips
13263 root 20 0 136m 21m 19m S 1 0.0 0:06.61 opensips
13269 root 20 0 136m 12m 10m S 1 0.0 0:00.20 opensips
13279 root 20 0 136m 11m 10m S 1 0.0 0:00.24 opensips
After calls start to terminate
13264 root 20 0 136m 23m 21m R 99 0.0 0:17.90 opensips
13264 root 20 0 136m 23m 21m R 98 0.0 0:17.97 opensips
13265 root 20 0 136m 23m 21m R 98 0.0 0:22.35 opensips
13265 root 20 0 136m 23m 21m R 100 0.0 0:25.36 opensips
13263 root 20 0 136m 23m 21m R 71 0.0 0:17.59 opensips
13287 root 20 0 136m 18m 17m S 0 0.0 0:00.37 opensips
13265 root 20 0 136m 23m 21m R 100 0.0 0:26.78 opensips
13264 root 20 0 136m 23m 21m R 31 0.0 0:21.43 opensips
13274 root 20 0 136m 17m 16m S 1 0.0 0:00.43 opensips
13263 root 20 0 136m 23m 21m R 92 0.0 0:19.15 opensips
13264 root 20 0 136m 23m 21m R 92 0.0 0:21.57 opensips
13263 root 20 0 136m 23m 21m R 101 0.0 0:19.30 opensips
13265 root 20 0 136m 23m 21m R 101 0.0 0:27.08 opensips
13264 root 20 0 136m 23m 21m R 100 0.0 0:21.93 opensips
13265 root 20 0 136m 23m 21m R 100 0.0 0:27.28 opensips
13264 root 20 0 136m 23m 21m R 97 0.0 0:22.10 opensips
13265 root 20 0 136m 23m 21m R 97 0.0 0:27.45 opensips
13260 root 20 0 136m 23m 21m S 74 0.0 0:16.65 opensips
13261 root 20 0 136m 22m 21m R 69 0.0 0:13.53 opensips
13258 root 20 0 136m 23m 21m S 20 0.0 0:22.09 opensips
13264 root 20 0 136m 23m 21m R 95 0.0 0:22.45 opensips
13265 root 20 0 136m 23m 21m S 47 0.0 0:27.73 opensips
13280 root 20 0 136m 15m 14m S 7 0.0 0:00.45 opensips
13263 root 20 0 136m 23m 21m R 77 0.0 0:20.14 opensips
13284 root 20 0 136m 17m 16m S 7 0.0 0:00.41 opensips
13257 root 20 0 136m 23m 21m R 92 0.0 0:17.49 opensips
13264 root 20 0 136m 23m 21m S 6 0.0 0:22.60 opensips
13262 root 20 0 136m 23m 21m R 93 0.0 0:12.40 opensips
13256 root 20 0 136m 23m 21m R 49 0.0 0:14.99 opensips
13260 root 20 0 136m 23m 21m S 5 0.0 0:17.12 opensips
13261 root 20 0 136m 22m 21m R 96 0.0 0:14.31 opensips
13263 root 20 0 136m 23m 21m S 6 0.0 0:20.50 opensips
13261 root 20 0 136m 22m 21m S 18 0.0 0:14.84 opensips
13263 root 20 0 136m 23m 21m S 15 0.0 0:20.96 opensips
13265 root 20 0 136m 23m 21m S 13 0.0 0:28.13 opensips
13262 root 20 0 136m 23m 21m S 12 0.0 0:12.91 opensips
13264 root 20 0 136m 23m 21m S 9 0.0 0:22.86 opensips
13254 root 20 0 136m 1604 184 S 0 0.0 0:01.20 opensips
13266 root 20 0 136m 16m 15m S 2 0.0 0:00.33 opensips
13263 root 20 0 136m 23m 21m S 8 0.0 0:20.97 opensips
I see opensips stuck(flood with warnings) durings calls termination process
which leads me to manually kill opensisp to prevent opensips from eating
all my server resources.
Test is performed using sipp with 30 cps and 2000 concurrent calls of
during 6 minutes.
:lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
CPU(s): 32
On-line CPU(s) list: 0-31
Thread(s) per core: 2
Core(s) per socket: 8
Socket(s): 2
NUMA node(s): 2
Vendor ID: GenuineIntel
CPU family: 6
Model: 45
Stepping: 7
CPU MHz: 1199.531
BogoMIPS: 4001.49
Virtualization: VT-x
L1d cache: 32K
L1i cache: 32K
L2 cache: 256K
L3 cache: 20480K
NUMA node0 CPU(s): 0-7,16-23
NUMA node1 CPU(s): 8-15,24-31
egrep --color 'Mem|Cache|Swap' /proc/meminfo
MemTotal: 49530560 kB
MemFree: 29677688 kB
MemAvailable: 45436220 kB
Let me know if you need anything else.
Thanks.
On 22 January 2016 at 21:18, Bogdan-Andrei Iancu <bogdan at opensips.org>
wrote:
> Yes, the "children" option - 10 should be more than ok.
>
> What is the CPU usage from opensips during the test ?
>
> Regards,
>
> Bogdan-Andrei Iancu
> OpenSIPS Founder and Developerhttp://www.opensips-solutions.com
>
> On 22.01.2016 18:08, Aqs Younas wrote:
>
> Hi, Bogdan
>
>
> You mean children? First I thought it is due to children(10 default) which I increased to 500 but no avail.
>
> This I have in my configuration file.
>
> debug=3
> log_stderror=no
> log_facility=LOG_LOCAL3
>
> fork=yes
> children=500
> open_files_limit=99999
>
>
> Thanks for replying.
>
>
> On 22 January 2016 at 20:49, Bogdan-Andrei Iancu < <bogdan at opensips.org>
> bogdan at opensips.org> wrote:
>
>> How many workers have you configured into opensips ?
>>
>> Regards,
>>
>> Bogdan-Andrei Iancu
>> OpenSIPS Founder and Developerhttp://www.opensips-solutions.com
>>
>> On 22.01.2016 17:43, Aqs Younas wrote:
>>
>> I see this warning when i am sending calls with more than 10 cps. On 5 to
>> 10 cps everything seems ok.
>>
>> On 22 January 2016 at 19:38, Aqs Younas < <aqsyounas at gmail.com>
>> aqsyounas at gmail.com> wrote:
>>
>>> Hi,
>>>
>>> I am using sipp to load test my opensips (version: opensips 2.1.2
>>> (x86_64/linux)) after calls get terminated i see my opensips being flood
>>> with below warnings.
>>>
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575170 ms (now 1575270 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575270 ms (now 1575370 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575370 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <rl-timer> already schedualed for
>>> 846540 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <nt-pinger> already schedualed for
>>> 867440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <nh-timer> already schedualed for
>>> 867440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <lb-pinger> already schedualed for
>>> 866440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <dlg-pinger> already schedualed for
>>> 866440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <dlg-timer> already schedualed for
>>> 867440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <ul-timer> already schedualed for
>>> 896290 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <tm-timer> already schedualed for
>>> 836590 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:timer_ticker: timer task <blcore-expire> already schedualed
>>> for 867440 ms (now 1575470 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575470 ms (now 1575570 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575570 ms (now 1575670 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575670 ms (now 1575770 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575770 ms (now 1575870 ms), it may overlap..
>>> Jan 22 14:31:38 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575870 ms (now 1575970 ms), it may overlap..
>>> Jan 22 14:31:39 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1575970 ms (now 1576070 ms), it may overlap..
>>> Jan 22 14:31:39 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1576070 ms (now 1576170 ms), it may overlap..
>>> Jan 22 14:31:39 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1576170 ms (now 1576270 ms), it may overlap..
>>> Jan 22 14:31:39 66-226-76-150
>>> /usr/local/origination/opensips/sbin/opensips[22844]:
>>> WARNING:core:utimer_ticker: utimer task <tm-utimer> already schedualed for
>>> 1576270 ms (now 1576360 ms), it may overlap..
>>>
>>> Below command never gets executed.
>>>
>>> /usr/local/origination/opensips/sbin/opensipsctl trap
>>> INFO: Trap file: /tmp/gdb_opensips_20160122_143249
>>> ^C/usr/local/origination/opensips//lib64/opensips/opensipsctl/opensipsctl.fifo:
>>> line 109: /tmp/opensips_fifo: Interrupted system call
>>> Terminated
>>>
>>> This files is empty
>>> cat /tmp/gdb_opensips_20160122_143249
>>>
>>> ps -el | grep opensips
>>>
>>>
>>> 1 S 0 22782 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22783 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22785 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22789 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22792 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22796 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22798 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22800 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22804 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22807 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22811 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22814 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22817 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22819 22762 0 80 0 - 39789 - ? 00:00:00
>>> opensips
>>> 1 S 0 22821 22762 0 80 0 - 39789 - ? 00:00:01
>>> opensips
>>> 5 S 0 22830 1 0 80 0 - 36876 - ? 00:00:00
>>> opensips
>>> 1 S 0 22833 22830 0 80 0 - 36876 - ? 00:00:00
>>> opensips
>>> 1 S 0 22834 22830 0 80 0 - 36876 - ? 00:00:00
>>> opensips
>>> 1 S 0 22835 22830 0 80 0 - 36876 - ? 00:00:00
>>> opensips
>>> 1 S 0 22838 22830 0 80 0 - 36878 - ? 00:00:00
>>> opensips
>>> 1 S 0 22840 22830 0 80 0 - 36876 - ? 00:00:01
>>> opensips
>>> 1 S 0 22844 22830 0 80 0 - 36876 - ? 00:00:01
>>> opensips
>>> 1 R 0 22846 22830 6 80 0 - 36876 - ? 00:01:56
>>> opensips
>>> 1 S 0 22847 22830 8 80 0 - 36876 - ? 00:02:28
>>> opensips
>>> 1 R 0 22849 22830 6 80 0 - 36876 - ? 00:01:58
>>> opensips
>>> 1 S 0 22852 22830 8 80 0 - 36876 - ? 00:02:30
>>> opensips
>>> 1 R 0 22855 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 R 0 22858 22830 8 80 0 - 36876 - ? 00:02:27
>>> opensips
>>> 1 S 0 22862 22830 8 80 0 - 36876 - ? 00:02:27
>>> opensips
>>> 1 R 0 22864 22830 6 80 0 - 36909 - ? 00:01:56
>>> opensips
>>> 1 S 0 22869 22830 8 80 0 - 36876 - ? 00:02:27
>>> opensips
>>> 1 S 0 22872 22830 6 80 0 - 36876 - ? 00:01:58
>>> opensips
>>> 1 S 0 22875 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 S 0 22878 22830 6 80 0 - 36876 - ? 00:01:58
>>> opensips
>>> 1 S 0 22879 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 S 0 22884 22830 6 80 0 - 36876 - ? 00:01:58
>>> opensips
>>> 1 S 0 22887 22830 3 80 0 - 36876 - ? 00:01:05
>>> opensips
>>> 1 S 0 22889 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 S 0 22892 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 S 0 22895 22830 3 80 0 - 36876 - ? 00:00:53
>>> opensips
>>> 1 S 0 22899 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>> 1 S 0 22902 22830 6 80 0 - 36876 - ? 00:01:57
>>> opensips
>>>
>>> CTRL+C does not seem to stop the warnings.
>>> I had to kill the opensips to restart it.
>>>
>>> Any help in this regard.
>>>
>>> Best Regards.
>>>
>>>
>>
>>
>> _______________________________________________
>> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users at lists.opensips.org
>> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>>
>>
>
>
> _______________________________________________
> Users mailing listUsers at lists.opensips.orghttp://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
>
> _______________________________________________
> Users mailing list
> Users at lists.opensips.org
> http://lists.opensips.org/cgi-bin/mailman/listinfo/users
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opensips.org/pipermail/users/attachments/20160122/fb197e0e/attachment-0001.htm>
More information about the Users
mailing list