BiTel

ID события: radius.wait.thread
Время регистрации события: 01.04.2015 00:00:17

В рамках отведенного переменными количества потоков threadCount=100 и размером очереди обработки maxQueueSize=500 RADIUS сервер не успеевает производить обработку аккаунтинг запросов.
Возможная причина - загруженность базы данных.

Radius:
  accounting-requests per minute start: 1; stop: 3; update: 1316
  access-requests per minute accept: 0; reject: 0
  ignore per minute access-request: 0; accounting-update: 0
Stack trace:

"MySQL Statement Cancellation Timer" Id=16163 TIMED_WAITING on java.util.TaskQueue@14703cca
        at java.lang.Object.wait(Native Method)
        -  waiting on java.util.TaskQueue@14703cca
        at java.util.TimerThread.mainLoop(Timer.java:552)
        at java.util.TimerThread.run(Timer.java:505)

connection 04-01/12:35:53 ERROR [sa-p-13-t-94] InetSaOptionsModifyEvent - Connection not found with id=474464
connection 04-01/12:58:48 ERROR [sa-p-13-t-93] InetSaStateModifyEvent - Connection not found with id=474983
connection 04-01/13:00:21 ERROR [sa-p-13-t-5] InetSaStateModifyEvent - Connection not found with id=472917
connection 04-01/14:14:46 ERROR [sa-p-13-t-83] InetSaStateModifyEvent - Connection not found with id=475217
connection 04-01/14:25:40 ERROR [sa-p-13-t-56] InetSaOptionsModifyEvent - Connection not found with id=472857
connection 04-01/14:30:15 ERROR [sa-p-13-t-88] InetSaStateModifyEvent - Connection not found with id=475268
connection 04-01/14:39:58 ERROR [sa-p-13-t-61] InetSaOptionsModifyEvent - Connection not found with id=472900
connection 04-01/14:45:20 ERROR [sa-p-13-t-21] InetSaOptionsModifyEvent - Connection not found with id=472873
connection 04-01/14:45:30 ERROR [sa-p-13-t-55] InetSaStateModifyEvent - Connection not found with id=472809
connection 04-01/15:14:35 ERROR [sa-p-13-t-63] InetSaStateModifyEvent - Connection not found with id=473131

./access_status.sh
Java Runtime: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM [1.7.0_65] /opt/java/jdk1.7.0_65/jre
  Java endorsed dirs: /lib/endorsed:/opt/java/jdk/lib/endorsed
  OS: Linux 3.2.0-4-amd64 [amd64], file.encoding: UTF-8, user.name: root
  Heap sizes: current=123392k  free=122080k  max=1824256k
Kernel version 6.1.1047 / 04.03.2015 19:50:23
Inet version 6.1.661 / 05.03.2015 19:12:18
Radius:
  accounting-requests per minute start: 0; stop: 0; update: 0
  access-requests per minute accept: 0; reject: 0
  ignore per minute access-request: 0; accounting-update: 0
Antispam ban count: 0; used per minute: 0

Started: 10.03.2015 10:32:30    Uptime: 22 d 03:36:40
Memory total: 192 413 696; max: 954 728 448; free: 8 268 840
Memory pools:
  Non-heap memory[Code Cache]: max: 50 331 648; used: 8 853 568; peek: 9 034 496
  Heap memory[PS Eden Space]: max: 357 040 128; used: 131 912; peek: 325 582 848
  Heap memory[PS Survivor Space]: max: 524 288; used: 163 840; peek: 119 009 248
  Heap memory[PS Old Gen]: max: 715 653 120; used: 183 852 032; peek: 554 713 168
  Non-heap memory[PS Perm Gen]: max: 85 983 232; used: 32 485 768; peek: 32 510 648
Thread count: 639
Trees in cache: 0
Connections pool to Master status Idle: 20; Active: 0; maxActive: 300; maxIdle: 20

./accounting_status.sh
Java Runtime: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM [1.7.0_65] /opt/java/jdk1.7.0_65/jre
  Java endorsed dirs: /lib/endorsed:/opt/java/jdk/lib/endorsed
  OS: Linux 3.2.0-4-amd64 [amd64], file.encoding: UTF-8, user.name: root
  Heap sizes: current=123392k  free=122736k  max=1824256k
Kernel version 6.1.1047 / 04.03.2015 19:50:23
Inet version 6.1.661 / 05.03.2015 19:12:18
Radius:
  accounting-requests per minute start: 3; stop: 0; update: 1339
  access-requests per minute accept: 0; reject: 0
  ignore per minute access-request: 0; accounting-update: 0

