IMXYLZ

健康

| Comments

晚上收到了上周体检的报告单,手机APP打开查看, 原来我已经有了众多问题。

  • 2013年的体检,没有一个异常
  • 2015年的体检,有两个异常
  • 2016年的体检,居然有九个异常

不知不觉中,身体状况竟如此低下,原来我已经处于“非常”不健康的地步了。

总结起来有几个问题:

  • 体验严重超标了,至少需要减少10kg
  • 睡眠不好,身体长期处于疲劳状态,多种指标超标
  • 运动过少,身体机能低下,多种血液细胞浓度过高
  • 喝水太少,多种酶和器官都处于缺水状态
  • 吃肉太多,吃蔬菜太少,影响微量元素和酶

很显然以后得学会控制自己,不仅仅是饮食、运动、休息,还有情绪。

自从加入创业公司后身心俱疲,明显感觉到身体大不如从前,高强度的工作 导致亚健康问题越来越严重。经常一下午坐在座位上低头工作,有时候一天 只喝一杯水。一直以为自己还很年轻,这些问题都不是问题,可见从思想上 并没有重视起来。

当前,想一下子改变也很困难,至少需要在战略上重视起来,有所行动。

一次程序宕机的辛酸追寻之路

| Comments

【前言】 如果你是工程师,你能够从下面的过程中学习到众多技能、思路和解决问题的办法,当然顺便鄙视下[前任]工程师; 如果你是测试工程师,你会发现很多问题是我们难以模拟和测试的,更困难的是我们很难想到这些问题,当然顺便羞辱下[提测]工程师; 如果你是管理者,你会想到代码检查/复查/重构是多么的重要,更重要的是要有思想上的觉悟,当然顺便体谅下[加班]工程师; 如果你是运维工程师,我想说“事出必有因”,即使寻找问题的道路很艰难和痛苦,更无人知晓,但[千万别放弃]; ……不想夸张了……

【开篇上】大约[15:00]

云X来找我说管理后台宕机了[admin-web],没找到原因,主服务机器sky1重启了,备机db1还不能正常提供服务。 通常遇到这种情况,Java程序的标准做法是:

  • jstat 查询内存使用率 –> 正常
  • jstack 查询线程栈状况 –> 大约正常,只有一个看起来像是错误的问题
  • jmap 查看内存状况 –> 正常
  • log4j日志文件 –> 基本正常(事实上不正常,只是未发现)
  • gc日志文件 –> 备机看到一堆内存分配失败
  • sql记录文件 –> 正常
  • jetty的日志文件 –> 大致正常

这时候一般会比较灰心,因为已经没有主机的现场了,如果没有发现明显的错误,一般是比较崩溃的, 找问题也是比较艰辛的。

云X还怀疑是机房的问题。我通过

curl –I 'http://127.0.0.1:8082' -H 'Host:c.xxx.com'

发现有时候好,有时候坏,就觉得莫名其妙了。 不过既然有时候坏,说明不是网络和机器问题,剩下的只是程序问题。

这时候只能将日志文件一行行看了,尤其是SQL文件,Log4j日志等,但收获有限。

【开篇下】大约[15:20]

再次说明下,我们有两台机器,主机器sky1 和 被机器 db1。 由于主机器sky1上的服务已经重启,所以内存状况,线程状况,gc状态都不在了, 虽然有一个当时的线程栈文件,但没有提供更多有用的线索。

现在有用的信息只能从各自日志文件中寻找了。 通过不断尝试,终于在log4j的日志文件中找到我们想要的关键字了:

org.springframework.web.util.NestedServletException: Handler processing failed; nested exception is java.lang.OutOfMemoryError: Java heap space
java.lang.RuntimeException: OOME with size 8
01-08 12:25:41:ERROR(32)qtp1690254271-21 ExceptionHandler -
org.eclipse.jetty.io.EofException
Caused by: java.io.IOException: 断开的管道

OOME,java.lang.OutOfMemoryError,最常见也是较难以处理的程序错误。 OOME 以后,很多程序的内存状态都不能很好恢复,比如jetty的连接就不能很好释放,所以会导致一部分死锁卡住。

这时候云X说是不是行程加载数据太多,导致内存用光了。

我把当前的内存栈都拿出来看看,【行程类】并没有发现异常,其它几个机器也看了下,都挺正常的。 也没有找到有用的线索。

事实上经过几次重构,现在【行程类】加载内存已经控制在一个合理的范围内了,对于1G以上的内存一般不会用满。 由于准A项目还有很多开发任务,我已经没有耐心继续跟进下去了,准备下次遇到的时候我再去抓现场。

