В последнее время я часто получаю сообщения о том, что процессор превышает порог, очевидно, что есть проблема. Итак, после некоторого расследования, когда я, наконец, нашел виновника, я вдруг понял, что на этот раз это была интересная «нетипичная» проблема с процессором, поэтому я специально записал ее здесь.
Почему это нетипично, ведь по моему опыту, типичный всплеск ЦП обычно представляет собой бесконечный цикл в бизнес-коде, или производительность определенного RPC слишком низкая, чтобы заблокировать большое количество потоков и т. д., И на этот раз проблема с процессором вызвана GC из-за того, что Sting
Давайте посмотрим на процесс расследования
Узнайте, какой поток потребляет процессор
top
Первое, что нужно сделать, это посмотреть, какие потоки занимают больше всего ЦП, это можно сделать с помощью команды top:
top -Hp $pid -b -n 1|sed -n "7,17p"
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
94349 app 20 0 11.2g 5.0g 12m S 15.0 32.1 215:03.69 java
94357 app 20 0 11.2g 5.0g 12m S 15.0 32.1 88:22.39 java
94352 app 20 0 11.2g 5.0g 12m S 13.1 32.1 215:05.71 java
94350 app 20 0 11.2g 5.0g 12m S 11.2 32.1 215:04.86 java
94351 app 20 0 11.2g 5.0g 12m S 11.2 32.1 215:04.99 java
94935 app 20 0 11.2g 5.0g 12m S 11.2 32.1 63:11.75 java
94926 app 20 0 11.2g 5.0g 12m S 9.4 32.1 63:10.58 java
94927 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:06.89 java
94932 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:12.65 java
94939 app 20 0 11.2g 5.0g 12m S 5.6 32.1 63:01.75 java
$pid - это идентификатор процесса нашего соответствующего процесса Java, sed -n "7,17p" должен занимать строки с 7-й по 17-ю, поскольку первые 7 строк являются информацией заголовка верхней команды, поэтому строки с 7-й по 17-ю 10 основных потоков, потребляющих больше всего ресурсов ЦП в этом потоке.
«PID» в первом столбце — это идентификатор соответствующего потока в JVM.Нам нужно только использовать идентификатор потока, чтобы найти соответствующий поток в jstack, чтобы узнать, кто делает трюк.
Однако следует отметить, что PID в верхней команде указан в десятичном формате, а идентификатор потока в jstack — в шестнадцатеричном, поэтому нам все еще нужно выполнить задание, которое заключается в преобразовании вышеуказанного PID в шестнадцатеричный, здесь я только преобразовал топ-3 самых ресурсоемких:
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94349
1708d
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94357
17095
[app@linux-v-l-02:/app/tmp/]$printf '%x\n' 94352
17090
jstack
Теперь, когда мы знаем идентификаторы потоков, которые потребляют ЦП, давайте посмотрим, каким потокам соответствуют эти идентификаторы потоков.
Сначала используйте jstack, чтобы распечатать всю информацию о потоках в JVM:
[app@linux-v-l-02:/app/tmp/]jstack -l $pid >>/tmp/jstack.txt
Стоит отметить, что поскольку потоки в JVM все время меняются, а также меняются потоки в ТОПе, то если команда jstack и команда top выполняются отдельно, то очень вероятно, что идентификаторы потоков два не будут соответствовать.Поэтому команду top и команду jstack лучше выполнять вместе со скриптом.На самом деле я написал скрипт и выполнил его вместе~
Далее смотрим какие потоки 1708d, 17095, 17090 есть:
[app@linux-v-l-02:/app/tmp/]$egrep "1708d|17095|17090" jstack.txt --color
"Gang worker#0 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c023000 nid=0x1708d runnable
"Gang worker#3 (Parallel GC Threads)" os_prio=0 tid=0x00007f4d4c028800 nid=0x17090 runnable
"G1 Concurrent Refinement Thread#0" os_prio=0 tid=0x00007f4d4c032000 nid=0x17095 runnable
Приведенный выше nid — это соответствующий идентификатор потока в шестнадцатеричном формате.Из jstack видно, что потоки, потребляющие больше всего ЦП, — это некоторые потоки GC.
Мы отслеживали ПОЛНЫЙ GC JVM.После того, как приложение изменилось на G1, ПОЛНЫЙ GC обычно происходит раз в неделю или около того, поэтому мы всегда думали, что наша куча JVM очень здорова, но есть много признаков того, что JVM действительно проблема
Проблемы с сборщиком мусора
журнал сборщика мусора
Мы все время печатаем журнал GC.Открыв его, оказывается, что пауз GC очень много, следующим образом
2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0907586 secs]
[Parallel Time: 84.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501598615.0, Avg: 501598615.0, Max: 501598615.0, Diff: 0.1]
[Ext Root Scanning (ms): Min: 4.9, Avg: 5.0, Max: 5.0, Diff: 0.2, Sum: 19.8]
[Update RS (ms): Min: 76.6, Avg: 76.7, Max: 76.7, Diff: 0.1, Sum: 306.7]
[Processed Buffers: Min: 945, Avg: 967.0, Max: 1007, Diff: 62, Sum: 3868]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 2.4, Avg: 2.5, Max: 2.6, Diff: 0.2, Sum: 9.8]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 84.2, Avg: 84.2, Max: 84.2, Diff: 0.1, Sum: 336.7]
[GC Worker End (ms): Min: 501598699.2, Avg: 501598699.2, Max: 501598699.2, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 5.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.3 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.7 ms]
[Free CSet: 0.2 ms]
[Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
[Times: user=0.34 sys=0.00, real=0.10 secs]
2019-08-12T20:12:23.094+0800: 501598.703: [GC concurrent-root-region-scan-start]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-root-region-scan-end, 0.0076353 secs]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-mark-start]
2019-08-12T20:12:23.634+0800: 501599.243: [GC concurrent-mark-end, 0.5323465 secs]
2019-08-12T20:12:23.639+0800: 501599.249: [GC remark 2019-08-12T20:12:23.639+0800: 501599.249: [Finalize Marking, 0.0019652 secs] 2019-08-12T20:12:23.641+0800: 501599.251: [GC ref-proc, 0.0027393 secs] 2019-08-12T20:12:23.644+0800: 501599.254: [Unloading, 0.0307159 secs], 0.0366784 secs]
[Times: user=0.13 sys=0.00, real=0.04 secs]
2019-08-12T20:12:23.682+0800: 501599.291: [GC cleanup 1245M->1226M(4096M), 0.0041762 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-start]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-end, 0.0000487 secs]
2019-08-12T20:12:30.022+0800: 501605.632: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted), 0.3849037 secs]
[Parallel Time: 165.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501605635.2, Avg: 501605635.2, Max: 501605635.3, Diff: 0.1]
[Ext Root Scanning (ms): Min: 3.5, Avg: 3.8, Max: 4.4, Diff: 0.9, Sum: 15.2]
[Update RS (ms): Min: 135.5, Avg: 135.8, Max: 136.0, Diff: 0.5, Sum: 543.3]
[Processed Buffers: Min: 1641, Avg: 1702.2, Max: 1772, Diff: 131, Sum: 6809]
[Scan RS (ms): Min: 1.5, Avg: 1.6, Max: 1.6, Diff: 0.0, Sum: 6.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 24.1, Avg: 24.4, Max: 24.6, Diff: 0.4, Sum: 97.4]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 165.6, Avg: 165.6, Max: 165.6, Diff: 0.0, Sum: 662.4]
[GC Worker End (ms): Min: 501605800.8, Avg: 501605800.9, Max: 501605800.9, Diff: 0.0]
[Code Root Fixup: 0.2 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 218.7 ms]
[Evacuation Failure: 210.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.5 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 2.2 ms]
[Free CSet: 0.2 ms]
[Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
[Times: user=1.44 sys=0.00, real=0.39 secs]
2019-08-12T20:12:32.225+0800: 501607.834: [GC pause (G1 Evacuation Pause) (mixed), 0.0800708 secs]
[Parallel Time: 74.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501607835.5, Avg: 501607835.6, Max: 501607835.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 3.7, Avg: 4.0, Max: 4.4, Diff: 0.6, Sum: 16.2]
[Update RS (ms): Min: 67.8, Avg: 68.0, Max: 68.1, Diff: 0.3, Sum: 272.0]
[Processed Buffers: Min: 863, Avg: 899.8, Max: 938, Diff: 75, Sum: 3599]
Недостатком журналов G1 является то, что их слишком много, что может ослепить.Для удобства описания я опускаю некоторые бессмысленные журналы GC и сжимаю их в следующие три абзаца:
2019-08-12T20:12:23.002+0800: 501598.612: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0907586 secs]
[Parallel Time: 84.5 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501598615.0, Avg: 501598615.0, Max: 501598615.0, Diff: 0.1]
......
[Eden: 230.0M(1968.0M)->0.0B(1970.0M) Survivors: 8192.0K->8192.0K Heap: 1693.6M(4096.0M)->1082.1M(4096.0M)]
[Times: user=0.34 sys=0.00, real=0.10 secs]
2019-08-12T20:12:23.094+0800: 501598.703: [GC concurrent-root-region-scan-start]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-root-region-scan-end, 0.0076353 secs]
2019-08-12T20:12:23.101+0800: 501598.711: [GC concurrent-mark-start]
2019-08-12T20:12:23.634+0800: 501599.243: [GC concurrent-mark-end, 0.5323465 secs]
2019-08-12T20:12:23.639+0800: 501599.249: [GC remark 2019-08-12T20:12:23.639+0800: 501599.249: [Finalize Marking, 0.0019652 secs] 2019-08-12T20:12:23.641+0800: 501599.251: [GC ref-proc, 0.0027393 secs] 2019-08-12T20:12:23.644+0800: 501599.254: [Unloading, 0.0307159 secs], 0.0366784 secs]
[Times: user=0.13 sys=0.00, real=0.04 secs]
2019-08-12T20:12:23.682+0800: 501599.291: [GC cleanup 1245M->1226M(4096M), 0.0041762 secs]
[Times: user=0.02 sys=0.00, real=0.01 secs]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-start]
2019-08-12T20:12:23.687+0800: 501599.296: [GC concurrent-cleanup-end, 0.0000487 secs]
2019-08-12T20:12:30.022+0800: 501605.632: [GC pause (G1 Humongous Allocation) (young) (to-space exhausted), 0.3849037 secs]
[Parallel Time: 165.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501605635.2, Avg: 501605635.2, Max: 501605635.3, Diff: 0.1]
......
[Eden: 666.0M(1970.0M)->0.0B(204.0M) Survivors: 8192.0K->0.0B Heap: 2909.5M(4096.0M)->1712.4M(4096.0M)]
[Times: user=1.44 sys=0.00, real=0.39 secs]
2019-08-12T20:12:32.225+0800: 501607.834: [GC pause (G1 Evacuation Pause) (mixed), 0.0800708 secs]
[Parallel Time: 74.8 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 501607835.5, Avg: 501607835.6, Max: 501607835.6, Diff: 0.1]
......
Этот лог выглядит намного понятнее, во-первых, из лога видно как минимум три проблемы:
- Появилась эвакуационная пауза смешанного типа
- Исчерпание пространства, вызванное частым огромным выделением G1, что указывает на то, что постоянно выделяется большое количество больших объектов.
- Время паузы GC достигает 0,3849037 сек, что для нас является самым невыносимым
Кроме того, есть более серьезная проблема, которую здесь не видно, а именно очень часты подобные логи!В пиковый период в основном печатается каждые 2 секунды.
jmap -histo
Из приведенного выше журнала GC мы можем в основном судить, что это вызвано тем, что приложение постоянно обновляет некоторые большие объекты.
Итак, что такое большой объект?
В общем случае это список локальных переменных, обычно с помощью jmap -histo можно проверить, какие объекты в куче занимают большой объем памяти и количество экземпляров.
Итак, давайте сначала посмотрим на распределение объектов в стеке через jmap -histo $pid:
num #instances #bytes class name
--------------------------------------------
1: 1120 1032796420 [B
2: 838370 105246813 [C
3: 117631 55348463 [I
4: 352652 31033457 java.lang.reflect.Method
5: 665505 13978410 java.lang.String
6: 198567 12368412 [Ljava.lang.Object
7: 268941 9467465 java.util.HashMap$Node
8: 268941 8064567 java.util.treeMap$Entry
9: 268941 7845665 java.lang.reflect.Field
10: 268941 7754771 [Ljava.util.HashMap$Node
....
Вообще говоря, если вам повезло и есть проблема с бизнес-кодом, вы обычно можете увидеть имена классов, задействованных в нашем бизнесе, в jmap-histo.
Но, к сожалению, не здесь.
Однако сообразительные студенты могут с первого взгляда увидеть, что эта куча на самом деле очень проблематична.
Давайте посмотрим на верхний [B (массив байтов), который занимает размер кучи 1032796420 (около 1G), в то время как экземпляров всего больше 1120. Просто разделив, каждый объект может иметь размер 1M!
Очевидно, что это большой объект, который мы ищем, но мы знаем только, что это какой-то массив байтов, и мы не знаем, что это за массив, поэтому нам нужно исследовать дальше.
Почему 1M большой объект?Поскольку наша куча имеет размер всего 4G, обычно G1 имеет максимум 2048 регионов, поэтому размер каждого региона составляет 2M.Когда G1 выделяет пространство памяти объекта нового поколения, он обнаруживает, что это объект больше, чем область. Половину размера можно рассматривать как большой объект, поэтому имеет место G1 Humongous Allocation
jmap -dump:format=b
Используйте команду jmap -dump:format=b,file=head.hprof $pid для создания дампа содержимого кучи JVM.После дампа вы ничего не увидите непосредственно в командной строке.Вы должны загрузить его локально и использовать некоторый анализ Инструменты для анализа Может быть много инструментов для анализа, таких как jvisualvm, jprofile, MAT и т. д.
Здесь я использую jvisualvm, откройте jvisualvm==>File==>Load==>Выберите только что загруженный файл head.hprof, затем нажмите «Класс», а затем нажмите «Сортировать по размеру», вы можете получить следующую картинку.
Видно, что количество экземпляров байтового массива в куче составляет всего 0,9%, а доля размера памяти достигает 30%, что указывает на то, что каждый экземпляр является большим объектом.
Затем мы дважды щелкаем «байт []» в первой строке, чтобы просмотреть детали этих массивов байтов.Мы видим, что многие объекты имеют размер 1048600 байт, что составляет ровно 1 М, но мы все еще не можем видеть содержимое этого массива, поэтому мы экспортируем этот массив в локальный, как показано ниже:
После экспорта откройте его с помощью Sublime Text и посмотрите, как показано ниже.
Хотя пока невозможно определить, какой код сгенерировал этот массив, но, по крайней мере, мы можем примерно определить причину проблемы: Где-то в коде должен быть новый массив байтов размером 1048600, а в реальной сцене этому массиву байтов требуется всего около 1 КБ, а незаполненные биты имеют значения по умолчанию 0.
Наконец, чтобы подтвердить нашу догадку, просто используйте
String str= new String (bytearr, "UTF-8");
System.out.println("str = [" + str + "]");
Распечатайте содержимое массива, и результат печати будет примерно следующим (я пропустил большую часть содержимого):
str = [p C0+org.apache.camel.impl.DefaultExchangeHolder�
exchangeIdinFaultFlagoutFaultFlag exceptioninBodyoutBody inHeaders
outHeaders
remoteOptRolefaceUrlversionfromIfromUserfailFaceUrl
.....
Затем найдите код с соответствующими ключевыми словами и, наконец, найдите настоящего виновника:
data = DefaultExchangeHolder.marshal(exchange, false);
baos = new ByteArrayOutputStream(1048600);// 真凶在这里
hessianOut = new Hessian2Output(baos);
hessianOut.startMessage();
hessianOut.writeObject(data);
hessianOut.completeMessage();
hessianOut.flush();
exchangeData = baos.toByteArray();
Конструктор ByteArrayOutputStream
public ByteArrayOutputStream(int size) {
if (size < 0) {
throw new IllegalArgumentException("Negative initial size: "
+ size);
}
buf = new byte[size];
}
На самом деле, перед использованием сериализации по Гессе был создан новый массив байтов размером 1 МБ, что привело к большому количеству больших объектов.Этот массив байтов используется только в качестве буфера и будет автоматически увеличиваться, когда размер недостаточен (буфер автоматически увеличивается по мере того, как в него записываются данные.), поэтому нет необходимости устанавливать его таким большим.