Started: 10.03.2015 10:32:37    Uptime: 22 d 03:53:55
Memory total: 103 809 024; max: 954 728 448; free: 32 674 936
Memory pools:
  Non-heap memory[Code Cache]: max: 50 331 648; used: 9 043 072; peek: 9 053 568
  Heap memory[PS Eden Space]: max: 357 040 128; used: 12 168 512; peek: 328 728 576
  Heap memory[PS Survivor Space]: max: 524 288; used: 332 408; peek: 14 664 128
  Heap memory[PS Old Gen]: max: 715 653 120; used: 58 639 040; peek: 90 872 320
  Non-heap memory[PS Perm Gen]: max: 85 983 232; used: 32 590 704; peek: 32 608 448
Thread count: 159
Trees in cache: 0
Connections pool to Master status Idle: 20; Active: 1; maxActive: 300; maxIdle: 20

./mysqltuner.pl
-------- General Statistics --------------------------------------------------
[--] Skipped version check for MySQLTuner script
[OK] Currently running supported MySQL version 5.5.41-0+wheezy1-log
[OK] Operating on 64-bit architecture

-------- Storage Engine Statistics -------------------------------------------
[--] Status: +Archive -BDB -Federated +InnoDB -ISAM -NDBCluster
[--] Data in InnoDB tables: 2G (Tables: 581)
[--] Data in PERFORMANCE_SCHEMA tables: 0B (Tables: 17)
[!!] Total fragmented tables: 75

-------- Security Recommendations  -------------------------------------------
[OK] All database users have passwords assigned

-------- Performance Metrics -------------------------------------------------
[--] Up for: 1d 4h 26m 18s (18M q [177.006 qps], 16K conn, TX: 3B, RX: 2B)
[--] Reads / Writes: 6% / 94%
[--] Total buffers: 3.1G global + 2.7M per thread (500 max threads)
[OK] Maximum possible memory usage: 4.4G (56% of installed RAM)
[OK] Slow queries: 0% (11K/18M)
[OK] Highest usage of available connections: 32% (162/500)
[OK] Key buffer size / total MyISAM indexes: 16.0M/97.0K
[OK] Key buffer hit rate: 100.0% (76K cached / 0 reads)
[OK] Query cache efficiency: 89.9% (5M cached / 6M selects)
[OK] Query cache prunes per day: 0
[OK] Sorts requiring temporary tables: 0% (0 temp sorts / 67K sorts)
[OK] Temporary tables created on disk: 1% (151 on disk / 13K total)
[OK] Thread cache hit rate: 97% (365 created / 16K connections)
[!!] Table cache hit rate: 17% (640 open / 3K opened)
[OK] Open file limit used: 0% (49/32K)
[OK] Table locks acquired immediately: 100% (72M immediate / 72M locks)
[OK] InnoDB data size / buffer pool: 2.2G/3.0G

-------- Recommendations -----------------------------------------------------
General recommendations:
    Run OPTIMIZE TABLE to defragment tables for better performance
    Increase table_cache gradually to avoid file descriptor limits
Variables to adjust:
    table_cache (> 4096)

  Сервер: вер. 6.1.1047 / 04.03.2015 19:50:23
    os: Linux; java: Java HotSpot(TM) 64-Bit Server VM, v.1.7.0_65

  card: вер. 6.1.204 / 04.03.2015 19:50:22
  inet: вер. 6.1.661 / 05.03.2015 19:12:18
  npay: вер. 6.1.184 / 11.02.2015 04:02:21
  reports: вер. 6.1.196 / 08.02.2015 20:45:22
  subscription: вер. 6.1.30 / 08.02.2015 20:45:31

/opt/apache-activemq-5.9.1/data/kahadb# ls -l
total 12772
-rw-r--r-- 1 root root 33030144 Apr  1 16:02 db-2642.log
-rw-r--r-- 1 root root  5763072 Apr  1 16:02 db.data
-rw-r--r-- 1 root root   931600 Apr  1 16:02 db.redo
-rw-r--r-- 1 root root        0 Feb 10 18:39 lock

connection 04-01/15:14:35 ERROR [sa-p-13-t-63] InetSaStateModifyEvent - Connection not found with id=473131