中间还有一些修改nginx配置,减少一些日志干扰等事情,由于后来发现和问题无关,这里就不表了。

这样就送走了云X。

【中篇上】大约[15:40]

过了一会,发现无法从刚才问题中恢复思路,所以还是想想到底是什么原因引起的。 继续追寻之路,事实上后面才是更痛苦的。

既然知道是OOM,那么很显然一定会有内存慢慢变化的过程。 主机器sky1服务重启了,备机器db1还在,

sky1机器上admin-web.gc.0.default 还保留着信息,首先当然是先备份此文件。 慢慢看。

下图是查找问题的过程,一直到最后发现想要的结果。

bugway

事后看来这张图很有价值,只是当时深陷其中,没有很深入的思考。 首先可以看到db1这台机器上11:58:38 有请求,很正常,内存申请1024M,GC回收766M,还有285M 紧接着下一个请求是 12:20:54 ,内存由1024释放到604 从12:20:56 开始,内存申请和占用持续增加,一直到 12:21:19 终于无法释放Failure失败了 由此可见,大约内存从12:20:56 开始慢慢增加一直到 12:25:41 最终彻底OOM 由于GC释放是一个滞后反应,所以日志中最终的结果是延后几分钟才奔溃:

01-08 12:25:41:ERROR(462)auditor_db1-1452149957746-633919db_watcher_executor ZookeeperConsumerConnector - error during syncedRebalance
java.lang.OutOfMemoryError: Java heap space

另外sky1机器上的日志有一些帮助(当时没发现),但更多的是干扰作用,比如:

01-08 12:17:29:INFO(41)runnerutils-1-thread-11 AppPushMsgUtil - push app message to :184180msg:{"push-data-type":"task-msg","alert":"有新任务啦!英国专属超级自由行快去抢吧","url":"http://m.xxx.com/task/list/"},cost time:20,resp:{"code":0,"msg":"发送消息成功"}
01-08 12:17:29:INFO(41)runnerutils-1-thread-11 AppPushMsgUtil - push app message to :52065msg:{"push-data-type":"task-msg","alert":"有新任务啦!英国专属超级自由行快去抢吧","url":"http://m.xxx.com/task/list/"},cost time:30,resp:{"code":0,"msg":"发送消息成功"}
01-08 12:17:30:INFO(41)runnerutils-1-thread-11 AppPushMsgUtil - push app message to :149669msg:{"push-data-type":"task-msg","alert":"有新任务啦!英国专属超级自由行快去抢吧","url":"http://m.xxx.com/task/list/"},cost time:34,resp:{"code":0,"msg":"发送消息成功"}
01-08 12:17:30:INFO(41)runnerutils-1-thread-11 AppPushMsgUtil - push app message to :32358msg:{"push-data-type":"task-msg","alert":"有新任务啦!英国专属超级自由行快去抢吧","url":"http://m.xxx.com/task/list/"},cost time:19,resp:{"code":0,"msg":"发送消息成功"}
01-08 12:17:30:INFO(41)runnerutils-1-thread-11 AppPushMsgUtil - push app message to :32358msg:{"push-data-type":"task-msg","alert":"有新任务啦!英国专属超级自由行快去抢吧","url":"http://m.xxx.com/task/list/"},cost time:19,resp:{"code":0,"msg":"发送消息成功"}
01-08 12:19:52:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:19:54:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (SyncConnected)
01-08 12:20:05:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:20:16:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Expired)
01-08 12:20:16:INFO(324)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - ZK expired; release old list of broker partitions for topics
01-08 12:20:16:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (SyncConnected)
01-08 12:20:16:INFO(169)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - read all brokers count: 2
01-08 12:20:16:INFO(174)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - Loading Broker 1.1.7.138-1426676227549:1.1.7.138:9092:true
01-08 12:20:16:INFO(174)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - Loading Broker 1.1.7.85-1426677889450:1.1.7.85:9092:true
01-08 12:20:26:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:20:35:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Expired)
01-08 12:20:35:INFO(324)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - ZK expired; release old list of broker partitions for topics
01-08 12:20:35:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (SyncConnected)
01-08 12:20:35:INFO(169)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - read all brokers count: 2
01-08 12:20:35:INFO(174)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - Loading Broker 1.1.7.138-1426676227549:1.1.7.138:9092:true
01-08 12:20:35:INFO(174)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - Loading Broker 1.1.7.85-1426677889450:1.1.7.85:9092:true
01-08 12:20:52:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:21:01:INFO(381)qtp1690254271-24-EventThread ZkClient - zookeeper state changed (Expired)
01-08 12:21:10:INFO(324)ZkClient-EventThread-4632-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181/xpower/jafka ZKBrokerPartitionInfo - ZK expired; release old list of broker partitions for topics
01-08 12:22:13:INFO(381)admin-consumers-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:23:03:INFO(381)admin-consumers-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:23:17:INFO(381)Thread-22-EventThread ZkClient - zookeeper state changed (Disconnected)
01-08 12:23:17:INFO(381)Thread-22-EventThread ZkClient - zookeeper state changed (Expired)
01-08 12:33:55:INFO(461)main DispatcherServlet - FrameworkServlet 'servlet': initialization started
01-08 12:33:55:INFO(513)main XmlWebApplicationContext - Refreshing WebApplicationContext for namespace 'servlet-servlet': startup date [Fri Jan 08 12:33:55 CST 2016]; root of context hierarchy
01-08 12:33:55:INFO(316)main XmlBeanDefinitionReader - Loading XML bean definitions from ServletContext resource [/WEB-INF/servlet-context.xml]
01-08 12:33:56:INFO(316)main XmlBeanDefinitionReader - Loading XML bean definitions from ServletContext resource [/WEB-INF/spring-quartz.xml]
01-08 12:33:57:INFO(69)ZkClient-EventThread-30-1.1.7.138:2181,1.1.8.231:2181,1.1.7.85:2181 ZkEventThread - Starting ZkClient event thread.
01-08 12:33:57:INFO(381)main-EventThread ZkClient - zookeeper state changed (SyncConnected)

AppPushMsgUtil有一些干扰效果,查看代码并没有发现问题,当然最后也是不因为此引起的。 ZkClient的日志从12:19:52前就不正常,一直到12:33:55重启都没能恢复过来,所以看起来系统应该是从12:19:52开始出问题的。

这时候剩下没有关注的日志只有nginx的access_log和error_log了,我们去看看。

从front1/front2开始,最终我们在front1的日志中发现一条异常日志:

2016/01/08 12:21:19 [error] 2103#0: *3529201742 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 10.255.252.2, server: c.xxx.com, request: "GET /privacy/crm/user/?uid=%7Bxxxx HTTP/1.1", upstream: "http://1.1.19.158:8082/privacy/crm/user/?uid=%7Bxxxx", host: "c.xxx.com"

有意思的是日志中的时间是12:21:19,和我猜想的错误时间 12:19:52不大一致,有点矛盾。 access_log 中12点左右的日志异常是:

[root@front1 tmp]# awk '{if($(NF-5)>0.1){print $0}}' /opt/logs/nginx/c.admin.access.log
"124.65.117.214" c.xxx.com - [08/Jan/2016:12:24:34 +0800] "GET /pack/update-coop-info/?packageId=1256 HTTP/1.1" 502 0 "-" "Mozilla/5.0 (Windows NT 6.3; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.63 Safari/537.36" "10.255.252.2" "240.002" "120.001, 120.001 : 0.000" "1.1.19.158:8082, 1.1.6.125:8082 : admin-web" - - 974d45ccbfa8668acf8574a530c81427-sA sA
"114.242.69.123" c.xxx.com - [08/Jan/2016:12:25:41 +0800] "GET /privacy/crm/user/?uid=%7Bxxxx HTTP/1.1" 504 0 "-" "Mozilla/5.0 (Macintxxh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36" "10.255.252.2" "382.022" "120.002, 120.001 : 120.000, 22.019" "1.1.19.158:8082, 1.1.6.125:8082 : 1.1.19.158:8082, 1.1.6.125:8082" - - 69b8c0ab86bac34202b3aaafe3a61ee6-63Z 63Z
"124.65.117.214" c.xxx.com - [08/Jan/2016:12:26:04 +0800] "GET /advisor/1016657/?ref=sales HTTP/1.1" 502 0 "-" "Mozilla/5.0 (Macintxxh; Intel Mac OS X 10_10_3) AppleWebKit/600.5.17 (KHTML, like Gecko) Version/8.0.5 Safari/600.5.17" "10.255.252.2" "240.002" "120.001, 0.000 : 120.001, 0.000" "1.1.19.158:8082, admin-web : 1.1.19.158:8082, admin-web" - - 48829b80937282485a9355500243730a-IKT IKT

时间都是在12:25分附近,这很奇怪。 但看到用户登录,并且有IP,就随机查询一个看看。当时查询的是:114.242.69.123。 结果让我很兴奋 [这玩意儿真NB]。

bugway

既然是同事,那么我就看看是谁,然后收集些信息。 bugway 查询下后台: bugway 发现居然是Rxx,于是就问问他,以下是对话:

