Изначально планировалось написать статью "Почему Alibaba не разрешает использовать конкатенацию строк в выводе журнала?" », я в основном хочу рассказать об этой проблеме с точки зрения производительности, но когда тест производительности был на середине статьи, была обнаружена нештатная проблема.Фактические результаты испытаний и результаты, описанные в руководстве, диаметрально противоположны.из!
Господи, как такое могло случиться? В это время мое сердце отказывало, потому что статья была уже наполовину написана, что мгновенно поставило меня в неловкое положение.
«Руководство по разработке Java» от Alibaba Taishan Edition (последнее издание) описывается таким образом, в 4-й спецификации третьего подраздела второй главы:
[Обязательно] При выводе журнала заполнители используются для соединения строковых переменных.
Примечание. Поскольку при сращивании строк String будет использоваться метод append() StringBuilder, производительность несколько снижается. Использование заполнителей — это просто заменяющее действие, которое может эффективно улучшитьпредставление.
Положительный пример: logger.debug("Обработка сделки с id: {} и symbol: {}", id, symbol);
Из приведенного выше описания видно, что Ali принудительно использует заполнители для объединения строк в выводе журнала, потому что это может эффективно повысить производительность программы.
Однако, когда мы использовали для тестирования фреймворк JMH (Java Microbenchmark Harness, JAVA Microbenchmark Test Suite), официально предоставленный Oracle, мы обнаружили, что результаты полностью отличаются от описанных в руководстве.
PS: Для друзей, которые не знакомы с JMH, вы можете прочитать другую статью, которую я опубликовал "Официальный рекомендуемый Oracle инструмент для тестирования производительности! Просто, точно и интуитивно понятно!》
Тестирование производительности
В этой статье мы используем Spring Boot 2.2.6 для завершения теста.Сначала мы добавляем зависимость среды JMH в pom.xml Spring Boot:
<!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-core -->
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-core</artifactId>
<version>1.23</version>
</dependency>
<!-- https://mvnrepository.com/artifact/org.openjdk.jmh/jmh-generator-annprocess -->
<dependency>
<groupId>org.openjdk.jmh</groupId>
<artifactId>jmh-generator-annprocess</artifactId>
<version>1.23</version>
<scope>provided</scope>
</dependency>
Здесь следует отметить, что для общих проектов нам нужно только добавитьjmh-coreС пакетом зависимостей все в порядке, но если это проект Spring Boot, мы также должны добавитьjmh-generator-annprocessзависимости пакета и поместитеscopeУстановить какprovidedтип, если используется его значение по умолчаниюtestзаставит программу сообщить об ошибкеUnable to find the resource: /META-INF/BenchmarkList.
описание значения объема:
- compile: значение по умолчанию, указывающее, что зависимый проект должен участвовать в фазах компиляции, тестирования и выполнения текущего проекта, и обычно его необходимо добавлять при упаковке;
- test: указывает, что зависимый проект участвует только в работе, связанной с тестированием, и не будет использоваться в среде компиляции и выполнения, не говоря уже об упаковке;
- при условии: подходит для компиляции и тестирования, не будет упакован в каталог lib;
- среда выполнения: применяется только к среде выполнения и не будет использоваться в средах компиляции и тестирования.
Далее мы написали полный тестовый код:
import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
import java.util.concurrent.TimeUnit;
@BenchmarkMode(Mode.AverageTime) // 测试完成时间
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 2, time = 1, timeUnit = TimeUnit.SECONDS) // 预热 2 轮，每次 1s
@Measurement(iterations = 5, time = 3, timeUnit = TimeUnit.SECONDS) // 测试 5 轮，每次 3s
@Fork(1) // fork 1 个线程
@State(Scope.Thread) // 每个测试线程一个实例
@RestController
@RequestMapping("/log")
public class LogPrint {
private final Logger log = LoggerFactory.getLogger(LogPrint.class);
private final static int MAX_FOR_COUNT = 100; // for 循环次数
public static void main(String[] args) throws RunnerException {
// 启动基准测试
Options opt = new OptionsBuilder()
.include(LogPrint.class.getName() + ".*") // 要导入的测试类
.build();
new Runner(opt).run(); // 执行测试
}
@Benchmark
public void appendLogPrint() {
for (int i = 0; i < MAX_FOR_COUNT; i++) { // 循环的意图是为了放大性能测试效果
StringBuilder sb = new StringBuilder();
sb.append("Hello, ");
sb.append("Java");
sb.append(".");
sb.append("Hello, ");
sb.append("Redis");
sb.append(".");
sb.append("Hello, ");
sb.append("MySQL");
sb.append(".");
log.info(sb.toString());
}
}
@Benchmark
public void logPrint() {
for (int i = 0; i < MAX_FOR_COUNT; i++) { // 循环的意图是为了放大性能测试效果
log.info("Hello, {}.Hello, {}.Hello, {}.", "Java", "Redis", "MySQL");
}
}
}
Результаты теста следующие:
Из вышеприведенных результатов видно, что прямое использованиеStringBuilderМетод сплайсинга явно более эффективен, чем использование заполнителей, я ошибаюсь?
Примечание. Тестовая среда — Spring Boot 2.2.6 RELEASE, JDK 8 (JDK 1.8.0_10), MacOS (MacMini 2018).
Анализ исходного кода
Со скептическим настроем мы открыли исходный код slf4j, чтобы посмотреть, как реализован лежащий в основе метод заполнителя, поэтому я последовал заlog.infoМетод находит окончательный исходный код реализации заполнителя:
final public static FormattingTuple arrayFormat(final String messagePattern, final Object[] argArray, Throwable throwable) {
if (messagePattern == null) {
return new FormattingTuple(null, argArray, throwable);
}
if (argArray == null) {
return new FormattingTuple(messagePattern);
}
int i = 0;
int j;
// use string builder for better multicore performance
StringBuilder sbuf = new StringBuilder(messagePattern.length() + 50);
int L;
// for 循环替换占位符
for (L = 0; L < argArray.length; L++) {
j = messagePattern.indexOf(DELIM_STR, i);
if (j == -1) {
// no more variables
if (i == 0) { // this is a simple string
return new FormattingTuple(messagePattern, argArray, throwable);
} else { // add the tail string which contains no variables and return
// the result.
sbuf.append(messagePattern, i, messagePattern.length());
return new FormattingTuple(sbuf.toString(), argArray, throwable);
}
} else {
if (isEscapedDelimeter(messagePattern, j)) {
if (!isDoubleEscaped(messagePattern, j)) {
L--; // DELIM_START was escaped, thus should not be incremented
sbuf.append(messagePattern, i, j - 1);
sbuf.append(DELIM_START);
i = j + 1;
} else {
// The escape character preceding the delimiter start is
// itself escaped: "abc x:\\{}"
// we have to consume one backward slash
sbuf.append(messagePattern, i, j - 1);
deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
i = j + 2;
}
} else {
// normal case
sbuf.append(messagePattern, i, j);
deeplyAppendParameter(sbuf, argArray[L], new HashMap<Object[], Object>());
i = j + 2;
}
}
}
// append the characters following the last {} pair.
sbuf.append(messagePattern, i, messagePattern.length());
return new FormattingTuple(sbuf.toString(), argArray, throwable);
}
Как видно из приведенного выше исходного кода, внизу фактически используется так называемый заполнитель.StringBuilderДля достижения неудивительно, что производительность не так хороша, как при непосредственном использованииStringBuilder. Поскольку при замене заполнителя некоторые столбцы проверяются перед заменой и напрямую используютсяStringBuilderЭта часть работы по валидации может быть опущена.
Для того, чтобы убедиться, что я не ошибся, я включил режим отладки с помощью Idea, и результаты отладки показаны на следующем рисунке:
Как видно из приведенного выше рисунка, этот метод является фактическим методом выполнения заполнителя, то естьПроблема с производительностью, написанная в руководстве, действительно неверна.
Так что я просто разместил круг друзей:
Но я обнаружил, что редактор, который писал бумажную книгу, оказался и моим другом:
Таким образом, этой проблемы можно избежать, и она появится непосредственно в будущих бумажных книгах, что также является заслугой.
Расширение
Когда мы используем логи в Spring Boot, мы обычно пишем так:
private final Logger log = LoggerFactory.getLogger(LogPrint.class);
И писать такую строчку кода в каждом классе немного хлопотно.
В этот момент мы можем использовать@Slf4jкомментарий для замены строки вышеLoggerКод для создания объекта, полный пример использования выглядит следующим образом:
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;
@Slf4j
class LogTest {
@Test
void show() {
log.debug("Hello, {}.", "Debug");
log.info("Hello, {}.", "Info");
log.error("Hello, {}.", "Error");
}
}
Результат выполнения программы:
14:33:18.377 [main] DEBUG com.example.demo.LogTestTest - Hello, Debug.
14:33:18.382 [main] INFO com.example.demo.LogTestTest - Hello, Info.
14:33:18.382 [main] ERROR com.example.demo.LogTestTest - Hello, Error.
Из вышеприведенных результатов видно, чтоЛог выводился на консоль нормально.
Примечание: аннотация @Slf4j принадлежит ломбоку, поэтому, если вы хотите использовать аннотацию @Slf4j в своем проекте, вам необходимо убедиться, что в проект добавлены зависимости ломбока.
Суммировать
При выводе журнала следует использовать заполнители для конкатенации строковых переменных, потому что так писать более элегантно. Мы проверили исходный код slf4j и обнаружили, что нижний слой заполнителя также проходит черезStringBuilderсращивание для достижения.
Старая статья:
В ответ на призыв страны к «низкоуглеродной жизни, зеленому путешествию» Лао Ван решил в будущем ездить на велосипеде, чтобы не только сэкономить деньги, но и избежать пробок. внести свой вклад в страну. Для достижения этой цели счастливый Лао Ван достал свой старомодный Nokia и купил на 80% новый велосипед 28. Он вообразил, что теперь сможет жить счастливой жизнью.
Но после того, как я купил машину, я обнаружил, что в восточной части деревни полно 2 юаней, чтобы покататься на общем велосипеде в течение месяца Тебе не кажется это раздражающим? Мало того, Лао Ван также обнаружил, что купленная им машина не только неудобна в управлении, но и не поддерживает ее возврат в течение семи дней без причины.Это разозлило Лао Вана, и возврат был пятизвездочным отрицательным. обзор.
Глядя на продавца, я совсем не торопилась, только холодно ответила: мальчик, я все еще тебя боюсь? я сделаю это в этом месяцеУстановил штатный прилавок, а интернет-магазин все равно не открывается., плохой отзыв - это плохой отзыв.
Эта история глубоко говорит нам правду: если кто-то уже предоставил нам «велосипед», то нам не нужно тратить деньги, чтобы продать еще один.
Увидев это, некоторые люди могут спросить: мальчик, ты что, серьёзные технические статьи? То, о чем вы говорите, не имеет ничего общего с технологиями?
Эта история действительно имеет отношение к сегодняшней теме, давайте официально начнем...
Подпишитесь на официальный аккаунт «Java Chinese Community» и ответьте на «Галантные товары», чтобы получить 50 оригинальных галантерейных товаров.Топ-лист.