Skip to content

Commit

Permalink
Profiling suites with focused specs no longer generates an erroneous …
Browse files Browse the repository at this point in the history 
…failure message

Because suites with programatic focus cause Ginkgo to exit early with a non-zero status code the go test profiling infrastructure fails to generate profiles.  The previous behavior emitted an error message about the profiles and swallowed the non-zero status code returning status code 1, instead.  The new behavior in this commit generates more meaningful logging to help the users understand what's going on.

Fixes #930
  • Loading branch information
@onsi
onsi committed Feb 11, 2022
1 parent 359913b commit 8fbfa02
Show file tree
Hide file tree
Showing 4 changed files with 224 additions and 37 deletions.
4 changes: 4 additions & 0 deletions docs/index.md
View file
Expand Up @@ -2877,11 +2877,15 @@ When run with `--cover`, Ginkgo will generate a single `coverprofile.out` file t

Ginkgo also honors the `--output-dir` flag when generating coverprofiles. If you specify `--output-dir` the generated coverprofile will be placed in the requested directory. If you also specify `--keep-separate-coverprofiles` individual package coverprofiles will be placed in the requested directory and namespaced with a prefix that contains the name of the package in question.

Finally, when running a suite that has [programatically focused specs](#focused-specs) (i.e. specs with the `Focus` decorator or with nodes prefixed with an `F`) Ginkgo exits the suite early with a non-zero exit code. This interferes with `go test`'s profiling code and prevents profiles from being generated. Ginkgo will you tell you this has happened. If you want to profile just a subset of your suite you'll need to use a different [mechanism](#filtering-specs) to filter your specs.

#### Other Profiles
Running `ginkgo` with any of `--cpuprofile=X`, `--memprofile=X`, `--blockprofile=X`, and `--mutexprofile=X` will generate corresponding profile files for suite that runs. Doing so will also preserve the test binary generated by Ginkgo to enable users to use `go tool pprof <BINARY> <PROFILE>` to analyze the profile.

By default, the test binary and various profile files are stored in the individual directories of any suites that Ginkgo runs. If you specify `--output-dir`, however, then these assets are moved to the requested directory and namespaced with a prefix that contains the name of the package in question.

As with coverage computation, these profiles will not generate a file if a suite includes programatically focused specs (see the discussion [above](#computing-coverage)).

## Ginkgo and Gomega Patterns
So far we've introduced and described the majority of Ginkgo's capabilities and building blocks. Hopefully the previous chapters have helped give you a mental model for how Ginkgo specs are written and run.

Expand Down
40 changes: 24 additions & 16 deletions ginkgo/internal/profiles_and_reports.go
View file
Expand Up @@ -34,25 +34,33 @@ func FinalizeProfilesAndReportsForSuites(suites TestSuites, cliConfig types.CLIC
if goFlagsConfig.Cover && !cliConfig.KeepSeparateCoverprofiles {
coverProfiles := []string{}
for _, suite := range suitesWithProfiles {
coverProfiles = append(coverProfiles, AbsPathForGeneratedAsset(goFlagsConfig.CoverProfile, suite, cliConfig, 0))
}
dst := goFlagsConfig.CoverProfile
if cliConfig.OutputDir != "" {
dst = filepath.Join(cliConfig.OutputDir, goFlagsConfig.CoverProfile)
}
err := MergeAndCleanupCoverProfiles(coverProfiles, dst)
if err != nil {
return messages, err
if !suite.HasProgrammaticFocus {
coverProfiles = append(coverProfiles, AbsPathForGeneratedAsset(goFlagsConfig.CoverProfile, suite, cliConfig, 0))
}
}

coverage, err := GetCoverageFromCoverProfile(dst)
if err != nil {
return messages, err
}
if coverage == 0 {
messages = append(messages, "composite coverage: [no statements]")
if len(coverProfiles) > 0 {
dst := goFlagsConfig.CoverProfile
if cliConfig.OutputDir != "" {
dst = filepath.Join(cliConfig.OutputDir, goFlagsConfig.CoverProfile)
}
err := MergeAndCleanupCoverProfiles(coverProfiles, dst)
if err != nil {
return messages, err
}
coverage, err := GetCoverageFromCoverProfile(dst)
if err != nil {
return messages, err
}
if coverage == 0 {
messages = append(messages, "composite coverage: [no statements]")
} else if suitesWithProfiles.AnyHaveProgrammaticFocus() {
messages = append(messages, fmt.Sprintf("composite coverage: %.1f%% of statements however some suites did not contribute because they included programatically focused specs", coverage))
} else {
messages = append(messages, fmt.Sprintf("composite coverage: %.1f%% of statements", coverage))
}
} else {
messages = append(messages, fmt.Sprintf("composite coverage: %.1f%% of statements", coverage))
messages = append(messages, "no composite coverage computed: all suites included programatically focused specs")
}
}

Expand Down
80 changes: 59 additions & 21 deletions ginkgo/internal/run.go
View file
Expand Up @@ -126,6 +126,24 @@ func runSerial(suite TestSuite, ginkgoConfig types.SuiteConfig, reporterConfig t
suite.State = TestSuiteStateFailed
}

if suite.HasProgrammaticFocus {
if goFlagsConfig.Cover {
fmt.Fprintln(os.Stdout, "coverage: no coverfile was generated because specs are programmatically focused")
}
if goFlagsConfig.BlockProfile != "" {
fmt.Fprintln(os.Stdout, "no block profile was generated because specs are programmatically focused")
}
if goFlagsConfig.CPUProfile != "" {
fmt.Fprintln(os.Stdout, "no cpu profile was generated because specs are programmatically focused")
}
if goFlagsConfig.MemProfile != "" {
fmt.Fprintln(os.Stdout, "no mem profile was generated because specs are programmatically focused")
}
if goFlagsConfig.MutexProfile != "" {
fmt.Fprintln(os.Stdout, "no mutex profile was generated because specs are programmatically focused")
}
}

return suite
}

Expand Down Expand Up @@ -243,37 +261,57 @@ func runParallel(suite TestSuite, ginkgoConfig types.SuiteConfig, reporterConfig
}

if len(coverProfiles) > 0 {
coverProfile := AbsPathForGeneratedAsset(goFlagsConfig.CoverProfile, suite, cliConfig, 0)
err := MergeAndCleanupCoverProfiles(coverProfiles, coverProfile)
command.AbortIfError("Failed to combine cover profiles", err)

coverage, err := GetCoverageFromCoverProfile(coverProfile)
command.AbortIfError("Failed to compute coverage", err)
if coverage == 0 {
fmt.Fprintln(os.Stdout, "coverage: [no statements]")
if suite.HasProgrammaticFocus {
fmt.Fprintln(os.Stdout, "coverage: no coverfile was generated because specs are programmatically focused")
} else {
fmt.Fprintf(os.Stdout, "coverage: %.1f%% of statements\n", coverage)
coverProfile := AbsPathForGeneratedAsset(goFlagsConfig.CoverProfile, suite, cliConfig, 0)
err := MergeAndCleanupCoverProfiles(coverProfiles, coverProfile)
command.AbortIfError("Failed to combine cover profiles", err)

coverage, err := GetCoverageFromCoverProfile(coverProfile)
command.AbortIfError("Failed to compute coverage", err)
if coverage == 0 {
fmt.Fprintln(os.Stdout, "coverage: [no statements]")
} else {
fmt.Fprintf(os.Stdout, "coverage: %.1f%% of statements\n", coverage)
}
}
}
if len(blockProfiles) > 0 {
blockProfile := AbsPathForGeneratedAsset(goFlagsConfig.BlockProfile, suite, cliConfig, 0)
err := MergeProfiles(blockProfiles, blockProfile)
command.AbortIfError("Failed to combine blockprofiles", err)
if suite.HasProgrammaticFocus {
fmt.Fprintln(os.Stdout, "no block profile was generated because specs are programmatically focused")
} else {
blockProfile := AbsPathForGeneratedAsset(goFlagsConfig.BlockProfile, suite, cliConfig, 0)
err := MergeProfiles(blockProfiles, blockProfile)
command.AbortIfError("Failed to combine blockprofiles", err)
}
}
if len(cpuProfiles) > 0 {
cpuProfile := AbsPathForGeneratedAsset(goFlagsConfig.CPUProfile, suite, cliConfig, 0)
err := MergeProfiles(cpuProfiles, cpuProfile)
command.AbortIfError("Failed to combine cpuprofiles", err)
if suite.HasProgrammaticFocus {
fmt.Fprintln(os.Stdout, "no cpu profile was generated because specs are programmatically focused")
} else {
cpuProfile := AbsPathForGeneratedAsset(goFlagsConfig.CPUProfile, suite, cliConfig, 0)
err := MergeProfiles(cpuProfiles, cpuProfile)
command.AbortIfError("Failed to combine cpuprofiles", err)
}
}
if len(memProfiles) > 0 {
memProfile := AbsPathForGeneratedAsset(goFlagsConfig.MemProfile, suite, cliConfig, 0)
err := MergeProfiles(memProfiles, memProfile)
command.AbortIfError("Failed to combine memprofiles", err)
if suite.HasProgrammaticFocus {
fmt.Fprintln(os.Stdout, "no mem profile was generated because specs are programmatically focused")
} else {
memProfile := AbsPathForGeneratedAsset(goFlagsConfig.MemProfile, suite, cliConfig, 0)
err := MergeProfiles(memProfiles, memProfile)
command.AbortIfError("Failed to combine memprofiles", err)
}
}
if len(mutexProfiles) > 0 {
mutexProfile := AbsPathForGeneratedAsset(goFlagsConfig.MutexProfile, suite, cliConfig, 0)
err := MergeProfiles(mutexProfiles, mutexProfile)
command.AbortIfError("Failed to combine mutexprofiles", err)
if suite.HasProgrammaticFocus {
fmt.Fprintln(os.Stdout, "no mutex profile was generated because specs are programmatically focused")
} else {
mutexProfile := AbsPathForGeneratedAsset(goFlagsConfig.MutexProfile, suite, cliConfig, 0)
err := MergeProfiles(mutexProfiles, mutexProfile)
command.AbortIfError("Failed to combine mutexprofiles", err)
}
}

return suite
Expand Down
137 changes: 137 additions & 0 deletions integration/profiling_test.go
View file
Expand Up @@ -11,6 +11,7 @@ import (
"fmt"

. "github.com/onsi/ginkgo/v2"
"github.com/onsi/ginkgo/v2/types"
. "github.com/onsi/gomega"
"github.com/onsi/gomega/gbytes"
"github.com/onsi/gomega/gexec"
Expand Down Expand Up @@ -278,6 +279,142 @@ var _ = Describe("Profiling Specs", func() {
})
})

Context("when a suite has programmatic focus", func() {
BeforeEach(func() {
fm.MountFixture("focused")
fm.MountFixture("coverage")
})

Context("and running in series", func() {
It("lets the user know that the test was focused so no profiles were generated", func() {
session := startGinkgo(fm.PathTo("focused"), "--no-color", "--cover", "--blockprofile=block.out", "--cpuprofile=cpu.out", "--memprofile=mem.out", "--mutexprofile=mutex.out")
Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
Ω(session).ShouldNot(gbytes.Say("could not finalize profiles"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no composite coverage computed: all suites included programatically focused specs"))
Ω(fm.PathTo("focused", "coverprofile.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "block.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "mem.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "mutex.out")).ShouldNot(BeAnExistingFile())
})
})

Context("and running in parallel", func() {
It("lets the user know that the test was focused so no profiles were generated", func() {
session := startGinkgo(fm.PathTo("focused"), "--no-color", "--procs=2", "--cover", "--blockprofile=block.out", "--cpuprofile=cpu.out", "--memprofile=mem.out", "--mutexprofile=mutex.out")
Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
Ω(session).ShouldNot(gbytes.Say("could not finalize profiles"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no composite coverage computed: all suites included programatically focused specs"))
Ω(fm.PathTo("focused", "coverprofile.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "block.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "mem.out")).ShouldNot(BeAnExistingFile())
Ω(fm.PathTo("focused", "mutex.out")).ShouldNot(BeAnExistingFile())
})
})

Context("and keeping coverage reports separate", func() {
It("lets the user know", func() {
session := startGinkgo(fm.TmpDir, "-r", "--no-color", "--cover", "--blockprofile=block.out", "--cpuprofile=cpu.out", "--memprofile=mem.out", "--mutexprofile=mutex.out", "--keep-separate-coverprofiles", "--output-dir=./output")
Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
Ω(session).Should(gbytes.Say("CoverageFixture Suite"))
Ω(session).Should(gbytes.Say("coverage: 80"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).ShouldNot(gbytes.Say("composite coverage"))
Ω(fm.ListDir("output")).Should(ConsistOf(
"coverage.test", "coverage_block.out", "coverage_coverprofile.out", "coverage_cpu.out", "coverage_mem.out", "coverage_mutex.out",
"focused.test", "focused_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
"focused_internal.test", "focused_internal_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
))
})
})

Context("and combining coverage reports", func() {
Context("and no suites generate coverage", func() {
It("lets the user know", func() {
session := startGinkgo(fm.PathTo("focused"), "-r", "--no-color", "--cover", "--blockprofile=block.out", "--cpuprofile=cpu.out", "--memprofile=mem.out", "--mutexprofile=mutex.out", "--output-dir=./output")
Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
Ω(session).ShouldNot(gbytes.Say("CoverageFixture Suite"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).Should(gbytes.Say("no composite coverage computed: all suites included programatically focused specs"))

Ω(fm.ListDir("focused", "output")).Should(ConsistOf(
"focused.test", "focused_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
"internal.test", "internal_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
))
})
})

Context("and at least one suite generates coverage", func() {
It("lets the user know", func() {
session := startGinkgo(fm.TmpDir, "-r", "--no-color", "--cover", "--blockprofile=block.out", "--cpuprofile=cpu.out", "--memprofile=mem.out", "--mutexprofile=mutex.out", "--output-dir=./output")
Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
Ω(session).Should(gbytes.Say("CoverageFixture Suite"))
Ω(session).Should(gbytes.Say("coverage: 80"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).Should(gbytes.Say("Focused Suite"))
Ω(session).Should(gbytes.Say("coverage: no coverfile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no block profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no cpu profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mem profile was generated because specs are programmatically focused"))
Ω(session).Should(gbytes.Say("no mutex profile was generated because specs are programmatically focused"))

Ω(session).Should(gbytes.Say("composite coverage: 80.0% of statements however some suites did not contribute because they included programatically focused specs"))

Ω(fm.ListDir("output")).Should(ConsistOf(
"coverprofile.out",
"coverage.test", "coverage_block.out", "coverage_cpu.out", "coverage_mem.out", "coverage_mutex.out",
"focused.test", "focused_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
"focused_internal.test", "focused_internal_cpu.out", //this is an inconsistency in go test where the cpu.out file is generated but empty
))
})
})
})
})

Context("with a read-only tree and a readable output-dir", func() {
BeforeEach(func() {
fm.MountFixture("profile")
Expand Down

0 comments on commit 8fbfa02

Please sign in to comment.