Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

HPCC-32931 Capture and report execute timings for splitters #19262

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

HPCC-32931 Capture and report execute timings for splitters #19262

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
ebafeda
HPCC-32931 Capture and report execute timings for splitters
shamser Nov 1, 2024
2d4617c
HPCC-32931 Changes following review
shamser Nov 6, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 12 additions & 0 deletions thorlcr/activities/nsplitter/thnsplitterslave.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,6 +58,9 @@ class CSplitterOutput : public CSimpleInterfaceOf<IStartableEngineRowStream>, pu
virtual bool isInputOrdered(bool consumerOrdered) const override;
virtual void setOutputStream(unsigned index, IEngineRowStream *stream) override;
virtual IStrandJunction *getOutputStreams(CActivityBase &ctx, unsigned idx, PointerArrayOf<IEngineRowStream> &streams, const CThorStrandOptions * consumerOptions, bool consumerOrdered, IOrderedCallbackCollection * orderedCallbacks) override;
// queryTotalCycles is used by downstream activities for the purpose of calculating local execute time.
// queryTotalCycles should include all time taken in start() and nextRow() methods.
// n.b. This totalCycles are not actually reported - it is only used by downstream activities.
virtual unsigned __int64 queryTotalCycles() const override { return COutputTiming::queryTotalCycles(); }
virtual unsigned __int64 queryEndCycles() const override { return COutputTiming::queryEndCycles(); }
virtual unsigned __int64 queryBlockedCycles() const { return COutputTiming::queryBlockedCycles(); }
Expand All @@ -77,6 +80,13 @@ class CSplitterOutput : public CSimpleInterfaceOf<IStartableEngineRowStream>, pu
//
// NSplitterSlaveActivity
//
// Note regarding NSplitterSlaveActivity::COutputTiming methods:
// - queryTotalCycles in NSplitterSlaveActivity is not used by downstream
// activities (like they are in other activities). Downstream activities
// use CSplitterOutput::queryTotalCycles for the purposes of calculating
// local execute time
// - totalCycles in this class is reported as the activity's StTotalExecuteTime
// and it is used to calculate & report the StLocalExecuteTime.

class NSplitterSlaveActivity : public CSlaveActivity, implements ISharedSmartBufferCallback
{
Expand Down Expand Up @@ -212,6 +222,7 @@ class NSplitterSlaveActivity : public CSlaveActivity, implements ISharedSmartBuf
if (!inputPrepared)
{
inputPrepared = true;
ActivityTimer t(slaveTimerStats, queryTimeActivities());
try
{
assertex(((unsigned)-1) != connectedOutputCount);
Expand Down Expand Up @@ -299,6 +310,7 @@ class NSplitterSlaveActivity : public CSlaveActivity, implements ISharedSmartBuf
}
inline const void *nextRow(unsigned outIdx, rowcount_t current)
{
ActivityTimer t(slaveTimerStats, queryTimeActivities());
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

are the ActivityTimer's in CSplitterOutput::start and CSplitterOutput::nextRow meaningful is anything looking at them?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sharedRowStream may block - I think need to time that blocktime and gather it into the activity blocked time,
but can be done separately - can you open another JIRA to come back to this and link to this one?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Activities downstream from the splitter arm make use of the CSplitterOutput timings. Downstream activities make use of the queryTotalCycles from the CSplitterOutput (they are not using not NSpitterSlaveActivity::queryTotalCycles).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've created a jira for implementing the blocked time for splitters: https://hpccsystems.atlassian.net/browse/HPCC-32952

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Activities downstream from the splitter arm make use of the CSplitterOutput timings. Downstream activities make use of the queryTotalCycles from the CSplitterOutput (they are not using not NSpitterSlaveActivity::queryTotalCycles).

right, but that means the activity's slaveTimerStats that are being accumulate here, and in prepareInput, aren't going to be used, and prepareInput time will already be counted by the CSplitterOutput::start() that 1st calls it..

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The activity's slaveTimerStats is used to report the activity's total time and calculate the activity's local time.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hm, this doesn't really make sense.
The downstream activities, will correctly use the timings from the CSplitterOutput's, as they are the inputs.

But the splitter activity will use these timings from NSplitterSlaveActivity::prepareInput and NSplitterSlaveActivity::nextRow, but that is not representative of how long this splitter activity took.
NB: NSplitterSlaveActivity::nextRow will not be called at all, if using newSplitter, and even when it is, it will be included in the CSplitterOutput::nextRow time (as will the prepareInput time).

How long did the splitter spend processing rows..?
Is it the sum of the time of it's arms (CSplitterOutput's)?
Maybe, that will include the time from the 1st that started the input (prepareInput), and all the time it spent reading off disk in the spilling case, but without accounting for block time, that will also count a lot of blocked time too, e.g. when arm 1 can't return any rows, because arm 2 is behind and blocking.

I don't think slaveTimerStats as a member in the activity, nor accumulating it there is correct.

if (1 == activeOutputCount) // will be true, if only 1 input connected, or only 1 input was active (others stopped) when it started reading
return inputStream->nextRow();
if (recsReady == current && writeAheadException.get())
Expand Down
Loading