предыстория истории
Ди~ди~ди~, авария на производстве, утечка памяти!
Вчера днем неожиданно получил известие по эксплуатации и обслуживанию, что в производственной среде некой системы в ветке произошла утечка памяти.Пожалуйста, помогите проверить.
Процесс устранения неполадок
Первый шаг — войти
Аварийный лог, данный веткой, вероятно, такой (ввиду регламента компании, запрещающего скриншоты, запрещающие фотографии, и запрещающего любую постороннюю информацию, вот похожая ошибка, которую я нашел в Интернете):
LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
#1:
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:273)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:253)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:646)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:581)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460)
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
java.lang.Thread.run(Thread.java:748)
Это невероятно, ByteBuf не освобождается, что приводит к утечке памяти.
Второй шаг, посмотрите на индикаторы памяти
Теперь, когда вы знаете, что это утечка памяти, пусть специалисты по эксплуатации и обслуживанию изучат использование памяти, особенно использование памяти вне кучи (поскольку используется Netty). использование в куче нормально, а память вне кучи остается высокой.
Хорошо, на данный момент можно четко утверждать, что за пределами кучи есть утечка памяти.
На данный момент есть два шага: один — заменить шлюз наблюдением стресс-теста zuul, а другой — устранить утечки памяти.
Третий шаг — закодировать
Пусть ответственный за этот проект в ветке даст код, я его открыл, и остолбенел, всего лишь простойSpring Cloud GatewayПроект также содержит два класса: AuthFilter для проверки разрешений и XssFilter для предотвращения атак.
Spring Cloud Gateway использует Netty, а zuul 1.x использует Tomcat.Эта статья взята из исходного кода Gong Zong Consumption Tong.
Четвертый шаг, первоначальное подозрение
Быстро просканируйте код каждого класса и посмотрите код, относящийся к ByteBuf в XssFilter.Однако нет явной информации о том, что ByteBuf не выпущен.Это очень просто.Сначала заблокируйте этот класс, чтобы увидеть, нет ли утечки памяти.
Однако как определить, есть ли утечка памяти? Вы не можете удалить этот класс, просто запустите его на производстве.
Пятый шаг, параметры и трансформация мониторинга
На самом деле это очень просто. Студенты, которые видели исходный код Netty, должны знать лучше. Netty использует по умолчанию池化的直接内存Реализованный ByteBuf — это PooledDirectByteBuf, поэтому для отладки в первую очередь следует отключить функцию объединения.
Прямая память, то есть память вне кучи.
Зачем отключать пул?
Поскольку пулинг — это кеш памяти, он выделяет 16М памяти за раз и не освобождает ее сразу.Неудобно наблюдать после включения пула, если только не отлаживать медленно.
Итак, как отключить функцию объединения?
В Netty все ByteBuf передаются черезByteBufAllocatorДля создания есть аллокатор по умолчанию в интерфейсе ByteBufAllocator, найдите аллокатор по умолчанию, а затем найдите место, где он был создан, вы можете увидеть соответствующий код.
public interface ByteBufAllocator {
ByteBufAllocator DEFAULT = ByteBufUtil.DEFAULT_ALLOCATOR;
}
public final class ByteBufUtil {
static final ByteBufAllocator DEFAULT_ALLOCATOR;
static {
// 本文来源于工纵耗彤哥读源码
String allocType = SystemPropertyUtil.get(
"io.netty.allocator.type", PlatformDependent.isAndroid() ? "unpooled" : "pooled");
allocType = allocType.toLowerCase(Locale.US).trim();
ByteBufAllocator alloc;
if ("unpooled".equals(allocType)) {
alloc = UnpooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: {}", allocType);
} else if ("pooled".equals(allocType)) {
alloc = PooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: {}", allocType);
} else {
alloc = PooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: pooled (unknown: {})", allocType);
}
DEFAULT_ALLOCATOR = alloc;
}
}
Видно, что черезio.netty.allocator.typeконтролируется этим параметром.
ОК, добавьте этот параметр в параметры запуска JVM и назначьте егоunpooled.
После отключения функции пулинга необходимо иметь возможность наблюдать, действительно ли происходит утечка памяти в режиме реального времени, как это сделать?
На самом деле это тоже очень просто, НеттиPlatformDependentЭтот класс будет подсчитывать все прямое использование памяти.
Недавно я изучал исходный код Netty, поэтому у меня есть четкое представление о различных деталях Netty. Эта статья взята из исходного кода Gong Zongxuan Tong. Я все еще готовлю ее недавно. Когда она будет закончена, я начнет создание столбца Netty.
Итак, нам нужно просто написать таймер и регулярно выводить эту статистическую информацию, здесь я приведу непосредственно код:
@Component
public class Metrics {
@PostConstruct
public void init() {
ScheduledExecutorService scheduledExecutorService = Executors.newSingleThreadScheduledExecutor();
scheduledExecutorService.scheduleAtFixedRate(()->{
System.out.println("used direct memory: " + PlatformDependent.usedDirectMemory());
}, 1, 1, TimeUnit.SECONDS);
}
}
Просто поместите его в каталог на том же или более низком уровне, что и класс запуска.
На этом этапе объединение и мониторинг завершены, а затем выполняется отладка.
Шестой шаг, предварительная отладка
Запустите класс запуска напрямую и просмотрите журналы.
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
В начале прямая память нормальная, всегда 0.
Отправьте случайный запрос, сообщите 404 и наблюдайте, что прямая память не изменилась, она по-прежнему равна 0, что указывает на то, что недостаточно случайно смоделировать запрос, который был напрямую перехвачен spring и еще не дошел до Netty.
Шаг седьмой, изменить конфигурацию
Если какой-либо запрос не работает, он может только имитировать обычную переадресацию запроса.Я быстро запустил проект SpringBoot, определил в нем запрос и изменил конфигурацию шлюза, чтобы его можно было переадресовать:
spring:
cloud:
gateway:
routes:
- id: test
uri: http://localhost:8899/test
predicates:
- Path=/test
Восьмой шаг, снова отладка
После изменения конфигурации запустите два проекта одновременно, один шлюз и один springboot, отправьте запрос и наблюдайте за использованием прямой памяти:
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
Конечно же, память не была освобождена.
Шаг девятый, удаляем XssFilter
Чтобы проверить изначально подозреваемый XssFilter, удалите его, снова запустите проект, отправьте запрос и понаблюдайте за использованием прямой памяти.
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
Проблема все еще существует, и она все еще того же размера, что и предыдущая утечка.
Дело обстоит именно так: Netty определяет размер каждого выделения памяти путем предположения. Начальное значение этого предположения равно 1024.
@Override
public ByteBuf allocate(ByteBufAllocator alloc) {
return alloc.ioBuffer(guess());
}
Разве вы не ожидали, что у Нетти будет такая милая сторона ^^, кхм, не в тему, насильно отодвиньте ее!
Затем есть еще один 7B, который хранит перевод строки и возврат каретки.Этот 7B не будет освобожден, и при суммировании он равен 1031.
private static final byte[] ZERO_CRLF_CRLF = { '0', CR, LF, CR, LF };
// 2B
private static final ByteBuf CRLF_BUF = unreleasableBuffer(directBuffer(2).writeByte(CR).writeByte(LF));
// 5B
private static final ByteBuf ZERO_CRLF_CRLF_BUF = unreleasableBuffer(directBuffer(ZERO_CRLF_CRLF.length)
.writeBytes(ZERO_CRLF_CRLF));
Ну интересно, раз это не проблема XssFilter, то будет ли проблема AuthFilter?
Десятый шаг, убить AuthFilter
Просто сделайте это, убейте AuthFiler, перезапустите проект, отправьте запрос и наблюдайте за прямой памятью:
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
Проблема все еще существует, или знакомый размер памяти.
В этот момент мое мышление уже не гладко, и следующий путь отклонения.
Одиннадцатый шаг, мышление
После удаления друг за другом XssFilter и AuthFilter остался только один класс запуска, ну и конечно новый класс мониторинга.
Может ли быть проблема с самим Spring Cloud Gateway?Эй, я кажется открыл для себя новый мир.Если я обнаружу, что есть проблема с Spring Cloud Gateway, я смогу хвастаться этим позже (внутренний YY ).
Поскольку выделение памяти не было освобождено, мы найдем место, где выделяется память, и сделаем точку останова.
Из предыдущего анализа мы уже знаем, что используемый распределитель памяти — UnpooledByteBufAllocator, а затем делаем точку останова в его методе newDirectBuffer(), потому что здесь у нас прямая утечка памяти.
Двенадцатый шаг, пошаговая отладка
По идее одиннадцатого шага, нажимаем точку останова в методе newDirectBuffer() UnpooledByteBufAllocator, отлаживаем шаг за шагом и, наконец, приходим к этому методу:
// io.netty.handler.codec.ByteToMessageDecoder.channelRead
@Override
public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
if (msg instanceof ByteBuf) {
CodecOutputList out = CodecOutputList.newInstance();
try {
first = cumulation == null;
// 1. 返回的是msg本身，msg是一个ByteBuf
cumulation = cumulator.cumulate(ctx.alloc(),
first ? Unpooled.EMPTY_BUFFER : cumulation, (ByteBuf) msg);
// 2. 解码，本文来源于工纵耗彤哥读源码
callDecode(ctx, cumulation, out);
} catch (DecoderException e) {
throw e;
} catch (Exception e) {
throw new DecoderException(e);
} finally {
if (cumulation != null && !cumulation.isReadable()) {
numReads = 0;
// 3. 释放内存
cumulation.release();
cumulation = null;
} else if (++ numReads >= discardAfterReads) {
// We did enough reads already try to discard some bytes so we not risk to see a OOME.
// See https://github.com/netty/netty/issues/4275
numReads = 0;
discardSomeReadBytes();
}
int size = out.size();
firedChannelRead |= out.insertSinceRecycled();
// 4. 读取完out中剩余的值
fireChannelRead(ctx, out, size);
// 5. 回收out
out.recycle();
}
} else {
ctx.fireChannelRead(msg);
}
}
В середине это занимало несколько часов, особенно если я случайно пропускал ChannelPipeLine, и мне приходилось начинать все сначала, действительно только по одному шагу за раз.
Этот метод в основном используется для преобразования ByteBuf в сообщение.Сообщение — это сообщение, которое можно понимать как простой объект Java.Основная логика отмечена в приведенном выше коде.
Как видите, естьcumulation.release();, это место, где память освобождается, но не освобождается.До вызова этой строки кода счетчик ссылок msg(=cumulation) равен 4, а после освобождения - 2, поэтому счетчик все еще есть , который не может быть переработан.
После шагов 4 и 5 ниже аут восстанавливается, а msg так и не восстанавливается Проблема должна быть в этом куске.
Я запутался здесь, включая код в декодировании. Я читал его много раз. Преобразованный объект в msg, который здесь не выпущен, — это DefaultHttpContent, который представляет собой тело запроса Http, но вот возвращаемое значение Тело HTTP-запроса.
Меня это тоже немного смущает.Я пробовал, и тело Http-запроса похоже не дошло до этой логики, и я неоднократно искал тело Http-запроса.Спустя долгое время не было прогресс.
К 21:00 офис был пуст и свет выключен (во время эпидемии в каждый отдел могли зайти всего несколько человек в день), поэтому я собрался и пошел домой.
Тринадцатый шаг, взять такси домой
Когда я был в машине, я все время думал над этим вопросом и вспоминал весь процесс, может быть, я ехал не в ту сторону?
Прошло много времени с выхода Spring Cloud Gateway, и я не слышал об утечках памяти, и тут я начал сомневаться в себе.
Нет, мне нужно самому написать проект, когда я приду домой, и попробовать его с помощью Spring Cloud Gateway.
Четырнадцатый шаг, напишите проект, использующий Spring Cloud Gateway.
Придя домой, я быстро включил компьютер, написал проект с использованием Spring Cloud Gateway и проект SpringBoot, включил мониторинг, убрал функцию пулинга, запустил проект, отправлял запросы и наблюдал за прямой памятью.
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
Нани, Axiba, здесь было совершенно ясно, что это не проблема Spring Cloud Gateway, в чем проблема?
Должно быть, это неправильная поза, но в проекте компании больше ничего нет, я удалил все классы, и остался только класс запуска.
О нет, pom-файл.
Откройте трамплин, войдите на компьютер компании, проверьте pom.xml и обнаружите, что там есть некоторые ссылки на SpringBoot или сам SpringCloud.
Ну нет, есть общий пакет, общий пакет, написанный самой веткой, нажимаешь на него, и в нем котируются три jar-пакета, среди которых особенно выделяется один, tomcat! ! ! !
О мой второй олимпиец, в это время очень хочется маму поругать, в чем дело~~
На самом деле, я должен был подумать о проблеме pom, когда удалял AuthFilter, в то время я только заботился о проблеме, что YY Spring Cloud Gateway может иметь ошибки, поэтому я погрузился в нее.
Мы знаем, что Spring Cloud Gateway использует Netty в качестве сервера для получения запросов, а затем перенаправляет их нижестоящим системам.Что произойдет, если мы упомянем здесь tomcat? Это действительно интересно.
Пятнадцатый шаг, убить кота
В файле pom исключите пакет jar tomcat, перезапустите проект, отправьте запрос и наблюдайте за прямой памятью:
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
О, нет проблем, это призрак кота.
Итак, как кот проделывает трюки? Добавление tomcat также может нормально отвечать на запрос, и запрос также может нормально пересылаться и возвращаться клиенту.Более того, что еще страшнее, это то, что Netty действительно используется внутри для чтения и записи запроса, что действительно волшебно.
Шаг 16: Откройте для себя новый мир
Чтобы проверить эту проблему, мы все равно сначала выйдем из трамплина, вернемся к своему компьютеру, добавим tomcat в pom, запустим проект, эй, я действительно могу встать, получайте удовольствие~~
Может быть, tomcat и Netty одновременно прослушивают один и тот же порт, и оба работают?
Обратите внимание на журнал запуска проекта:
Connected to the target VM, address: '127.0.0.1:52162', transport: 'socket'
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.2.6.RELEASE)
2020-05-19 08:50:04.448 INFO 7896 --- [ main] com.alan.test.Application : No active profile set, falling back to default profiles: default
2020-05-19 08:50:04.829 INFO 7896 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=082e67ca-d4c7-3a8c-b051-e806722fd225
2020-05-19 08:50:04.998 INFO 7896 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2020-05-19 08:50:05.006 INFO 7896 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2020-05-19 08:50:05.006 INFO 7896 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.33]
2020-05-19 08:50:05.859 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [After]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Before]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Between]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Cookie]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Header]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Host]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Method]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Path]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Query]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [ReadBodyPredicateFactory]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [RemoteAddr]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : 本文来源于工纵耗彤哥读源码
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [CloudFoundryRouteService]
2020-05-19 08:50:06.731 INFO 7896 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2020-05-19 08:50:07.304 INFO 7896 --- [ main] com.alan.test.Application : Started Application in 4.271 seconds (JVM running for 5.0)
Выяснилось, что запущен только tomcat, так как же он передает запрос Netty для обработки?
Шаг 17, кот -> Нетти
Учащиеся, изучившие NIO, должны знать, что NIO делит SocketChannel на два типа: ServerSocketChannel и SocketChannel.Среди них ServerSocketChannel создается при запуске службы для отслеживания прибытия клиентских подключений, а SocketChannel представляет соединение между клиентом и сервером.
Учащиеся, прочитавшие исходный код NIO, также знают, что SocketChannel создается через ServerSocketChannel.
Студенты, которые читали исходный код Netty, также знают, что Netty делит эти каналы на NioXxxChannel, EpollXxxChannel и т. д. в соответствии с различными протоколами Каналы для каждого протокола также делятся на NioServerSocketChannel, NioSocketChannel и т. д.
На платформе Windows NioXxxChannel используется по умолчанию, и из вышеизложенного видно, что NioSocketChannel нужно создавать через NioServerSocketChannel, если Netty используется нормально, то это действительно так.
На следующем рисунке показан стек потоков, когда NioSocketChannel создается при обычном использовании Netty:
Однако наша текущая сцена — кот + Нетти, так что же это?
В этот момент нажмите точку останова в методе построения NioSocketChannel, отправьте запрос, обнаружите, что точка останова находится в методе построения NioSocketChannel, и наблюдайте за ситуацией в стеке потоков (снизу вверх):
Видно, что после tomcat->spring->reactor->reactor-netty->netty, после тысяч ходов, наконец-то был создан NioSocketChannel.
Ситуация здесь немного сложная, и мы ее подробно разберем позже, когда будет время.
Шаг 18, утечка памяти
Как видно из вышесказанного, Tomcat наконец-то передал обработку запроса Netty, но почему происходит утечка памяти? Это все еще проблема.
После моего сравнения и тестирования проблема осталась в коде двенадцатого шага, при использовании обычного запроса Netty в NioEventLoop в fireChannelRead() будет добавлена задача, вызываемаяMonoSendMany.SendManyInner.AsyncFlush:
final class AsyncFlush implements Runnable {
@Override
public void run() {
if (pending != 0) {
ctx.flush();
}
}
}
Это используется для фактической записи данных в буфер записи (чтения и записи), и в то же время, это также очистит данные в буфере записи, то есть клиент может получить только результат ответ после вызова этого метода, и При использовании tomcat + Netty эта задача не выполняется, и данные отправляются клиенту (предположим, что они могут быть отправлены через соединение tomcat вместо самого NioSocketChannel), это устаревшая проблема , и я изучу это позже.
Суммировать
В этом производственном событии хоть и весь код относительно простой, но делается давно.Вот несколько моментов:
- Не сомневайтесь в фреймворках с открытым исходным кодом, особенно в таких, как Spring, которые используются многими людьми.
- Когда вы не можете найти причину проблемы, вы можете сделать перерыв, расслабиться и передумать;
- Почему tomcat и Netty могут сосуществовать в Spring Cloud Gateway?Это проблема, и вопрос следует поднять официальному лицу.Когда обнаруживается, что они существуют одновременно, не лучше, чтобы программа не запускалась напрямую ;
В данный момент готовлю колонку Нетти, меня ждут старые утюги.