Добрый день!
На почту приходят письма
Код:
ID события: radius.wait.thread
Время регистрации события: 21.04.2014 18:34:34
Хост сервера: bgb.mynet.ru/111.111.111.26
В рамках отведенного переменными количества потоков threadCount и размером очереди обработки maxQueueSize RADIUS сервер не успеевает производить обработку аккаунтинг запросов.
Возможная причина - загруженность базы данных.
Radius:
accounting-requests per minute start: 0; stop: 255; update: 0
access-requests per minute accept: 0; reject: 0
ignore per minute access-request: 0; accounting-update: 195
В логах accounting вываливается в большом количестве подряд
Код:
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
radius 04-21/18:36:58 WARN [InetRadiusListener] RadiusListener - RadiusListener accounting queue is full!
Далее:
Код:
collector 04-21/18:37:36 ERROR [flow-p-9-t-10] WorkerTask - Lock wait timeout for ContractRuntime[1644]@968246912
java.lang.RuntimeException: Lock wait timeout for ContractRuntime[1644]@968246912
at ru.bitel.common.util.CheckReentrantLock.lock(CheckReentrantLock.java:46)
at ru.bitel.bgbilling.kernel.contract.runtime.ContractRuntime.lock(ContractRuntime.java:104)
at ru.bitel.bgbilling.modules.inet.runtime.InetServRuntime.lock(InetServRuntime.java:501)
at ru.bitel.bgbilling.modules.inet.accounting.InetConnectionRuntime.lockIfSessionActive(InetConnectionRuntime.java:828)
at ru.bitel.bgbilling.modules.inet.accounting.ip.CallConnectionAddressSet.get(CallConnectionAddressSet.java:101)
at ru.bitel.bgbilling.modules.inet.accounting.ip.HourlyCallConnectionSet.getSession(HourlyCallConnectionSet.java:203)
at ru.bitel.bgbilling.modules.inet.accounting.FlowAgentInterface.getConnection(FlowAgentInterface.java:88)
at ru.bitel.bgbilling.modules.inet.accounting.FlowAgentInterface.processFlow(FlowAgentInterface.java:157)
at ru.bitel.bgbilling.modules.inet.collector.FlowListenerWorker.processPacketImpl0(FlowListenerWorker.java:248)
at ru.bitel.bgbilling.modules.inet.collector.FlowListenerWorker.processPacketImpl(FlowListenerWorker.java:141)
at ru.bitel.bgbilling.modules.inet.collector.FlowListenerWorkerNetFlow.processPacket(FlowListenerWorkerNetFlow.java:29)
at ru.bitel.bgbilling.modules.inet.collector.FlowListenerWorker.runImpl(FlowListenerWorker.java:58)
at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
Caused by: java.lang.RuntimeException: OwnerThread: Thread[rdsLstnr-p-7-t-85,5,main]
at org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1700)
at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:231)
at org.apache.activemq.ActiveMQMessageProducerSupport.send(ActiveMQMessageProducerSupport.java:269)
at ru.bitel.bgbilling.kernel.event.Producer.send(Producer.java:153)
at ru.bitel.bgbilling.kernel.event.EventProcessor.publish(EventProcessor.java:791)
at ru.bitel.bgbilling.modules.inet.accounting.Accounting.connectionStop(Accounting.java:1606)
at ru.bitel.bgbilling.modules.inet.radius.InetNas.stopConnection(InetNas.java:703)
at ru.bitel.bgbilling.modules.inet.radius.InetNas.stopConnection(InetNas.java:613)
at ru.bitel.bgbilling.modules.inet.radius.InetNas.stopConnection(InetNas.java:1)
at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accounting(RadiusProcessor.java:584)
at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accountingRequest(RadiusProcessor.java:519)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accountingRequest(InetRadiusListenerWorker.java:182)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accountingRequest(InetRadiusListenerWorker.java:1)
at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processAccountingRequest(RadiusListenerWorker.java:271)
at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:242)
at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
... 5 more
У абонентов, авторизующихся через радиус при этом выскакивает 691 ошибка.
]# ./accounting_status.sh
Код:
Java Runtime: Sun Microsystems Inc. Java HotSpot(TM) 64-Bit Server VM [1.6.0_43] /opt/jdk1.6.0_43/jre
Runtime name: 89195@bgb.mynet.ru
Java endorsed dirs: /lib/endorsed:/opt/java/lib/endorsed
OS: Linux 3.6.10-4.fc18.x86_64 [amd64], file.encoding: UTF-8, user.name: root
Heap sizes: current=118080k free=117464k max=1753088k
Kernel version 5.2 build 1538 from 23.08.2013 15:51:00
Inet version 5.2 build 1226 from 21.08.2013 14:18:49
Radius:
accounting-requests per minute start: 0; stop: 247; update: 0
access-requests per minute accept: 0; reject: 0
ignore per minute access-request: 0; accounting-update: 190
Flow listener [111.111.111.26:2001]
flow packets in current minute: 29291
Started: 15.04.2014 15:46:46 Uptime: 6 d 02:51:47
Memory total: 155 582 464; max: 1 908 932 608; free: 12 920 608
Memory pools:
Non-heap memory[Code Cache]: max: 50 331 648; used: 8 918 272; peek: 9 092 736
Heap memory[PS Eden Space]: max: 704 512 000; used: 3 747 816; peek: 523 567 104
Heap memory[PS Survivor Space]: max: 720 896; used: 720 896; peek: 30 605 472
Heap memory[PS Old Gen]: max: 1 431 699 456; used: 138 193 144; peek: 149 184 456
Non-heap memory[PS Perm Gen]: max: 85 983 232; used: 35 955 040; peek: 35 968 176
Thread count: 201
Trees in cache: 0
Connections pool to Master status Idle: 3; Active: 56; maxActive: 300; maxIdle: 20
В логах access:
Код:
radius 04-21/18:39:27 ERROR [rdsLstnr-p-8-t-73] RadiusListenerWorker - Lock wait timeout for ContractRuntime[4486]@1857435516
java.lang.RuntimeException: Lock wait timeout for ContractRuntime[4486]@1857435516
at ru.bitel.common.util.CheckReentrantLock.tryLockEx(CheckReentrantLock.java:88)
at ru.bitel.bgbilling.kernel.contract.runtime.ContractRuntime.tryLockEx(ContractRuntime.java:165)
at ru.bitel.bgbilling.modules.inet.runtime.InetServRuntime.tryLockEx(InetServRuntime.java:518)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authenticationImpl(InetRadiusProcessor.java:609)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:470)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authentication(InetRadiusProcessor.java:1)
at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.authentication(RadiusSession.java:115)
at ru.bitel.bgbilling.kernel.network.radius.RadiusSession.accessRequest(RadiusSession.java:92)
at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequestImpl(RadiusProcessor.java:438)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:386)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.accessRequestImpl(InetRadiusProcessor.java:1)
at ru.bitel.bgbilling.kernel.network.radius.RadiusProcessor.accessRequest(RadiusProcessor.java:423)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:59)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusListenerWorker.accessRequest(InetRadiusListenerWorker.java:1)
at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.processPacket(RadiusListenerWorker.java:216)
at ru.bitel.bgbilling.kernel.network.radius.RadiusListenerWorker.runImpl(RadiusListenerWorker.java:135)
at ru.bitel.common.worker.WorkerTask.run(WorkerTask.java:86)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
at java.lang.Thread.run(Thread.java:662)
at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:40)
Caused by: java.lang.RuntimeException: OwnerThread: Thread[rdsLstnr-p-8-t-99,5,main]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:114)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:161)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:189)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2549)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3002)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:2991)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3532)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2002)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2163)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2624)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2127)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2427)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2345)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2330)
at org.apache.commons.dbcp.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:105)
at ru.bitel.bgbilling.modules.inet.api.server.bean.InetConnectionDao.insert(InetConnectionDao.java:138)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authorization(InetRadiusProcessor.java:934)
at ru.bitel.bgbilling.modules.inet.radius.InetRadiusProcessor.authenticationImpl(InetRadiusProcessor.java:612)
... 17 more
# ./access_status.sh
Код:
Java Runtime: Sun Microsystems Inc. Java HotSpot(TM) 64-Bit Server VM [1.6.0_43] /opt/jdk1.6.0_43/jre
Runtime name: 89308@bgb.mynet.ru
Java endorsed dirs: /lib/endorsed:/opt/java/lib/endorsed
OS: Linux 3.6.10-4.fc18.x86_64 [amd64], file.encoding: UTF-8, user.name: root
Heap sizes: current=118080k free=117464k max=1753088k
Kernel version 5.2 build 1538 from 23.08.2013 15:51:00
Inet version 5.2 build 1226 from 21.08.2013 14:18:49
Radius:
accounting-requests per minute start: 0; stop: 0; update: 0
access-requests per minute accept: 0; reject: 459
ignore per minute access-request: 0; accounting-update: 0
Antispam ban count: 134; used per minute: 0
Started: 15.04.2014 15:48:32 Uptime: 6 d 02:52:04
Memory total: 145 883 136; max: 954 466 304; free: 10 566 528
Memory pools:
Non-heap memory[Code Cache]: max: 50 331 648; used: 7 169 216; peek: 7 183 744
Heap memory[PS Eden Space]: max: 352 976 896; used: 289 040; peek: 199 557 120
Heap memory[PS Survivor Space]: max: 2 424 832; used: 1 802 336; peek: 12 858 792
Heap memory[PS Old Gen]: max: 715 849 728; used: 133 227 936; peek: 142 262 880
Non-heap memory[PS Perm Gen]: max: 85 983 232; used: 33 555 272; peek: 33 769 112
Thread count: 385
Trees in cache: 0
Connections pool to Master status Idle: 15; Active: 132; maxActive: 300; maxIdle: 20
]# ./server_status.sh
Код:
BGBillingServer v 5.2 build 1559 from 26.11.2013 12:44:50
Started: 15.04.2014 15:53:48 Uptime: 6 d 02:48:19
Memory total: 165 937 152; max: 477 233 152; free: 30 426 336
Memory pools:
Non-heap memory[Code Cache]: max: 50 331 648; used: 13 032 192; peek: 13 037 632
Heap memory[PS Eden Space]: max: 176 947 200; used: 519 608; peek: 164 888 576
Heap memory[PS Survivor Space]: max: 983 040; used: 298 680; peek: 22 766 808
Heap memory[PS Old Gen]: max: 357 957 632; used: 134 692 528; peek: 351 870 864
Non-heap memory[PS Perm Gen]: max: 134 217 728; used: 78 940 008; peek: 79 870 520
Thread count: 45
Connections pool to Master status Idle: 0; Active: 10; maxActive: 300; maxIdle: 20
Myslql:
Код:
show processlist;
| 17862 | bill | localhost:57456 | bgbilling | Query | 92 | update | INSERT INTO inet_connection_1 (id, parentId, deviceId, devicePort, agentDeviceId, acctSessionId, use |
| 17863 | root | localhost | mysql | Query | 0 | NULL | show processlist |
+-------+------+-----------------+-----------+---------+------+--------+------------------------------------------------------------------------------------------------------+
225 rows in set (0.00 sec)
Код:
mysql> SHOW VARIABLES LIKE '%connections%';
+----------------------+-------+
| Variable_name | Value |
+----------------------+-------+
| max_connections | 1000 |
| max_user_connections | 0 |
+----------------------+-------+
2 rows in set (0.00 sec)
top:
Код:
top - 18:43:39 up 32 days, 15:36, 1 user, load average: 0,56, 0,46, 0,43
Tasks: 117 total, 2 running, 115 sleeping, 0 stopped, 0 zombie
%Cpu0 : 3,7 us, 1,3 sy, 0,0 ni, 88,3 id, 5,3 wa, 0,3 hi, 1,0 si, 0,0 st
%Cpu1 : 5,0 us, 1,0 sy, 0,0 ni, 93,4 id, 0,7 wa, 0,0 hi, 0,0 si, 0,0 st
%Cpu2 : 2,0 us, 0,3 sy, 0,0 ni, 97,7 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
%Cpu3 : 2,0 us, 0,7 sy, 0,0 ni, 97,3 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
KiB Mem: 7883444 total, 7753744 used, 129700 free, 413664 buffers
KiB Swap: 7897084 total, 675436 used, 7221648 free, 2447236 cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
85784 mysql 20 0 3710m 1,5g 5048 S 7,3 20,4 1359:32 mysqld
38544 root 20 0 3595m 323m 5616 S 4,3 4,2 166:02.19 java
38255 root 20 0 5712m 1,6g 5700 S 2,7 20,9 704:06.70 java
8340 root 20 0 2738m 139m 5536 S 0,3 1,8 52:38.99 java
htop:
Код:
1 [||| 6.4%] Tasks: 44, 1389 thr; 1 running
2 [||| 5.2%] Load average: 0.73 0.50 0.44
3 [||| 6.5%] Uptime: 32 days, 15:36:55
4 [| 1.3%]
Mem[|||||||||||||||||||4804/7698MB]
Swp[||| 659/7711MB]
PID USER PRI NI VIRT RES SHR S CPU% MEM% TIME+ Command
85784 mysql 20 0 3710M 1573M 5048 S 7.1 20.4 22h39:34 /usr/libexec/my
38544 root 20 0 3599M 326M 5616 S 3.9 4.2 2h46:03 /opt/java/bin/j
89473 root 20 0 117M 3672 1344 R 3.2 0.0 0:00.60 htop
38255 root 20 0 5777M 1625M 5700 S 2.6 21.1 11h44:07 /opt/java/bin/j
98476 mysql 20 0 3710M 1573M 5048 S 1.3 20.4 0:49.57 /usr/libexec/my
38368 root 20 0 5777M 1625M 5700 S 1.3 21.1 36:09.94 /opt/java/bin/j
98360 mysql 20 0 3710M 1573M 5048 S 1.3 20.4 2:13.94 /usr/libexec/my
85848 mysql 20 0 3710M 1573M 5048 S 1.3 20.4 47:13.88 /usr/libexec/
activemq log:
Код:
2014-04-21 18:10:26,039 | INFO | Usage Manager Memory Limit (134217728) reached on queue://BG.Event.ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingManageEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:37785@61616
2014-04-21 18:10:26,170 | INFO | Usage(default:memory:topic://BG.Event.ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent:memory) percentUsage=0%, usage=0, limit=134217728, percentUsageMinDelta=1%;Parent:Usage(default:memory) percentUsage=99%, usage=134216424, limit=134217728, percentUsageMinDelta=1%, Usage Manager memory limit reached for topic://BG.Event.ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Topic | ActiveMQ Transport: tcp:///127.0.0.1:37707@61616
2014-04-21 18:10:26,740 | INFO | Usage Manager Memory Limit (134217728) reached on queue://BG.Event.ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaConnectionCloseEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:37785@61616
2014-04-21 18:11:03,662 | INFO | Usage Manager Memory Limit (134217728) reached on queue://BG.Event.ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaAccountingEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:37707@61616
2014-04-21 18:12:33,569 | WARN | ignoring ack MessageAck {commandId = 1620917, responseRequired = false, ackType = 2, consumerId = ID:bgb.mynet.ru-34755-1397562407298-0:1:3:1, firstMessageId = ID:bgb.mynet.ru-45905-1397562512894-0:1:1:4:78975, lastMessageId = ID:bgb.mynet.ru-45905-1397562512894-0:1:1:4:78975, destination = queue://BG.Event.ru.bitel.bgbilling.modules.inet.accounting.event.InetAccountingManageEvent, transactionId = null, messageCount = 1, poisonCause = null}, for already expired message: Message ID:bgb.mynet.ru-45905-1397562512894-0:1:1:4:78975 dropped=true acked=true locked=false | org.apache.activemq.broker.region.QueueSubscription | ActiveMQ Transport: tcp:///127.0.0.1:37707@61616
2014-04-21 18:12:33,569 | INFO | Usage Manager Memory Limit (134217728) reached on temp-queue://ID:bgb.mynet.ru-45905-1397562512894-0:1:2. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:37707@61616
2014-04-21 18:15:30,415 | INFO | Usage Manager Memory Limit (134217728) reached on queue://BG.Event.ru.bitel.bgbilling.kernel.contract.balance.server.event.PaymentEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:38019@61616
2014-04-21 18:30:00,645 | INFO | Usage Manager Memory Limit (134217728) reached on queue://BG.Event.ru.bitel.bgbilling.modules.inet.access.sa.event.InetSaServModifyEvent. Producers will be throttled to the rate at which messages are removed from this destination to prevent flooding it. See http://activemq.apache.org/producer-flow-control.html for more info | org.apache.activemq.broker.region.Queue | ActiveMQ Transport: tcp:///127.0.0.1:57693@61616