Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with
or
.
Download ZIP
Browse files

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.
  • Loading branch information...
commit fa8830b546428e1daa829d0ddf2465697e0d9bb3 1 parent 3f7f99f
@martine authored
View
30 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);
}
View
64 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) {
View
10 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;
}
};
View
6 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);
}
Please sign in to comment.
Something went wrong with that request. Please try again.