Комментарии 33
Любопытный момент: скорость сохранения логов на HDD диск (TOSHIBA HDWD120) оказалась выше чем на SSD
очень странный результат. может быть у вас используется синхронная запись? (хотя и в этом режиме ssd должен быть быстрее)
"Ложка дегтя" заключается в том, что память под очередь сообщений выделяется в момент создания Spdlog, и остается занятой на всем протяжении работы логгера. В данном тесте Spdlog использовал 1170 Мб. Остальные участники тестирования выделяют память по мере повышения нагрузки, и освобождают по мере понижения.
зачастую правильнее выделить один раз память, чем выделять-освобождать, получая фрагментацию.
хотя гигабайт памяти под логирование выглядит, конечно, ужасающе. ещё в ходу 32-битные операционные системы, где приложению всего доступно 2-3 ГБ )
15.10.2020
заметьте, все «конкуренты» используют естественным образом сортируемое представление даты.
очень странный результат. может быть у вас используется синхронная запись? (хотя и в этом режиме ssd должен быть быстрее)
По идее, в обоих случаях данные пишутся в кэш (write-back caching), а операционная система уже в фоне пишет их на диск.
С Twelve-Factor App methodology и отстреливанием логов по UDP в graylog/elk насколько актуален логгер в backend'e?
log_debug2_m << «Message was sent to socket»
<< ". Id: " << message->id()
<< ". Command: " << CommandNameLog(message->command())
<< ". Type: " << message->type()
<< ". ExecStatus: " << message->execStatus();
Вместо вызова одной функции форматирования типа snprintf здесь вызывается 9 функций operator<<.
С таким коленкором ни о каком быстродействии речи не может быть.
Вместо вызова одной функции форматирования типа snprintf здесь вызывается 9 функций operator<<. С таким коленкором ни о каком быстродействии речи не может быть.
А вот не факт, snprintf, возможно, будет медленнее, т.к. ему надо дополнительно каждый раз парсить форматную строку, у автора же всё разрешается на этапе компиляции:
https://github.com/hkarel/SharedTools/blob/master/logger/logger.h
Проблема же в другом месте:
https://github.com/hkarel/SharedTools/blob/master/logger/format.h
Каждое использование Format дорого обходится из-за аллокации памяти:
_buff = (char*)malloc(strlen(descript) + 1);
vector<char*> _chunks;
Я вообще не понимаю, зачем там выделять память.
Задача: имеется форматная строка и набор аргументов, которые надо зааппендить в Line вместо комбинации %?.
Решение:
#include <utility>
#include <tuple>
#include <iostream>
#include <boost/hana.hpp>
#include <boost/hana/ext/std/tuple.hpp>
template<typename... Args>
class Format
{
const char* _descript;
std::tuple<Args...> _args;
public:
Format(const char* descript, Args&&... args)
: _descript(descript), _args(std::forward<Args>(args)...)
{ }
template <typename TLine>
void WriteTo(TLine &line);
};
template <typename TLine>
class FormatWriter
{
const char* _descript;
TLine &line;
public:
FormatWriter(const char* descript, TLine &line)
: _descript(descript), line(line) {}
template <typename Arg>
void operator()(const Arg& arg)
{
while (*_descript != '\0')
{
if (_descript[0] != '%' || _descript[1] != '?')
{
line << *_descript++;
}
else
{
_descript += 2;
line << arg;
break;
// line << arg;
}
}
}
void Finish()
{
while (*_descript != '\0')
line << *_descript++;
}
};
template <typename... Args>
template <typename TLine>
void Format<Args...>::WriteTo(TLine &line)
{
FormatWriter formatWriter(_descript, line);
boost::hana::for_each(_args, formatWriter);
formatWriter.Finish();
}
template <typename... Args>
Format<Args...> format(const char *fmt, Args... args)
{
return Format<Args...>(fmt, std::forward<Args>(args)...);
}
int main(int argc, char **argv)
{
format("Hello, %?-%?%?! You are awesome!\n", "Meow", 4, 5).WriteTo(std::cout);
format("Too few arguments %?, %?, %?.\n", 1).WriteTo(std::cout);
format("Too much arguments %?\n", 1, 2, 3).WriteTo(std::cout);
return 0;
}Оператор << доопределите самостоятельно.
1. Появляется новая зависимость в виде boost библиотеки;
2. Предложенное решение нужно тестировать на быстродействие. DistortNeo, возьметесь?
Обход tuple легко переписывается на ванильном C++. Просто вместо одной строчки кода их будет десять. Собственно, в оригинальном коде так и было сделано.
Я предложил идею. Принимать её или нет — дело ваше. С удовольствием бы потестировал, но из-за сильно связанного кода мне придётся тащить весь проект и разбираться с зависимостями. Короче, оно того не стоит.
В случае логгера там не поток, а локальный строковый буфер.
Это не повод отказываться от оптимизации остального кода. Лучше одно выделение памяти под строковый буфер, чем одно — под буфер и ещё по два — под каждый вызов Format.
вы заранее знаете размер финальной строки в логе? или таки будем стандартный использовать с реалокацией?
да и подсунуть свой аллокатор, как делает тот же P7 вам вера не позволяет?
ну и знаете, может у вас логи по 5 букв, а у нас знаете бывает строка и на экран не влазит. хотя это уже крайности. глянул ради прикола, ну в принципе на nginx банальный access log, ну так, по 256 букв в строке будет на глазок, предложите Сысоеву свою оптимизацию логера )
коли вы так уверены в своем подходе, докажите цифрами )
фреймворк тестовый есть, реализация логера практически готова, устройте революцию )))
одно выделение под буфер?
В чём проблема выделять буфер по 2-4 кб сразу? Для 90% сообщений, а то и больше, этого хватит с запасом. Для более длинных сообщений понадобится реаллокация. Опять же, кастомные аллокаторы проблему решают, но у автора они не используются.
коли вы так уверены в своем подходе, докажите цифрами )
фреймворк тестовый есть, реализация логера практически готова, устройте революцию )))
Оплатите мне рабочее время — с радостью прооптимизирую и потестирую.
Я вообще не понимаю, зачем там выделять память.
Оператор << доопределите самостоятельно.
Доопределил. Ветка distortneo-format
Boost-решение немного отстает от исходного, всего на 3-5%. Однако, с увеличением длины формат-строки отставание так же увеличивается. При длине строки в 100 символов разница составляет уже 20%.
Несколько советов по улучшению:
1. ostream-style логгирование — это медленно. Особенно если логировать произвольные типы, которые умеют сериализоваться в std::ostream.
2. В вашем логгере в каждой вызове явное выделение памяти в Line (new Impl) + выделение памяти в деструкторе Line (new Message) + неявнЫЕ в std::string. Лучше использовать что-то типа ring buffer queue. Имея синтаксис printf/std::format практически всегда можно вычислить необходимое количество байт для передачи через ring buffer (есть нюансы).
3. Вместо спинлока в Logger::addMessage можно сделать N очередей для N потоков. Лок, в данном случае, будет только в момент создания очереди. В потоках использовать thread local storage.
Вместо спинлока в Logger::addMessage можно сделать N очередей для N потоков.
Или concurrent контейнеры.
Меня больше напрягает другое: потоки никак не передают информацию о новых сообщениях в мастер-поток. Он просто делает опрос по таймеру:
if (!threadStop() && messagesIsEmpty && (_flushLoop == 0))
{
static chrono::milliseconds sleepThread {20};
this_thread::sleep_for(sleepThread);
}1. ostream-style логгирование — это медленно. Особенно если логировать произвольные типы, которые умеют сериализоваться в std::ostream.Действительно, первичная реализация использовала std::stringstream, сейчас только строковый буфер.
2. В вашем логгере в каждой вызове явное выделение памяти в Line (new Impl) + выделение памяти в деструкторе Line (new Message) + неявнЫЕ в std::string. Лучше использовать что-то типа ring buffer queue. Имея синтаксис printf/std::format практически всегда можно вычислить необходимое количество байт для передачи через ring buffer (есть нюансы).Про выделение памяти явное и неявное — все верно. std::format, насколько я понимаю, доступен только с С++20, а у меня сейчас потолок С++17, да и основной формат вывода все таки потоковый.
Допустим, я буду использовать кольцевой буфер. Как определиться с его размером? Длина лог-сообщений в моих задачах варьируется от 100 символов, до 5Мб символов (бывает и больше).
3. Вместо спинлока в Logger::addMessage можно сделать N очередей для N потоков. Лок, в данном случае, будет только в момент создания очереди. В потоках использовать thread local storage.Не очень понятна мысль про N очередей для N потоков. Вы предлагаете для каждого рабочего потока иметь свою очередь?
Про выделение памяти явное и неявное — все верно. std::format, насколько я понимаю, доступен только с С++20, а у меня сейчас потолок С++17, да и основной формат вывода все таки потоковый.
Тут имелось ввиду использование в целом printf-style форматитирование.
Допустим, я буду использовать кольцевой буфер. Как определиться с его размером? Длина лог-сообщений в моих задачах варьируется от 100 символов, до 5Мб символов (бывает и больше).
Для начало стоит сказать, что ваш логгер форматирует строку в вызывающем потоке. Это медленно и этого можно избежать. Да, это можно сделать с ostream-style логгером, но с printf-style сделать будет проще и без костылей. Проще, потому что на момент логгирования можно подсчитать сколько нужно байт для логгирования (например: sizeof(указатель на метаданные: fmtstring, loglevel, etc) + sizeof (timestamp type) + sizeof (для тривиальных типов) + strlen(для строковых)) и очень часто размер известен на момент компиляции (жаль что в c++ нет constexpr аргументов, можно было бы сделать с гарантиями). Далее все это memcpy в ring buffer. Форматирование и другая обработка делается в отдельном потоке.
Да, тут нужно сделать оговорку, что ring buffer может переполниться, если пишущий поток медленно вычитывает. Но думаю это решаемо и в общем случае это увеличение размера ring buffer-а. В реальном приложении врятли получится создать такую нагрузку, что бы начать переписывать ring buffer по кругу.
Не очень понятна мысль про N очередей для N потоков. Вы предлагаете для каждого рабочего потока иметь свою очередь?
Именно, т.к. меньше потоков (логгирующих потоков) будут иметь доступ к примитиву синхронизации. А примитивы так или иначе точно будут. Даже спинлок будет давать задержку, если к ниму одновременно будут обращаться N потоков.
В своём простом логгере я неявно добавляю имя класса __PRETTY_FUNCTION__ внутри макроса
MYLOG("Hello %1 %2", param1, param2) и позже при выводе имею возможность фильтровать по имени класса — была ли такая идея в ALog ?
Добавить в текущее решение ALog фильтрацию по имени класса — возможно, но это уже будет новое решение (клон).
Несколько минут назад прогнал результаты для SpdLog и для P7.
Размер памяти 1мб под очередь сообщений, я даже не говорю про 1 гигабайт.
Условия:
- I7 870, Samsung 960, DDR 1600MHz — куда более старое железо по сравнению с тем что используется в статье
- Windows 10, Visual studio 2019, O3
- 5,000,000 messages
- 4 & 1 thread
Вот результаты:
- SpdLog, 1 thread => 1.7 seconds
- SpdLog, 4 threads => 1.3 seconds (метки времени перемешаны в выходном файле)
- P7, 1 thread => 0.6 seconds
- P7, 4 threads => 1.1 seconds (метки времени по порядку)
Расхождение с цифрами в статье в несколько раз.
Честно говоря теряюсь в догадках от куда такое соотношение.
Я попросил коллег прогнать мои тесты. У всех Ubuntu 18.04. Тесты на 4 потока, 5 млн. записей. Первое значение Logging time, второе — Flush time (в секундах).
AMD Ryzen 7 3800X (Десктоп)
ALog: 1.47/2.23
P7: 2.43/2.86
Spdlog: 3.79/3.79
Core i5-8400 2.80GHz (Десктоп)
ALog: 1.51/2.85
P7: 5.49/5.49
Spdlog: 3.19/3.19
Core i5-8300H 2.30GHz (Ноутбук)
ALog: 3.36/5.04
P7: 13.34/14.04
Spdlog: 3.12/3.12
Нельзя сказать, что результаты идеально бьются со значениями из статьи, но по крайней мере в рамках одного процессора можно заметить корреляции. В этой связи к Lau возникает вопрос: как у него получились такие результаты? Возможно, причина в Windows, или в ключе -O3. Выяснить это можно собрав оригинальный тест/тесты под Linux, но кода тестов нет.
Уточнение: тест для ноутбука выполнялся на аккумуляторе. Ниже тест "от сети"
Core i5-8300H 2.30GHz (Ноутбук, от сети)
ALog: 1.49/2.62
P7: 5.19/5.91
Spdlog: 3.06/3.06
ALog: плюс один логгер для C++ приложений