cmake: Capture more complete configure/generate steps in printed durations

Extend the start/end times from commit 5f0c5ec49b (cmake: Print
configure/generate time, 2023-01-17, v3.26.0-rc1~67^2) to capture
generator-specific Configure/Generate actions, and the time spent
in the internal "Compute" step at the start of generation.

Fixes: #25482
This commit is contained in:
Brad King 2024-05-10 14:42:43 -04:00
parent f106df8f96
commit 29404cfd92
3 changed files with 35 additions and 29 deletions

View File

@ -0,0 +1,8 @@
print-configure-generate-time
-----------------------------
* The durations printed after "Configuring done" and "Generating done"
messages now reflect time spent in generator-specific steps, and
in a code model evaluation step at the beginning of generation that
was not previously captured. Printed durations may appear longer
than in previous versions of CMake.

View File

@ -4,13 +4,11 @@
#include <algorithm>
#include <cassert>
#include <chrono>
#include <cstdio>
#include <cstdlib>
#include <cstring>
#include <functional>
#include <initializer_list>
#include <iomanip>
#include <iterator>
#include <sstream>
#include <type_traits>
@ -1351,8 +1349,6 @@ void cmGlobalGenerator::CreateLocalGenerators()
void cmGlobalGenerator::Configure()
{
auto startTime = std::chrono::steady_clock::now();
this->FirstTimeProgress = 0.0f;
this->ClearGeneratorMembers();
this->NextDeferId = 0;
@ -1407,21 +1403,6 @@ void cmGlobalGenerator::Configure()
this->GetCMakeInstance()->AddCacheEntry(
"CMAKE_NUMBER_OF_MAKEFILES", std::to_string(this->Makefiles.size()),
"number of local generators", cmStateEnums::INTERNAL);
auto endTime = std::chrono::steady_clock::now();
if (this->CMakeInstance->GetWorkingMode() == cmake::NORMAL_MODE) {
std::ostringstream msg;
if (cmSystemTools::GetErrorOccurredFlag()) {
msg << "Configuring incomplete, errors occurred!";
} else {
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
endTime - startTime);
msg << "Configuring done (" << std::fixed << std::setprecision(1)
<< ms.count() / 1000.0L << "s)";
}
this->CMakeInstance->UpdateProgress(msg.str(), -1);
}
}
void cmGlobalGenerator::CreateGenerationObjects(TargetTypes targetTypes)
@ -1683,8 +1664,6 @@ bool cmGlobalGenerator::Compute()
void cmGlobalGenerator::Generate()
{
auto startTime = std::chrono::steady_clock::now();
// Create a map from local generator to the complete set of targets
// it builds by default.
this->InitializeProgressMarks();
@ -1775,14 +1754,6 @@ void cmGlobalGenerator::Generate()
this->GetCMakeInstance()->IssueMessage(MessageType::AUTHOR_WARNING,
w.str());
}
auto endTime = std::chrono::steady_clock::now();
auto ms =
std::chrono::duration_cast<std::chrono::milliseconds>(endTime - startTime);
std::ostringstream msg;
msg << "Generating done (" << std::fixed << std::setprecision(1)
<< ms.count() / 1000.0L << "s)";
this->CMakeInstance->UpdateProgress(msg.str(), -1);
}
bool cmGlobalGenerator::ComputeTargetDepends()

View File

@ -4,10 +4,12 @@
#include <algorithm>
#include <array>
#include <chrono>
#include <cstdio>
#include <cstdlib>
#include <cstring>
#include <initializer_list>
#include <iomanip>
#include <iostream>
#include <sstream>
#include <stdexcept>
@ -2557,7 +2559,22 @@ int cmake::ActualConfigure()
#endif
// actually do the configure
auto startTime = std::chrono::steady_clock::now();
this->GlobalGenerator->Configure();
auto endTime = std::chrono::steady_clock::now();
if (this->GetWorkingMode() == cmake::NORMAL_MODE) {
std::ostringstream msg;
if (cmSystemTools::GetErrorOccurredFlag()) {
msg << "Configuring incomplete, errors occurred!";
} else {
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(
endTime - startTime);
msg << "Configuring done (" << std::fixed << std::setprecision(1)
<< ms.count() / 1000.0L << "s)";
}
this->UpdateProgress(msg.str(), -1);
}
#if !defined(CMAKE_BOOTSTRAP)
this->ConfigureLog.reset();
@ -2889,10 +2906,20 @@ int cmake::Generate()
auto profilingRAII = this->CreateProfilingEntry("project", "generate");
#endif
auto startTime = std::chrono::steady_clock::now();
if (!this->GlobalGenerator->Compute()) {
return -1;
}
this->GlobalGenerator->Generate();
auto endTime = std::chrono::steady_clock::now();
{
auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(endTime -
startTime);
std::ostringstream msg;
msg << "Generating done (" << std::fixed << std::setprecision(1)
<< ms.count() / 1000.0L << "s)";
this->UpdateProgress(msg.str(), -1);
}
if (!this->GraphVizFile.empty()) {
std::cout << "Generate graphviz: " << this->GraphVizFile << '\n';
this->GenerateGraphViz(this->GraphVizFile);