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
+12 −0
Open

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

Changes from 1 commit
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
6 changes: 5 additions & 1 deletion thorlcr/activities/nsplitter/thnsplitterslave.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -217,7 +217,10 @@ class NSplitterSlaveActivity : public CSlaveActivity, implements ISharedSmartBuf
assertex(((unsigned)-1) != connectedOutputCount);
activeOutputCount = connectedOutputCount;

PARENT::start();
{
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.

I think it would be more correct if this was after "if (!inputPrepared)" (i.e. included all time in it).
Because this is the total 'start()' time of splitter. It is initiated from the 1st CSplitterOutput::start() to be called.
i.e. if this was a simple act. it would do all this work in start and time it as such.

PARENT::start();
}
initMetaInfo(cachedMetaInfo);
cachedMetaInfo.suppressLookAhead = spill; // only suppress downstream lookaheads if this is a spilling splitter

Expand Down Expand Up @@ -299,6 +302,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