Java の問題の場所と解決策のまとめ

背景
「オフラインでは問題ない」、「システムのせいでコードに問題があるはずがない」、「オンラインでリモートからデバッグできるか?」
オンラインの問題は開発中のバグとは異なり、ランタイムに関連します。環境、プレッシャー、同時実行条件、特定のビジネス関連。オンラインの問題の場合は、オンライン環境で利用可能なツールを使用して、問題を特定するために必要な情報を収集することが重要です。
問題の原因となるバグやリソースのボトルネックに関するデータを直感的に取得することは困難であり、リソースの使用状況データやログなどの情報に基づいて問題の根本原因を推測する必要があります。そして、困難な問題の場所を特定するには、通常、さまざまな方法を使用して原因を追跡する必要があります。
この Wiki では、私が使用したツールをまとめ、いくつかの事例を共有しました。

1. よくある質問
1.1 可用性
サービスの可用性につながる一般的な状況をいくつか示します:
a) 502 Bad Gateway
アプリケーション システム、特に http ベースのアプリケーションにとって最も深刻な問題は、「502 Bad Gateway」です。これは、バックエンド サービスが完全に利用できないことを意味します。 考えられる理由
リソース不足 1: CMS がアプリケーション メモリをリークするか、メモリが不足すると、アプリケーションが深刻に停止します。
リソース不足 2: サーバー スレッドの数が不足しています。Tomcat Jetty などの一般的な Web サーバーが最大作業スレッドで構成されています。
リソース不足 3: データベース リソースが不足していると、通常、接続プール設定が不足し、クエリが多すぎると発生します。 Web サーバーの作業スレッドをブロックします
リソース不足 4: IO リソースのボトルネック、オンライン環境 特に混合環境では IO が共有されます (幸いなことに CRM にはこのような状況はありませんが、エージェントが多数あります)。一般的に使用される log4j ログ ツールは次のとおりです。記録された各ログ ファイルも排他的リソースです。スレッドは、データをログに記録する前に、まずロックを取得する必要があります。
... ...
さまざまな OOM
b) ソケット例外
ピアによる共通接続リセット、パイプ切断、EOFException
ネットワークの問題: オペレーターやコンピュータ ルームを越えてアクセスするときに発生する可能性があります
プログラムのバグ: ソケットが異常に閉じられています
1.2 平均応答時間
システム問題が発生したときの最も直感的な症状。このパラメーターは、状況が悪化して他のサービスに影響を及ぼし、システム全体が使用できなくなる前に、早期に警告を発します。
リソース競合 1: CPU
リソース競合。 2: IO
リソースの競合 3: ネットワーク IO
リソースの競合 4: データベース
リソースの競合 5: solr、medis
ダウンストリームインターフェイス: 例外による応答遅延の原因
1.3 マシンアラーム
アプリケーションサービスの利用不能と比較すると、このタイプのエラーは直接発生しません。サービス障害の原因 利用できず、混乱がある場合、マシンにデプロイされた複数のサービスが相互に干渉する可能性があります:
CPU
ディスク
fd
IO (ネットワーク ディスク)
1.4 概要
書くのに長い時間がかかり、多くの状況が発生しました繰り返し言及されますが、通常はオンラインの問題です。その理由は、システム リソースとアプリケーションに他なりません。これらのリソースとデータを監視および表示するツールを知っていれば、オンラインの問題を簡単に見つけることができます。
2 一般的に使用されるツール
2.1 Linux ツール
a) sysstat:
iostat: 読み取りおよび書き込み圧力を表示

    [sankuai@cos-mop01 logs]$ iostat
    Linux 2.6.32-20131120.mt (cos-mop01.lf.sankuai.com)     2015年10月21日     _x86_64_    (4 CPU)
    avg-cpu:  %user   %nice %system %iowait  %steal   %idle
               1.88    0.00    0.87    0.12    0.05   97.07
    Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
    vda               1.88        57.90        12.11 2451731906  512911328
    vdb               0.01         0.40         1.41   17023940   59522616
    vdc               1.14        28.88        36.63 1223046988 1551394969

