From 2e50624b2827e147b93307e41cb242ac5e395f54 Mon Sep 17 00:00:00 2001 From: Peter Conrad Date: Thu, 12 Sep 2019 16:01:09 +0200 Subject: [PATCH 1/4] Check + rotate logs while logging not by scheduled task --- src/log/file_appender.cpp | 52 ++++++++++++--------------------------- 1 file changed, 16 insertions(+), 36 deletions(-) diff --git a/src/log/file_appender.cpp b/src/log/file_appender.cpp index c2efebf2f..4f5ab14de 100644 --- a/src/log/file_appender.cpp +++ b/src/log/file_appender.cpp @@ -21,15 +21,7 @@ namespace fc { boost::mutex slock; private: - future _rotation_task; - time_point_sec _current_file_start_time; - - time_point_sec get_file_start_time( const time_point_sec& timestamp, const microseconds& interval ) - { - int64_t interval_seconds = interval.to_seconds(); - int64_t file_number = timestamp.sec_since_epoch() / interval_seconds; - return time_point_sec( (uint32_t)(file_number * interval_seconds) ); - } + boost::atomic _current_file_number; public: impl( const config& c) : cfg( c ) @@ -54,22 +46,22 @@ namespace fc { } } - ~impl() - { - try - { - _rotation_task.cancel_and_wait("file_appender is destructing"); - } - catch( ... ) - { - } - } - void rotate_files( bool initializing = false ) { - FC_ASSERT( cfg.rotate ); + if( !cfg.rotate ) return; + + int64_t interval_seconds = cfg.rotation_interval.to_seconds(); fc::time_point now = time_point::now(); - fc::time_point_sec start_time = get_file_start_time( now, cfg.rotation_interval ); + int64_t new_file_number = now.sec_since_epoch() / interval_seconds; + if( initializing ) + _current_file_number.store( new_file_number ); + else + { + int64_t prev_file_number = _current_file_number.load(); + if( prev_file_number >= new_file_number ) return; + if( !_current_file_number.compare_exchange_weak( prev_file_number, new_file_number ) ) return; + } + fc::time_point_sec start_time = time_point_sec( (uint32_t)(new_file_number * interval_seconds) ); string timestamp_string = start_time.to_non_delimited_iso_string(); fc::path link_filename = cfg.filename; fc::path log_filename = link_filename.parent_path() / (link_filename.filename().string() + "." + timestamp_string); @@ -79,14 +71,6 @@ namespace fc { if( !initializing ) { - if( start_time <= _current_file_start_time ) - { - _rotation_task = schedule( [this]() { rotate_files(); }, - _current_file_start_time + cfg.rotation_interval.to_seconds(), - "rotate_files(2)" ); - return; - } - out.flush(); out.close(); } @@ -127,11 +111,6 @@ namespace fc { { } } - - _current_file_start_time = start_time; - _rotation_task = schedule( [this]() { rotate_files(); }, - _current_file_start_time + cfg.rotation_interval.to_seconds(), - "rotate_files(3)" ); } }; @@ -151,8 +130,9 @@ namespace fc { // MS THREAD METHOD MESSAGE \t\t\t File:Line void file_appender::log( const log_message& m ) { + my->rotate_files(); + std::stringstream line; - //line << (m.get_context().get_timestamp().time_since_epoch().count() % (1000ll*1000ll*60ll*60))/1000 <<"ms "; line << string(m.get_context().get_timestamp()) << " "; line << std::setw( 21 ) << (m.get_context().get_thread_name().substr(0,9) + string(":") + m.get_context().get_task_name()).c_str() << " "; From 5cd9f7d6311f2e3ea9cf37eb4bf30ec8509e798d Mon Sep 17 00:00:00 2001 From: Peter Conrad Date: Sun, 15 Sep 2019 14:09:44 +0200 Subject: [PATCH 2/4] Move log file deletion into separate task --- src/log/file_appender.cpp | 42 +++++++++++++++++++++++++++++---------- 1 file changed, 32 insertions(+), 10 deletions(-) diff --git a/src/log/file_appender.cpp b/src/log/file_appender.cpp index 4f5ab14de..3d8c26d20 100644 --- a/src/log/file_appender.cpp +++ b/src/log/file_appender.cpp @@ -21,6 +21,7 @@ namespace fc { boost::mutex slock; private: + future _deletion_task; boost::atomic _current_file_number; public: @@ -36,6 +37,7 @@ namespace fc { FC_ASSERT( cfg.rotation_limit >= cfg.rotation_interval ); rotate_files( true ); + delete_files(); } else { out.open( cfg.filename, std::ios_base::out | std::ios_base::app); } @@ -46,6 +48,17 @@ namespace fc { } } + ~impl() + { + try + { + _deletion_task.cancel_and_wait("file_appender is destructing"); + } + catch( ... ) + { + } + } + void rotate_files( bool initializing = false ) { if( !cfg.rotate ) return; @@ -78,29 +91,35 @@ namespace fc { out.open( log_filename, std::ios_base::out | std::ios_base::app ); create_hard_link(log_filename, link_filename); } + } + void delete_files() + { /* Delete old log files */ - fc::time_point limit_time = now - cfg.rotation_limit; + auto current_file = _current_file_number.load(); + int64_t interval_seconds = cfg.rotation_interval.to_seconds(); + fc::time_point_sec start_time = time_point_sec( (uint32_t)(current_file * interval_seconds) ); + fc::time_point limit_time = time_point::now() - cfg.rotation_limit; + fc::path link_filename = cfg.filename; string link_filename_string = link_filename.filename().string(); directory_iterator itr(link_filename.parent_path()); + string timestamp_string = start_time.to_non_delimited_iso_string(); for( ; itr != directory_iterator(); itr++ ) { try { string current_filename = itr->filename().string(); - if (current_filename.compare(0, link_filename_string.size(), link_filename_string) != 0 || - current_filename.size() <= link_filename_string.size() + 1) - continue; + if( current_filename.compare(0, link_filename_string.size(), link_filename_string) != 0 + || current_filename.size() <= link_filename_string.size() + 1 ) + continue; string current_timestamp_str = current_filename.substr(link_filename_string.size() + 1, timestamp_string.size()); fc::time_point_sec current_timestamp = fc::time_point_sec::from_iso_string( current_timestamp_str ); - if( current_timestamp < start_time ) + if( current_timestamp < start_time + && ( current_timestamp < limit_time || file_size( current_filename ) <= 0 ) ) { - if( current_timestamp < limit_time || file_size( current_filename ) <= 0 ) - { - remove_all( *itr ); - continue; - } + remove_all( *itr ); + continue; } } catch (const fc::canceled_exception&) @@ -111,6 +130,9 @@ namespace fc { { } } + _deletion_task = schedule( [this]() { delete_files(); }, + start_time + cfg.rotation_interval.to_seconds(), + "delete_files(3)" ); } }; From f6fd6a7cf73882788549f39927de6d091228876f Mon Sep 17 00:00:00 2001 From: Peter Conrad Date: Sun, 15 Sep 2019 14:18:57 +0200 Subject: [PATCH 3/4] Avoid re-computing seconds --- src/log/file_appender.cpp | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/src/log/file_appender.cpp b/src/log/file_appender.cpp index 3d8c26d20..633f0971c 100644 --- a/src/log/file_appender.cpp +++ b/src/log/file_appender.cpp @@ -23,9 +23,10 @@ namespace fc { private: future _deletion_task; boost::atomic _current_file_number; + const int64_t _interval_seconds; public: - impl( const config& c) : cfg( c ) + impl( const config& c) : cfg( c ), _interval_seconds( cfg.rotation_interval.to_seconds() ) { try { @@ -63,9 +64,8 @@ namespace fc { { if( !cfg.rotate ) return; - int64_t interval_seconds = cfg.rotation_interval.to_seconds(); fc::time_point now = time_point::now(); - int64_t new_file_number = now.sec_since_epoch() / interval_seconds; + int64_t new_file_number = now.sec_since_epoch() / _interval_seconds; if( initializing ) _current_file_number.store( new_file_number ); else @@ -74,7 +74,7 @@ namespace fc { if( prev_file_number >= new_file_number ) return; if( !_current_file_number.compare_exchange_weak( prev_file_number, new_file_number ) ) return; } - fc::time_point_sec start_time = time_point_sec( (uint32_t)(new_file_number * interval_seconds) ); + fc::time_point_sec start_time = time_point_sec( (uint32_t)(new_file_number * _interval_seconds) ); string timestamp_string = start_time.to_non_delimited_iso_string(); fc::path link_filename = cfg.filename; fc::path log_filename = link_filename.parent_path() / (link_filename.filename().string() + "." + timestamp_string); @@ -97,8 +97,7 @@ namespace fc { { /* Delete old log files */ auto current_file = _current_file_number.load(); - int64_t interval_seconds = cfg.rotation_interval.to_seconds(); - fc::time_point_sec start_time = time_point_sec( (uint32_t)(current_file * interval_seconds) ); + fc::time_point_sec start_time = time_point_sec( (uint32_t)(current_file * _interval_seconds) ); fc::time_point limit_time = time_point::now() - cfg.rotation_limit; fc::path link_filename = cfg.filename; string link_filename_string = link_filename.filename().string(); @@ -130,8 +129,7 @@ namespace fc { { } } - _deletion_task = schedule( [this]() { delete_files(); }, - start_time + cfg.rotation_interval.to_seconds(), + _deletion_task = schedule( [this]() { delete_files(); }, start_time + _interval_seconds, "delete_files(3)" ); } }; From e168b6400b461f2953aa062b9eb6fe2bb4495125 Mon Sep 17 00:00:00 2001 From: Peter Conrad Date: Tue, 17 Sep 2019 13:46:02 +0200 Subject: [PATCH 4/4] Avoid time calculation when not rotating --- src/log/file_appender.cpp | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/log/file_appender.cpp b/src/log/file_appender.cpp index 633f0971c..aec6bec91 100644 --- a/src/log/file_appender.cpp +++ b/src/log/file_appender.cpp @@ -24,6 +24,7 @@ namespace fc { future _deletion_task; boost::atomic _current_file_number; const int64_t _interval_seconds; + time_point _next_file_time; public: impl( const config& c) : cfg( c ), _interval_seconds( cfg.rotation_interval.to_seconds() ) @@ -65,6 +66,8 @@ namespace fc { if( !cfg.rotate ) return; fc::time_point now = time_point::now(); + if( now < _next_file_time ) return; + int64_t new_file_number = now.sec_since_epoch() / _interval_seconds; if( initializing ) _current_file_number.store( new_file_number ); @@ -75,6 +78,7 @@ namespace fc { if( !_current_file_number.compare_exchange_weak( prev_file_number, new_file_number ) ) return; } fc::time_point_sec start_time = time_point_sec( (uint32_t)(new_file_number * _interval_seconds) ); + _next_file_time = start_time + _interval_seconds; string timestamp_string = start_time.to_non_delimited_iso_string(); fc::path link_filename = cfg.filename; fc::path log_filename = link_filename.parent_path() / (link_filename.filename().string() + "." + timestamp_string);