生产问题排查

2017/06/06 1223点热度 0人点赞 0条评论

查看日志

tail: 显示指定文件末尾内容
#动态读取文件内容(基本实时刷新)
tail -f catalina.out

# 读取文件最后100行
tail -n 100 catalina.out

#动态读取包含指定内容的行
tail -f catalina.out |grep "actionKey"

grep:文本搜索命令
#搜索指定文件catalina.out中的异常信息
grep "Exception" catalina.out

#搜索异常信息,并上下5行显示
grep -C 5 "Exception" catalina.out
# -C n 上下加n行显示
# -c 计算符合条件的行数
# -A n 下加n行显示
# -b n  上加n行显示
# -v 反转查询
# -E "[1-9]+" 使用正则表达式查询

查看cpu内存占用top

M: 根据驻留内存大小进行排序。
P: 根据CPU使用百分比大小进行排序

[root@iZ25lcuxanpZ apache-tomcat-7.0.70]# top
top - 09:02:23 up 227 days, 17:51,  3 users,  load average: 0.00, 0.00, 0.00
# 09:02:23 当前时间
# up 227 days, 17:51, 系统运行时间 227天17小51分
# 3 users 当前登录用户数
# load average: 0.00, 0.00, 0.00 系统负载,即任务队列的平均长度。 三个数值分别为  1分钟、5分钟、15分钟前到现在的平均值
Tasks:  98 total,   1 running,  96 sleeping,   1 stopped,   0 zombie
Cpu(s):  1.3%us,  0.7%sy,  0.0%ni, 98.0%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
# Tasks:  任务说明
# 98 total 进程总数
# 1 running 正在运行的进程
# 96 sleeping 睡眠的进程数
# 1 stopped 停止的进程数
# 0 zombie 僵尸进程数
#Cpu(s): cpu占用说明
# 1.3%us 用户控件占用cpu百分比
# 0.7%sy 内核控件占用cpu百分比
# 0.0%ni 用户进程空间内改变过优先级的进程占用CPU百分比
# 98.0%id 空闲cpu百分比

Mem:   3921112k total,  3770900k used,   150212k free,   179864k buffers
Swap:        0k total,        0k used,        0k free,  1013688k cached
# Mem: 内存占用说明
# 3921112k total 物理内存总量
# 3770900k used 使用的物理内存总量
# 150212k free 空闲内存总量
# 179864k buffers 用作内核缓存的内存量
# Swap:   交换区说明
# 0k total 交换区总量
# 0k used 使用的交换区总量
# 0k free 空闲交换区总量
# 1013688k cached 缓冲的交换区总量。 内存中的内容被换出到交换区,而后又被换入到内存,但使用过的交换区尚未被覆盖, 该数值即为这些内容已存在于内存中的交换区的大小。相应的内存再次被换出时可不必再对交换区写入

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                               
# PID 进程id
# USER 进程启动的用户
# PR   优先级
# NI  nice值。负值表示高优先级,正值表示低优先级
# VIRT 进程使用的虚拟内存总量,单位kb。VIRT=SWAP+RES
# RES 进程使用的、未被换出的物理内存大小,单位kb。RES=CODE+DATA
# SHR 共享内存大小,单位kb
# S 进程状态  D=不可中断的睡眠状态 R=运行 S=睡眠 T=跟踪/停止 Z=僵尸进程
# %CPU 上次更新到现在的CPU时间占用百分比
# %MEM 进程使用的物理内存百分比
# TIME+ 进程使用的CPU时间总计,单位1/100秒
# COMMAND 命令名/命令行
13114 ddtest    20   0 4497m 1.2g  11m S  1.7 32.7  15:10.17 java                  
1610 ddtest    20   0 2292m 451m 5840 S  0.0 11.8  72:18.00 java                 
17688 root      20   0 2374m 209m 5328 S  0.3  5.5 933:48.77 java                 
16190 root      20   0 2381m 200m 2216 S  1.3  5.2   2369:47 java               
6068 root      20   0 2257m 119m 9756 S  0.0  3.1  24:36.29 java                   
9527 root      20   0 2378m  70m 3048 S  0.0  1.9   1491:22 java                 
18052 root      20   0 1378m  27m 3656 T  0.3  0.7  91:44.36 titanagent        
7865 root      20   0  117m  13m 8788 S  0.7  0.4   2:35.85 AliYunDun

