Skip to content

Commit 2667877

Browse files
narasamdyanarasamdya
committed
Merged PR 730792: Workaround for execution log high memory consumption issue
This PR consists of two changes: 1. revert of commit e2ca19c, and 2. a temporary way of handling exception when writing events. For (2), we simply stop writing all events. The consequence is the execution log is incomplete and cannot be read (corrupted).
1 parent b9e4ef1 commit 2667877

File tree

5 files changed

+77
-297
lines changed

5 files changed

+77
-297
lines changed

‎Public/Src/Engine/Scheduler/Tracing/ExecutionLog.Events.cs‎

Lines changed: 1 addition & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -129,11 +129,6 @@ public interface IExecutionLogTarget : IDisposable
129129
/// Build Manifest hash and relative file path is reported
130130
/// </summary>
131131
void RecordFileForBuildManifest(RecordFileForBuildManifestEventData data);
132-
133-
/// <summary>
134-
/// Test custom event. Used only by unit tests.
135-
/// </summary>
136-
void TestCustom(TestCustomEventData data);
137132
}
138133

139134
/// <summary>
@@ -220,11 +215,6 @@ public enum ExecutionEventId : byte
220215
/// See <see cref="IExecutionLogTarget.DynamicDirectoryContentsDecided"/>
221216
/// </summary>
222217
DynamicDirectoryContentsDecided = 16,
223-
224-
/// <summary>
225-
/// See <see cref="IExecutionLogTarget.TestCustom"/>
226-
/// </summary>
227-
TestCustom = 17,
228218
}
229219

230220
/// <summary>
@@ -354,14 +344,6 @@ public static class ExecutionLogMetadata
354344
ExecutionEventId.RecordFileForBuildManifest,
355345
(data, target) => target.RecordFileForBuildManifest(data));
356346

357-
/// <summary>
358-
/// Event description for <see cref="IExecutionLogTarget.PipExecutionDirectoryOutputs"/>
359-
/// </summary>
360-
public static readonly ExecutionLogEventMetadata<TestCustomEventData> TestCustom =
361-
new ExecutionLogEventMetadata<TestCustomEventData>(
362-
ExecutionEventId.TestCustom,
363-
(data, target) => target.TestCustom(data));
364-
365347
/// <summary>
366348
/// All execution log events.
367349
/// </summary>
@@ -381,8 +363,7 @@ public static class ExecutionLogMetadata
381363
PipExecutionDirectoryOutputs,
382364
CacheMaterializationError,
383365
RecordFileForBuildManifest,
384-
DynamicDirectoryContentsDecided,
385-
TestCustom,
366+
DynamicDirectoryContentsDecided
386367
};
387368
}
388369

@@ -1482,30 +1463,4 @@ public void DeserializeAndUpdate(BinaryLogReader.EventReader reader)
14821463
r => (reader.ReadFileArtifact(), new ContentHash(reader)));
14831464
}
14841465
}
1485-
1486-
/// <summary>
1487-
/// Custom event for testing purposes.
1488-
/// </summary>
1489-
[SuppressMessage("Microsoft.Performance", "CA1815:OverrideEqualsAndOperatorEqualsOnValueTypes")]
1490-
public struct TestCustomEventData : IExecutionLogEventData<TestCustomEventData>
1491-
{
1492-
/// <summary>
1493-
/// Custom serialization function.
1494-
/// </summary>
1495-
public static Action<BinaryLogger.EventWriter> SerializeFunc;
1496-
1497-
/// <summary>
1498-
/// Custom deserialization function.
1499-
/// </summary>
1500-
public static Action<BinaryLogReader.EventReader> DeserializeAndUpdateFunc;
1501-
1502-
/// <inheritdoc />
1503-
public ExecutionLogEventMetadata<TestCustomEventData> Metadata => ExecutionLogMetadata.TestCustom;
1504-
1505-
/// <inheritdoc />
1506-
public void DeserializeAndUpdate(BinaryLogReader.EventReader reader) => DeserializeAndUpdateFunc(reader);
1507-
1508-
/// <inheritdoc />
1509-
public void Serialize(BinaryLogger.EventWriter writer) => SerializeFunc(writer);
1510-
}
15111466
}

