Commit df97bd27 authored by Andrew Heather's avatar Andrew Heather
Browse files

Merge branch 'feature-profiling' into 'develop'

ENH: reduce profiling overhead (issue #764)

See merge request !194
parents ff9d1213 805085e9
......@@ -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()");
functionObjects_.execute();
endProfiling(foExec);
addProfiling(foEnd, "functionObjects.end()");
functionObjects_.end();
endProfiling(foEnd);
{
addProfiling(fo, "functionObjects.execute()");
functionObjects_.execute();
}
{
addProfiling(fo, "functionObjects.end()");
functionObjects_.end();
}
}
}
......
......@@ -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
return info;
}
Foam::profilingInformation* Foam::profiling::store(profilingInformation *info)
Foam::profilingInformation* Foam::profiling::create
(
profilingInformation *parent,
const string& descr
)
{
// Profile information lookup is qualified by parent id
hash_.insert(Key(info->description(), info->parent().id()), info);
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;
}
void Foam::profiling::push(profilingInformation *info, clockTime& timer)
void Foam::profiling::beginTimer(profilingInformation *info)
{
stack_.push(info);
timers_.set(info->id(), &timer);
info->push(); // mark as on stack
stack_.append(info);
times_.append(clockValue::now());
info->setActive(true); // Mark as on stack
}
Foam::profilingInformation* Foam::profiling::pop()
Foam::profilingInformation* Foam::profiling::endTimer()
{
profilingInformation *info = stack_.pop();
timers_.erase(info->id());
info->pop(); // mark as off stack
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,24 +146,10 @@ 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
}
......@@ -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
{
os.beginBlock("profiling");
static DynamicList<scalar> elapsed;
const clockValue now(clockValue::now());
// Add extra new line between entries
label nTrigger = 0;
const label nstack = stack_.size();
// write on-stack items
// newest is first on the stack, top-level is at the end
// this is how the child times are summed
elapsed.resize(nstack+1); // extend for last entry, which has no child.
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 (nTrigger++)
{
os << nl;
}
info->write(os, true, elapsed, oldElapsed);
oldElapsed = elapsed;
}
elapsed[stacki] = (now - times_[stacki]);
}
elapsed.last() = 0;
os.beginBlock("profiling");
// write off-stack items
// using an additional Map to sort by Id
// Active items
for (label stacki=0; stacki < nstack; ++stacki)
{
typedef Map<const Information*> LookupContainer;
LookupContainer lookup;
if (stacki) os << nl; // Extra line between entries
forAllConstIter(StorageContainer, hash_, iter)
{
const profilingInformation *info = iter();
if (!info->onStack())
{
lookup.set(info->id(), info);
}
}
stack_[stacki]->write
(
os,
true,
elapsed[stacki], // elapsedTime
elapsed[stacki+1] // childTimes
);
}
forAllConstIter(LookupContainer, lookup, iter)
// Non-active items
for (const Information& info : pool_)
{
if (!info.active())
{
if (nTrigger++)
{
os << nl;
}
iter()->write(os);
os << nl;
info.write(os);
}
}
......
......@@ -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_;
//- Parent/child relationships for lookup purposes
DynamicList<DynamicList<Information*,16>> children_;
//- Local stack of profiling information
StackContainer stack_;
//- LIFO stack of profiling information
DynamicList<Information*> stack_;
//- Note the timers (by Id) for the correct stack-output
Map<clockTime*> timers_;
//- 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);
......
......@@ -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),