[logging] flush_log_cache doesn't flush everything?
I'm not sure I understand correctly, but it appears that flush_log_cache in the logging library doesn't actually force everything in the pipeline to be written by the logging thread to be written. Empirically, it seems that I had to add a sleep to the end of my program to cause everything to be written. Code-review-wise, and here I'm pretty sure I don't completely understand, it appears that flush_log_cache pushes things further down the pipeline but doesn't actually synchronize (wait for) the writing thread to complete. It seems like there maybe should be some kind of routine that "blocks" until all pending writes are complete, maybe just a wrapper around the ability to request the writing thread to finish, and then wait for it to complete. Maybe this mechanism is already present? I suppose that brings up other complications, such as what if some other thread logs something after we've asked it to stop. In the code I was testing, I had a ts_appender, to which I added a appender_array, to which I added 4 write_to_files. For ~ 10 seconds I wrote to the log. Then I call flush_log_cache. If I don't then sleep a few seconds, the files are not all identical. <?xml version="1.0" encoding="Windows-1252"?> <VisualStudioProject ProjectType="Visual C++" Version="7.10" Name="LogFlushTest" ProjectGUID="{E0693D56-29D0-435D-BB13-8DED291C84AE}" Keyword="Win32Proj"> <Platforms> <Platform Name="Win32"/> </Platforms> <Configurations> <Configuration Name="Debug|Win32" OutputDirectory="Debug" IntermediateDirectory="Debug" ConfigurationType="1" CharacterSet="2"> <Tool Name="VCCLCompilerTool" Optimization="0" AdditionalIncludeDirectories="$(BOOST_ROOT)" PreprocessorDefinitions="WIN32;_DEBUG;_CONSOLE" MinimalRebuild="TRUE" BasicRuntimeChecks="3" RuntimeLibrary="1" UsePrecompiledHeader="0" WarningLevel="3" Detect64BitPortabilityProblems="TRUE" DebugInformationFormat="4"/> <Tool Name="VCCustomBuildTool"/> <Tool Name="VCLinkerTool" OutputFile="$(OutDir)/LogFlushTest.exe" LinkIncremental="2" AdditionalLibraryDirectories=""$(BOOST_ROOT)\bin\boost\libs\thread\build\libboost_thread.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\log\build\libboost_log.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\program_options\build\libboost_program_options.lib\vc-7_1\debug\runtime-link-static\threading-multi";"$(BOOST_ROOT)\bin\boost\libs\log\build\libboost_log.lib\vc-7_1\debug\runtime-link-static";"$(BOOST_ROOT)\bin\boost\libs\program_options\build\libboost_program_options.lib\vc-7_1\debug\runtime-link-static";"$(BOOST_ROOT)\bin";"$(BOOST_ROOT)\bin\boost";"$(BOOST_ROOT)\bin\boost\libs"" GenerateDebugInformation="TRUE" ProgramDatabaseFile="$(OutDir)/LogFlushTest.pdb" SubSystem="1" TargetMachine="1"/> <Tool Name="VCMIDLTool"/> <Tool Name="VCPostBuildEventTool"/> <Tool Name="VCPreBuildEventTool"/> <Tool Name="VCPreLinkEventTool"/> <Tool Name="VCResourceCompilerTool"/> <Tool Name="VCWebServiceProxyGeneratorTool"/> <Tool Name="VCXMLDataGeneratorTool"/> <Tool Name="VCWebDeploymentTool"/> <Tool Name="VCManagedWrapperGeneratorTool"/> <Tool Name="VCAuxiliaryManagedWrapperGeneratorTool"/> </Configuration> <Configuration Name="Release|Win32" OutputDirectory="Release" IntermediateDirectory="Release" ConfigurationType="1" CharacterSet="2"> <Tool Name="VCCLCompilerTool" PreprocessorDefinitions="WIN32;NDEBUG;_CONSOLE" RuntimeLibrary="4" UsePrecompiledHeader="3" WarningLevel="3" Detect64BitPortabilityProblems="TRUE" DebugInformationFormat="3"/> <Tool Name="VCCustomBuildTool"/> <Tool Name="VCLinkerTool" OutputFile="$(OutDir)/LogFlushTest.exe" LinkIncremental="1" GenerateDebugInformation="TRUE" SubSystem="1" OptimizeReferences="2" EnableCOMDATFolding="2" TargetMachine="1"/> <Tool Name="VCMIDLTool"/> <Tool Name="VCPostBuildEventTool"/> <Tool Name="VCPreBuildEventTool"/> <Tool Name="VCPreLinkEventTool"/> <Tool Name="VCResourceCompilerTool"/> <Tool Name="VCWebServiceProxyGeneratorTool"/> <Tool Name="VCXMLDataGeneratorTool"/> <Tool Name="VCWebDeploymentTool"/> <Tool Name="VCManagedWrapperGeneratorTool"/> <Tool Name="VCAuxiliaryManagedWrapperGeneratorTool"/> </Configuration> </Configurations> <References> </References> <Files> <Filter Name="Source Files" Filter="cpp;c;cxx;def;odl;idl;hpj;bat;asm;asmx" UniqueIdentifier="{4FC737F1-C7A5-4376-A066-2A32D752A2FF}"> <File RelativePath=".\LogFlushTest.cpp"> </File> </Filter> <Filter Name="Header Files" Filter="h;hpp;hxx;hm;inl;inc;xsd" UniqueIdentifier="{93995380-89BD-4b04-88EB-625FBE52EBFB}"> </Filter> <Filter Name="Resource Files" Filter="rc;ico;cur;bmp;dlg;rc2;rct;bin;rgs;gif;jpg;jpeg;jpe;resx" UniqueIdentifier="{67DA6AB6-F800-4c08-8B7A-83BB121AAD01}"> </Filter> <File RelativePath=".\ReadMe.txt"> </File> </Files> <Globals> </Globals> </VisualStudioProject> // set environment variable BOOST_ROOT to point to your top level boost directory // (for example mine points to e:\C++\Boost\boost_1_32_0). #include "windows.h" #include <iostream> #include <iterator> #include <boost/bind.hpp> #include <boost/function.hpp> #include <boost/ref.hpp> //#include <boost/signals.hpp> #include <boost/tuple/tuple.hpp> #include <list> #include <functional> #include <fstream> #include <boost/log/log.hpp> #include <boost/log/functions.hpp> #include <boost/log/functions_ts.hpp> using namespace std; using namespace boost; using namespace boost::logging; void write_to_cout(const std::string &, const std::string &msg) { std::cout << msg; } DWORD WINAPI ThreadProc1(LPVOID lpParameter) { logger* l_pLogger = (logger*) lpParameter; DWORD l_dwEndTick = GetTickCount() + 5000; DWORD l_dwThreadID = GetCurrentThreadId(); static DWORD s_dwI = 0; static s_dwTIdx = 0; DWORD l_dwTIdx = ++s_dwTIdx; DWORD l_dwI = 0; while(GetTickCount() < l_dwEndTick) { l_dwI++; s_dwI++; BOOST_SCOPEDLOG(*l_pLogger) << "TID: " << l_dwThreadID << " (" << l_dwTIdx << "/" << s_dwTIdx << " i:" << l_dwI << " s:" << s_dwI << " abcdefghijklmnopqrstuvwxyz" << endl; } BOOST_SCOPEDLOG(*l_pLogger) << "TID: " << l_dwThreadID << " (" << l_dwTIdx << "/" << s_dwTIdx << " done" << endl; flush_log_cache(); --s_dwTIdx; return 0; } void ThreadTest(logger& rLogger, DWORD dwThreads, DWORD dwPostSleep) { BOOST_SCOPEDLOG(rLogger) << "Starting Thread test shortly for " << rLogger.name() << "..." << endl; Sleep(3000); list<HANDLE> l_l; for(DWORD i = 0; i < dwThreads; ++i) { DWORD l_dw = 0; HANDLE l_h = CreateThread(NULL, 0, ThreadProc1, &rLogger, 0, &l_dw); l_l.push_back(l_h); } while(l_l.begin() != l_l.end()) { HANDLE l_h = *l_l.begin(); WaitForSingleObject(l_h, INFINITE); l_l.pop_front(); } BOOST_SCOPEDLOG(rLogger) << "Thread test for " << rLogger.name() << " done." << endl; } int main(int argc, char* argv[]) { set_log_caching(true); logger l_lgArray("lgArray"); logger l_lgCout("lgCout"); add_appender("lgCout", write_to_cout); add_appender("lgArray", ts_appender( appender_array() .add(write_to_file("btArrayFile1.txt")) .add(write_to_file("btArrayFile2.txt")) .add(write_to_file("btArrayFile3.txt")) .add(write_to_file("btArrayFile4.txt")))); ThreadTest(l_lgArray, 1, 20000); flush_log_cache(); //If these sleeps aren't included, the btArrayFiles //are not all equal. for(int i = 0; i < 10; ++i) { Sleep(1000); BOOST_SCOPEDLOG(l_lgCout) << " " << i; } BOOST_SCOPEDLOG(l_lgCout) << endl; return 0; }
Hi Andy, Sorry for not explaining the role of flush_log_cache() in the docs. The flush_log_cache() should be called after you've *initialized* all the logs (in other words, after you've added all appenders and/or modifiers). In your code, it should be: // note: no need for the below call // set_log_caching(true); logger l_lgArray("lgArray"); logger l_lgCout("lgCout"); add_appender("lgCout", write_to_cout); add_appender("lgArray", ts_appender( appender_array() .add(write_to_file("btArrayFile1.txt")) .add(write_to_file("btArrayFile2.txt")) .add(write_to_file("btArrayFile3.txt")) .add(write_to_file("btArrayFile4.txt")))); flush_log_cache(); ThreadTest(l_lgArray, 1, 20000); The purpose of flush_log_cache() is to flush everything you've written to logs, before they were ***fully initialized***. This is especially useful in case you do logging when static variables are initialized -- without this mechanism, logging would happen too soon, and would end up writing nowhere. Example: BOOST_DEFINE_LOG(app,"app"); BOOST_LOG(app) << "where does this get written?"; // [1] add_appender("app", write_to_cout); add_appender("app", write_to_debug); // here, it knows where to log [1] flush_log_cache(); As for making all pending writes complete -- this is a defect of ts_appender() class -- which I want to correct. Best, John
I'm not sure I understand correctly, but it appears that flush_log_cache in the logging library doesn't actually force everything in the pipeline to be written by the logging thread to be written. Empirically, it seems that I had to add a sleep to the end of my program to cause everything to be written. Code-review-wise, and here I'm pretty sure I don't completely understand, it appears that flush_log_cache pushes things further down the pipeline but doesn't actually synchronize (wait for) the writing thread to complete. It seems like there maybe should be some kind of routine that "blocks" until all pending writes are complete, maybe just a wrapper around the ability to request the writing thread to finish, and then wait for it to complete. Maybe this mechanism is already present? I suppose that brings up other complications, such as what if some other thread logs something after we've asked it to stop.
In the code I was testing, I had a ts_appender, to which I added a appender_array, to which I added 4 write_to_files. For ~ 10 seconds I wrote to the log. Then I call flush_log_cache. If I don't then sleep a few seconds, the files are not all identical.
-- John Torjo, Contributing editor, C/C++ Users Journal -- "Win32 GUI Generics" -- generics & GUI do mix, after all -- http://www.torjo.com/win32gui/ -v1.6.3 (Resource Splitter) -- http://www.torjo.com/cb/ - Click, Build, Run!
John Torjo wrote:
Sorry for not explaining the role of flush_log_cache() in the docs.
The flush_log_cache() should be called after you've *initialized* all the logs (in other words, after you've added all appenders and/or modifiers).
Got it, thanks. In retrospect, I think the docs are actually reasonably clear on that point.
participants (2)
-
Andy Schweitzer -
John Torjo