‎Public/Src/Engine/Scheduler/Tracing/ExecutionLog.cs‎

Lines changed: 18 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@
55
using System.Collections.Generic;
66
using System.Diagnostics.ContractsLight;
77
using System.IO;
8+
using BuildXL.Utilities;
89
using BuildXL.Utilities.Core;
910
using BuildXL.Utilities.Tracing;
1011
using static BuildXL.Utilities.Core.FormattableStringEx;
@@ -242,10 +243,18 @@ public virtual void DynamicDirectoryContentsDecided(DynamicDirectoryContentsDeci
242243
ReportUnhandledEvent(data);
243244
}
244245

245-
/// <nodoc />
246-
public virtual void TestCustom(TestCustomEventData data)
246+
/// <summary>
247+
/// Disables all events.
248+
/// </summary>
249+
/// <remarks>
250+
/// This method can be called when there is an exception is writing an event.
251+
/// </remarks>
252+
protected void DisableAllEvents()
247253
{
248-
ReportUnhandledEvent(data);
254+
for (int i = 0; i < m_disabledEvents.Length; i++)
255+
{
256+
m_disabledEvents[i] = true;
257+
}
249258
}
250259
}
251260

@@ -287,10 +296,7 @@ public sealed class ExecutionLogEventMetadata<TEventData> : ExecutionLogEventMet
287296

288297
/// <nodoc />
289298
public ExecutionLogEventMetadata(ExecutionEventId eventId, Action<TEventData, IExecutionLogTarget> logToTarget)
290-
: base(eventId)
291-
{
292-
m_process = logToTarget;
293-
}
299+
: base(eventId) => m_process = logToTarget;
294300

295301
/// <inheritdoc />
296302
public override void DeserializeAndLogToTarget(BinaryLogReader.EventReader eventReader, IExecutionLogTarget target)
@@ -378,26 +384,24 @@ public ExecutionLogFileTarget(BinaryLogger logFile, bool closeLogFileOnDispose =
378384
/// Clones the execution log target with the same backing binary logger but against a different worker id
379385
/// </summary>
380386
private ExecutionLogFileTarget(BinaryLogger logFile, uint workerId, IReadOnlyList<int> disabledEventIds)
381-
: this(logFile, closeLogFileOnDispose: false, disabledEventIds: disabledEventIds)
382-
{
383-
m_workerId = workerId;
384-
}
387+
: this(logFile, closeLogFileOnDispose: false, disabledEventIds: disabledEventIds) => m_workerId = workerId;
385388

386389
private void Log<TEventData>(TEventData data) where TEventData : struct, IExecutionLogEventData<TEventData>
387390
{
388391
using (BinaryLogger.EventScope eventScope = m_logFile.StartEvent((uint)data.Metadata.EventId, m_workerId))
389392
{
390-
391393
try
392394
{
393395
data.Serialize(eventScope.Writer);
394396
}
395397
catch (Exception e)
396398
{
397-
// Set exception so that event is not serialized to the log file.
398399
eventScope.SetException(e);
399400

400-
// Inform users that an event is not logged due to an exception.
401+
// Disable all events writing.
402+
DisableAllEvents();
403+
404+
// Warn users that an event is not logged due to an exception, and this exception can corrupt the execution log.
401405
Logger.Log.FailedLoggingExecutionLogEventData(Events.StaticContext, data.Metadata.EventId.ToString(), e.ToString());
402406
}
403407
}

‎Public/Src/Engine/Scheduler/Tracing/Log.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4028,7 +4028,7 @@ internal abstract void ProcessPipExecutionInfo(
40284028
EventLevel = Level.Warning,
40294029
Keywords = (int)Keywords.UserMessage,
40304030
EventTask = (ushort)Tasks.Scheduler,
4031-
Message = "Failed logging execution log event data '{eventId}'. This does not impact build correctness but will cause the execution log to be incomplete for post-build analysis. Failure reason: {error}")]
4031+
Message = "Failed logging execution log event data '{eventId}'. This does not impact build correctness but will cause the execution log to be incomplete (or corrupted) for post-build analysis. Failure reason: {error}")]
40324032
internal abstract void FailedLoggingExecutionLogEventData(LoggingContext loggingContext, string eventId, string error);
40334033
}
40344034
}