我  16:02:51
"114.242.69.123" c.xxx.com - [08/Jan/2016:12:25:41 +0800] "GET /privacy/crm/user/?uid=%7Bxxxx HTTP/1.1" 504 0 "-" "Mozilla/5.0 (Macintxxh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36" "10.255.252.2" "382.022" "120.002, 120.001 : 120.000, 22.019" "1.1.19.158:8082, 1.1.6.125:8082 : 1.1.19.158:8082, 1.1.6.125:8082" - - 69b8c0ab86bac34202b3aaafe3a61ee6-63Z 63Z
我  16:03:03
中文12:25 是你访问的?        [中文应当是中午,手误]
张Sir  16:03:28
是,jordan给我发的链接
张Sir  16:03:53
有问题?
我  16:03:56
然后你访问下 把我们机器搞死啦?
我  16:04:02
当时应该是打不开吧?
张Sir  16:04:01
啊?
张Sir  16:04:10
是啊
张Sir  16:04:19
我还以为网挂了
张Sir  16:05:00

bugway

张Sir  16:05:11
是个坑吗?
我  16:06:49
不知道 但是第一个错误 确实是从这里开始的
张Sir  16:07:27
{}嵌套了吗?
张Sir  16:08:12
好怕啊,我需要畏罪潜逃吗?
我  16:09:16
其实我没找到原因
张Sir  16:11:06
uid参数不识别除了int 以外的类型?
张Sir  16:28:51
我想起来了,当时是这样
张Sir  16:31:29
以前点过这个链接,并没问题。后来,mars用他账号在我电脑登录CRM查了些别的,后来我又点这个链接,但是进入了登录页面。用我账号登录后自动重定向到这个链接,然后挂了。后来我点开新的窗口进,就正常了
我  16:33:34
不懂 好神奇啊
张Sir  16:34:37
情况就是,换了俩账号点这个链接,前一个是没权限的,后一个被重定向过来的
张Sir  16:35:05
我如果不潜逃,是不是可以得查BUG大奖?
我  16:35:33
如果你能帮助找到bug 可得之
张Sir  16:35:57
听上去,还是得潜逃
张Sir  16:38:29
估计是uid={XXX}这个,程序并没有校验
我  16:42:31
我看了代码 这个参数有处理
我  16:42:45
其实我想说的是 出问题的时候居然刚好是你访问的时候 太巧合了
张Sir  16:46:13
阴差阳错啊

我看了代码,事实上RequestUtils.geInt函数是我写的,因此并不会导致问题,更不会导致OOM。

bugway

没有得到我想要的答案,我继续陷于了深深的沉思中。

事实上,我已经准备放弃了。

【中篇下】[大约16:50分]

就在我准备放弃的时候,我灵机一想,如果是OOM,要么是定时任务,要么是数据库读取数据太多(这个比较常见,因为只有数据库中才有那么多的数据)。 定时任务看不到,数据库访问的sql.log文件中没有,会不会是某个人使用《事务》操作Connection导致的呢?

因为操作Connection 我并不能拿到执行的SQL语句,所以通常不知道执行时间,sql.log中当然不会有。 但我想到了mysql.slowlog. 于是去数据库中查询。

mysql> select * from slow_log where start_time > '2016-01-08 11:30' limit 10\G
*************************** 1. row ***************************
    start_time: 2016-01-08 12:05:19
     user_host: messaging[messaging] @  [1.1.19.158]
    query_time: 00:00:11
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 1727769
            db: messaging
last_insert_id: 0
     insert_id: 0
     server_id: 168166858
      sql_text: SELECT count(*) FROM message WHERE 1 and sender = 277376
*************************** 2. row ***************************
    start_time: 2016-01-08 12:19:42
     user_host: txx[txx] @  [1.1.19.158]
    query_time: 00:00:22
     lock_time: 00:00:00
     rows_sent: 1756890
 rows_examined: 1756890
            db: compass
last_insert_id: 0
     insert_id: 0
     server_id: 168166858
      sql_text: select * from advisor_travel_session where uid=0 order by created_at desc
*************************** 3. row ***************************
    start_time: 2016-01-08 12:19:42
     user_host: txx[txx] @  [1.1.19.158]
    query_time: 00:00:49
     lock_time: 00:00:00
     rows_sent: 1756890
 rows_examined: 1756890
            db: compass
last_insert_id: 0
     insert_id: 0
     server_id: 168166858
      sql_text: select * from advisor_travel_session where uid=0 order by created_at desc
*************************** 4. row ***************************
    start_time: 2016-01-08 12:21:08
     user_host: txx[txx] @  [1.1.6.125]
    query_time: 00:00:15
     lock_time: 00:00:00
     rows_sent: 1756898
 rows_examined: 1756898
            db: compass
