http://henrikwarne.com/2015/04/16/lessons-learned-in-software-development/
11. Reproduce the problem.
12. Fix the known errors, then see what’s left. Sometimes there are several problems present that you know about. The different bugs can interact with each other and cause strange things to happen. Instead of trying to work out what happens in those cases, fix all the know problems and then see what symptoms remain.
13. Assume no coincidences. When testing and troubleshooting, never believe in coincidences. You changed a timer value, and now the system restarts more often. Not a coincidence. A new feature was added, and an unrelated feature becomes slower? Not a coincidence. Instead, investigate.
Crontab 不执行的问题以及解决方法
http://colobu.com/2015/08/12/using-Eclipse-Memory-Analyzer-by-the-command-line/
http://yq.aliyun.com/articles/2390
Greys Java在线问题诊断工具
http://yq.aliyun.com/articles/56
Java调试那点事
http://jicc.cc/post/a-debug-story.html
最近我在操作一个页面时,程序出现了这样的错误:
Fatal error: mysql error: [1: Can't create/write to file '/var/tmp/#sql_9469_0.MYI' (Errcode: 28)]
$ perror 28
OS error code 28: No space left on device
似乎引起错误的原因已经找到了,如果是硬盘空间不足,只需要扩充存储空间或删除一些无用的文件就行了。那是真的因为硬盘空间不足吗?使用df命令查看一下:
意外的是,系统还有充足的空间,系统盘只使用了15%,数据盘只使用了25%。奇怪吧,错误提示信息和真正情况并不能统一。
果然,在一篇文章里看到有人说Errcode: 28所指示的No space并不一定是指空间不足,也可能是磁盘上的文件数过多,这位网友这样说:
I had same problem but disk space was okay (only 40% full). Problem were inodes, I had too many small files and my inodes were full.
You can check inode status with df -i
他说的这个问题我是遇到过的,linux文件系统里对文件数是有限制的,当文件数达到最大数量是,你将无法新增文件。错误信息里提到了无法读写tmp目录下的临时文件,也行正是因为无法创建新的文件。
那么使用df -i会是什么结果呢?让我吓一跳,在/dev/vda1盘上的文件数竟然快到200多万。看来文件就出自这里了。
下面的任务是找到哪个目录里藏了这么多文件。我使用了笨办法,手工从根目录一个一个的搜:
find DIR_NAME -type f ¦ wc -l
上面的命令可以统计出指定目录下一共有多少个文件。这是个体力活儿,但体力活儿是最容易出结果的,没用多久,我就发现了一个可疑目录:
/var/spool/postfix/maildrop
这个目录下竟然有180万个文件。
看来凶手就是它了。只要将maildrop下的文件全部删掉,磁盘文件数会全部释放,问题也就解决了。可是,为什么会有这么多文件,为什么会在postfix目录下,这个问题如果不搞清楚,相同的服务器异常不久后还会出现。
那么,postfix;是个东西,而maildrop又是个什么东西。
原来postfix是一个邮件服务器软件:
What is Postfix? It is Wietse Venema’s mail server that started life at IBM research as an alternative to the widely-used Sendmail program. Now at Google, Wietse continues to support Postfix.
而maildrop是邮件队列,里面存放的都是一个个邮件。
可问题又来了,哪里来的这么多邮件,谁发给谁的?
我从maildrop下载了一个邮件文本,打开一看,是发给root用户的,邮件的内容是Cron Daemon执行信息。
祸首原来是任务调度程序,这几百万封邮件都是它发的,每执行完一个Cron任务,它都会发给root一份任务完成情况的邮件。在/etc/crontab文件里陈列着30多个定时调度任务,而且很多任务执行的频度很高,所以才在短时间里发送了这么多的文件。
根源是找到了,只要禁止这些调度任务给root发邮件,系统文件数就不会大量增加,我的程序就不会出现Errcode: 28错误了,可我不能简单的删除这些调度任务来禁止它们发邮件。对/etc/crontab文件熟悉的系统管理员会知道,就在它的前几行是配置信息:
SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
HOME=/
其中第三行是配置邮件的,它指明要把邮件发给root用户,只需要把这行信息改成MAILTO="",它就再也不发邮件了。
近期竞价服务的几个性能优化点
JVM飙高排查脚本-结构分析
11. Reproduce the problem.
12. Fix the known errors, then see what’s left. Sometimes there are several problems present that you know about. The different bugs can interact with each other and cause strange things to happen. Instead of trying to work out what happens in those cases, fix all the know problems and then see what symptoms remain.
13. Assume no coincidences. When testing and troubleshooting, never believe in coincidences. You changed a timer value, and now the system restarts more often. Not a coincidence. A new feature was added, and an unrelated feature becomes slower? Not a coincidence. Instead, investigate.
Crontab 不执行的问题以及解决方法
Crontab命令执行不了的原因通常有三个:
- 没有权限
- 命令shell写错了
- 环境问题
前面两个很简单,这里就不赘述了来讲讲第三个,环境问题。
我们在终端下先运行crontab : crontab -e
这句话的意思是说把当前的环境变量打出来到我的桌面文件:env.output上面
现在我们查看一下env.output,以下是我的内容
好的,现在再在终端下输入env | grep PATH 查看正常的PATH
看到了吗?完全不一样。
所以crontab使用的是一些基本的变量它根本不知道你要用到的那些依赖的路径!(如java/mvn 等等)
解决方法也是很简单的。
直接进入crontab -e
在内容顶部加入你的PATH 比如以下是我的crontab -e
首先你需要修改MemoryAnalyzer.ini中的Xmx值,确保有充足的硬盘空间(至少dump文件的两倍)。
然后运行
./ParseHeapDump.sh heap.bin org.eclipse.mat.api:suspects org.eclipse.mat.api:overview org.eclipse.mat.api:top_components
会得到suspects, overview和top_components三个视图的信息。
http://yq.aliyun.com/articles/2390
Greys Java在线问题诊断工具
http://yq.aliyun.com/articles/56
Java调试那点事
http://jicc.cc/post/a-debug-story.html
最近我在操作一个页面时,程序出现了这样的错误:
Fatal error: mysql error: [1: Can't create/write to file '/var/tmp/#sql_9469_0.MYI' (Errcode: 28)]
$ perror 28
OS error code 28: No space left on device
似乎引起错误的原因已经找到了,如果是硬盘空间不足,只需要扩充存储空间或删除一些无用的文件就行了。那是真的因为硬盘空间不足吗?使用df命令查看一下:
意外的是,系统还有充足的空间,系统盘只使用了15%,数据盘只使用了25%。奇怪吧,错误提示信息和真正情况并不能统一。
果然,在一篇文章里看到有人说Errcode: 28所指示的No space并不一定是指空间不足,也可能是磁盘上的文件数过多,这位网友这样说:
I had same problem but disk space was okay (only 40% full). Problem were inodes, I had too many small files and my inodes were full.
You can check inode status with df -i
他说的这个问题我是遇到过的,linux文件系统里对文件数是有限制的,当文件数达到最大数量是,你将无法新增文件。错误信息里提到了无法读写tmp目录下的临时文件,也行正是因为无法创建新的文件。
那么使用df -i会是什么结果呢?让我吓一跳,在/dev/vda1盘上的文件数竟然快到200多万。看来文件就出自这里了。
下面的任务是找到哪个目录里藏了这么多文件。我使用了笨办法,手工从根目录一个一个的搜:
find DIR_NAME -type f ¦ wc -l
上面的命令可以统计出指定目录下一共有多少个文件。这是个体力活儿,但体力活儿是最容易出结果的,没用多久,我就发现了一个可疑目录:
/var/spool/postfix/maildrop
这个目录下竟然有180万个文件。
看来凶手就是它了。只要将maildrop下的文件全部删掉,磁盘文件数会全部释放,问题也就解决了。可是,为什么会有这么多文件,为什么会在postfix目录下,这个问题如果不搞清楚,相同的服务器异常不久后还会出现。
那么,postfix;是个东西,而maildrop又是个什么东西。
原来postfix是一个邮件服务器软件:
What is Postfix? It is Wietse Venema’s mail server that started life at IBM research as an alternative to the widely-used Sendmail program. Now at Google, Wietse continues to support Postfix.
而maildrop是邮件队列,里面存放的都是一个个邮件。
可问题又来了,哪里来的这么多邮件,谁发给谁的?
我从maildrop下载了一个邮件文本,打开一看,是发给root用户的,邮件的内容是Cron Daemon执行信息。
祸首原来是任务调度程序,这几百万封邮件都是它发的,每执行完一个Cron任务,它都会发给root一份任务完成情况的邮件。在/etc/crontab文件里陈列着30多个定时调度任务,而且很多任务执行的频度很高,所以才在短时间里发送了这么多的文件。
根源是找到了,只要禁止这些调度任务给root发邮件,系统文件数就不会大量增加,我的程序就不会出现Errcode: 28错误了,可我不能简单的删除这些调度任务来禁止它们发邮件。对/etc/crontab文件熟悉的系统管理员会知道,就在它的前几行是配置信息:
SHELL=/bin/bash
PATH=/sbin:/bin:/usr/sbin:/usr/bin
MAILTO=root
HOME=/
其中第三行是配置邮件的,它指明要把邮件发给root用户,只需要把这行信息改成MAILTO="",它就再也不发邮件了。
自上次做竞价服务的性能优化已经过了一段时间。这几天做频次数据库线下测试,遇到了一些问题,一个是数据库延时过高,另一个是CPU不稳定。于是找找原因,顺带看看竞价服务这边的情况。
据说流量压力正常,有时候CPU会暴涨到600%。为了定位问题,还是先祭出神器pprof。pprof没有看出问题了,跟最近一次的对比,垃圾回收的比以前升高了一些,以前大概4%,现在到6%了。这个是由于新加的一些业务代码中引入的小内存分配。
另一个跟以前不同的地方是有2%的CPU开销浪费在了抢锁上面。来源是rand.Float64的调用,系统的rand.Floa64会加锁,而这边代码在一个高并发请求下,有几个循环中调用rand.Float64函数,导致锁的占用严重。上次优化时没观察到这个问题,这部分代码没变过,问了一下是不是Go版本变过了,果然是这方面的原因。
最高的几项,mapaccess占了9%优化不了,这个是因为业务代码中太多地使用map数据结构,不好动。
然后排第二的syscall调用,主要来源是net.http库和redis的库一直调用到net.Write,也是没法优化的,标准库自不必说,都是bufio过的。
接着有regex的,这个是判断浏览器类型使用到了,每来一个竞价请求都会判断浏览器类型信息,用到正则。请求量很大之后这边就引入了3%以上的CPU开销。上次尝试优化这块,可耻的失败了。
然后的mallocgc什么的,内存分配和垃圾回收相关的,比上次涨了一些,业务需要引入的。
还有system和futex,推测跟我们自己的日志库实现相关,多个goroutine同时写日志,用锁保护。我上次就提过merge了,日志发到channel,由单个goroutine在后台写log。只不过还没合到master。
总体来说简单能做的上次都优化掉了。然后看内存,内存占用在100MB-200MB之间,跟之前差不多。其中大概50M多是加载IP数据库所占用的。这种单个大块内存对垃圾回收没什么影响。但是代码写得太恶劣了
ioutil.ReadAll
,顺手优化下,改成多进程共享内存的了。因为我们会在一个物理机器上起很多的竞价进程,而每个进程都加载一份IP数据库到内存,实在太浪费了。这份数据是只读的,很容易共享。虽然说单个进程节省50M并不多,总的竞价进程至少也有100+,算一下起码可以省下5G的内存。
顺便说说单机多进程,为什么要这么搞?为什么不是一个大进程呢?至少在垃圾回收方面,拆分是明显有好处的。每个进程中的对象更少了,则垃圾回收的停顿时间就更短。目前的Go的实现,是并行的垃圾回收,但是停下来后,并不是所有goroutine都去回收垃圾了,只有最多8个参与垃圾回收工作,其它都闲着。另外,拆成多个小进程,一个挂掉了影响并不严重,换成一个大进程挂掉受影响的连接就多得多。
按理说从我上次优化完代码后,正常压力下CPU使用不应该超过200%的,大概1500QPS时160%左右的CPU。pprof没问题,内存使用率也很正常,到底是什么导致不稳定的暴涨呢。
再看看GC的情况了,终于定位了问题所在:
gc1897(8): 10+26+6891+59 us, 52 -> 105 MB, 549368 (604823203-604273835) objects, 19379/9699/0 sweeps, 72(3501) handoff, 32(466) steal, 613/133/8 yields
gc1898(8): 57+21+7989+167 us, 52 -> 105 MB, 558217 (605170322-604612105) objects, 19379/10265/0 sweeps, 120(6726) handoff, 69(940) steal, 696/199/14 yields
gc1899(8): 9+25+8149+8 us, 52 -> 105 MB, 541706 (605502236-604960530) objects, 19379/10346/0 sweeps, 128(11526) handoff, 22(420) steal, 869/308/20 yields
gc1900(8): 34+23+7647+46 us, 52 -> 105 MB, 560347 (605852769-605292422) objects, 19379/10342/0 sweeps, 140(7751) handoff, 46(800) steal, 875/246/20 yields
gc1901(8): 10+1405+9143+56 us, 52 -> 105 MB, 552926 (606195933-605643007) objects, 19379/10043/0 sweeps, 143(7594) handoff, 43(935) steal, 689/197/13 yields
gc1902(8): 30088+10246+28392+45 us, 52 -> 105 MB, 549819 (606535495-605985676) objects, 19379/10331/0 sweeps, 84(7100) handoff, 49(1301) steal, 444/148/17 yields
gc1903(8): 44+25+6694+143 us, 53 -> 106 MB, 549086 (606872247-606323161) objects, 19379/10699/0 sweeps, 44(4354) handoff, 47(702) steal, 466/131/26 yields
gc1904(8): 31+23+6411+7 us, 53 -> 107 MB, 555695 (607214066-606658371) objects, 19379/3515/0 sweeps, 107(10192) handoff, 67(1024) steal, 657/219/16 yields
gc1905(8): 36+29+6668+14 us, 53 -> 107 MB, 550426 (607551487-607001061) objects, 19379/5634/0 sweeps, 96(6921) handoff, 21(294) steal, 679/176/22 yields
gc1906(8): 9+31+8006+148 us, 52 -> 105 MB, 548565 (607890212-607341647) objects, 19379/10430/0 sweeps, 158(9644) handoff, 47(567) steal, 881/219/11 yields
gc1907(8): 3+33+8252+81 us, 52 -> 105 MB, 539877 (608220352-607680475) objects, 19379/10218/0 sweeps, 63(4975) handoff, 19(372) steal, 474/148/9 yields
gc1908(8): 22+30+7976+137 us, 52 -> 105 MB, 552635 (608563239-608010604) objects, 19379/10103/0 sweeps, 68(7029) handoff, 69(918) steal, 538/126/11 yields
平时正常的垃圾回收时间大概在7-8ms,现在gc的压力变大了一些,以前应该在5ms的。
注意到其中有异常的一项,30088+10246+28392+45us,居然有68ms!!!问题找到了,大部分时候垃圾回收正常,时间稳定在7-8ms,但一阵一阵的突然变到好几十毫秒,接来下就是CPU暴涨到几百了。应该是垃圾回收期间积压了大量请求,导致后面处理不过来...
继续调查,为什么会有一阵一阵的垃圾回收时间变化这么长呢?我仔细观察测试服务器的负载情况,结果发现是受到了外界的影响。ngnix那边会一阵一阵的突然蹦一下,跑满5 6个核以上。然后平静下去又好了,结果就是导致这边跟着一阵一阵垃圾回收受到影响,继而在stop the world期间积压大量请求,导致的竞价服务处理不过来,又一波的CPU暴涨。蝴蝶效应,呵呵。至此至少已经确定不是我这边的问题,ngnix那边就由其它同事去看了
http://yq.aliyun.com/articles/55JVM飙高排查脚本-结构分析
#!/bin/ksh typeset top=${1:-10} typeset pid=${2:-$(pgrep -u $USER java)} typeset tmp_file=/tmp/java_${pid}_$$.trace $JAVA_HOME/bin/jstack $pid > $tmp_file ps H -eo user,pid,ppid,tid,time,%cpu --sort=%cpu --no-headers\ | tail -$top\ | awk -v "pid=$pid" '$2==pid{print $4"\t"$6}'\ | while read line; do typeset nid=$(echo "$line"|awk '{printf("0x%x",$1)}') typeset cpu=$(echo "$line"|awk '{print $2}') awk -v "cpu=$cpu" '/nid='"$nid"'/,/^$/{print $0"\t"(isF++?"":"cpu="cpu"%");}' $tmp_file done rm -f $tmp_file