Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Change the format of output produced by --progress #5341

Merged
merged 3 commits into from
Apr 23, 2024
Merged

Change the format of output produced by --progress #5341

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
3bff5a9
Change the format of output produced by --progress
atomb Apr 19, 2024
d04d106
Fix tests
atomb Apr 19, 2024
25cba72
Merge branch 'master' into progress-reformat
atomb Apr 22, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 3 additions & 3 deletions Source/DafnyDriver/CliCompilation.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -183,12 +183,12 @@ public async IAsyncEnumerable<CanVerifyResult> VerifyAllLazily(int? randomSeed)
if (Options.Get(CommonOptionBag.ProgressOption)) {
var token = BoogieGenerator.ToDafnyToken(false, boogieUpdate.VerificationTask.Split.Token);
var runResult = completed.Result;
var resourcesUsed = runResult.ResourceCount.ToString("E1", CultureInfo.InvariantCulture);
var timeString = runResult.RunTime.ToString("g");
Options.OutputWriter.WriteLine(
$"Verification part {canVerifyResult.CompletedParts.Count}/{canVerifyResult.Tasks.Count} of {boogieUpdate.CanVerify.FullDafnyName}" +
$", on line {token.line}, " +
$"{DescribeOutcome(Compilation.GetOutcome(runResult.Outcome))}" +
$", taking {runResult.RunTime.Milliseconds}ms and consuming {resourcesUsed} resources");
$" (time: {timeString}, resource count: {runResult.ResourceCount})");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do you want to put the two time properties in parenthesis, instead of include them in the sentence? Also why "time" instead of "duration" ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ultimately this makes the message shorter, making it more likely that it'll fit on a single line. When you're seeing many of these go by, the ability to quickly do pattern recognition on the output without explicitly reading it is very helpful, in my experience.

Copy link
Member

@keyboardDrummer keyboardDrummer Apr 23, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could you change "time" into "duration", and possibly resource count into resources or ticks, although I appreciate the latter might be a bigger change?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thinking about this more, I'm slightly inclined to make it more like the IDE and include something like (0:00:1.25, 23947 RU). I'm worried about using multiple terms to describe resource usage. So far, we've always said "resource count" as an overall descriptor or used the abbreviation "RU" for the units, and the IDE uses "RU" heavily.

When using a unit suffix instead of a descriptive prefix, having either "time: " or "duration: " before the other one feels inconsistent to me. And it'll be formatted in such a way that I think it's obvious that it's describing a time/duration.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One solution would be to list units for both, and not format the duration in "H:M:S" structure. So it would be something like "(3274.86 s, 23194090 RU)". I think perhaps that's my favorite, because it also makes high duration easier to pick out.

}
if (canVerifyResult.CompletedParts.Count == canVerifyResult.Tasks.Count) {
canVerifyResult.Finished.TrySetResult();
Expand Down Expand Up @@ -311,4 +311,4 @@ record VerificationStatistics {
public int OutOfResourceCount;
public int OutOfMemoryCount;
public int SolverExceptionCount;
}
}
26 changes: 26 additions & 0 deletions ...ts/TestFiles/LitTests/LitTest/verification/Inputs/outOfResourceAndIsolateAssertions.check
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
CHECK: Verified 0/2 symbols. Waiting for f to verify.
CHECK: Verification part 1/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 2/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 3/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 4/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 5/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 6/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 7/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 8/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 9/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 10/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 11/11 of f, on line 5, verified successfully \(time: .*, resource count: .*\)
CHECK: Verified 1/2 symbols. Waiting for L to verify.
CHECK: Verification part 1/9 of L, on line 7, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 2/9 of L, on line 9, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 3/9 of L, on line 10, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 4/9 of L, on line 10, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 5/9 of L, on line 10, ran out of resources \(time: .*, resource count: .*\)
CHECK: Verification part 6/9 of L, on line 11, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 7/9 of L, on line 12, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 8/9 of L, on line 12, verified successfully \(time: .*, resource count: .*\)
CHECK: Verification part 9/9 of L, on line 12, ran out of resources
outOfResourceAndIsolateAssertions.dfy\(10,18\): Error: Verification out of resource \(L\)
outOfResourceAndIsolateAssertions.dfy\(12,18\): Error: Verification out of resource \(L\)