last_insert_id: 0
     insert_id: 0
     server_id: 168166858
      sql_text: select * from advisor_travel_session where uid=0 order by created_at desc
*************************** 5. row ***************************
    start_time: 2016-01-08 12:25:03
     user_host: txx[txx] @  [1.1.6.125]
    query_time: 00:03:44
     lock_time: 00:00:00
     rows_sent: 227487
 rows_examined: 227487
            db: compass
last_insert_id: 0
     insert_id: 0
     server_id: 168166858
      sql_text: select * from advisor_travel_session where uid=0 order by created_at desc

看到 rows_sent: 1756890 这一行我就什么都明白了,什么都明白了,都明白了,明白了,白了,了……

网站允许游客提小帮手,由于没有登录,所以用户uid=0,而我们去查一个用户uid=0的小帮手,结果帮3年累计的小帮手全查出来了。 数据有175万啊,兄弟姐妹们,175万啊。 这是什么概念?将近一千万啊,一千万数据放内存中,能不爆么? 关键是还查询了4次,4次是什么概念? 4次我都有 杀死 [前任] 程序员的冲动!!!

当然很兴奋的和Roy同学说了。

我  16:52:01
我靠,还真是你引起的!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
张Sir  16:52:27
我已经打包跑路了
张Sir  16:53:32
咋回事?
我  16:54:22
前一分钟真的准备放弃不查询了 结果居然让我找到问题了!!
张Sir  16:54:42
啥问题?
我  16:55:40
大意就是 游客可以留小帮手 由于没登录 所以uid=0

而你访问的那个链接 是一个不合法的uid,解析错误会当做0  而数据库中有数十万uid=0的小帮手

结果全部查询出来放内存中

内存爆了!!!!
张Sir  16:56:01
啊,没有limit ?
我  16:56:20
所以说  ---->  锉
我  16:56:36
    public List<AdvisorTravelSession> queryTravelSessionsByUid(int uid) {
        String sql = "select * from advisor_travel_session where uid=? order by created_at desc";
        return dao.queryList(new DefaultOpList<AdvisorTravelSession>(sql, bizName, new AdvisorTravelSessionMapper()).addParams(uid));
    }
    public List<AdvisorTravelSession> queryTravelSessionsByUid(int uid,int limit) {
        String sql = "select * from advisor_travel_session where uid=? order by created_at desc limit ? ";
        return dao.queryList(new DefaultOpList<AdvisorTravelSession>(sql, bizName, new AdvisorTravelSessionMapper()).addParams(uid,limit));
    }
我  16:56:50
其实有两个方法 只是用成第一个了
我  16:57:00
当然事实上 第一个也确实不应当存在!
我  16:57:16
哎 @xxx 哥跑路了 我想砍他
张Sir  16:57:16
开始我也想是没有limit, 后来觉得不可能这么弱
张Sir  16:57:41
哦,xx大拿的。那就不奇怪了
张Sir  16:59:54
大拿的思维果然异于常人,挖坑都用这么个奇怪的逻辑
我  17:02:59
我操 查询了无数的数据  累死了

【下篇上】 [大约17:03]

既然找到问题了,动手修改就很容易了。

bugway

事实上有两个方法(见上面QQ聊天),所以我将第一个方法重定向到第二个方法上,同时强制使用limit=10。 另外为了防止游客查询uid=0出来的数据错误,在第二个方法中判断uid<=0是返回空列表。 因为游客实际上是根据tsid(小帮手主键id)来查询的,并不是根据uid来查询的。

这样问题就得到了解决。 但解决这样,显然是不满足的。

【下篇中】[大约17:10]

接下里我想做的是,将所有SQL查询记录下来,不仅包括时间还是可能的结果集条数和更新数量。

/**

 * 记录SQL语句执行状况
 * @param begin 此次查询的开始时间(unix毫秒)
 * @param op 操作符
 * @param rownum 结果行数或者受影响记录行数
 */
private void endLog(long begin, Op op, int rownum) {
    if (begin > 0) {
        log.debug(format("SQL_EXECUTE#%s#%s#%s#%d#%d", op.bizName, op.getRoutePattern(), op.sql, (System.currentTimeMillis() - begin), rownum));
    }
}

这就需要修改大量的代码,因为以前未曾想过记录数和行数,而且也不容易。 总之修改大量的代码后基本上除了Connection/Transation这类无法记录的情况下, 其它都可以记录SQL执行的时间和行数。@seven 可看看是否受此影响。 例如上线后现在的结果:

tac sql.log|grep SQL_EXECUTE|awk -F'#' '{if($NF>100){print $0}}'|head
01-08 19:49:48:DEBUG(73)qtp1690254271-23 IDao - SQL_EXECUTE#compass#compass#select * from poas_review where pid in (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)#11#219
01-08 19:49:15:DEBUG(73)qtp1690254271-25 IDao - SQL_EXECUTE#admin#admin#select path,pathdesc from aclresources order by path#1#193
01-08 19:49:15:DEBUG(73)qtp1690254271-25 IDao - SQL_EXECUTE#admin#admin#select * from users where status=0  order by username#3#196

可以看到这几个SQL语句执行的条数分别为219,193,196,但是时间还算很快,除了poas_review这个表本身字段很多和解析困难之外。

【下篇下】[19:52]

我会说整理这封邮件花了我2个小时么?2个小时么?(所有现场都需要重新重复一遍,并记录下来)

所以下面是谈谈结论时间: 所有查询类SQL必须有limit的,除非有明确的主键查询(明知道结果是1条),不然不能保证未来是否修改条件从而爆表! 应当正确使用Dao操作,严格使用Connection/Transaction等来直接操作数据库,这样无法记录SQL语句和执行时间以及影响条数! 输入参数应当尽可能的保证安全,不要信任外界输入。 最后既然是个问题,千万别放弃,搞明白才是最重要的。要有一个探索未来的心! 如果在DAO层增加limit 或者 uid<=0 判断,都不会引起此问题。

如果你还关心问题,解释下上面日志时间问题:

bugway

"114.242.xx.xxx" c.xxx.com - [08/Jan/2016:12:25:41 +0800] "GET /privacy/crm/user/?uid=%7Bxxxx HTTP/1.1" 504 0 "-" "Mozilla/5.0 (Macintxxh; Intel Mac OS X 10_9_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/46.0.2490.86 Safari/537.36" "10.255.252.2" "382.022" "120.002, 120.001 : 120.000, 22.019" "1.1.19.158:8082, 1.1.6.125:8082 : 1.1.19.158:8082, 1.1.6.125:8082" - - 69b8c0ab86bac34202b3aaafe3a61ee6-63Z 63Z

有此可见问题大约发生于12:19:19秒附近,这和前面推导的 ZkClient的日志从12:19:52前就不正常,一直到12:33:55重启都没能恢复过来,所以看起来系统应该是从12:19:52开始出问题的。 是一致的。 这与zabbix也是吻合的。

bugway

一言难尽] . . . . . .

最后,我最近看了《神探狄仁杰》第二部,虽然是柯南式骗人手法,但是弄明白真相却是提升自己的良好机会。

素质有感

| Comments

拼车上班路上,大公交车连续并到两条线,妹子看不过去,抱怨道:“连续并道,你是原始人吗?讨厌!”。

这让我感触颇深。

换做是别的男司机,肯定会说:“靠,找死啊!MLGB!”。

同样的场景,表达的意思相同,不同的人表达出来的方式和语言完全不一样。我想这应该和从小受到的良好教育有关。 当然后天的生活环境也影响颇深。

人都是会思考的高等动物,注意言行举止能够有效避免与人冲突或者令人厌恶。 人的生活习惯和品质,也是一点点积累起来的。

明十三陵之献陵

| Comments

周末骑行十三陵路过长陵(明成祖朱棣),看见大门金碧辉煌,供万千游人参观。

发现旁边有一个皇泉寺,看名字很有意思,正好也不远,过去瞧瞧。

这个村子叫皇泉寺村,村门口的几个红字,还自带倒影。 xianling

刚进村子就发现献陵(明仁宗朱高炽),大吃一惊,原来如此破败不堪。

xianling

xianling

xianling

xianling

维基百科十三陵中有这么一段:

1966年08月24日:“文化大革命”時期,在“打倒地主階級頭子萬曆”的口號聲中,十幾個紅衛兵衝進定陵地下博物館,把「明神宗朱翊钧」、「孝端显皇后」王氏及「孝靖皇后」王氏的三具屍骨拉出來擺放在博物館大紅門前廣場上,進行批鬥,最終付之一炬。

维基百科居然有文言文立传。

相对于父亲陵墓的金碧辉煌,也许陵前长满荒草是登基仅仅八个月的洪熙皇帝更好的归宿。

致自己

| Comments

最怕的是迷失在自己的世界里。

年龄大了,果然没有年少时候的轻狂,也意味着失去了更多的勇气和智慧。

越来越意识到思考的深度决定了垂直的高度,行动的迅速决定了水平的广度。

自我封闭肯定是不行的,

有太多的事情要做了,而时间越来越觉得不够用了。失去目标更是远离梦想。

做回自己太难了。

果然到了羡慕年轻的年纪了。

读书越来越少了,内心的进步越来越不明显了,反而是岁月的印记在不断加深。

每次想到在妥协中徘徊挺难受的。

人性的不完美在我心中不断放大,充斥着无尽的负能量。

改变自己更是改造内心。

“世界那么大,我想去看看”。

world

End of 2014

| Comments

开篇

春节过新年时定下三大愿望。

中篇

年中四处奔波想办法,折腾无限,酸甜苦辣咸,冷暖自知。

尾篇

赶在2014年结束前完成了三个愿望中的两个半,已经非常不错了。 剩下的半个只能听天由命,这也是挺讽刺的事情。

[果然现在没有总结的愿望,懒惰成性! 此坑待填!]

CentOS 6 命令行下安装 VirtualBox 虚拟机

| Comments

1、 准备工作

安装内核更新

yum install kernel-devel
yum update kernel*

如果内核有更新,则需要重新启动操作系统。

2、 安装VirtualBox

wget http://download.virtualbox.org/virtualbox/debian/oracle_vbox.asc
rpm --import oracle_vbox.asc
wget http://download.virtualbox.org/virtualbox/rpm/el/virtualbox.repo -O /etc/yum.repos.d/virtualbox.repo
yum install VirtualBox-4.3

3、 安装扩展包,以便使用RDP协议3389远程登录安装操作系统

wget http://download.virtualbox.org/virtualbox/4.3.2/Oracle_VM_VirtualBox_Extension_Pack-4.3.2-90405.vbox-extpack
VBoxManage extpack install Oracle_VM_VirtualBox_Extension_Pack-4.3.2-90405.vbox-extpack

4、 创建虚拟机

创建一个2.6或者3.0内核的操作系统虚拟机,名称为centos6,虚拟机文件存放路径在/opt/virtualbox/

VBoxManage createvm --name centos6 --ostype Linux26_64 --register --basefolder /opt/virtualbox/

在创建之前可以查看下支持的客户操作系统类型:

VBoxManage list vms

5、 创建虚拟磁盘

创建一个150G的虚拟磁盘

VBoxManage createvdi --filename /opt/virtualbox/centos6.vdi --size 150000

6、 创建虚拟机的硬盘控制器

VBoxManage storagectl centos6 --name storage_controller_1 --add ide

7、 挂在虚拟硬盘和虚拟光驱

VBoxManage storageattach centos6 --storagectl storage_controller_1 --type hdd --port 0 --device 0  --medium /opt/virtualbox/centos6.vdi
VBoxManage storageattach centos6 --storagectl storage_controller_1 --type dvddrive --port 1 --device 0 --medium /opt/setup/CentOS-6.3-x86_64-LiveCD.iso

这里将5创建好的虚拟磁盘挂载在虚拟机上,同时挂在一个虚拟光驱,加载ISO镜像文件。

8、 设置启动顺序

将光驱设置为第一启动顺序,以便安装操作系统。

VBoxManage modifyvm centos6 --boot1 dvd
VBoxManage modifyvm centos6 --boot2 disk

9、 创建桥接的网络

VBoxManage modifyvm centos6 --nic1 bridged --cableconnected1 on --nictype1 82540EM --bridgeadapter1 em1 --intnet1 brigh1 --macaddress1 auto

在创建之前查看下当前宿主机器的网卡名称,例如此处是 em1

10、 启动vrde模块

VRDE模块用于启动RDP协议,使用微软的3389客户端即可连接。

VBoxManage modifyvm centos6 --vrde on

最后操作系统安装、设置完成后可以考虑关闭此屏幕输出。

VBoxManage modifyvm centos6 --vrde off

11、 调整系统参数

可以此时调整虚拟机的CPU、内存等参数

VBoxManage modifyvm centos6 --memory 4096
VBoxManage modifyvm centos6 --cpus 2

12、 启动虚拟机

VBoxHeadless -startvm centos6

13、 3389远程连接安装操作系统

安装完操作系统即可正常使用。


一些常见问题

遇到问题 ‘WARNING: The vboxdrv kernel module is not loaded.’

确认当前使用的内核和内核头文件版本完全一致:

yum list installed|grep kernel

然后使用vboxdrv进行配置

/etc/init.d/vboxdrv setup

启动、关闭虚拟机

可以使用下列方式启动虚拟机 https://www.virtualbox.org/manual/ch08.html#vboxmanage-startvm

VBoxManage startvm centos6 --type headless
VBoxHeadless -startvm centos6

关闭虚拟机,如果是前台运行的VBoxHeadless,直接CTRL+C即可。 如果是后台运行的VBoxHeadless或者VBoxManage startvm,使用

VBoxManage controlvm centos6 poweroff

无法使用3389端口连接?

检查端口是否存活:

netstat -nap|grep 3389
ss -nap|grep 3389

检查防火墙是否允许通过。

虚拟机控制常用操作

常用操作地址https://www.virtualbox.org/manual/ch08.html#vboxmanage-controlvm

VBoxManage controlvm pause|resume|poweroff|savestate centos6

无法使用rsa publickey登录?

检查是否selinux禁止登录。

谋划台湾自由行

| Comments

taiwan

台湾通行证和港澳通行证已经到手,可以着手准备2014年的台湾自由行计划了。

事实上机票已经购买好了,日期当然也确定了,剩下的就是准备行程和预定酒店等服务。 好在我们剩下的时间还比较“久远”,因此倒也不是很着急。

入台证也是必须的,只是暂时还不用办理。总之确定好行程后,瞅着日子再办理入台证。

监听github,自动编译octopress博客

| Comments

为了方便在任何地方修改blog,我将blog源码存放于github上,挂在一个web hook,这样一旦blog有更新, VPS上就会执行脚本重新生成新的blog,看起来还是非常方便的。

1. 添加github钩子

首先需要将octopress的代码(我比较懒,全部的代码)放到github上。 在github的项目设置的Service Hooks中添加一个WebHook URLs的钩子, 例如:

http://imxylz.com/blog-update

下载github代码,例如存放于/data目录下:

git clone git@github.com:adyliu/imxylz.com.git /data/imxylz.com

2. 设置nginx

nginx增加一个location配置

location /blog-update {
    proxy_pass http://127.0.0.1:1111;
}

3. 增加web钩子

这里使用python 开启一个web服务,拦截任何HTTP请求都执行我们的编译脚本

[root@www imxylz.com]# cat hook.py
#!/usr/bin/env python3
#-*- coding:utf-8 -*-
# start a python service and watch the nginx request dog

from http.server import HTTPServer,CGIHTTPRequestHandler
from threading import Thread,RLock
import subprocess
import logging
import sys
import os.path


_PWD=os.path.abspath(os.path.dirname(__file__))
def execute_cmd(args,cwd=None,timeout=30):
    if isinstance(args,str): args = [args]
    try:
        with subprocess.Popen(args,stdout=subprocess.PIPE,cwd=cwd) as proc:
            try:
                output,unused_err = proc.communicate(timeout=timeout)
            except:
                proc.kill()
                raise
            retcode = proc.poll()
            if retcode:
                raise subprocess.CalledProcessError(retcode, proc.args, output=output)
            return output.decode('utf-8','ignore') if output else ''
    except Exception as ex:
        logging.error('EXECUTE_CMD_ERROR: %s',' '.join(str(x) for x in args))
        raise ex

class HttpHandler(CGIHTTPRequestHandler):
    _lock = RLock()
    _counter = 0
    _building = False

    def build(self):
        with HttpHandler._lock:
            if HttpHandler._counter == 0 or HttpHandler._building:
                return
        HttpHandler._counter = 0
        HttpHandler._building = True
        logging.info("BUILDING NOW...")
        try:
            resp = execute_cmd(os.path.join(_PWD,'build.sh'),cwd=_PWD,timeout=600)
            logging.info(resp)
        finally:
            HttpHandler._building = False
            self.build()

    def do_GET(self):
        self.do_POST()
    def do_POST(self):
        self.send_response(200,'OK')
        self.end_headers()
        self.wfile.write(b'OK')
        self.wfile.flush()
        with HttpHandler._lock:
            HttpHandler._counter += 1
        Thread(target=self.build).start()

if __name__ == '__main__':
    logging.basicConfig(format='%(asctime)s %(levelname)s: %(message)s',level=logging.INFO)

    port = int(sys.argv[1]) if len(sys.argv) > 1 else 1111
    logging.info('starting the server at 127.0.0.1:%s',port)
    httpd = HTTPServer(('127.0.0.1',port),HttpHandler)
    httpd.serve_forever()

4. 生成blog脚本

为了方便扩展,这里使用一个build.sh脚本来编译octopress。

#!/bin/bash

echo "build at `date`"
git pull
rake generate

5. 启动hook

最后启动hook来监听github变更:

nohup python3 hook.py >> /tmp/hook.log 2>&1 &

需要注意的是,build.sh/hook.py 需要放在octopress的根目录下面,另外rake环境也需要准备好,如果不能可以在build.sh里面设置环境变量。

如果要测试可以发送http请求即可。

curl http://127.0.0.1:1111/

此时我只需要将本地blog源码修改后push到github上,VPS机器就会执行脚本重新发布blog了。

回顶部