mysql> select * from inet_session_log_2_201504 where connectionId=473131;
+--------+----------+------------+--------------+--------------------+----------+------------+---------------+----------------------+--------------+-------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+---------------------+---------------------+---------------------+-------------+---------------+-------------+-------------+--------+
| id     | parentId | splittedId | connectionId | parentConnectionId | deviceId | devicePort | agentDeviceId | acctSessionId        | username     | realm | type | accessCode | servId | calledStationId | callingStationId | ipResourceId | ipAddress | connectionStart     | sessionStart        | sessionStop         | lastActive          | deviceState | deviceOptions | sessionTime | sessionCost | status |
+--------+----------+------------+--------------+--------------------+----------+------------+---------------+----------------------+--------------+-------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+---------------------+---------------------+---------------------+-------------+---------------+-------------+-------------+--------+
| 779424 |        0 |          0 |       473131 |                  0 |        2 |  162462877 |             0 | 15/0/1/1001_09AEFC9D | 109.XXX.49.8 | NULL  |   40 |          0 |    415 |                 | E8DE27503CF7     |           -1 | m      | 2015-04-01 00:05:31 | 2015-04-01 00:05:31 | 2015-04-01 15:14:32 | 2015-04-01 15:13:46 |           0 |               |       54542 |     0.00000 |      4 |
| 782399 |        0 |     779424 |       473131 |                  0 |        2 |  162462877 |             0 | 15/0/1/1001_09AEFC9D | 109.XXX.49.8 | NULL  |   42 |          0 |    415 |                 | E8DE27503CF7     |           -1 | m      | 2015-04-01 00:05:31 | 2015-04-01 15:14:33 | 2015-04-01 15:14:32 | 2015-04-01 15:14:48 |           1 |               |           0 |     0.00000 |      4 |
+--------+----------+------------+--------------+--------------------+----------+------------+---------------+----------------------+--------------+-------+------+------------+--------+-----------------+------------------+--------------+-----------+---------------------+---------------------+---------------------+---------------------+-------------+---------------+-------------+-------------+--------+

all.log:accounting 04-01/17:18:07  INFO [accwrkr-2-p-11-t-1] SessionFlushingWorker - Flushed 500 sessions for 1214(1207) ms.
all.log:accounting 04-01/17:18:28  INFO [accwrkr-2-p-11-t-1] SessionFlushingWorker - Flushed 500 sessions for 1185(1181) ms.
all.log:accounting 04-01/17:18:49  INFO [accwrkr-2-p-11-t-1] SessionFlushingWorker - Flushed 500 sessions for 1119(1116) ms.
all.log:accounting 04-01/17:19:10  INFO [accwrkr-2-p-11-t-1] SessionFlushingWorker - Flushed 471 sessions for 1034(1029) ms.

connection 04-01/21:21:22 ERROR [sa-p-13-t-54] InetSaStateModifyEvent - Connection not found with id=475988
connection 04-01/21:21:27 ERROR [sa-p-13-t-63] InetSaStateModifyEvent - Connection not found with id=475988
connection 04-02/00:33:29 ERROR [sa-p-13-t-80] InetSaStateModifyEvent - Connection not found with id=477104
connection 04-02/00:33:36 ERROR [sa-p-13-t-83] InetSaStateModifyEvent - Connection not found with id=477104
connection 04-02/00:33:47 ERROR [sa-p-13-t-17] InetSaStateModifyEvent - Connection not found with id=477104

ID события: db.master.connect.error
Время регистрации события: 02.04.2015 08:54:25


Необходимо срочно восстановить соединение с Master базой.

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
        at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1116)
        at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:344)
        at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2332)
        at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2369)
        at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2153)
        at com.mysql.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:792)
        at com.mysql.jdbc.JDBC4Connection.<init>(JDBC4Connection.java:47)
        at sun.reflect.GeneratedConstructorAccessor46.newInstance(Unknown Source)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
        at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:381)
        at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:305)
        at java.sql.DriverManager.getConnection(DriverManager.java:571)
        at java.sql.DriverManager.getConnection(DriverManager.java:215)
        at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:75)
        at ru.bitel.bgbilling.server.util.DefaultServerSetup$2.makeObject(DefaultServerSetup.java:376)
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1188)
        at ru.bitel.bgbilling.server.util.DatabaseConnectionPool$1.getConnection(DatabaseConnectionPool.java:30)
        at ru.bitel.bgbilling.server.util.DefaultServerSetup.getDBConnectionFromPool(DefaultServerSetup.java:572)
        at ru.bitel.bgbilling.modules.inet.access.OldConnectionsRemover.run(OldConnectionsRemover.java:30)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:304)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:178)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
        at ru.bitel.common.worker.WorkerThread.run(WorkerThread.java:46)
Caused by: java.net.SocketTimeoutException: connect timed out
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339)
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200)
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
        at java.net.Socket.connect(Socket.java:579)
        at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:606)
        at com.mysql.jdbc.StandardSocketFactory.connect(StandardSocketFactory.java:330)
        at com.mysql.jdbc.MysqlIO.<init>(MysqlIO.java:294)
        ... 27 more