Dafny program verifier finished with 18 verified, 0 errors, 2 out of resource
24 changes: 12 additions & 12 deletions ...egrationTests/TestFiles/LitTests/LitTest/verification/Inputs/progressSecondSequence.check
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,12 +1,12 @@
// CHECK-L:Verification part 1/3 of Foo, on line 6, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/3 of Foo, on line 8, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK-L:Verification part 3/3 of Foo, on line 9, verified successfully, redacted and consuming 2.8E+003 resources
// CHECK-L:Verification part 1/2 of Faz, on line 12, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/2 of Faz, on line 12, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK-L:Verification part 1/2 of Fopple, on line 14, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/2 of Fopple, on line 14, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK-L:Verification part 1/3 of Burp, on line 16, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/3 of Burp, on line 18, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK-L:Verification part 3/3 of Burp, on line 19, verified successfully, redacted and consuming 2.8E+003 resources
// CHECK-L:Verification part 1/2 of Blanc, on line 22, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/2 of Blanc, on line 22, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK:Verification part 1/3 of Foo, on line 6, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/3 of Foo, on line 8, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 3/3 of Foo, on line 9, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 1/2 of Faz, on line 12, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/2 of Faz, on line 12, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 1/2 of Fopple, on line 14, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/2 of Fopple, on line 14, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 1/3 of Burp, on line 16, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/3 of Burp, on line 18, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 3/3 of Burp, on line 19, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 1/2 of Blanc, on line 22, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/2 of Blanc, on line 22, verified successfully \(time: .*, resource count: .*\)
16 changes: 8 additions & 8 deletions Source/IntegrationTests/TestFiles/LitTests/LitTest/verification/isolate-assertions.dfy
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,11 +1,11 @@
// RUN: %verify --progress --cores=1 %s &> %t.raw
// RUN: %sed 's/taking \d*ms/redacted/g' %t.raw > %t
// RUN: %verify --progress --cores=1 %s &> %t
// RUN: %OutputCheck --file-to-check "%t" "%s"
// CHECK-L:Verification part 1/3 of Foo, on line 10, verified successfully, redacted and consuming 8.7E+002 resources
// CHECK-L:Verification part 2/3 of Foo, on line 11, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK-L:Verification part 3/3 of Foo, on line 12, verified successfully, redacted and consuming 2.8E+003 resources
// CHECK-L:Verified 1/2 symbols. Waiting for Bar to verify.
// CHECK-L:Verification part 1/1 of Bar, on line 15, verified successfully, redacted and consuming 3.1E+003 resources
// CHECK:Verification part 1/3 of Foo, on line 10, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 2/3 of Foo, on line 11, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verification part 3/3 of Foo, on line 12, verified successfully \(time: .*, resource count: .*\)
// CHECK:Verified 1/2 symbols. Waiting for Bar to verify.
// CHECK:Verification part 1/1 of Bar, on line 15, verified successfully \(time: .*, resource count: .*\)


method {:isolate_assertions} Foo() {
assert true;
Expand All @@ -15,4 +15,4 @@ method {:isolate_assertions} Foo() {
method Bar() {
assert true;
assert true;
}
}
8 changes: 0 additions & 8 deletions ...ce/IntegrationTests/TestFiles/LitTests/LitTest/verification/isolate-assertions.dfy.expect
View file
Open in desktop

This file was deleted.

6 changes: 3 additions & 3 deletions ...rationTests/TestFiles/LitTests/LitTest/verification/outOfResourceAndIsolateAssertions.dfy
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
// RUN: ! %verify --isolate-assertions --cores=1 --progress "%s" &> %t.raw
// RUN: %sed 's/taking \d*ms/redacted/g' %t.raw > %t
// RUN: %diff "%s.expect" %t
// RUN: ! %verify --isolate-assertions --cores=1 --progress "%s" &> "%t"
// RUN: %OutputCheck --file-to-check "%t" "%S/Inputs/outOfResourceAndIsolateAssertions.check"


ghost function f(i:nat, j:nat):int {if i == 0 then 0 else f(i - 1, i * j + 1) + f(i - 1, 2 * i * j)}

Expand Down
26 changes: 0 additions & 26 deletions ...ests/TestFiles/LitTests/LitTest/verification/outOfResourceAndIsolateAssertions.dfy.expect
View file
Open in desktop

This file was deleted.

6 changes: 3 additions & 3 deletions Source/IntegrationTests/TestFiles/LitTests/LitTest/verification/progress.dfy
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,8 @@
// RUN: %verify --progress --isolate-assertions --cores=1 %s > %t.raw
// RUN: %sed 's/taking \d*ms/redacted/g' %t.raw > %t
// RUN: %verify --progress --isolate-assertions --cores=1 %s > %t
// RUN: %OutputCheck --file-to-check %t "%S/Inputs/progressFirstSequence.check"
// RUN: %OutputCheck --file-to-check %t "%S/Inputs/progressSecondSequence.check"


method Foo()
{
assert true;
Expand All @@ -19,4 +19,4 @@ method Burp()
assert true;
}

method Blanc() ensures true { }
method Blanc() ensures true { }
19 changes: 0 additions & 19 deletions Source/IntegrationTests/TestFiles/LitTests/LitTest/verification/progress.dfy.expect
View file
Open in desktop

This file was deleted.

Loading