ENH: reduce profiling overhead (issue #764)

- avoid clockTime in favour of clockValue.

- avoid allocations when profiling is not active.

- replace hashing with manual pointer lists
This commit is contained in:
Mark Olesen
2018-03-26 21:38:47 +02:00
parent e0d075ff89
commit d901b4f450
8 changed files with 214 additions and 303 deletions

View File

@ -846,13 +846,14 @@ bool Foam::Time::run() const
{
// Ensure functionObjects execute on last time step
// (and hence write uptodate functionObjectProperties)
addProfiling(foExec, "functionObjects.execute()");
{
addProfiling(fo, "functionObjects.execute()");
functionObjects_.execute();
endProfiling(foExec);
addProfiling(foEnd, "functionObjects.end()");
}
{
addProfiling(fo, "functionObjects.end()");
functionObjects_.end();
endProfiling(foEnd);
}
}
}

View File

@ -3,7 +3,7 @@
\\ / F ield | OpenFOAM: The Open Source CFD Toolbox
\\ / O peration |
\\ / A nd | Copyright (C) 2009-2016 Bernhard Gschaider
\\/ M anipulation | Copyright (C) 2016-2017 OpenCFD Ltd.
\\/ M anipulation | Copyright (C) 2016-2018 OpenCFD Ltd.
-------------------------------------------------------------------------------
License
This file is part of OpenFOAM.
@ -33,47 +33,72 @@ License
// * * * * * * * * * * * * * * Static Data Members * * * * * * * * * * * * * //
int Foam::profiling::allowed
(
Foam::debug::infoSwitch("allowProfiling", 1)
);
Foam::profiling* Foam::profiling::pool_(nullptr);
int Foam::profiling::allowed(Foam::debug::infoSwitch("allowProfiling", 1));
Foam::profiling* Foam::profiling::singleton_(nullptr);
// * * * * * * * * * * * * Protected Member Functions * * * * * * * * * * * //
Foam::profilingInformation* Foam::profiling::find
(
const string& descr,
const label parentId
)
Foam::profilingInformation* Foam::profiling::create(const zero)
{
return hash_.lookup(Key(descr, parentId), nullptr);
}
// Top-level entry: reset everything
pool_.clear();
children_.clear();
stack_.clear();
times_.clear();
Information* info = new Information();
pool_.append(info);
children_.resize(pool_.size());
children_.last().clear(); // safety
Foam::profilingInformation* Foam::profiling::store(profilingInformation *info)
{
// Profile information lookup is qualified by parent id
hash_.insert(Key(info->description(), info->parent().id()), info);
return info;
}
void Foam::profiling::push(profilingInformation *info, clockTime& timer)
Foam::profilingInformation* Foam::profiling::create
(
profilingInformation *parent,
const string& descr
)
{
stack_.push(info);
timers_.set(info->id(), &timer);
info->push(); // mark as on stack
const label parentId = parent->id();
for (Information* child : children_[parentId])
{
if (descr == child->description())
{
return child; // Found existing
}
}
Information* info = new Information(parent, descr, pool_.size());
pool_.append(info);
children_.resize(pool_.size());
children_.last().clear(); // safety
children_[parentId].append(info);
return info;
}
Foam::profilingInformation* Foam::profiling::pop()
void Foam::profiling::beginTimer(profilingInformation *info)
{
profilingInformation *info = stack_.pop();
timers_.erase(info->id());
info->pop(); // mark as off stack
stack_.append(info);
times_.append(clockValue::now());
info->setActive(true); // Mark as on stack
}
Foam::profilingInformation* Foam::profiling::endTimer()
{
Information *info = stack_.remove();
clockValue clockval = times_.remove();
info->update(clockval.elapsed()); // Update elapsed time
info->setActive(false); // Mark as off stack
return info;
}
@ -83,7 +108,7 @@ Foam::profilingInformation* Foam::profiling::pop()
bool Foam::profiling::active()
{
return allowed && pool_;
return allowed && singleton_;
}
@ -97,7 +122,7 @@ bool Foam::profiling::print(Ostream& os)
{
if (active())
{
return pool_->writeData(os);
return singleton_->writeData(os);
}
return false;
@ -108,7 +133,7 @@ bool Foam::profiling::writeNow()
{
if (active())
{
return pool_->regIOobject::write();
return singleton_->regIOobject::write();
}
return false;
@ -121,26 +146,12 @@ void Foam::profiling::initialize
const Time& owner
)
{
if (allowed && !pool_)
if (allowed && !singleton_)
{
pool_ = new profiling(ioObj, owner);
profilingInformation *info = pool_->store
(
new profilingInformation()
);
pool_->push(info, pool_->clockTime_);
if (argList::bannerEnabled())
{
Info<< "profiling initialized" << nl;
singleton_ = new profiling(ioObj, owner);
}
}
// silently ignore multiple initializations
// eg, decomposePar uses multiple simultaneous Times
}
void Foam::profiling::initialize
(
@ -149,63 +160,40 @@ void Foam::profiling::initialize
const Time& owner
)
{
if (allowed && !pool_)
if (allowed && !singleton_)
{
pool_ = new profiling(dict, ioObj, owner);
profilingInformation *info = pool_->store
(
new profilingInformation()
);
pool_->push(info, pool_->clockTime_);
if (argList::bannerEnabled())
{
Info<< "profiling initialized" << nl;
singleton_ = new profiling(dict, ioObj, owner);
}
}
// silently ignore multiple initializations
// eg, decomposePar uses multiple simultaneous Times
}
void Foam::profiling::stop(const Time& owner)
{
if (pool_ && &owner == &(pool_->owner_))
if (singleton_ && &owner == &(singleton_->owner_))
{
delete pool_;
pool_ = nullptr;
delete singleton_;
singleton_ = nullptr;
}
}
Foam::profilingInformation* Foam::profiling::New
(
const string& descr,
clockTime& timer
)
Foam::profilingInformation* Foam::profiling::New(const string& descr)
{
profilingInformation *info = nullptr;
Information *info = nullptr;
if (active())
{
profilingInformation *parent = pool_->stack_.top();
Information *parent = singleton_->stack_.last();
info = pool_->find(descr, parent->id());
if (!info)
{
info = pool_->store(new profilingInformation(descr, parent));
}
info = singleton_->create(parent, descr);
singleton_->beginTimer(info);
pool_->push(info, timer);
if (pool_->memInfo_)
if (singleton_->memInfo_)
{
info->maxMem_ = Foam::max
(
info->maxMem_,
pool_->memInfo_->update().size()
singleton_->memInfo_->update().size()
);
}
}
@ -218,7 +206,7 @@ void Foam::profiling::unstack(const profilingInformation *info)
{
if (active() && info)
{
profilingInformation *top = pool_->pop();
Information *top = singleton_->endTimer();
if (info->id() != top->id())
{
@ -245,14 +233,22 @@ Foam::profiling::profiling
:
IOdictionary(io),
owner_(owner),
clockTime_(),
hash_(),
pool_(),
children_(),
stack_(),
timers_(),
times_(),
sysInfo_(new profilingSysInfo()),
cpuInfo_(new cpuInfo()),
memInfo_(new memInfo())
{}
{
Information *info = this->create(Zero);
this->beginTimer(info);
if (argList::bannerEnabled())
{
Info<< "profiling initialized" << nl;
}
}
Foam::profiling::profiling
@ -264,10 +260,10 @@ Foam::profiling::profiling
:
IOdictionary(io),
owner_(owner),
clockTime_(),
hash_(),
pool_(),
children_(),
stack_(),
timers_(),
times_(),
sysInfo_
(
dict.lookupOrDefault("sysInfo", false)
@ -283,7 +279,15 @@ Foam::profiling::profiling
dict.lookupOrDefault("memInfo", false)
? new memInfo() : nullptr
)
{}
{
Information *info = this->create(Zero);
this->beginTimer(info);
if (argList::bannerEnabled())
{
Info<< "profiling initialized" << nl;
}
}
// * * * * * * * * * * * * * * * * Destructor * * * * * * * * * * * * * * * //
@ -294,10 +298,9 @@ Foam::profiling::~profiling()
deleteDemandDrivenData(cpuInfo_);
deleteDemandDrivenData(memInfo_);
if (pool_ == this)
if (singleton_ == this)
{
pool_ = nullptr;
profilingInformation::nextId_ = 0;
singleton_ = nullptr;
}
}
@ -318,54 +321,43 @@ Foam::label Foam::profiling::size() const
bool Foam::profiling::writeData(Ostream& os) const
{
static DynamicList<scalar> elapsed;
const clockValue now(clockValue::now());
const label nstack = stack_.size();
elapsed.resize(nstack+1); // extend for last entry, which has no child.
for (label stacki=0; stacki < nstack; ++stacki)
{
elapsed[stacki] = (now - times_[stacki]);
}
elapsed.last() = 0;
os.beginBlock("profiling");
// Add extra new line between entries
label nTrigger = 0;
// write on-stack items
// newest is first on the stack, top-level is at the end
// this is how the child times are summed
// Active items
for (label stacki=0; stacki < nstack; ++stacki)
{
scalar oldElapsed = 0;
forAllConstIter(StackContainer, stack_, iter)
{
const profilingInformation *info = *iter;
scalar elapsed = timers_[info->id()]->elapsedTime();
if (stacki) os << nl; // Extra line between entries
if (nTrigger++)
stack_[stacki]->write
(
os,
true,
elapsed[stacki], // elapsedTime
elapsed[stacki+1] // childTimes
);
}
// Non-active items
for (const Information& info : pool_)
{
if (!info.active())
{
os << nl;
}
info->write(os, true, elapsed, oldElapsed);
oldElapsed = elapsed;
}
}
// write off-stack items
// using an additional Map to sort by Id
{
typedef Map<const Information*> LookupContainer;
LookupContainer lookup;
forAllConstIter(StorageContainer, hash_, iter)
{
const profilingInformation *info = iter();
if (!info->onStack())
{
lookup.set(info->id(), info);
}
}
forAllConstIter(LookupContainer, lookup, iter)
{
if (nTrigger++)
{
os << nl;
}
iter()->write(os);
info.write(os);
}
}

View File

@ -3,7 +3,7 @@
\\ / F ield | OpenFOAM: The Open Source CFD Toolbox
\\ / O peration |
\\ / A nd | Copyright (C) 2009-2016 Bernhard Gschaider
\\/ M anipulation | Copyright (C) 2016-2107 OpenCFD Ltd.
\\/ M anipulation | Copyright (C) 2016-2018 OpenCFD Ltd.
-------------------------------------------------------------------------------
License
This file is part of OpenFOAM.
@ -54,10 +54,8 @@ SourceFiles
#include "profilingTrigger.H"
#include "IOdictionary.H"
#include "HashPtrTable.H"
#include "Tuple2.H"
#include "LIFOStack.H"
#include "Map.H"
#include "DynamicList.H"
#include "PtrDynList.H"
#include "Time.H"
#include "clockTime.H"
@ -82,7 +80,7 @@ class profiling
{
public:
// Public typedefs
// Public Typedefs
typedef profilingInformation Information;
typedef profilingTrigger Trigger;
@ -98,38 +96,11 @@ private:
typedef profilingSysInfo sysInfo;
//- Profile information lookup is qualified by parent id
typedef Tuple2<string, label> Key;
//- Hashing for information lookup
class HashKey
:
public Hash<Key>
{
public:
HashKey()
{}
//- Hash qualified by the parent id to avoid collisions
unsigned operator()(const Key& key) const
{
return
(
Hash<string>()(key.first())
+ Hash<label>()(key.second())
);
}
};
typedef HashPtrTable<Information, Key, HashKey> StorageContainer;
typedef LIFOStack<Information*> StackContainer;
// Private Static Data Members
//- Only one global pool object is possible
static profiling* pool_;
//- Only one global object is possible
static profiling* singleton_;
// Private Data Members
@ -137,17 +108,17 @@ private:
//- The owner of the profiling
const Time& owner_;
//- A global timer for the profiling
clockTime clockTime_;
//- Storage of profiling information
StorageContainer hash_;
PtrDynList<Information> pool_;
//- Local stack of profiling information
StackContainer stack_;
//- Parent/child relationships for lookup purposes
DynamicList<DynamicList<Information*,16>> children_;
//- Note the timers (by Id) for the correct stack-output
Map<clockTime*> timers_;
//- LIFO stack of profiling information
DynamicList<Information*> stack_;
//- LIFO stack of clock values
DynamicList<clockValue> times_;
//- General system information (optional)
sysInfo* sysInfo_;
@ -161,10 +132,10 @@ private:
// Private Member Functions
//- Disallow default bitwise copy construct
//- Disallow copy construct
profiling(const profiling&) = delete;
//- Disallow default bitwise assignment
//- Disallow copy assignment
void operator=(const profiling&) = delete;
@ -196,20 +167,25 @@ protected:
// Protected Member Functions
//- Find named profiling information element with specified parent.
// Return nullptr on failure.
profilingInformation* find(const string& descr, const label parentId);
//- Clear all profiling and restart with new profiling
// \return pointer to stored information element
Information* create(const zero);
//- Add to hashed storage,
// \return pointer to newly stored element for chaining
profilingInformation* store(profilingInformation* info);
//- Get or create named profiling information element with the
//- specified parent.
// \return pointer to stored information element
Information* create
(
Information* parent,
const string& descr
);
//- Add to stack and set timer lookup (based on Id)
void push(profilingInformation* info, clockTime& timer);
//- Add to stack of active information and begin timer datum
void beginTimer(Information* info);
//- Remove from stack and remove timer lookup (based on Id).
// \return pointer to profiling information element
profilingInformation* pop();
//- Remove from stack of active information and update elapsed time
// \return pointer to profiling information element (for reference)
Information* endTimer();
// Static control elements
@ -233,12 +209,8 @@ protected:
static void stop(const Time& owner);
//- Existing or new element on pool, add to stack.
// Returns null if profiling has not been initialized
static profilingInformation* New
(
const string& descr,
clockTime& timer
);
// Returns nullptr if profiling has not been initialized
static profilingInformation* New(const string& descr);
//- Remove the information from the top of the stack
static void unstack(const profilingInformation* info);

View File

@ -3,7 +3,7 @@
\\ / F ield | OpenFOAM: The Open Source CFD Toolbox
\\ / O peration |
\\ / A nd | Copyright (C) 2009-2016 Bernhard Gschaider
\\/ M anipulation | Copyright (C) 2016 OpenCFD Ltd.
\\/ M anipulation | Copyright (C) 2016-2018 OpenCFD Ltd.
-------------------------------------------------------------------------------
License
This file is part of OpenFOAM.
@ -27,57 +27,36 @@ License
#include "Switch.H"
#include "IOstreams.H"
// * * * * * * * * * * * * * * Static Data Members * * * * * * * * * * * * * //
Foam::label Foam::profilingInformation::nextId_(0);
// * * * * * * * * * * * * * Static Member Functions * * * * * * * * * * * * //
Foam::label Foam::profilingInformation::getNextId()
{
return nextId_++;
}
void Foam::profilingInformation::raiseId(label maxVal)
{
if (nextId_ < maxVal)
{
nextId_ = maxVal;
}
}
// * * * * * * * * * * * * * * * * Constructors * * * * * * * * * * * * * * //
Foam::profilingInformation::profilingInformation()
:
id_(getNextId()),
id_(0),
description_("application::main"),
parent_(this),
calls_(0),
totalTime_(0),
childTime_(0),
maxMem_(0),
onStack_(false)
active_(false)
{}
Foam::profilingInformation::profilingInformation
(
profilingInformation *parent,
const string& descr,
profilingInformation *parent
const label id
)
:
id_(getNextId()),
id_(id),
description_(descr),
parent_(parent),
calls_(0),
totalTime_(0),
childTime_(0),
maxMem_(0),
onStack_(false)
active_(false)
{}
@ -88,24 +67,18 @@ void Foam::profilingInformation::update(const scalar elapsed)
++calls_;
totalTime_ += elapsed;
if (id_ != parent().id())
if (id_ != parent_->id())
{
parent().childTime_ += elapsed;
parent_->childTime_ += elapsed;
}
}
// * * * * * * * * * * * * * * * Member Functions * * * * * * * * * * * * * //
void Foam::profilingInformation::push() const
void Foam::profilingInformation::setActive(bool state) const
{
onStack_ = true;
}
void Foam::profilingInformation::pop() const
{
onStack_ = false;
active_ = state;
}
@ -128,7 +101,7 @@ Foam::Ostream& Foam::profilingInformation::write
os.writeEntry("totalTime", totalTime() + elapsedTime);
os.writeEntry("childTime", childTime() + childTimes);
os.writeEntryIfDifferent<int>("maxMem", 0, maxMem_);
os.writeEntry("onStack", Switch(onStack()));
os.writeEntry("active", Switch(active()));
os.endBlock();

View File

@ -58,18 +58,6 @@ Ostream& operator<<(Ostream& os, const profilingInformation& info);
class profilingInformation
{
// Private Static Data Members
//- Counter to generate the ids
static label nextId_;
//- Get a new ID and update the counter
static label getNextId();
//- Raise the next possible ID (to avoid ID-clashes during reading)
static void raiseId(label maxVal);
// Private Data Members
//- Unique id to identify it
@ -81,7 +69,7 @@ class profilingInformation
//- Pointer to the parent object (or self for top-level)
profilingInformation* parent_;
//- Nr of times this was called
//- Number of times this was called
long calls_;
//- Total time spent
@ -94,16 +82,16 @@ class profilingInformation
// Only valid when the calling profiling has memInfo active.
mutable int maxMem_;
//- Is this information currently on the stack?
mutable bool onStack_;
//- Is this information active or passive (ie, on the stack)?
mutable bool active_;
// Private Member Functions
//- Disallow default bitwise copy construct
//- No copy construct
profilingInformation(const profilingInformation&) = delete;
//- Disallow default bitwise assignment
//- No copy assignment
void operator=(const profilingInformation&) = delete;
@ -122,12 +110,8 @@ protected:
// Member Functions
//- Mark as being on the stack
void push() const;
//- Mark as being off the stack
void pop() const;
//- Mark as being active or passive)
void setActive(bool state) const;
//- Write the profiling times, optionally with additional values
// Use dictionary format.
@ -147,8 +131,9 @@ public:
//- Construct from components
profilingInformation
(
profilingInformation* parent,
const string& descr,
profilingInformation* parent
const label id
);
@ -202,9 +187,9 @@ public:
}
inline bool onStack() const
inline bool active() const
{
return onStack_;
return active_;
}

View File

@ -40,7 +40,7 @@ inline static void printEnv
const std::string& envName
)
{
const std::string value = Foam::getEnv(envName);
const std::string value(Foam::getEnv(envName));
if (!value.empty())
{
os.writeEntry(key, value);

View File

@ -3,7 +3,7 @@
\\ / F ield | OpenFOAM: The Open Source CFD Toolbox
\\ / O peration |
\\ / A nd | Copyright (C) 2009-2016 Bernhard Gschaider
\\/ M anipulation | Copyright (C) 2016-2017 OpenCFD Ltd.
\\/ M anipulation | Copyright (C) 2016-2018 OpenCFD Ltd.
-------------------------------------------------------------------------------
License
This file is part of OpenFOAM.
@ -24,23 +24,26 @@ License
\*---------------------------------------------------------------------------*/
#include "profiling.H"
#include "profilingInformation.H"
#include "profilingTrigger.H"
#include "profilingInformation.H"
// * * * * * * * * * * * * * * * * Constructors * * * * * * * * * * * * * * //
Foam::profilingTrigger::profilingTrigger()
:
ptr_(nullptr)
{}
Foam::profilingTrigger::profilingTrigger(const char* name)
:
clock_(),
ptr_(profiling::New(name, clock_))
ptr_(profiling::New(name))
{}
Foam::profilingTrigger::profilingTrigger(const string& name)
:
clock_(),
ptr_(profiling::New(name, clock_))
ptr_(profiling::New(name))
{}
@ -64,10 +67,10 @@ void Foam::profilingTrigger::stop()
{
if (ptr_)
{
ptr_->update(clock_.elapsedTime());
// profiling info pointer managed by pool storage, so no delete here
profiling::unstack(ptr_);
// pointer is managed by pool storage -> thus no delete here
}
ptr_ = nullptr;
}

View File

@ -3,7 +3,7 @@
\\ / F ield | OpenFOAM: The Open Source CFD Toolbox
\\ / O peration |
\\ / A nd | Copyright (C) 2009-2016 Bernhard Gschaider
\\/ M anipulation | Copyright (C) 2016-2107 OpenCFD Ltd.
\\/ M anipulation | Copyright (C) 2016-2018 OpenCFD Ltd.
-------------------------------------------------------------------------------
License
This file is part of OpenFOAM.
@ -35,7 +35,6 @@ SourceFiles
#ifndef profilingTrigger_H
#define profilingTrigger_H
#include "clockTime.H"
#include "string.H"
// * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * * //
@ -43,7 +42,7 @@ SourceFiles
namespace Foam
{
// Forward declaration of classes
// Forward declarations
class profilingInformation;
/*---------------------------------------------------------------------------*\
@ -54,19 +53,16 @@ class profilingTrigger
{
// Private Data Members
//- The timer for the profiling information
clockTime clock_;
//- The profiling information
profilingInformation *ptr_;
// Private Member Functions
//- Disallow default bitwise copy construct
//- No copy construct
profilingTrigger(const profilingTrigger&) = delete;
//- Disallow default bitwise assignment
//- No copy assignment
void operator=(const profilingTrigger&) = delete;
@ -74,6 +70,9 @@ public:
// Constructors
//- Construct null, no profiling trigger
profilingTrigger();
//- Construct profiling with given description.
// Descriptions beginning with 'application::' are reserved for
// internal use.
@ -91,14 +90,9 @@ public:
// Member Functions
// Access
//- True if the triggered profiling is active
bool running() const;
// Edit
//- Stop triggered profiling
void stop();
@ -113,21 +107,13 @@ public:
// Macros
//- Define profiling with specified name and description string
// This is required if the description contains space, colons etc.
// \sa addProfiling0
//- Define profiling trigger with specified name and description string
// \sa endProfiling
#define addProfiling(name,descr) \
::Foam::profilingTrigger profilingTriggerFor##name(descr)
//- Define profiling with specified name and description correspond to the name
// \sa addProfiling
// \sa endProfiling
#define addProfiling0(name) \
::Foam::profilingTrigger profilingTriggerFor##name(#name)
//- Define profiling with specified name and description correspond to the
// compiler-defined function name string:
//- Define profiling trigger with specified name and description
//- corresponding to the compiler-defined function name string
// \sa addProfiling
// \sa endProfiling
#ifdef __GNUC__
@ -140,7 +126,6 @@ public:
//- Remove profiling with specified name
// \sa addProfiling
// \sa addProfiling0
#define endProfiling(name) profilingTriggerFor##name.stop()