Asterisk 16.2.0 app_queue high context switches


#1

Hello. After update asterisk from 11 to 16 i have high context switches with 200 concurrent calls in queue.

asterisk 16.2.0
2 x Xeon E5630 | 30gb ram

calling app queue in lua dialplan:

app.answer();
app.queue('income'..math.random(1, 11)..'_cc,t,,,60,,,,,');

queues conf:

[income_cc]
weight=5
ringinuse=no
strategy=rrmemory
musiconhold=default
timeout=7
retry=1
servicelevel=60
autopause=all
autopausebusy=yes
autopauseunavail=yes
setqueueentryvar=yes
wrapuptime=2

example composition of queue from cli:

income4_cc has 0 calls (max unlimited) in 'rrmemory' strategy (20s holdtime, 32s talktime), W:5, C:137, A:0, SL:100.0%, SL2:100.0% within 60s
   Members: 
      1876 (SIP/1876) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1750 secs ago)
      1832 (SIP/1832) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1866 (SIP/1866) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1741 (SIP/1741) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1744 secs ago)
      5132 (SIP/5132) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1735 secs ago)
      1765 (SIP/1765) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1731 secs ago)
      1856 (SIP/1856) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1717 secs ago)
      1506 (SIP/1506) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1742 secs ago)
      1846 (SIP/1846) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1720 secs ago)
      1711 (SIP/1711) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1727 secs ago)
      1745 (SIP/1745) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1724 secs ago)
      1769 (SIP/1769) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1726 secs ago)
      1735 (SIP/1735) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1723 secs ago)
      5648 (SIP/5648) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1737 secs ago)
      8593 (SIP/8593) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1734 secs ago)
      9311 (SIP/9311) with penalty 3 (ringinuse disabled) (dynamic) (Unavailable) has taken no calls yet
      1792 (SIP/1792) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1734 secs ago)
      5412 (SIP/5412) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1736 secs ago)
      1782 (SIP/1782) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1744 secs ago)
      1749 (SIP/1749) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1733 secs ago)
      1739 (SIP/1739) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1724 secs ago)
      1897 (SIP/1897) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1719 secs ago)
      1887 (SIP/1887) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1843 (SIP/1843) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1722 secs ago)
      1877 (SIP/1877) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1750 secs ago)
      5837 (SIP/5837) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1743 secs ago)
      1867 (SIP/1867) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1749 secs ago)
      5406 (SIP/5406) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1748 secs ago)
      1857 (SIP/1857) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1749 secs ago)
      1756 (SIP/1756) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1732 secs ago)
      1880 (SIP/1880) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1745 secs ago)
      5386 (SIP/5386) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1739 secs ago)
      8786 (SIP/8786) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1739 secs ago)
      1870 (SIP/1870) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1751 secs ago)
      1860 (SIP/1860) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1731 secs ago)
      1736 (SIP/1736) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1725 secs ago)
      1894 (SIP/1894) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1719 secs ago)
      1840 (SIP/1840) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1720 secs ago)
      4039 (SIP/4039) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1736 secs ago)
      5470 (SIP/5470) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1746 secs ago)
      9191 (SIP/9191) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1742 secs ago)
      1763 (SIP/1763) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1726 secs ago)
      8554 (SIP/8554) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1737 secs ago)
      1878 (SIP/1878) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1722 secs ago)
      8850 (SIP/8850) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1738 secs ago)
      9353 (SIP/9353) with penalty 2 (ringinuse disabled) (dynamic) (Unavailable) has taken no calls yet
      5474 (SIP/5474) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1735 secs ago)
      1891 (SIP/1891) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1748 secs ago)
      8356 (SIP/8356) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1738 secs ago)
      9141 (SIP/9141) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1732 secs ago)
      5865 (SIP/5865) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1740 secs ago)
      5400 (SIP/5400) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1740 secs ago)
      1895 (SIP/1895) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1760 (SIP/1760) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1729 secs ago)
      1818 (SIP/1818) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1728 secs ago)
      1885 (SIP/1885) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1751 secs ago)
      1794 (SIP/1794) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1746 secs ago)
      1784 (SIP/1784) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1730 secs ago)
      9145 (SIP/9145) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1730 secs ago)
      1717 (SIP/1717) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1727 secs ago)
      1774 (SIP/1774) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1729 secs ago)
      8871 (SIP/8871) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1741 secs ago)
      1831 (SIP/1831) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1721 secs ago)
      1899 (SIP/1899) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1730 (SIP/1730) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1728 secs ago)
      1889 (SIP/1889) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1764 (SIP/1764) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1747 secs ago)
      1821 (SIP/1821) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1747 secs ago)
      1505 (SIP/1505) with penalty 1 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1741 secs ago)
      9354 (SIP/9354) with penalty 2 (ringinuse disabled) (dynamic) (Unavailable) has taken no calls yet
      1835 (SIP/1835) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1768 (SIP/1768) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1733 secs ago)
      1859 (SIP/1859) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1721 secs ago)
      1892 (SIP/1892) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1872 (SIP/1872) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1718 secs ago)
      1738 (SIP/1738) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1723 secs ago)
      1862 (SIP/1862) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1717 secs ago)
      1795 (SIP/1795) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 2 calls (last was 1725 secs ago)
      1761 (SIP/1761) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1745 secs ago)
      1852 (SIP/1852) with penalty 2 (ringinuse disabled) (dynamic) (Not in use) has taken 1 calls (last was 1743 secs ago)
   No Callers

vmstat 1(sipp load with 2cps):

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 25135816   1224 5477744    0    0     6     9    2    1  1  1 99  0  0
 0  0      0 25135676   1224 5477744    0    0     0    97  852 1742  0  0 100  0  0
 0  0      0 25135488   1224 5477748    0    0     0    98  850 1688  0  0 100  0  0
 0  0      0 25135628   1224 5477744    0    0     0    97  771 1653  0  0 100  0  0
 0  0      0 25135876   1224 5477744    0    0     0    81  718 1629  0  0 100  0  0
 1  0      0 25135720   1224 5477748    0    0     0   105 1615 3023  1  0 99  0  0
 0  0      0 25135920   1224 5477744    0    0     0   134 2429 4212  1  0 99  0  0
 1  0      0 25135252   1224 5477760    0    0     0    91 2603 5886  1  0 99  0  0
 0  0      0 25135032   1224 5477764    0    0     0   163 2819 7441  1  0 99  0  0
 1  0      0 25134452   1224 5477772    0    0     0    89 3236 8999  1  0 98  0  0
 0  0      0 25134252   1224 5477780    0    0     0    91 3320 12162  1  1 98  0  0
 1  0      0 25134032   1224 5477788    0    0     0   103 3514 13439  1  1 98  0  0
 1  0      0 25133904   1224 5477792    0    0     0   155 3523 13758  1  1 98  0  0
 0  0      0 25133764   1224 5477796    0    0     0   108 4410 19542  1  1 98  0  0
 0  0      0 25133340   1224 5477808    0    0     0    87 4125 20899  1  1 98  0  0
 0  0      0 25133436   1224 5477808    0    0     0   119 4682 23616  1  1 98  0  0
 0  0      0 25132752   1224 5477820    0    0     0    66 5152 26940  1  1 97  0  0
 0  0      0 25133020   1224 5477832    0    0     0   103 5039 28540  1  1 98  0  0
 0  0      0 25132428   1224 5477848    0    0     0    87 6003 31507  1  1 97  0  0
 0  0      0 25131960   1224 5477844    0    0     0   103 4585 24864  1  1 98  0  0
 0  0      0 25132252   1224 5477852    0    0     0    71 5397 28498  1  1 97  0  0
 0  0      0 25132468   1224 5477864    0    0     0    83 6951 39710  1  2 97  0  0
 1  0      0 25131004   1224 5477876    0    0     0    87 6413 38189  2  2 97  0  0
 0  0      0 25130932   1224 5477892    0    0     0   103 6045 35768  2  2 97  0  0
 1  0      0 25130984   1224 5477896    0    0     0   103 7192 46646  2  2 96  0  0
 0  0      0 25130816   1224 5477904    0    0     0   103 7590 49876  2  2 96  0  0
 0  0      0 25131432   1224 5477828    0    0     0    83 7635 52457  2  2 96  0  0
 0  0      0 25131080   1224 5477840    0    0     0    99 8243 56619  2  2 96  0  0
 0  0      0 25130756   1224 5477852    0    0     0    99 8219 58019  2  2 96  0  0
 1  0      0 25130768   1224 5477860    0    0     0    95 8753 59667  2  2 96  0  0
 0  0      0 25130704   1224 5477872    0    0     0   107 8541 62575  2  2 96  0  0
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0      0 25129792   1224 5477872    0    0     0   115 8573 65304  2  2 96  0  0
 0  0      0 25129896   1224 5477752    0    0     0   262 8339 63947  2  2 96  0  0
 1  0      0 25129808   1224 5477756    0    0     0   102 8293 42092  1  2 97  0  0
 0  0      0 25129388   1224 5477764    0    0     0    99 9612 73152  2  3 95  0  0
 0  0      0 25128440   1224 5477780    0    0     0    83 9333 72548  2  3 95  0  0
 0  0      0 25127668   1224 5477756    0    0     0    99 9410 63274  2  2 96  0  0
 0  0      0 25127400   1224 5477800    0    0     0    91 10219 84001  2  3 95  0  0
 0  0      0 25126912   1224 5477816    0    0     0   146 9620 75893  2  3 95  0  0
 0  0      0 25126504   1224 5477852    0    0     0   102 9004 66692  2  2 96  0  0
 1  0      0 25127180   1224 5477924    0    0     0   107 9315 63113  2  2 96  0  0
 0  0      0 25126928   1224 5477992    0    0     0    91 9767 70991  2  3 95  0  0
 1  0      0 25125728   1224 5478040    0    0     0   103 11341 87457  2  3 94  0  0
 0  0      0 25125516   1224 5478060    0    0     0    99 8261 53044  2  2 96  0  0
 0  0      0 25126204   1224 5478064    0    0     0    87 9670 68531  2  3 95  0  0
 0  0      0 25126548   1224 5478148    0    0     0    83 9094 56266  2  2 96  0  0
 0  0      0 25125328   1224 5478180    0    0     0   103 12380 104773  3  4 94  0  0
 0  0      0 25124388   1224 5478252    0    0     0    91 11934 94429  3  3 94  0  0
 0  0      0 25123980   1224 5478268    0    0     0   103 11224 78711  2  3 95  0  0
 1  0      0 25124024   1224 5478276    0    0     0    63 13179 101861  3  3 94  0  0
 0  0      0 25123696   1224 5478284    0    0     0    87 11975 85001  2  3 95  0  0
 0  0      0 25123408   1224 5478288    0    0     0   103 12537 89469  2  3 94  0  0
 1  0      0 25123016   1224 5478364    0    0     0   235 15357 113462  3  4 93  0  0
 0  0      0 25122956   1224 5478368    0    0     0   118 13573 106624  3  4 94  0  0
 1  0      0 25122968   1224 5478440    0    0     0    95 12095 92065  2  3 95  0  0
 0  0      0 25121832   1224 5478516    0    0     0    87 12269 94376  3  4 94  0  0
 1  0      0 25121632   1224 5478544    0    0     0   119 12118 90474  2  3 94  0  0
 9  0      0 25121540   1224 5478548    0    0     0   103 11468 82363  2  3 95  0  0
 8  0      0 25121328   1224 5478624    0    0     0    99 16345 141842  4  5 92  0  0
 4  0      0 25121196   1224 5478772    0    0     0    91 16677 138044  3  5 92  0  0
 6  0      0 25120252   1224 5478824    0    0     0    95 26285 281506  6  9 85  0  0
 4  0      0 25119068   1224 5478988    0    0     0    83 29354 301057  6 10 84  0  0
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 7  0      0 25118700   1224 5479108    0    0     0    96 30698 314174  6 10 83  0  0
 9  0      0 25118404   1224 5479112    0    0     0   107 32493 343831  7 11 82  0  0
12  0      0 25117456   1224 5479136    0    0     0    84 31328 328535  6 11 82  0  0
 4  0      0 25116980   1224 5479288    0    0     0    88 32970 341524  7 11 82  0  0
13  0      0 25116968   1224 5479312    0    0     0    88 32484 379992  7 12 81  0  0
 2  0      0 25116592   1224 5479352    0    0     0   111 30587 312769  6 10 84  0  0

300k context switches with 170-180 concurrent calls.

200 simple bridged concurrent calls have 30-40k context switches.