diff options
author | Evan Martin <martine@danga.com> | 2011-05-09 23:24:24 (GMT) |
---|---|---|
committer | Evan Martin <martine@danga.com> | 2011-05-11 18:29:01 (GMT) |
commit | fa8830b546428e1daa829d0ddf2465697e0d9bb3 (patch) | |
tree | e824209be8b0276109ae419ef024e28b59ec35bd | |
parent | 3f7f99fbb5b064f2850543cf5574a6dc2b8d3a9d (diff) | |
download | Ninja-fa8830b546428e1daa829d0ddf2465697e0d9bb3.zip Ninja-fa8830b546428e1daa829d0ddf2465697e0d9bb3.tar.gz Ninja-fa8830b546428e1daa829d0ddf2465697e0d9bb3.tar.bz2 |
add a versioning header to build log, switch to v2
In v2 we store both the start and end time of the command.
This allows better visualization of the build process.
-rw-r--r-- | src/build.cc | 30 | ||||
-rw-r--r-- | src/build_log.cc | 64 | ||||
-rw-r--r-- | src/build_log.h | 10 | ||||
-rw-r--r-- | src/build_log_test.cc | 6 |
4 files changed, 83 insertions, 27 deletions
diff --git a/src/build.cc b/src/build.cc index 7f7ae6d..1deb08a 100644 --- a/src/build.cc +++ b/src/build.cc @@ -49,15 +49,19 @@ struct BuildStatus { BuildStatus(); void PlanHasTotalEdges(int total); void BuildEdgeStarted(Edge* edge); - /// Returns the time the edge took, in ms. - int BuildEdgeFinished(Edge* edge); + void BuildEdgeFinished(Edge* edge, int* start_time, int* end_time); void PrintStatus(Edge* edge); + /// Time the build started. + int64_t start_time_millis_; + /// Time we last printed an update. int64_t last_update_millis_; + int finished_edges_, total_edges_; - typedef map<Edge*, int64_t> RunningEdgeMap; + /// Map of running edge to time the edge started running. + typedef map<Edge*, int> RunningEdgeMap; RunningEdgeMap running_edges_; BuildConfig::Verbosity verbosity_; @@ -66,7 +70,8 @@ struct BuildStatus { }; BuildStatus::BuildStatus() - : last_update_millis_(GetTimeMillis()), + : start_time_millis_(GetTimeMillis()), + last_update_millis_(start_time_millis_), finished_edges_(0), total_edges_(0), verbosity_(BuildConfig::NORMAL) { #ifndef WIN32 @@ -82,12 +87,15 @@ void BuildStatus::PlanHasTotalEdges(int total) { } void BuildStatus::BuildEdgeStarted(Edge* edge) { - running_edges_.insert(make_pair(edge, GetTimeMillis())); + int start_time = (int)(GetTimeMillis() - start_time_millis_); + running_edges_.insert(make_pair(edge, start_time)); PrintStatus(edge); } -int BuildStatus::BuildEdgeFinished(Edge* edge) { +void BuildStatus::BuildEdgeFinished(Edge* edge, + int* start_time, + int* end_time) { int64_t now = GetTimeMillis(); ++finished_edges_; @@ -106,10 +114,9 @@ int BuildStatus::BuildEdgeFinished(Edge* edge) { } RunningEdgeMap::iterator i = running_edges_.find(edge); - int ms = (int)(now - i->second); + *start_time = i->second; + *end_time = (int)(now - start_time_millis_); running_edges_.erase(i); - - return ms; } void BuildStatus::PrintStatus(Edge* edge) { @@ -487,7 +494,8 @@ void Builder::FinishEdge(Edge* edge) { if (edge->is_phony()) return; - int ms = status_->BuildEdgeFinished(edge); + int start_time, end_time; + status_->BuildEdgeFinished(edge, &start_time, &end_time); if (log_) - log_->RecordCommand(edge, ms); + log_->RecordCommand(edge, start_time, end_time); } diff --git a/src/build_log.cc b/src/build_log.cc index 66b85a9..cd74bd1 100644 --- a/src/build_log.cc +++ b/src/build_log.cc @@ -29,6 +29,13 @@ // Once the number of redundant entries exceeds a threshold, we write // out a new file and replace the existing one with it. +namespace { + +const char kFileSignature[] = "# ninja log v2\n"; +const int kCurrentVersion = 2; + +} + BuildLog::BuildLog() : log_file_(NULL), config_(NULL), needs_recompaction_(false) {} @@ -48,10 +55,18 @@ bool BuildLog::OpenForWrite(const string& path, string* err) { return false; } setvbuf(log_file_, NULL, _IOLBF, 0); + + if (ftell(log_file_) == 0) { + if (fwrite(kFileSignature, sizeof(kFileSignature) - 1, 1, log_file_) < 1) { + *err = strerror(errno); + return false; + } + } + return true; } -void BuildLog::RecordCommand(Edge* edge, int time_ms) { +void BuildLog::RecordCommand(Edge* edge, int start_time, int end_time) { if (!log_file_) return; @@ -69,7 +84,8 @@ void BuildLog::RecordCommand(Edge* edge, int time_ms) { } log_entry->output = path; log_entry->command = command; - log_entry->time_ms = time_ms; + log_entry->start_time = start_time; + log_entry->end_time = end_time; WriteEntry(log_file_, *log_entry); } @@ -90,19 +106,43 @@ bool BuildLog::Load(const string& path, string* err) { return false; } + int log_version = 0; int unique_entry_count = 0; int total_entry_count = 0; char buf[256 << 10]; while (fgets(buf, sizeof(buf), file)) { + if (!log_version) { + log_version = 1; // Assume by default. + if (strcmp(buf, kFileSignature) == 0) { + log_version = 2; + continue; + } + } char* start = buf; char* end = strchr(start, ' '); if (!end) continue; - *end = 0; - int time_ms = atoi(start); - start = end + 1; + + int start_time = 0, end_time = 0; + if (log_version == 1) { + // In v1 we logged how long the command took; we don't use this info. + // int time_ms = atoi(start); + start = end + 1; + } else { + // In v2 we log the start time and the end time. + start_time = atoi(start); + start = end + 1; + + char* end = strchr(start, ' '); + if (!end) + continue; + *end = 0; + end_time = atoi(start); + start = end + 1; + } + end = strchr(start, ' '); string output = string(start, end - start); @@ -117,8 +157,9 @@ bool BuildLog::Load(const string& path, string* err) { } ++total_entry_count; - entry->time_ms = time_ms; entry->output = output; + entry->start_time = start_time; + entry->end_time = end_time; start = end + 1; end = strchr(start, '\n'); @@ -126,10 +167,12 @@ bool BuildLog::Load(const string& path, string* err) { } // Mark the log as "needs rebuiding" if it has kCompactionRatio times - // too many log entries. + // too many log entries or it's the wrong version. int kCompactionRatio = 3; - if (total_entry_count > unique_entry_count * kCompactionRatio) + if (total_entry_count > unique_entry_count * kCompactionRatio || + log_version < kCurrentVersion) { needs_recompaction_ = true; + } fclose(file); @@ -144,8 +187,9 @@ BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) { } void BuildLog::WriteEntry(FILE* f, const LogEntry& entry) { - fprintf(f, "%d %s %s\n", - entry.time_ms, entry.output.c_str(), entry.command.c_str()); + fprintf(f, "%d %d %s %s\n", + entry.start_time, entry.end_time, + entry.output.c_str(), entry.command.c_str()); } bool BuildLog::Recompact(const string& path, string* err) { diff --git a/src/build_log.h b/src/build_log.h index 5d8d6a2..81a745f 100644 --- a/src/build_log.h +++ b/src/build_log.h @@ -35,7 +35,7 @@ struct BuildLog { void SetConfig(BuildConfig* config) { config_ = config; } bool OpenForWrite(const string& path, string* err); - void RecordCommand(Edge* edge, int time_ms); + void RecordCommand(Edge* edge, int start_time, int end_time); void Close(); /// Load the on-disk log. @@ -44,9 +44,13 @@ struct BuildLog { struct LogEntry { string output; string command; - int time_ms; + int start_time; + int end_time; + + // Used by tests. bool operator==(const LogEntry& o) { - return output == o.output && command == o.command && time_ms == o.time_ms; + return output == o.output && command == o.command && + start_time == o.start_time && end_time == o.end_time; } }; diff --git a/src/build_log_test.cc b/src/build_log_test.cc index 66f88c3..caf1540 100644 --- a/src/build_log_test.cc +++ b/src/build_log_test.cc @@ -35,8 +35,8 @@ TEST_F(BuildLogTest, WriteRead) { string err; EXPECT_TRUE(log1.OpenForWrite(kTestFilename, &err)); ASSERT_EQ("", err); - log1.RecordCommand(state_.edges_[0], 15); - log1.RecordCommand(state_.edges_[1], 20); + log1.RecordCommand(state_.edges_[0], 15, 18); + log1.RecordCommand(state_.edges_[1], 20, 25); log1.Close(); BuildLog log2; @@ -50,7 +50,7 @@ TEST_F(BuildLogTest, WriteRead) { BuildLog::LogEntry* e2 = log2.LookupByOutput("out"); ASSERT_TRUE(e2); ASSERT_TRUE(*e1 == *e2); - ASSERT_EQ(15, e1->time_ms); + ASSERT_EQ(15, e1->start_time); ASSERT_EQ("out", e1->output); } |