|
程序升级正常之后，过了一天发现程序到了12点之后异常的慢，用户不能访问，然后使用ssh远程登录发现很慢，操作简单的shell命令都卡几秒。 使用top命令查看cpu、内存使用资源，没有发现tomcat异常，只是mongodbcpu高，mongodb平时也很高，mongodb不能说明问题。 1、强制将tomcat重启。 怪异现象tomcat停止后，重新启动的时候很慢。大约过了30分钟之后tomcat才启动成功。 也就是说明tomcat启动的时候哪里出现问题了？？？ 2、查看tomcat日志发现数据库连接占满，再次获取连接的时候报错 这次过去之后，查看了一些日志就是发现获取不到数据库连接。数据库连接池最大数设置的是100，连接池的数量按理说应该足够了。难道是程序哪里没有释放掉数据库连接，一直占有者？？ 昨天程序升级了一次代码，难道是程序哪里隐藏着陷进？？？ 简单解决：100个连接不够，设置成200个。 时间过去了...第二天中午12点程序再次慢了下来，远程访问网站失败。 3、使用top命令查看到tomcat的线程id，然后使用jstack -l 24999 > 24999.stack，打印当前tomcat的栈信息，再使用jmap命令打印当前tomcat内存对象信息。 查看jmap信息中数据库连接的对象，连接对象显示的也不正常啊。 #instances #bytesClass description 16431853304com.mysql.jdbc.JDBC4Connection 607353887040com.mysql.jdbc.ConnectionPropertiesImpl$StringConnectionProperty 459683309696com.mysql.jdbc.ConnectionPropertiesImpl$IntegerConnectionProperty 4928394240com.mysql.jdbc.ConnectionPropertiesImpl$MemorySizeConnectionProperty 1641118152com.mysql.jdbc.ConnectionPropertiesImpl$LongConnectionProperty 147759080com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException 164052480com.mysql.jdbc.JDBC4DatabaseMetaData 13933360com.mysql.jdbc.MysqlIO 164026240com.mysql.jdbc.log.StandardLogger 1393336com.mysql.jdbc.StandardSocketFactory 116com.mysql.jdbc.Driver 1176com.mysql.jdbc.JDBC4ResultSet 4 再次查看的tomcat日志发现，请求日志处理保存的时候activemq生产者报错。 "http-8080-200" daemon prio=10 tid=0x00007f67e1920800 nid=0x7d27 waiting for monitor entry [0x00007f67be764000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.activemq.ActiveMQSession.send(ActiveMQSession.java:1752) - waiting to lock <0x000000066139ccb8> (a java.lang.Object) at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:289) at org.apache.activemq.ActiveMQMessageProducer.send(ActiveMQMessageProducer.java:224) at org.apache.activemq.ActiveMQMessageProducerSupport.send(ActiveMQMessageProducerSupport.java:241) at com.doeis.utils.mq.ActiveMqManage.sendAccessLog(ActiveMqManage.java:452) 再次一查发现有200个同样的错误htpp-8080-0 到http-8080-200,一共201个同样的错误，我们的数据库连接池设置的是200，那说明确实数据库连接池消费完了。问题来了，为什么这201个线程没有释放数据库链接呢？？ activeMQ生产者怎么没有返回，一直卡在某一个地方，activeMQ send消息一路跟踪下去，发现最后ActiveMQSession中send（）方法在获取一把锁的地方卡着，为什么在这卡着呢？？
继续查看日志发现另一个ActiveMQ错误信息：ActiveMQ BrokerService 也在等待获取锁，这是为什么，ActiveMQ都在等待获取锁？？难道是消费者有问题？？？ "ActiveMQ BrokerService[doeisBroker] Task-855" daemon prio=10 tid=0x00007f67e624f000 nid=0x3b6 waiting for monitor entry [0x00007f67beb6a000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.activemq.broker.region.PrefetchSubscription.dispatchPending(PrefetchSubscription.java:653) - waiting to lock <0x0000000661e346e0> (a java.lang.Object) - locked <0x00000006614ff020> (a java.lang.Object) at org.apache.activemq.broker.region.PrefetchSubscription.add(PrefetchSubscription.java:161) at org.apache.activemq.broker.region.Queue.doActualDispatch(Queue.java:1998) at org.apache.activemq.broker.region.Queue.doDispatch(Queue.java:1946) at org.apache.activemq.broker.region.Queue.pageInMessages(Queue.java:2086) at org.apache.activemq.broker.region.Queue.iterate(Queue.java:1581) - locked <0x0000000660f3e080> (a java.lang.Object) at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:129) at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:47) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) 简单解决：ActiveMQ底层没有研究过，一时想不清为什么？准备把最近修改的代码还原回去。 代码还原回去后.... 等待12点是否还能tomca慢... 5、查看nginx请求日志记录,发现有一些非法请求，请求了一些常见漏洞的接口。 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /docs/ HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /User/Login.aspx HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /License.txt HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /API/DW/Dwplugin/TemplateManage/manage_site.htm HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /API/DW/Dwplugin/TemplateManage/save_template.htm HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /API/DW/Dwplugin/ThirdPartyTags/SiteFactory.xml HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Admin/Common/HelpLinks.xml HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /API/DW/Dwplugin/TemplateManage/login_site.htm HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /API/DW/Dwplugin/SystemLabel/SiteConfig.htm HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Admin/Login.aspx HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Admin/Images/LoginImages/admin_text.gif HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Template/Default/Skin/user/images/login_back.jpg HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Prompt/images/P_Wrong.gif HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /Admin/Images/LoginImages/admin_top.gif HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /cms/ HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" 183.60.244.30 - - [20/Nov/2015:12:20:08 +0800] "GET /cms/ HTTP/1.1" 404 570 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_9_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/36.0.1985.125 Safari/537.36" "-" .... 解决办法：使用nginx禁止掉这些国外的非法ip，再使用nginx过滤掉一些常见的非法请求 6、查看tomcat日志发现too many open files 严重: Socket accept failed java.net.SocketException: Too many open files at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408) at java.net.ServerSocket.implAccept(ServerSocket.java:462) at java.net.ServerSocket.accept(ServerSocket.java:430) at org.apache.tomcat.util.net.DefaultServerSocketFactory.acceptSocket(DefaultServerSocketFactory.java:61) at org.apache.tomcat.util.net.JIoEndpoint$Acceptor.run(JIoEndpoint.java:352) at java.lang.Thread.run(Thread.java:662) 2015-11-20 12:57:52 org.apache.tomcat.util.net.JIoEndpoint$Acceptor run too many open files问题是程序打开的文件/socket连接数量超过系统设定值， （1）看每个用户最大允许打开文件数量ulimit -a core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 20 file size (blocks, -f) unlimited pending signals (-i) 16382 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 1024 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) unlimited virtual memory (kbytes, -v) unlimited file locks (-x) unlimited 其中 open files (-n) 1024 表示每个用户最大允许打开的文件数量是1024 （2）查看当前系统打开的文件数量 lsof | wc -l watch "lsof | wc -l" （3）查看某一进程的打开文件数量 lsof -p 1234 | wc -l 解决办法：修改open files 最大数量。 网上普遍解决方法：（1）ulimit -n 2048 当前用户的最大允许打开文件数量设置为2048 （2）在 /etc/security/limits.conf 加入 * soft nofile 4096 * 表示所有用户 * hard nofile 4096 但是上面的方法设置open files失败，tomcat还是会报错too many open files 正确的方法是：（1）打开/etc/init.d/tomcat文件 （2）在start命令后面增加 ulimit -f unlimited ulimit -t unlimited ulimit -v unlimited ulimit -n 64000 ulimit -m unlimited # In dash, ulimit takes -p for maximum user processes # In ba**'s -u if readlink /proc/$$/exe | grep -q dash then ulimit -p 32000 else ulimit -u 32000 fi 如下：：： ... case "$1" in start) if [ -z "$JAVA_HOME" ]; then log_failure_msg "no JDK found - please set JAVA_HOME" exit 1 fi if [ ! -d "$CATALINA_BASE/conf" ]; then log_failure_msg "invalid CATALINA_BASE: $CATALINA_BASE" exit 1 fi ulimit -f unlimited ulimit -t unlimited ulimit -v unlimited ulimit -n 64000 ulimit -m unlimited # In dash, ulimit takes -p for maximum user processes # In bash, it's -u if readlink /proc/$$/exe | grep -q dash then ulimit -p 32000 else ulimit -u 32000 fi log_daemon_msg "Starting $DESC" "$NAME" if start-stop-daemon --test --start --pidfile "$CATALINA_PID" \ --user $TOMCAT6_USER --exec "$JAVA_HOME/bin/java" \ >/dev/null; then .... （3）解决了tomcat的too many open files问题 7、tomcat的too many open files问题解决了，但是发现12点还是会慢。 这次监控tomcat、nginx日志没有打印任何请求，也就是说机器根本没有接受到请求。为什么呢？？难道是网络堵塞了？？？查看了外网流量图没有发现异常，那是哪里出现了问题呢？？？ 为什么每次慢都是12点多呢？？？查看了程序定时任务和系统crontab任务，没有发现12点执行的任务啊。使用top，命令查看到了一个线程rsync远程备份，登陆到备份机器看到了一个12点多执行的rsync远程备份任务，需要备份的文件很大，文件数量也很多（600个）。到此原因找到了：（1）远程备份的时候占用了大量open files，导致tomcat那边不够用了（2）备份占用了大量open files导致activeMQ生产者和消费者一直获取不到文件，导致一直释放不了锁，大量请求都堆积到一起（3）备份的文件量比较大，是局域网网络占满，导致外网请求堵塞。 |
