Overhaul of the Logging Infrastructure #1596
Conversation
…ace to satisfy ADL requirements.
- LogLevel is now a top level enum class. - Added a new log level Off to disable output from a specific module. - Logger::LogLevel is a deprecated alias to LogLevel. - Logger::Info, Debug, Error are deprecated aliases to LogLevel::... - Removed public "internal*" functions from Logger.Logger - Added LogSource struct to encapsulate source information. - Added shouldLog method to check if a log should be emitted for a given level and module. - Removed nonfunctional artifacts "m_LogStream" and "Logger::operator<<" - Added templated "log" functions that are friends to Logger. - Reworked PCPP_LOG macros to no longer utilize the now removed internal functions. - Added PCPP_LOG_INFO macro level. - Changed PCPP_LOG_ERROR to now check if the log should be emitted. - Fixed NetworkUtils log module name overlapping with NetworkUtils class. - Fixed missing enum value for PacketLogModuleSll2Layer.
Dimi1010
force-pushed
the
refactor/log-templates
branch
from
bd53c74
to
f21f85d
Compare
Codecov ReportAttention: Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## dev #1596 +/- ##
==========================================
- Coverage 83.15% 83.12% -0.03%
==========================================
Files 277 278 +1
Lines 48196 48307 +111
Branches 9991 10085 +94
==========================================
+ Hits 40078 40157 +79
+ Misses 7225 7040 -185
- Partials 893 1110 +217
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. |
Dimi1010
added
breaking change
Common++/header/Logger.h
Outdated
| std::ostringstream sstream; \ | ||
| sstream << message; \ |
There was a problem hiding this comment.
Can you please check if this change affects the PcapPlusPlus binary sizes?
I made a change in this PR a couple of years ago to significantly reduce the binary sizes: #748
There was a problem hiding this comment.
This is a breakdown on the install directory for the x64 release w/npcap.
Folder1 is the new size. Folder2 is the old size.
File Folder1Size Folder2Size AbsoluteDelta RelativeDelta
---- ----------- ----------- ------------- -------------
bin\Arping.exe 714240 639488 74752 10.47%
bin\ArpSpoofing.exe 703488 631296 72192 10.26%
bin\benchmark.exe 599552 562688 36864 6.15%
bin\DisplayLiveDevices.exe 30208 30208 0 0.00%
bin\DNSResolver.exe 748032 664064 83968 11.23%
bin\DnsSpoofing.exe 747520 671232 76288 10.21%
bin\HttpAnalyzer.exe 832512 743936 88576 10.64%
bin\IcmpFileTransfer-catcher.exe 730624 658432 72192 9.88%
bin\IcmpFileTransfer-pitcher.exe 742400 666112 76288 10.28%
bin\IPDefragUtil.exe 711680 655360 56320 7.91%
bin\IPFragUtil.exe 693248 637952 55296 7.98%
bin\PcapPrinter.exe 658432 612352 46080 7.00%
bin\PcapSearch.exe 661504 618496 43008 6.50%
bin\PcapSplitter.exe 720384 667648 52736 7.32%
bin\SSLAnalyzer.exe 822272 733184 89088 10.83%
bin\TcpReassembly.exe 799232 710144 89088 11.15%
bin\TLSFingerprinting.exe 796672 712704 83968 10.54%
lib\Common++.lib 5045102 4887832 157270 3.12%
lib\Packet++.lib 19849740 18454316 1395424 7.03%
lib\Pcap++.lib 3620658 2896688 723970 20.00%
Full breakdown: npcap-x64-release.txt
There was a problem hiding this comment.
Did you test it with MSVC or MinGW? Also, did you have a chance to test on Linux also?
I don't remember in which platform the impact was the highest, but I think it was Linux 🤔
There was a problem hiding this comment.
Msvc, I dont think I have mingw setup. I should be able to test the sizes on Unix via WSL.
There was a problem hiding this comment.
@Dimi1010 I see you're still working on it. Please let me know when the changes are done and when you want me to review the PR again.
It'd be good to make sure binary sizes don't increase. I'd test at least on Windows and Linux
There was a problem hiding this comment.
@seladb Ok, ended up keeping the optimization.
As bc82caf: Release builds ended up being:
- Windows
- Static Libraries
- Common++.lib - 4.7MB -> 5MB
- Packet++.lib - 17.6MB -> 19.7MB
- Pcap++.lib - 2.8MB -> 3.3MB
- Examples
- Same binary size or <=10KB increase.
- Static Libraries
- Linux (WSL)
- Static Libraries
- libCommon++.a - 408KB -> 444KB
- libPakcet++.a - 3.1MB -> 3.3MB
- libPcap++.a - 676KB -> 748KB
- Examples
- On average ~0.1MB increase on each binary.
- Static Libraries
This reverts commit be95ab8.
- Added optional compile time elimination of log calls below set level.
- Renamed printLogMessage to emit and changed visibility to public. - Added new class LogContext to encapsulate a single emittable log message. - Added new methods createLogContext which is practically a rework of internalCreateLogStream but returns a LogContext. - Added optional use of object pooling optimization for reusing log contexts. (Enabled via preprocessor flag PCPP_LOG_USE_OBJECT_POOL)
… minimum log level set to too high severity..
…ntext pooling. - Removed preprocessor variable PCPP_LOG_USE_OBJECT_POOL. - Disabled context pooling for the unit tests as it interferes with the memory leak checker.
… time minimum log level set to too high severity..
- Added documentation to new methods and classes. - Addressed explicit constructor warnings. - Moved disable of context pooling for unit tests to the main.cpp files of the respective tests.
- Added 2 preallocated log contexts to the object pool.
…hreading and eliminate possibility of data races during log emission.
| std::size_t m_maxPoolSize; /**< The maximum number of objects in the pool */ | ||
| std::mutex m_mutex; /**< Mutex for thread safety */ | ||
| std::stack<T*> m_pool; /**< The pool of objects */ |
There was a problem hiding this comment.
nit: the convention we usually have is for members to begin with m_ and then a capital letter, for example: m_MaxPoolSize, m_Mutex, m_Pool
| if (m_pool.empty()) | ||
| { | ||
| // We don't need the lock anymore, so release it. | ||
| lock.unlock(); |
There was a problem hiding this comment.
nit: do we really need to call unlock() here? The next line returns and will automatically release the lock 🤔
There was a problem hiding this comment.
The new T() operation will be under mutex lock in that case, which we don't want as it might be expensive in relation to the other operations in the function. In this branch the critical section ends when the pool determines that the context creation will be delegated to the heap allocator.
There was a problem hiding this comment.
while I agree with this statement, I'm not sure the performance gain is significant between the 2 options, and IMO, the simpler / more readable option is not to explicitly call unlock(). Having said that, I don't have a strong opinion about it, so if you insist this is better I'm ok with that
There was a problem hiding this comment.
Benchmarked the pool acquire/release perf and the new/delete perf (combined as I assume for each newly created context above the max, it will have to be deleted too).
All benchmarks are on MSVC x64 Release.
new/delete(warmup 5000, count 30000)- Total time: 9390600ns
- Avg time: 313ns
- Pool
acquireObjectRaw/releaseObjectRaw(warmup 5000, count 30000) - Single thread, only pooled items used.- Total time: 1191600ns
- Avg time: 39ns
So essentially, if the new T() is done under mutex lock, that essentially blocks all acquire/release operations in the pool for ~8x times the length of one pooled acquire/release cycle.
Benchmark sample code
#include <iostream>
#include <chrono>
#include "Logger.h"
template <class T> void benchmark(int warmup, int count, T fn)
{
for (size_t i = 0; i < warmup; i++)
{
fn();
}
auto clk = std::chrono::high_resolution_clock();
auto start = clk.now();
for (size_t i = 0; i < count; i++)
{
fn();
}
auto end = clk.now();
auto total_duration = std::chrono::duration_cast<std::chrono::nanoseconds>(end - start).count();
std::cout << "Total time: " << total_duration << "ns" << std::endl;
std::cout << "Avg time: " << total_duration / count << "ns" << std::endl;
}
void benchmarkNewDelete()
{
constexpr auto W = 5000;
constexpr auto N = 30000;
std::cout << "Benchmarking new/delete\n";
benchmark(W, N, []() {
pcpp::internal::LogContext* ctx = new pcpp::internal::LogContext();
delete ctx;
});
}
void benchmarkPool()
{
constexpr auto W = 5000;
constexpr auto N = 30000;
pcpp::ObjectPool<pcpp::internal::LogContext> pool(5, 2);
std::cout << "Benchmarking pool\n";
benchmark(W, N, [&pool]() {
auto* ctx = pool.acquireObjectRaw();
pool.releaseObjectRaw(ctx);
});
}
int main()
{
benchmarkNewDelete();
benchmarkPool();
return 0;
}
| else | ||
| { | ||
| // We don't need the lock anymore, so release it. | ||
| lock.unlock(); |
There was a problem hiding this comment.
Maybe add tests for this class?
In order to test it we might need to add properties like currentPoolSize() etc., but it'd be good to add tests to cover edge cases that are not covered in the logger
There was a problem hiding this comment.
Where do we keep the common tests?
There was a problem hiding this comment.
We don't have a place for it right now, so we put them under Pcap++Test
| @@ -66,6 +66,7 @@ namespace pcpp | |||
| } | |||
| catch (const std::invalid_argument& e) | |||
| { | |||
| (void)e; // Suppress the unreferenced local variable warning when PCPP_LOG_ERROR is disabled | |||
There was a problem hiding this comment.
Maybe instead of adding these we can change the macros to use message if disabled:
#if PCPP_ACTIVE_LOG_LEVEL >= PCPP_LOG_LEVEL_ERROR
# define PCPP_LOG_ERROR(message) PCPP_LOG(pcpp::LogLevel::Error, message)
#else
# define PCPP_LOG_ERROR(message) (void)message
#endifThere was a problem hiding this comment.
The issue there is that then these don't compile, and the statement to the right of the void cast needs to be valid.
PCPP_LOG_ERROR("Optional parameter length is out of bounds: " << (int)op.length);
There was a problem hiding this comment.
oh you're right. I'm wondering it we can find a way around it, however I can't think of something... maybe look at what other libraries do?
There was a problem hiding this comment.
I tried this which can sometimes discard the entire statement under optimizations, but not always and it depends on the compiler.
There was a problem hiding this comment.
well, I guess if there's no simple way around it we can leave it as is... 🤷♂️
| * @param level The log level for this message. | ||
| * @param source The log source. | ||
| */ | ||
| explicit LogContext(LogLevel level, LogSource const& source = {}) : level(level), m_Source(source) |
There was a problem hiding this comment.
Maybe call this parameter logLevel so it doesn't shadow the field with the same name?
| /** | ||
| * @brief The log level at which the message will be emitted. | ||
| */ | ||
| LogLevel level = LogLevel::Info; |
There was a problem hiding this comment.
Why not make it a private member? 🤔
There was a problem hiding this comment.
It is left from prior to createLogContext having overloads to accept LogSource and LogLevel, so the level needed to be switched manually afterwards. I suppose it can be set to private, as it is not used directly atm.
| */ | ||
| void internalPrintLogMessage(std::ostringstream* logStream, Logger::LogLevel logLevel, const char* file, | ||
| const char* method, int line); | ||
| void useContextPooling(bool enabled, std::size_t preallocate = 2) |
There was a problem hiding this comment.
We don't use this method anymore because we always use context pooling. Do we still need it?
If we decide we don't need it, we can probably remove m_UseContextPooling also
There was a problem hiding this comment.
Eh, it depends. The unit tests started having memory leak false positives again, after I added a mutex on the defaultLogPrinter to remove the possibility of data races when outputting to the console. Need to fix that before a final call can be made.
| * @return A new LogContext. | ||
| */ | ||
| std::unique_ptr<internal::LogContext> createLogContext(); | ||
| /** |
There was a problem hiding this comment.
nit: add a line break. Also in line 434
| * @param source The log source. | ||
| * @param message The object to be logged. | ||
| */ | ||
| template <class T> void logError(LogSource const& source, T const& message) |
There was a problem hiding this comment.
do we need logError(), logInfo() and logDebug()? We have the macros for that, no?
Overhaul of the Logging Infrastructure
Changes
LogLevelhas been updated to anenum classand moved to thepcppnamespace.Loggerretains aliases to the new enum.LogModulevalues in theLoggingModuleenum.LogSource: Encapsulates file, function, line number and module information.LogContext: Encapsulates the context of a single log message.Loggerclass into public methods with documentation.internalCreateLogStreamwithcreateLogContext.internalPrintLogMessagewithemit.log*functions toLoggerclass to allow logging, through runtime methods.LogContextto reduce allocation overhead.ObjectPool<T>class to facilitate pooling for reusable objects.useContextPooling(false)on theLoggerinstance.PCPP_LOGmacros at compile time viaPCPP_ACTIVE_LOG_LEVELpreprocessor variable.std::mutexlocking indefaultLogPrinterto eliminate possible data races during log message emission.ostream& operator<<overloads forIPAddressandMacAddressinsidepcppto satisfy ADL (Argument-Dependent Lookup).LogContext Pooling Optimization
When enabled, the pooling optimization introduces the following behavior:
Allocation on
createLogContext:createLogContextis called, the pool is queried for an availableLogContext.LogContextis found, a new one is created immediately.Releasing on
emit:emitmethod with aunique_ptr<LogContext>parameter is called, theLogContextis returned to the pool after the operation completes.LogContextis stored for reuse.LogContextis deleted.Optimization Benchmarks
Performance benchmarks highlight the impact of enabling the pooling optimization:
Windows 10 - MSVC x64 (Release Build)
WSL (Ubuntu 22.04) - GCC x64 (Release Build)
Notes
LogLeveland other enums may introduce minor compatibility issues, they align with modern C++ best practices.