задний план
В прошлом Double Eleven объем заказов компании снова удвоился.Пока босс сидит в офисе и хихикает, мы все время дрожим на рабочей станции.Сталкиваясь с заббиксом, который время от времени выскакивает оповещения процессора, молча молимся что ничего не пойдет не так.
Молитвами, конечно, проблему не решить, даже включенным сервером.Тревогает ЦП, и надо честно посмотреть, почему пульсирует ЦП.
Далее следует трилогия по устранению неполадок процессора.
1. top -Hp $pid 找到最耗CPU的线程.
2. 将最耗CPU的线程ID转成16进制
3. 打印jstack, 到jstack里面查这个线程在干嘛
Конечно, если в вашей онлайн-среде установлены такие инструменты, как arthas, вы можете напрямую распечатать стеки n потоков, потребляющих больше всего ресурсов ЦП, запустив thread -n.Три шага помогут вам.
Наконец, найдите стек потоков, который потребляет больше всего ЦП, следующим образом:
"operate-api-1-thread-6" #1522 prio=5 os_prio=0 tid=0x00007f4b7006f800 nid=0x1b67c waiting on condition [0x00007f4ac8c4a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c10828c8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
...
Стоит отметить, что подобных потоков более 800... но некоторые из них не потребляют CPU.
проблема
Очевидно, это вызвано тем, что журнал печатает слишком много журналов (в этот момент должна быть неловкая, но вежливая ухмылка).
Когда все перешли к обсуждению того, как оптимизировать журналирование и ведение журнала дальше. Я нахмурился, чувствуя, что все не так просто:
Разве этот поток не приостановлен LockSupport.park и находится в состоянии WAITING?Если он приостановлен, это означает, что он перестанет занимать ЦП, так почему же он все еще потребляет ЦП?
Взгляните на комментарии в LockSupport.park, в которых явно упоминается, что потоки парковки больше не будут планироваться ЦП:
/**
* Disables the current thread for thread scheduling purposes unless the
* permit is available.
*
* <p>If the permit is available then it is consumed and the call
* returns immediately; otherwise the current thread becomes disabled
* for thread scheduling purposes and lies dormant until one of three
* things happens:
*
*/
public static void park() {
UNSAFE.park(false, 0L);
}
Экспериментируйте, чтобы увидеть правду
С этим вопросом я искал stackoverflow и обнаружил, что у многих людей есть этот вопрос.
Содержание нескольких вышеперечисленных вопросов многовато, да и переводить мне лень, поэтому прямо резюмирую выводы:
1. 处于waittig和blocked状态的线程都不会消耗CPU
2. 线程频繁地挂起和唤醒需要消耗CPU, 而且代价颇大
Но это чужой вывод, так ли это? Давайте проведем эксперимент с visualvm.
проблемный код
Сначала посмотрите на кусок кода, который точно будет потреблять 100% CPU:
package com.test;
public class TestCpu {
public static void main(String[] args) {
while(true){
}
}
}
visualvm показывает, что ЦП действительно потребляет 1 ядро, и основной поток также потребляет 100% ЦП:
Поток припаркован
Затем посмотрите, будут ли потоки парка потреблять процессор.
Код:
import java.util.concurrent.locks.LockSupport;
public class TestCpu {
public static void main(String[] args) {
while(true){
LockSupport.park();
}
}
}
visualvm показывает, что все спокойно и процессор не загружен:
заблокированная нить
Давайте посмотрим, потребляет ли заблокированный поток ЦП. И давайте на этот раз поиграем немного больше, чтобы увидеть, есть ли взаимоблокировка, будет ли резко увеличиваться ЦП (тупиковая блокировка — это два потока, блокирующих друг друга).
Код блокировки выглядит следующим образом:
package com.test;
public class DeadLock {
static Object lock1 = new Object();
static Object lock2 = new Object();
public static class Task1 implements Runnable {
@Override
public void run() {
synchronized (lock1) {
System.out.println(Thread.currentThread().getName() + " 获得了第一把锁!!");
try {
Thread.sleep(50);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lock2) {
System.out.println(Thread.currentThread().getName() + " 获得了第二把锁!!");
}
}
}
}
public static class Task2 implements Runnable {
@Override
public void run() {
synchronized (lock2) {
System.out.println(Thread.currentThread().getName() + " 获得了第二把锁!!");
synchronized (lock1) {
System.out.println(Thread.currentThread().getName() + " 获得了第一把锁!!");
}
}
}
}
public static void main(String[] args) throws InterruptedException {
Thread thread1 = new Thread(new Task1(), "task-1");
Thread thread2 = new Thread(new Task2(), "task-2");
thread1.start();
thread2.start();
thread1.join();
thread2.join();
System.out.println(Thread.currentThread().getName() + " 执行结束!");
}
}
Также видно, что, хотя VisualVm может обнаружить тупик, ЦП, потребляемый всей JVM, не сильно колеблется, то есть даже если тупик произойдет, теоретически он не повлияет на системный ЦП.
Конечно, несмотря на то, что тупик не повлияет на ЦП, ресурсы системы - это не только ЦП. Возникновение тупика может привести к исчерпанию определенных ресурсов и, в конечном итоге, к недоступности службы, поэтому тупик по-прежнему следует избегать.
Сценарии, которые часто переключают контексты потоков
Наконец, давайте посмотрим, влияет ли большое количество переключений потоков на ЦП JVM.
Сначала мы генерируем 2000 потоков и используем функцию LockSupport.park(), предоставленную jdk, для постоянной приостановки этих потоков, а затем используем LockSupport.unpark(t) для непрерывного пробуждения этих потоков. После пробуждения он немедленно приостанавливается, что позволяет постоянно переключать потоки.
код показывает, как показано ниже:
package com.test;
import java.util.ArrayList;
import java.util.List;
import java.util.Random;
import java.util.concurrent.locks.LockSupport;
public class TestCpu {
public static void main(String[] args) {
int threadCount = 2000;
if(args.length > 0){
threadCount = Integer.parseInt(args[0].trim());
}
final List<Thread> list = new ArrayList<>(threadCount);
// 启动threadCount个线程, 不断地park/unpark, 来表示线程间的切换
for(int i =0; i<threadCount; i++){
Thread thread = new Thread(()->{
while(true){
LockSupport.park();
System.out.println(Thread.currentThread() +" was unpark");
}
});
thread.setName("cpuThread" + i);
list.add(thread);
thread.start();
}
// 随机地unpark某个线程
while(true){
int i = new Random().nextInt(threadCount);
Thread t = list.get(i);
if(t != null){
LockSupport.unpark(t);
}
try {
Thread.sleep(1000);
} catch (InterruptedException e) {
e.printStackTrace();
}finally {
}
}
}
}
Снова взглянув на visualVm, обнаруживается, что ЦП всей JVM действительно начал увеличиваться, но когда дело доходит до уровня потоков, обнаружится, что каждый поток в основном не потребляет ЦП, что означает, что ЦП не потребляется самими этими нитями. Вместо этого система потребляет, когда выполняется переключение контекста потока:
состояние процессора JVM:
Загрузка процессора каждым потоком:
Анализ и заключение
Вернемся к стеку потоков в начале нашей статьи (15% загрузки ЦП):
"operate-api-1-thread-6" #1522 prio=5 os_prio=0 tid=0x00007f4b7006f800 nid=0x1b67c waiting on condition [0x00007f4ac8c4a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c10828c8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:209)
at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:210)
at ch.qos.logback.core.rolling.RollingFileAppender.subAppend(RollingFileAppender.java:235)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:100)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:383)
at ch.qos.logback.classic.Logger.info(Logger.java:579)
...
Как показано выше, потоки в состоянии WAITING не будут потреблять ресурсы ЦП, поэтому ЦП здесь определенно не потребляется после приостановки, а потребляется перед приостановкой.
Какой фрагмент кода потребляет больше всего? Ответ кроется в этом фрагменте кода в стеке:
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
Как мы все знаем, нижний уровень ReentrantLock реализован с использованием платформы AQS. Возможно, вы знакомы с AQS. Если вы не знакомы с ним, вот общее описание AQS:
1. AQS有个临界变量state,当一个线程获取到state==0时, 表示这个线程进入了临界代码(获取到锁), 并原子地把这个变量值+1
2. 没能进入临界区(获取锁失败)的线程, 会利用CAS的方式添加到到CLH队列尾去, 并被LockSupport.park挂起.
3. 当线程释放锁的时候, 会唤醒head节点的下一个需要唤醒的线程(有些线程cancel了就不需要唤醒了)
4. 被唤醒的线程检查一下自己的前置节点是不是head节点(CLH队列的head节点就是之前拿到锁的线程节点)的下一个节点,
如果不是则继续挂起, 如果是的话, 与其他线程重新争夺临界变量,即重复第1步
CAS
На втором этапе AQS, если конкурирующая блокировка не работает, она будет добавлена в конец очереди с использованием оптимистической блокировки CAS.Основной код выглядит следующим образом:
/**
* Inserts node into queue, initializing if necessary. See picture above.
* @param node the node to insert
* @return node's predecessor
*/
private Node enq(final Node node) {
for (;;) {
Node t = tail;
if (t == null) { // Must initialize
if (compareAndSetHead(new Node()))
tail = head;
} else {
node.prev = t;
if (compareAndSetTail(t, node)) {
t.next = node;
return t;
}
}
}
}
Глядя на приведенный выше код, представьте, что в крайних случаях (очень высокий параллелизм), если каждое выполнение compareAndSetTail терпит неудачу (т. е. возвращает false), то этот код довольно долго (правда) бесконечный цикл.
В нашем реальном случае, хотя это и не экстремальный случай, количество параллелизма также чрезвычайно велико (каждый поток вызывает logback каждый момент для регистрации), поэтому в некоторых случаях отдельные потоки будут автоматически запускаться в этом коде. и занимая процессор в течение длительного времени, В конечном итоге привести к тревоге процессора
CAS также является оптимистической блокировкой.Так называемый оптимизм означает, что ситуация конкуренции менее вероятна.Поэтому CAS не подходит для сценариев с жесткой конкуренцией блокировок, а пессимистические блокировки больше подходят для сценариев с жесткой конкуренцией блокировок, поэтому что поток приостановлен. Это сэкономит больше ресурсов процессора.
Переключение контекста потока в AQS
В реальной среде, если время выполнения кода критической секции относительно короткое (достаточно короткое время записи журнала), третий и четвертый этапы вышеупомянутого AQS также вызовут частое пробуждение потоков очереди CLH, и из-за to preemption Сбои блокировки часто приостанавливаются, поэтому это также приведет к большому количеству переключений контекста, потребляющих ресурсы процессора системы.
Судя по экспериментальным результатам, я думаю, что эта причина более вероятна.
Расширенное мышление
Так называемая высокая загрузка ЦП означает, что «загрузка ЦП» слишком высока. Например, для машины с 1 ядром ЦП использует 100%, а 8 ядер используют 800%, что означает, что ЦП используется полностью. Тогда 90% 1 ядра, 700% 8 ядер можно считать слишком высокой загрузкой ЦП.
Следствием использования ЦП является то, что другие задачи операционной системы не могут вытеснить ресурсы ЦП.В окне производительность зависает, а движение мыши очень неплавное.На стороне сервера вся JVM не может принимать новые запросы , и текущая логика обработки также не может быть выполнена, в результате чего происходит тайм-аут, а внешнее исполнение заключается в том, что вся система недоступна.
CPU% = (1 - idleTime / sysTime) * 100
idleTime: CPU空闲时间
sysTime: CPU在用户态和内核态的使用时间之和
Процессор планируется на основе квантов времени. Теоретически, независимо от того, сколько времени требуется потоку для обработки, время, которое он может выполнять, является временем кванта времени. После обработки процессор должен быть освобожден. Однако после того, как он освобождает ЦП, он все равно сразу пойдет снова хватать ЦП, а вероятность захвата такая же.Так что с уровня приложения иногда видно, что этот поток занимает 100%
Наконец, по опыту, высокая загрузка ЦП системы JVM обычно связана со следующими причинами:
- В коде есть бесконечный цикл
- JVM частый сборщик мусора
- Логика шифрования и дешифрования
- Обработка регулярных выражений
- Частые переключения контекста потока
Если вы действительно столкнулись с проблемой высокой загрузки процессора в онлайн-среде, вы можете проанализировать ее с этих точек зрения.
И последнее, но не менее важное: я хотел бы порекомендовать вам инструмент для анализа веб-сайта jstack в Интернете, который очень полезен.
Адрес веб-сайта:fastthread.io/