查询指定进程的资源占用
top -p 7865

分析cpu过高原因

1,top,并根据cpu占用排序(shift+m)
2,用top -Hp pid 查询cpu过高进程下所有线程的运行情况
top -Hp 24700
3,找到cpu最高的pid,用printf ‘%x\n’ pid 转换为16进制
printf '%x\n' 24743
60a7

4,用jstack 进程id | grep 16进制线程id 找到线程信息
jstack 24700 | grep 60a7
根据打印值判断

dump分析

 jstack用于打印出给定的java进程ID或core file或远程调试服务的Java堆栈信息。
 jstack [-l][F] pid
如果java程序崩溃生成core文件,jstack工具可以用来获得core文件的java stack和native stack的信息,从而可以轻松地知道java程序是如何崩溃和在程序何处发生问题。另外,jstack工具还可以附属到正在运行的java程序中,看到当时运行的java程序的java stack和native stack的信息, 如果现在运行的java程序呈现hung的状态,jstack是非常有用的。进程处于hung死状态可以用-F强制打出stack

dump 文件里,值得关注的线程状态有:
死锁,Deadlock(重点关注)
执行中,Runnable
等待资源,Waiting on condition(重点关注)
等待获取监视器,Waiting on monitor entry(重点关注)
暂停,Suspended
对象等待中,Object.wait() 或 TIMED_WAITING
阻塞,Blocked(重点关注)
停止,Parked

实例一:Waiting to lock 和 Blocked

"RMI TCP Connection(267865)-172.16.5.25" daemon prio=10 tid=0x00007fd508371000 nid=0x55ae waiting for monitor entry [0x00007fd4f8684000]
   java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.log4j.Category.callAppenders(Category.java:201)
- waiting to lock <0x00000000acf4d0c0> (a org.apache.log4j.Logger)
at org.apache.log4j.Category.forcedLog(Category.java:388)
at org.apache.log4j.Category.log(Category.java:853)
at org.apache.commons.logging.impl.Log4JLogger.warn(Log4JLogger.java:234)
at com.tuan.core.common.lang.cache.remote.SpyMemcachedClient.get(SpyMemcachedClient.java:110)
说明:
1)线程状态是 Blocked,阻塞状态。说明线程等待资源超时!
2)“ waiting to lock <0x00000000acf4d0c0>”指,线程在等待给这个 0x00000000acf4d0c0 地址上锁(英文可描述为:trying to obtain  0x00000000acf4d0c0 lock)。
3)在 dump 日志里查找字符串 0x00000000acf4d0c0,发现有大量线程都在等待给这个地址上锁。如果能在日志里找到谁获得了这个锁(如locked < 0x00000000acf4d0c0 >),就可以顺藤摸瓜了。
4)“waiting for monitor entry”说明此线程通过 synchronized(obj) {……} 申请进入了临界区,从而进入了下图1中的“Entry Set”队列,但该 obj 对应的 monitor 被其他线程拥有,所以本线程在 Entry Set 队列中等待。
5)第一行里,"RMI TCP Connection(267865)-172.16.5.25"是 Thread Name 。tid指Java Thread id。nid指native线程的id。prio是线程优先级。[0x00007fd4f8684000]是线程栈起始地址。

实例二:Waiting on condition 和 TIMED_WAITING

"RMI TCP Connection(idle)" daemon prio=10 tid=0x00007fd50834e800 nid=0x56b2 waiting on condition [0x00007fd4f1a59000]
   java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198)
at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:874)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:945)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:662)
说明:

1)“TIMED_WAITING (parking)”中的 timed_waiting 指等待状态,但这里指定了时间,到达指定的时间后自动退出等待状态;parking指线程处于挂起中。

2)“waiting on condition”需要与堆栈中的“parking to wait for  <0x00000000acd84de8> (a java.util.concurrent.SynchronousQueue$TransferStack)”结合来看。首先,本线程肯定是在等待某个条件的发生,来把自己唤醒。其次,SynchronousQueue 并不是一个队列,只是线程之间移交信息的机制,当我们把一个元素放入到 SynchronousQueue 中时必须有另一个线程正在等待接受移交的任务,因此这就是本线程在等待的条件。

实例三:in Obejct.wait() 和 TIMED_WAITING

"RMI RenewClean-[172.16.5.19:28475]" daemon prio=10 tid=0x0000000041428800 nid=0xb09 in Object.wait() [0x00007f34f4bd0000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00000000aa672478> (a java.lang.ref.ReferenceQueue$Lock)
at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:516)
at java.lang.Thread.run(Thread.java:662)
1)“TIMED_WAITING (on object monitor)”,对于本例而言,是因为本线程调用了 java.lang.Object.wait(long timeout) 而进入等待状态。

2)“Wait Set”中等待的线程状态就是“ in Object.wait() ”。当线程获得了 Monitor,进入了临界区之后,如果发现线程继续运行的条件没有满足,它则调用对象(一般就是被 synchronized 的对象)的 wait() 方法,放弃了 Monitor,进入 “Wait Set”队列。只有当别的线程在该对象上调用了 notify() 或者 notifyAll() ,“ Wait Set”队列中线程才得到机会去竞争,但是只有一个线程获得对象的 Monitor,恢复到运行态。

3)RMI RenewClean 是 DGCClient 的一部分。DGC 指的是 Distributed GC,即分布式垃圾回收。

4)请注意,是先 locked <0x00000000aa672478>,后 waiting on <0x00000000aa672478>,之所以先锁再等同一个对象,请看下面它的代码实现:
static private class  Lock { };
private Lock lock = new Lock();
public Reference<? extends T> remove(long timeout)
{
    synchronized (lock) {
        Reference<? extends T> r = reallyPoll();
        if (r != null) return r;
        for (;;) {
            lock.wait(timeout);
            r = reallyPoll();
            ……
       }
}
即,线程的执行中,先用 synchronized 获得了这个对象的 Monitor(对应于  locked <0x00000000aa672478> );当执行到 lock.wait(timeout);,线程就放弃了 Monitor 的所有权,进入“Wait Set”队列(对应于  waiting on <0x00000000aa672478> )。
5)从堆栈信息看,是正在清理 remote references to remote objects ,引用的租约到了,分布式垃圾回收在逐一清理呢。

查看磁盘占用

# 查看整体磁盘占用情况
df -h
# 查询当前目录下,最大深度为1的所有文件大小
du -h --max-depth=1

# 查询指定目录
du -h --max-depth=1  /app

查看进程总数

ps -ef  | wc -l
# 查询指定进程的数量
ps -ef | grep java | wc -l
# 查询tcp网络连接处于TIME_WAIT的数量
netstat -a | grep "TIME_WAIT" | wc -l

# 查看各个状态的连接
netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'

有大量TIME_WAIT的时候,查看日志查找阻塞的原因

netstat 命令

-a  列出所有的连接   # netstat -a
-t  列出tcp协议的连接 # netstat -at
-u  列出udp协议的连接 # netstat -au
-n  禁用反向域名解析  # netstat -ant
-l  列出正在监听的连接  # netstat -tnl
-p  查看进程信息     # netstat -nlpt
-

慢sql查询

SELECT * from information_schema.`PROCESSLIST` t where t.INFO is not null ORDER BY t.TIME desc;
等同于 show processlist,可选择性更高

yxkong

这个人很懒,什么都没留下

文章评论