sar: CPU ネットワーク IO IO を表示、パラメーターを有効にして履歴データを表示

    /etc/sysconfig/sysstat
    HISTORY=7
    /etc/cron.d/sysstat
    */10 * * * * root /usr/lib/sa/sa1 1 1
       
    sar -u/-r/-B/-b/-q/-P/-n -f /var/log/sa/sa09

b) トップ
負荷に注意する、cpu、mem、swap
スレッドごとにリソース情報を表示できます(バージョン3.2.7以降)

top - 19:33:00 up 490 days,  4:33,  2 users,  load average: 0.13, 0.39, 0.42
Tasks: 157 total,   1 running, 156 sleeping,   0 stopped,   0 zombie
Cpu(s):  4.9%us,  2.7%sy,  0.0%ni, 92.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.3%st
Mem:   5991140k total,  5788884k used,   202256k free,     4040k buffers
Swap:  2096440k total,   447332k used,  1649108k free,   232884k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  SWAP CODE DATA COMMAND
18720 sankuai   20   0 8955m 4.3g 6744 S 22.6 74.5 174:30.73    0    4 8.6g java
27794 sankuai   20   0 5715m 489m 2116 S 11.6  8.4   3922:43 121m    4 3.9g java
13233 root      20   0  420m 205m 2528 S  0.0  3.5   1885:15  91m    4 304m puppetd
21526 sankuai   20   0 2513m  69m 4484 S  0.0  1.2  45:56.28  37m    4 2.4g java

c)vmstat

[sankuai@cos-mop01 logs]$ vmstat
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0 447332 200456   4160 234512    0    0    11     6    0    0  2  1 97  0  0

d)tcpdump
ネットワークの問題を特定するためのツールです。 TCPIP メッセージ。Wireshark と組み合わせて使用​​する場合は、同時に TCPIP プロトコルについても理解する必要があります。
複雑な環境におけるネットワーク遅延、ネットワークパケット損失、およびネットワーク問題の一般的なシナリオ分析。

#!/bin/bash
tcpdump -i eth0 -s 0 -l -w - dst port 3306 | strings | perl -e '
while() { chomp; next if /^[^ ]+[ ]*$/;
    if(/^(SELECT|UPDATE|DELETE|INSERT|SET|COMMIT|ROLLBACK|CREATE|DROP|ALTER|CALL)/i)
    {
        if (defined $q) { print "$q\n"; }
        $q=$_;
    } else {
        $_ =~ s/^[ \t]+//; $q.=" $_";
    }
}'

3.2 Java ツール
a) jstat

[sankuai@cos-mop01 logs]$ jstat -gc 18704
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
3584.0 3584.0  0.0    0.0   24064.0  13779.7   62976.0      0.0     4480.0 677.9  384.0   66.6       0    0.000   0      0.000    0.000

b) jmap

jmap -dump:format=b,file=heap.bin $pid

c) jstack または kill -3
デッドロックとスレッド待機を表示します。
スレッド ステータス: n 実行中
Timed_waiting (オブジェクト モニター上)
Timed_waiting (スリープ中)
Timed_waiting (パーキング中)
待機中 (オブジェクト モニター上) JHANSOLE HAT は、JMX 経由で情報を取得するために JConsole を使用するのが難しく、パフォーマンスに影響を与えます
e) gc ログ
-XX:+UseParallelOld
-XX:+ConcurrentMultiSoup
3.3 サードパーティツール
a) mat
オブジェクトの詳細

受信/送信

スレッドの概要

配置项

./MemoryAnalyzer -keep_unreachable_objects  heap_file
4. 案例分析
4.1 cpu高

现象：CPU报警
定位问题：
    查看CPU占用高的线程

