Commit e934aa58 authored by Martin Marinov's avatar Martin Marinov

Add logging to the Progress::Context and nodes.

parent bc9d3473
......@@ -5,18 +5,53 @@
#include "ProgressNode.hh"
#include "Base/Utils/BaseError.hh"
#include "Base/Utils/IOutputStream.hh"
#include <exception>
#include <fstream>
#include <chrono>
#ifdef PROGRESS_ON
namespace Progress {
struct Context::LogData
{
typedef Base::OutputStreamAdaptT<std::ofstream> FileOutputStream;
FileOutputStream strm;
typedef std::chrono::high_resolution_clock Clock;
typedef Clock::time_point Time;
typedef std::chrono::seconds Seconds;
typedef std::chrono::milliseconds Milliseconds;
typedef std::chrono::nanoseconds Nanoseconds;
LogData() : strm(LOG_FILENAME) {}
void record_entry_time() { entr_time = Clock::now(); }
TickNumber elapsed_nanoseconds() const
{
const auto exit_time = Clock::now();
const auto elpd_time = exit_time - entr_time;
const auto elpd_mlsc = std::chrono::duration_cast<Nanoseconds>(elpd_time);
return elpd_mlsc.count();
}
private:
Time entr_time;
};
/// Context implementation
Context::Context()
: abrt_stte_(AST_NONE), abrt_alwd_(false), phny_root_("phony"),
root_node_(&phny_root_), actv_node_(&phny_root_)
root_node_(&phny_root_), actv_node_(&phny_root_), log_data_(nullptr)
{}
Context::~Context()
{
delete log_data_;
}
void Context::abort()
{
// Don't throw if abort is not permitted or
......@@ -44,15 +79,22 @@ void Context::end_abort()
abrt_stte_ = AST_NONE;
}
void Context::enter_node(Node* _node)
void Context::enter_node(Node* const _node)
{ // NOTE: this function is written carefully to allow asynchronous inspection
// of the node graph from a tracking thread. It assumes the tracking thread
// does not use the node parent.
_node->tick_nmbr_ = 0;
if (phony())
root_node_ = _node;
else
_node->prnt_ = actv_node_;
if (phony()) // no active node, ...
root_node_ = _node; // ... so the node to enter is the root
else // the current active node becomes the parent of the node to enter
_node->prnt_ = actv_node_;
if (logging()) // record the entry time
{
if (actv_node_ != nullptr) // add the elapsed time to the active node
actv_node_->time_ns_ += log_data_->elapsed_nanoseconds();
_node->time_ns_ = 0; // restart counting in the active node
log_data_->record_entry_time(); // record the entry time into _node
}
actv_node_ = _node;
}
......@@ -62,11 +104,38 @@ void Context::exit_node()
// does not use the node parent.
if (phony())
return; // TODO: this condition is a bug, so we need a DEB_error() here?
if (logging())
{// log the node on exit
actv_node_->time_ns_ += log_data_->elapsed_nanoseconds();
auto& os = log_data_->strm;
os << actv_node_->name << LOG_COMMA <<
actv_node_->tick_number() << LOG_COMMA <<
actv_node_->time_ns_ / 1000000 << LOG_COMMA; // convert to milliseconds
actv_node_->log(os);
os << Base::ENDL;
// record the re-entry time into the parent _node
log_data_->record_entry_time();
}
auto* const prnt = actv_node_->prnt_;
actv_node_->prnt_ = nullptr;
actv_node_ = prnt == nullptr ? &phny_root_ : prnt;
}
void Context::set_logging(const bool _lgng)
{
if (_lgng == logging())
return;
if (_lgng)
log_data_ = new LogData; // turn on logging
else
{// turn off logging.
delete log_data_;
log_data_ = nullptr;
}
}
BASE_THREAD_LOCAL Context cntx;
/// Node implementation
......@@ -78,5 +147,8 @@ TickNumber Node::tick_number_max() const
return 1;
}
void Node::log(IOutputStream& /*_os*/) const
{}
} //namespace Progress
#endif//PROGRESS_ON
......@@ -7,11 +7,29 @@
#include <Base/Utils/Thread.hh>
namespace Base {
class IOutputStream;
}
namespace Progress {
//! Progress stream type
typedef Base::IOutputStream IOutputStream;
//! Progress tick counter type
typedef unsigned long long TickNumber;
/*!
The name of the progress log file, uses the .csv format.
Each line contains comma-separated values for a progress node as follows:
node_name, tick#, ms#, param0, param1, ...
*/
const char* const LOG_FILENAME = "progress.csv";
//! The log value separator
const char* const LOG_COMMA = ", ";
//! Represent an operational node in the progress graph
class Node
{
......@@ -32,7 +50,8 @@ public:
Node(const char* const _name,
Node* _next = nullptr, Node* _chld = nullptr)
: name(_name), next_(_next), chld_(_chld), prnt_(nullptr), tick_nmbr_(0)
: name(_name), next_(_next), chld_(_chld), prnt_(nullptr),
tick_nmbr_(0), time_ns_(0)
{}
virtual ~Node();
......@@ -40,16 +59,35 @@ public:
const Node* next() const { return next_; };
const Node* child() const { return chld_; };
void tick() { ++tick_nmbr_; }
TickNumber tick_number() const { return tick_nmbr_; }
/*!
Estimate the maximum number of ticks in this node.
The function is virtual so that the node can make use of some custom logic
and specific parameters.
*/
virtual TickNumber tick_number_max() const;
void tick() { ++tick_nmbr_; }
/*!
Log custom logic parameter values used by the estimation in tick_number_max().
The values have to be separated by \ref LOG_COMMA.
*/
virtual void log(IOutputStream& _os) const;
/**/
protected:
Node* next_; //!< next node on the same level, last if nullptr
Node* chld_; //!< first child node, leaf if nullptr
Node* prnt_; //!< parent node, set temporarily
TickNumber tick_nmbr_; // number of ticks in the node
TickNumber tick_nmbr_; /*!< number of ticks in the node, exclusive of the
ticks in child nodes */
private:
TickNumber time_ns_; /*!< Time in nanoseconds spent in the node since it was
entered, exclusive of the time spent in child nodes. This is recorded only
if the Context is logging, and is accessible only by the Context. */
friend class Context;
};
......@@ -59,6 +97,7 @@ class Context
public:
//! Default constructor
Context();
~Context();
/*!
Get if the progress is "faking" tracking, i.e., using a phony root node.
......@@ -108,12 +147,18 @@ public:
abort();
}
void enter_node(Node* _node);
void enter_node(Node* const _node);
void exit_node();
void set_abort_allowed(bool _abrt_alwd) { abrt_alwd_ = _abrt_alwd; }
bool abort_allowed() const { return abrt_alwd_; }
//! Turn on/off progress logging
void set_logging(const bool _lgng);
//! Check if progress logging is on/off
bool logging() const { return log_data_ != nullptr; }
private:
enum AbortStateType
{
......@@ -122,12 +167,15 @@ private:
AST_PROCESSING
};
struct LogData;
private:
AbortStateType abrt_stte_; //!< Abort state
bool abrt_alwd_; //!< Abort allowed flag, ignores AST_REQUEST if false
Node phny_root_; //!< "phony" root
Node* root_node_; //!< Root node
Node* actv_node_; //!< Active node
LogData* log_data_; //!< Log data, exists only when logging
private:
//! Throws PROGRESS_ABORTED to abort the current operation.
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment