Skip to content

Comments

[multistage][observability] Add an option to log operator stats to log.info#10179

Closed
61yao wants to merge 6 commits intoapache:masterfrom
61yao:operator_logging
Closed

[multistage][observability] Add an option to log operator stats to log.info#10179
61yao wants to merge 6 commits intoapache:masterfrom
61yao:operator_logging

Conversation

@61yao
Copy link
Contributor

@61yao 61yao commented Jan 25, 2023

The option is set using logMultistageOperatorStats.
It is tested in MulitstageEngineIntegrationTest.

Copy link
Contributor

Choose a reason for hiding this comment

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

error seems like a weird log level for this - why not make it INFO and then just have people configure log4j properly for it?

Copy link
Member

Choose a reason for hiding this comment

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

+1 lets put this in info. we can remove this once join is GA

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Because it is easier to see in IDE..... the whole stats is quite hacky anyway. So I put loggeer.error.
We probably need to rewrite the logging later.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

updated to log info

@codecov-commenter
Copy link

codecov-commenter commented Jan 25, 2023

Codecov Report

Merging #10179 (018a104) into master (ed66031) will decrease coverage by 1.94%.
The diff coverage is 35.00%.

@@             Coverage Diff              @@
##             master   #10179      +/-   ##
============================================
- Coverage     70.45%   68.51%   -1.94%     
+ Complexity     5796     5135     -661     
============================================
  Files          2020     2020              
  Lines        109107   109124      +17     
  Branches      16555    16562       +7     
============================================
- Hits          76874    74769    -2105     
- Misses        26853    29052    +2199     
+ Partials       5380     5303      -77     
Flag Coverage Δ
integration1 24.62% <2.50%> (+<0.01%) ⬆️
integration2 ?
unittests1 67.79% <35.00%> (-0.06%) ⬇️
unittests2 13.69% <0.00%> (-0.02%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files Coverage Δ
...uery/runtime/executor/OpChainSchedulerService.java 81.69% <0.00%> (-6.72%) ⬇️
...inot/query/runtime/operator/AggregateOperator.java 94.07% <0.00%> (-2.23%) ⬇️
...e/pinot/query/runtime/operator/FilterOperator.java 83.33% <0.00%> (-8.34%) ⬇️
...pinot/query/runtime/operator/HashJoinOperator.java 91.47% <0.00%> (-3.11%) ⬇️
...e/operator/LeafStageTransferableBlockOperator.java 84.40% <0.00%> (-1.84%) ⬇️
...t/query/runtime/operator/LiteralValueOperator.java 88.46% <0.00%> (-7.70%) ⬇️
...query/runtime/operator/MailboxReceiveOperator.java 91.30% <0.00%> (-2.90%) ⬇️
...ot/query/runtime/operator/MailboxSendOperator.java 87.50% <0.00%> (-5.36%) ⬇️
...che/pinot/query/runtime/operator/SortOperator.java 92.94% <0.00%> (-3.53%) ⬇️
...inot/query/runtime/operator/TransformOperator.java 90.90% <0.00%> (-6.82%) ⬇️
... and 193 more

📣 We’re building smart automated test selection to slash your CI/CD build times. Learn more

@61yao 61yao changed the title [multistage][observability] Add an option to log operator stats to log.error [multistage][observability] Add an option to log operator stats to log.info Jan 26, 2023
public String toExplainString() {
_dataTableBlockBaseOperator.toExplainString();
LOGGER.debug(_operatorStats.toString());
LOGGER.info(_operatorStats.toString());
Copy link
Contributor

Choose a reason for hiding this comment

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

can we move these to MultiStageOperator looks like they are all identical on every concrete impl

Copy link
Contributor

Choose a reason for hiding this comment

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

we can also move _operatorStats.startTimer(); and _operatorStats.endTimer() to MultiStageOperator and overwrite the nextBlock() method.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Can move in next PR since it is urgent.

Comment on lines +125 to +127
if (operatorChain.shouldLogOpStats()) {
operatorChain.getRoot().toExplainString();
}
Copy link
Contributor

Choose a reason for hiding this comment

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

move these to operatorChain.close()?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

ditto

public String toExplainString() {
_upstreamOperator.toExplainString();
LOGGER.debug(_operatorStats.toString());
LOGGER.info(_operatorStats.toString());
Copy link
Contributor

Choose a reason for hiding this comment

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

although not introduced in this PR. but looks like there are a lot of start/stop timer within each operator on how they record the timer. Let's clean them up by recording the entire time e2e and later when logging, subtract current and upstream timer, this way

  1. all the timer operations can be done/wrapped inside MultiStageOperator.nextBlock() method.
  2. avoid the unnecessary start/stop on the stopwatch (although minuscule, it is still perform on a per-block basis)
  3. makes the code cleaner

good example:

try (InvocationScope ignored = Tracing.getTracer().createScope(getClass())) {
return getNextBlock();
}

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This is more complicated implementation. Since we need the time now, I'll check in this PR and have followups. Thanks

@61yao 61yao closed this Feb 8, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants