From 6a9c2f4f98817b8c4e38c7d1fde00a8837694bce Mon Sep 17 00:00:00 2001 From: Fedor Sergeev Date: Fri, 15 Mar 2019 22:15:23 +0000 Subject: [PATCH] [TimePasses] allow -time-passes reporting into a custom stream TimePassesHandler object (implementation of time-passes for new pass manager) gains ability to report into a stream customizable per-instance (per pipeline). Intended use is to specify separate time-passes output stream per each compilation, setting up TimePasses member of StandardInstrumentation during PassBuilder setup. That allows to get independent non-overlapping pass-times reports for parallel independent compilations (in JIT-like setups). By default it still puts timing reports into the info-output-file stream (created by CreateInfoOutputFile every time report is requested). Unit-test added for non-default case, and it also allowed to discover that print() does not work as declared - it did not reset the timers, leading to yet another report being printed into the default stream. Fixed print() to actually reset timers according to what was declared in print's comments before. Reviewed By: philip.pfaffe Differential Revision: https://reviews.llvm.org/D59366 llvm-svn: 356305 --- llvm/include/llvm/IR/PassTimingInfo.h | 16 +++-- .../include/llvm/Passes/StandardInstrumentations.h | 2 + llvm/lib/IR/PassTimingInfo.cpp | 11 ++- llvm/test/Other/time-passes.ll | 10 +++ llvm/unittests/IR/CMakeLists.txt | 1 + llvm/unittests/IR/TimePassesTest.cpp | 78 ++++++++++++++++++++++ 6 files changed, 111 insertions(+), 7 deletions(-) create mode 100644 llvm/unittests/IR/TimePassesTest.cpp diff --git a/llvm/include/llvm/IR/PassTimingInfo.h b/llvm/include/llvm/IR/PassTimingInfo.h index ddddbdf..22a473e 100644 --- a/llvm/include/llvm/IR/PassTimingInfo.h +++ b/llvm/include/llvm/IR/PassTimingInfo.h @@ -26,6 +26,7 @@ namespace llvm { class Pass; class PassInstrumentationCallbacks; +class raw_ostream; /// If -time-passes has been specified, report the timings immediately and then /// reset the timers to zero. @@ -62,18 +63,18 @@ class TimePassesHandler { /// Stack of currently active timers. SmallVector TimerStack; + /// Custom output stream to print timing information into. + /// By default (== nullptr) we emit time report into the stream controlled by + /// -info-output-file. + raw_ostream *OutStream = nullptr; + bool Enabled; public: TimePassesHandler(bool Enabled = TimePassesIsEnabled); /// Destructor handles the print action if it has not been handled before. - ~TimePassesHandler() { - // First destroying the timers from TimingData, which deploys all their - // collected data into the TG time group member, which later prints itself - // when being destroyed. - TimingData.clear(); - } + ~TimePassesHandler() { print(); } /// Prints out timing information and then resets the timers. void print(); @@ -84,6 +85,9 @@ public: void registerCallbacks(PassInstrumentationCallbacks &PIC); + /// Set a custom output stream for subsequent reporting. + void setOutStream(raw_ostream &OutStream); + private: /// Dumps information for running/triggered timers, useful for debugging LLVM_DUMP_METHOD void dump() const; diff --git a/llvm/include/llvm/Passes/StandardInstrumentations.h b/llvm/include/llvm/Passes/StandardInstrumentations.h index 5672543..3d3002e 100644 --- a/llvm/include/llvm/Passes/StandardInstrumentations.h +++ b/llvm/include/llvm/Passes/StandardInstrumentations.h @@ -63,6 +63,8 @@ public: StandardInstrumentations() = default; void registerCallbacks(PassInstrumentationCallbacks &PIC); + + TimePassesHandler &getTimePasses() { return TimePasses; } }; } // namespace llvm diff --git a/llvm/lib/IR/PassTimingInfo.cpp b/llvm/lib/IR/PassTimingInfo.cpp index 57efdca..dcbfff1 100644 --- a/llvm/lib/IR/PassTimingInfo.cpp +++ b/llvm/lib/IR/PassTimingInfo.cpp @@ -181,7 +181,16 @@ Timer &TimePassesHandler::getPassTimer(StringRef PassID) { TimePassesHandler::TimePassesHandler(bool Enabled) : TG("pass", "... Pass execution timing report ..."), Enabled(Enabled) {} -void TimePassesHandler::print() { TG.print(*CreateInfoOutputFile()); } +void TimePassesHandler::setOutStream(raw_ostream &Out) { + OutStream = &Out; +} + +void TimePassesHandler::print() { + if (!Enabled) + return; + TG.print(OutStream ? *OutStream : *CreateInfoOutputFile()); + TG.clear(); +} LLVM_DUMP_METHOD void TimePassesHandler::dump() const { dbgs() << "Dumping timers for " << getTypeName() diff --git a/llvm/test/Other/time-passes.ll b/llvm/test/Other/time-passes.ll index 066ff26..743b4eb 100644 --- a/llvm/test/Other/time-passes.ll +++ b/llvm/test/Other/time-passes.ll @@ -4,6 +4,16 @@ ; RUN: opt < %s -disable-output -passes='instcombine,loop(licm),instcombine,loop(licm)' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME --check-prefix=TIME-NEW -check-prefix=TIME-DOUBLE-LICM-NEW ; RUN: opt < %s -disable-output -passes='default' -time-passes 2>&1 | FileCheck %s --check-prefix=TIME ; +; The following 4 test runs verify -info-output-file interaction (default goes to stderr, '-' goes to stdout). +; RUN: opt < %s -disable-output -O2 -time-passes -info-output-file='-' 2>/dev/null | FileCheck %s --check-prefix=TIME +; RUN: opt < %s -disable-output -passes='default' -time-passes -info-output-file='-' 2>/dev/null | FileCheck %s --check-prefix=TIME +; +; RUN: rm -f %t; opt < %s -disable-output -O2 -time-passes -info-output-file=%t +; RUN: cat %t | FileCheck %s --check-prefix=TIME +; +; RUN: rm -f %t; opt < %s -disable-output -passes='default' -time-passes -info-output-file=%t +; RUN: cat %t | FileCheck %s --check-prefix=TIME +; ; TIME: Pass execution timing report ; TIME: Total Execution Time: ; TIME: Name diff --git a/llvm/unittests/IR/CMakeLists.txt b/llvm/unittests/IR/CMakeLists.txt index c3cdf90..5b35dc7 100644 --- a/llvm/unittests/IR/CMakeLists.txt +++ b/llvm/unittests/IR/CMakeLists.txt @@ -30,6 +30,7 @@ add_llvm_unittest(IRTests ModuleTest.cpp PassManagerTest.cpp PatternMatch.cpp + TimePassesTest.cpp TypesTest.cpp UseTest.cpp UserTest.cpp diff --git a/llvm/unittests/IR/TimePassesTest.cpp b/llvm/unittests/IR/TimePassesTest.cpp new file mode 100644 index 0000000..7014436 --- /dev/null +++ b/llvm/unittests/IR/TimePassesTest.cpp @@ -0,0 +1,78 @@ +//===- unittests/IR/TimePassesTest.cpp - TimePassesHandler tests ----------===// +// +// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions. +// See https://llvm.org/LICENSE.txt for license information. +// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception +// +//===----------------------------------------------------------------------===// + +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace llvm; + +namespace { + +class MyPass1 : public PassInfoMixin {}; +class MyPass2 : public PassInfoMixin {}; + +TEST(TimePassesTest, CustomOut) { + PassInstrumentationCallbacks PIC; + PassInstrumentation PI(&PIC); + + LLVMContext Context; + Module M("TestModule", Context); + MyPass1 Pass1; + MyPass2 Pass2; + + SmallString<0> TimePassesStr; + raw_svector_ostream ReportStream(TimePassesStr); + + // Setup time-passes handler and redirect output to the stream. + std::unique_ptr TimePasses = + llvm::make_unique(true); + TimePasses->setOutStream(ReportStream); + TimePasses->registerCallbacks(PIC); + + // Running some passes to trigger the timers. + PI.runBeforePass(Pass1, M); + PI.runBeforePass(Pass2, M); + PI.runAfterPass(Pass2, M); + PI.runAfterPass(Pass1, M); + + // Generating report. + TimePasses->print(); + + // There should be Pass1 and Pass2 in the report + EXPECT_FALSE(TimePassesStr.empty()); + EXPECT_TRUE(TimePassesStr.str().contains("report")); + EXPECT_TRUE(TimePassesStr.str().contains("Pass1")); + EXPECT_TRUE(TimePassesStr.str().contains("Pass2")); + + // Clear and generate report again. + TimePassesStr.clear(); + TimePasses->print(); + // Since we did not run any passes since last print, report should be empty. + EXPECT_TRUE(TimePassesStr.empty()); + + // Now run just a single pass to populate timers again. + PI.runBeforePass(Pass2, M); + PI.runAfterPass(Pass2, M); + + // Generate report by deleting the handler. + TimePasses.reset(); + + // There should be Pass2 in this report and no Pass1. + EXPECT_FALSE(TimePassesStr.str().empty()); + EXPECT_TRUE(TimePassesStr.str().contains("report")); + EXPECT_FALSE(TimePassesStr.str().contains("Pass1")); + EXPECT_TRUE(TimePassesStr.str().contains("Pass2")); +} + +} // end anonymous namespace -- 2.7.4