‎Public/Src/Engine/UnitTests/Scheduler/ExecutionLogTests.cs‎

Lines changed: 18 additions & 159 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ public ExecutionLogTests(ITestOutputHelper output)
3838
[Fact]
3939
public void TestRoundTripExecutionLog()
4040
{
41-
TestExecutionLogHelper(ExpectProcessMonitoringEventData);
41+
TestExecutionLogHelper(verifier => ExpectProcessMonitoringEventData(verifier));
4242
}
4343

4444
[Fact]
@@ -78,155 +78,22 @@ public void TestPipCacheMissEventData()
7878
public void TestPipExecutionDirectoryOutputs()
7979
{
8080
TestExecutionLogHelper(verifier =>
81-
{
82-
verifier.Expect(new PipExecutionDirectoryOutputs
83-
{
84-
PipId = new PipId(123),
85-
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
86-
(
87-
CreateDirectory(),
88-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(CreateSourceFile(), CreateOutputFile())
89-
),
90-
(
91-
CreateDirectory(),
92-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(CreateOutputFile(), CreateSourceFile())
93-
)
94-
)
95-
});
96-
});
97-
}
98-
99-
[Fact]
100-
public void TestCustomEvent()
101-
{
102-
TestExecutionLogHelper(verifier =>
103-
{
104-
var pipId = new PipId(123);
105-
var sourceFile = CreateSourceFile();
106-
var outputFile = CreateOutputFile();
107-
108-
TestCustomEventData.SerializeFunc = writer =>
109-
{
110-
pipId.Serialize(writer);
111-
writer.Write(sourceFile);
112-
writer.Write(outputFile);
113-
};
114-
115-
TestCustomEventData.DeserializeAndUpdateFunc = reader =>
116-
{
117-
var dPipId = PipId.Deserialize(reader);
118-
var dSourceFile = reader.ReadFileArtifact();
119-
var dOutputFile = reader.ReadFileArtifact();
120-
XAssert.AreEqual(pipId, dPipId);
121-
XAssert.AreEqual(sourceFile, dSourceFile);
122-
XAssert.AreEqual(outputFile, dOutputFile);
123-
};
124-
125-
verifier.Expect(new TestCustomEventData());
126-
});
127-
}
128-
129-
[Fact]
130-
public void TestSkipEventDueToFailedSerialization()
131-
{
132-
TestExecutionLogHelper(verifier =>
133-
{
134-
var outputFile1 = CreateOutputFile();
135-
var outputFile2 = CreateOutputFile();
136-
var outputFile3 = CreateOutputFile();
137-
var outputFile4 = CreateOutputFile();
138-
139-
verifier.Expect(new PipExecutionDirectoryOutputs
140-
{
141-
PipId = new PipId(123),
142-
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
143-
(
144-
CreateDirectory(),
145-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(outputFile1, outputFile2)
146-
))
147-
});
148-
149-
TestCustomEventData.SerializeFunc = writer =>
150-
{
151-
writer.Write(outputFile2);
152-
writer.Write(outputFile3);
153-
throw new OutOfMemoryException("Fake OOM exception");
154-
};
155-
156-
TestCustomEventData.DeserializeAndUpdateFunc = reader =>
157-
{
158-
XAssert.Fail("Deserialization should never be called due to failed serialization");
159-
};
160-
161-
verifier.LogUnexpectedExpect(new TestCustomEventData());
162-
163-
verifier.Expect(new PipExecutionDirectoryOutputs
164-
{
165-
PipId = new PipId(234),
166-
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
167-
(
168-
CreateDirectory(),
169-
// Although outputFile2 was not serialized by the test custom event, it should still be
170-
// serialized by this event, and so the deserialization should succeed.
171-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(outputFile2, outputFile3, outputFile4)
172-
))
173-
});
174-
});
175-
}
176-
177-
[Fact]
178-
[Trait("Category", "LongRunningTest")]
179-
public void TestSkipEventDueToTooLargeSerialization()
180-
{
181-
TestExecutionLogHelper(verifier =>
182-
{
183-
var outputFile1 = CreateOutputFile();
184-
var outputFile2 = CreateOutputFile();
185-
var outputFile3 = CreateOutputFile();
186-
var outputFile4 = CreateOutputFile();
187-
var dummyFile = CreateOutputFile();
188-
189-
verifier.Expect(new PipExecutionDirectoryOutputs
190-
{
191-
PipId = new PipId(123),
192-
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
193-
(
194-
CreateDirectory(),
195-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(outputFile1, outputFile2)
196-
))
197-
});
198-
199-
TestCustomEventData.SerializeFunc = writer =>
200-
{
201-
writer.Write(outputFile2);
202-
writer.Write(outputFile3);
203-
204-
// The following should cause OutOfMemory exception on the underlying MemoryStream.
205-
while (true)
206-
{
207-
writer.Write(dummyFile);
208-
}
209-
};
210-
211-
TestCustomEventData.DeserializeAndUpdateFunc = reader =>
212-
{
213-
XAssert.Fail("Deserialization should never be called due to failed serialization");
214-
};
215-
216-
verifier.LogUnexpectedExpect(new TestCustomEventData());
217-
218-
verifier.Expect(new PipExecutionDirectoryOutputs
219-
{
220-
PipId = new PipId(234),
221-
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
222-
(
223-
CreateDirectory(),
224-
// Although outputFile2 was not serialized by the test custom event, it should still be
225-
// serialized by this event, and so the deserialization should succeed.
226-
ReadOnlyArray<FileArtifact>.FromWithoutCopy(outputFile2, outputFile3, outputFile4)
227-
))
228-
});
229-
});
81+
{
82+
verifier.Expect(new PipExecutionDirectoryOutputs
83+
{
84+
PipId = new PipId(123),
85+
DirectoryOutputs = ReadOnlyArray<(DirectoryArtifact, ReadOnlyArray<FileArtifact>)>.FromWithoutCopy(
86+
(
87+
CreateDirectory(),
88+
ReadOnlyArray<FileArtifact>.FromWithoutCopy(CreateSourceFile(), CreateOutputFile())
89+
),
90+
(
91+
CreateDirectory(),
92+
ReadOnlyArray<FileArtifact>.FromWithoutCopy(CreateOutputFile(), CreateSourceFile())
93+
)
94+
)
95+
});
96+
});
23097
}
23198

23299
[Fact]
@@ -447,8 +314,7 @@ private class ExecutionLogVerifier : ExecutionLogTargetBase,
447314
IEqualityVerifier<ProcessFingerprintComputationEventData>,
448315
IEqualityVerifier<ObservedInputsEventData>,
449316
IEqualityVerifier<PipCacheMissEventData>,
450-
IEqualityVerifier<PipExecutionDirectoryOutputs>,
451-
IEqualityVerifier<TestCustomEventData>
317+
IEqualityVerifier<PipExecutionDirectoryOutputs>
452318
{
453319
private readonly Queue<object> m_expectedData = new Queue<object>();
454320
private readonly ExecutionLogTests m_parent;
@@ -493,11 +359,6 @@ public override void PipExecutionDirectoryOutputs(PipExecutionDirectoryOutputs d
493359
VerifyEvent(data);
494360
}
495361

496-
public override void TestCustom(TestCustomEventData data)
497-
{
498-
VerifyEvent(data);
499-
}
500-
501362
public virtual void Expect<TEventData>(TEventData data)
502363
where TEventData : struct, IExecutionLogEventData<TEventData>
503364
{
@@ -659,8 +520,6 @@ public bool VerifyEquals(PipExecutionDirectoryOutputs expected, PipExecutionDire
659520
return true;
660521
}
661522

662-
public bool VerifyEquals(TestCustomEventData expected, TestCustomEventData actual) => true;
663-
664523
private class DirectoryOutputComparer : IEqualityComparer<(DirectoryArtifact directoryArtifact, ReadOnlyArray<FileArtifact> contents)>
665524
{
666525
public static readonly DirectoryOutputComparer Instance = new DirectoryOutputComparer();

0 commit comments

Comments
 (0)