sankuai@sin2:~$ ps H -eo user,pid,ppid,tid,time,%cpu|sort -rnk6 |head -10
sankuai  13808 13807 13808 00:00:00  8.4
sankuai  29153     1 29211 00:21:13  0.9
sankuai  29153     1 29213 00:20:01  0.8
sankuai  29153     1 29205 00:17:35  0.7
sankuai  29153     1 29210 00:11:50  0.5
sankuai  29153     1  1323 00:08:37  0.5
sankuai  29153     1 29207 00:10:02  0.4
sankuai  29153     1 29206 00:07:10  0.3
sankuai  29153     1 29208 00:06:44  0.2

 thread dump

    jstack $pid > a.txt
    printf %x $tid
        $xTID

 查找线程执行的代码

"main-SendThread(cos-zk13.lf.sankuai.com:9331)" #25 daemon prio=5 os_prio=0 tid=0x00007f78fc350000 nid=$TIDx runnable [0x00007f79c4d09000]
java.lang.Thread.State: RUNNABLE
    at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1035)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)

4.2 io高

现象：磁盘IO报警
环境：需要安装sysstat工具
定位问题：
a) 查看CPU占用高的线程

1

   

pidstat -d -t -p $pid

   

b) 其他同4.1

4.3 资源
a) 数据库

"DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000]
java.lang.Thread.State: BLOCKED (on object monitor)
                at ConnectionPool.getConnection(ConnectionPool.java:102)
                - waiting to lock <0xe0375410> (a beans.ConnectionPool)
                at Service.getCount(ServiceCnt.java:111)
                at Service.insert(ServiceCnt.java:43)
"DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020]
java.lang.Thread.State: BLOCKED (on object monitor)
                at ConnectionPool.getConnection(ConnectionPool.java:102)
                - waiting to lock <0xe0375410> (a beans.ConnectionPool)
                at Service.getCount(ServiceCnt.java:111)
                at Service.insertCount(ServiceCnt.java:43)

b) log

"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.xxx.core.common.lang.cache.remote.MemcachedClient.get(MemcachedClient.java:110)

c) web server

有两个非常重要的系统参数：

maxThread: 工作线程数

backlog：TCP连接缓存数，Jetty(ServerConnector.acceptQueueSize) Tomcat(Connector.acceptCount)，高并发下设置过小会有502

 
4.4 gc

a) CMS fail
    promotion failed

    172966 2015-09-18T03:47:33.108+0800: 627188.183: [GC 627188.183: [ParNew (promotion failed)
     172967 Desired survivor size 17432576 bytes, new threshold 1 (max 6)
     172968 - age   1:   34865032 bytes,   34865032 total
     172969 : 306688K->306688K(306688K), 161.1284530 secs]627349.311: [CMS CMS: abort preclean due to time 2015-09-18T03:50:14.743+0800: 627349.818:
    [CMS-concurrent-abortable-preclean: 1.597/162.729 secs] [Times: user=174.58 sys=84.57, real=162.71 secs]
     172970  (concurrent mode failure): 1550703K->592286K(1756416K), 2.9879760 secs]
    1755158K->592286K(2063104K), [CMS Perm : 67701K->67695K(112900K)], 164.1167250 secs] [Times: user=175.61 sys=84.57, real=164.09 secs]

 concurrent fail

    [CMS2015-09-18T07:07:27.132+0800: 639182.207: [CMS-concurrent-sweep: 1.704/13.116 secs] [Times: user=17.16 sys=5.20,real=13.12 secs]
    443222 (concurrent mode failure): 1546078K->682301K(1756416K), 4.0745320 secs] 1630977K->682301K(2063104K), [CMS Perm :67700K->67693K(112900K)], 15.4860730 secs] [Times: user=19.40 sys=5.20, real=15.48 secs]

b) 连续Full GC

应用存在内存泄漏，垃圾收集会占用系统大量cpu时间，极端情况下可能发生90%以上时间在做GC的情况。
在系统使用http访问check alive或者使用了Zookeeper这种通过心跳保证存活性的应用中，会可用性异常或者被zk的master剔除。

5. 注意
    保留现场：threaddump top heapdump
    注意日志记录：文件 数据库

以上がJava の問題の場所と解決策のまとめの詳細内容です。詳細については、PHP 中国語 Web サイトの他の関連記事を参照してください。