Uploaded image for project: 'Clover'
  1. Clover
  2. CLOV-1189

Report generation seems to get into an infinite loop, never finishes

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Highest Highest
    • 3.1.11
    • 3.1.8
    • Grails Plugin
    • None
    • Redhat 6.1, Sun 64-bit JVM, 1.6.0_34, Grails 2.1.1 with plugin version 3.1.8

      For some reason, in our Grails test environment, clover is stuck in what seems to be an infinite loop recording the data for all the files instrumented during the run.

      This occurs at the end of a run started with "grails test-app -clover.on" which runs both unit and integration tests.

      Our project is fairly reasonable in size:

          +----------------------+-------+-------+
          | Name                 | Files |  LOC  |
          +----------------------+-------+-------+
          | Controllers          |     8 |   435 |
          | Domain Classes       |   401 | 18552 |
          | Services             |    36 |  4773 |
          | Tag Libraries        |     5 |   790 |
          | Groovy Helpers       |   345 | 17830 |
          | Java Helpers         |     3 |   141 |
          | Unit Tests           |    68 |  5040 |
          | Integration Tests    |   401 | 14290 |
          | Scripts              |     6 |    83 |
          +----------------------+-------+-------+
          | Totals               |  1273 | 61934 |
          +----------------------+-------+-------+
      

      During the run, Clover generates an amazing number of files in the .clover/ directory (about 600,000 files *.s files)

      At the end of the run we get:

      [Step 2/3] | Completed 563 integration tests, 0 failed in 328038ms
      [09:31:13][Step 2/3] | Tests PASSED - view reports in /home/teamcity/TeamCity/buildAgent1/work/7f907064610a9f8f/common/target/test-reports
      [09:31:13][Step 2/3] Clover: Tests ended
      [09:31:13][Step 2/3] Clover: Generating report using default 'clover-report' task
      

      I've attached a chunk of the log file looping on the report generation, the full log file is 4GB before I stopped it.

      Also, I've attached a stack trace taken while it is seemingly looping.

      It's weird, we are evaluating clover and it works fine on our other project module, but not this one. The configuration is the same:

      clover {
          excludes = ['**/conf/**', '**/plugins/**', '**/migrations/**', '**/drillDown/**', '**/generator/**']
          initstring = ".clover/common.db"
      }
      

        1. stacktrace.txt
          55 kB
        2. clover_loop.zip
          904 kB
        3. grails-clover-3.1.11.zip
          11 kB
        4. CLOVER-CoverageRecorders-200313-0908-462.pdf
          145 kB

            [CLOV-1189] Report generation seems to get into an infinite loop, never finishes

            I have raised CLOV-1264, could you describe the problem and attach profiler data in this new issue, please?

            Marek Parfianowicz added a comment - I have raised CLOV-1264 , could you describe the problem and attach profiler data in this new issue, please?

            Aaron Long added a comment -

            Marek,
            I'll run a profile session with and without the testsources, both using a Shared recorder and see what the differences are. The problem with creating a ton of *.s files is definitely resolved and technically the coverage doesn't really hang although it's so slow we can't really use it.

            As for 3, I'm not sure I have that kind of control over the Grails build process. I'll see what I can do.

            Stay tuned. You want to open a separate performance ticket for this issue since this one is closed?

            Aaron Long added a comment - Marek, I'll run a profile session with and without the testsources, both using a Shared recorder and see what the differences are. The problem with creating a ton of *.s files is definitely resolved and technically the coverage doesn't really hang although it's so slow we can't really use it. As for 3, I'm not sure I have that kind of control over the Grails build process. I'll see what I can do. Stay tuned. You want to open a separate performance ticket for this issue since this one is closed?

            Hi Aaron,

            > I'll try profiling a different way to see if I can tell where the time is spent.

            1) Could you attach profiler results? Tip: regarding tuning of the profiler - it might be worth to focus on GrowableCoverageRecorder, GrowableCoverageRecorder$FixedProxy, SharedCoverageRecorder, CoverageMatrix, PerTestRecorder$Diffing classes as well as static initialization blocks in other classes.

            > With the above configuration it's been running for about 3 hours and is about half finished.

            2) Does it mean that the problem is improved, compared to the FIXED recorder? I remember that you wrote that in case of FIXED recorder it took a lot of memory and time during report generation and it was unable to complete the task.

            3) I've got one suspicion what could be wrong... Could you try to change your build in such way that the last class instrumented will be loaded into JVM as first one? For example: run the last compiled unit test as first. This might reduce number of memory reallocations due to growing coverage array.

            Cheers
            Marek

            Marek Parfianowicz added a comment - Hi Aaron, > I'll try profiling a different way to see if I can tell where the time is spent. 1) Could you attach profiler results? Tip: regarding tuning of the profiler - it might be worth to focus on GrowableCoverageRecorder, GrowableCoverageRecorder$FixedProxy, SharedCoverageRecorder, CoverageMatrix, PerTestRecorder$Diffing classes as well as static initialization blocks in other classes. > With the above configuration it's been running for about 3 hours and is about half finished. 2) Does it mean that the problem is improved, compared to the FIXED recorder? I remember that you wrote that in case of FIXED recorder it took a lot of memory and time during report generation and it was unable to complete the task. 3) I've got one suspicion what could be wrong... Could you try to change your build in such way that the last class instrumented will be loaded into JVM as first one? For example: run the last compiled unit test as first. This might reduce number of memory reallocations due to growing coverage array. Cheers Marek

            Aaron Long added a comment -

            I'm running with the latest snapshot and it doesn't seem to be creating all the .s files, however it's almost unbearably slow unless I disable testsources (as I was doing before). My setuptask is:

                setuptask = { ant, binding, plugin ->
                    ant.'clover-setup'(initstring: ".clover/common.db") {
                        ant.fileset(dir: "grails-app", includes: "**/domain/**, **/controllers/**, **/jobs/**, **/services/**, **/taglib/**, **/utils/**") { }
                        ant.fileset(dir: "src", includes: "**/*.groovy, **/*.java", excludes: "**/script@*.groovy, **/system/generator/**, **/system/database/generators/**, **/castor/**") { }
                        ant.fileset(dir: "test", includes: "**/*.groovy") { }
                        // ant.testsources(dir: "test", enabled: false) { }
                        ant.profiles {
                            ant.profile(name: "default", coverageRecorder: "SHARED")
                        }
                    }
                }
            

            If I uncomment the testsources enabled:false line, it runs about as quickly as before. Normally our coverage run takes about 42 minutes. With the above configuration it's been running for about 3 hours and is about half finished. I attached YourKit to try and see where the time is going but something clover does seems to be confusing the profiler. All the method invocation times say 0ms which I've never seen before. I'll try profiling a different way to see if I can tell where the time is spent.

            Aaron Long added a comment - I'm running with the latest snapshot and it doesn't seem to be creating all the .s files, however it's almost unbearably slow unless I disable testsources (as I was doing before). My setuptask is: setuptask = { ant, binding, plugin -> ant. 'clover-setup' (initstring: ".clover/common.db" ) { ant.fileset(dir: "grails-app" , includes: "**/domain /**, **/ controllers /**, **/ jobs /**, **/ services /**, **/ taglib /**, **/ utils/**" ) { } ant.fileset(dir: "src" , includes: "** /*.groovy, **/ *.java" , excludes: "**/script@*.groovy, **/system/generator /**, **/ system/database/generators /**, **/ castor/**" ) { } ant.fileset(dir: "test" , includes: "**/*.groovy" ) { } // ant.testsources(dir: "test" , enabled: false ) { } ant.profiles { ant.profile(name: " default " , coverageRecorder: "SHARED" ) } } } If I uncomment the testsources enabled:false line, it runs about as quickly as before. Normally our coverage run takes about 42 minutes. With the above configuration it's been running for about 3 hours and is about half finished. I attached YourKit to try and see where the time is going but something clover does seems to be confusing the profiler. All the method invocation times say 0ms which I've never seen before. I'll try profiling a different way to see if I can tell where the time is spent.

            Hi Aaron, did you manage to install new SNAPSHOT version? Do you need any help? It would be great if you could give me a feedback till Friday the latest as I'm about to release the 3.1.11. Later feedback will be also very appreciated, but then fixes (if any) will go into the 3.1.12.

            Marek Parfianowicz added a comment - Hi Aaron, did you manage to install new SNAPSHOT version? Do you need any help? It would be great if you could give me a feedback till Friday the latest as I'm about to release the 3.1.11. Later feedback will be also very appreciated, but then fixes (if any) will go into the 3.1.12.

            Created CLOV-1257.

            Marek Parfianowicz added a comment - Created CLOV-1257 .

            Great idea! I'll check what can be done.

            Marek Parfianowicz added a comment - Great idea! I'll check what can be done.

            Aaron Long added a comment - - edited

            Any plans to support the coverageRecorder natively in the plugin config? It would be nice to go back to using the simpler configuration instead of the setuptask/reporttask closures. Like:

            clover {
              coverageRecorder: 'SHARED'
            }
            

            Aaron Long added a comment - - edited Any plans to support the coverageRecorder natively in the plugin config? It would be nice to go back to using the simpler configuration instead of the setuptask/reporttask closures. Like: clover { coverageRecorder: 'SHARED' }

            I'm attaching also a PDF with short description how new coverage recorders work. This will be also available on confluence.atlassian.com as soon as 3.1.11 is released.

            Marek Parfianowicz added a comment - I'm attaching also a PDF with short description how new coverage recorders work. This will be also available on confluence.atlassian.com as soon as 3.1.11 is released.

            Marek Parfianowicz added a comment - - edited

            Hello Aaron,

            Snapshot of Clover core is available here: https://maven.atlassian.com/content/repositories/atlassian-public-snapshot/com/cenqua/clover/clover/3.1.11-SNAPSHOT/

            For Clover-for-Grails plugin please take the attached grails-clover-3.1.11.zip - it contains a dependency to 3.1.11-SNAPSHOT. Install this plugin and next update a dependency to Clover-for-Grails plugin in your project to version 3.1.11 (in BuildConfig.groovy). In order to use a new coverage recorder type, define Clover configuration as below:

            clover {
                setuptask = { ant, binding, plugin ->
                    ant.delete(dir: "target/clover/db")
                    ant.delete(dir: "target/clover/tmp")
                    ant.'clover-setup'(initstring: "target/clover/db/clover.db",
                                       tmpDir: "target/clover/tmp") {
                        ant.profiles {
                            ant.profile(name: "default", coverageRecorder: "SHARED")
                        }
                    }
                }
                reporttask =  { ant, binding, plugin ->
                    ant.delete(dir: "target/clover/report")
                    ant.'clover-report'(initstring: "target/clover/db/clover.db") {
                        ant.current(outfile: "target/clover/report/clover.xml") {
                            ant.format(type: "xml")
                        }
                        ant.current(outfile: "target/clover/report") {
                            ant.format(type: "html")
                        }
                    }
                }
             }
            

            Regards
            Marek

            Marek Parfianowicz added a comment - - edited Hello Aaron, Snapshot of Clover core is available here: https://maven.atlassian.com/content/repositories/atlassian-public-snapshot/com/cenqua/clover/clover/3.1.11-SNAPSHOT/ For Clover-for-Grails plugin please take the attached grails-clover-3.1.11.zip - it contains a dependency to 3.1.11-SNAPSHOT. Install this plugin and next update a dependency to Clover-for-Grails plugin in your project to version 3.1.11 (in BuildConfig.groovy). In order to use a new coverage recorder type, define Clover configuration as below: clover { setuptask = { ant, binding, plugin -> ant.delete(dir: "target/clover/db") ant.delete(dir: "target/clover/tmp") ant.'clover-setup'(initstring: "target/clover/db/clover.db", tmpDir: "target/clover/tmp") { ant.profiles { ant.profile(name: "default", coverageRecorder: "SHARED") } } } reporttask = { ant, binding, plugin -> ant.delete(dir: "target/clover/report") ant.'clover-report'(initstring: "target/clover/db/clover.db") { ant.current(outfile: "target/clover/report/clover.xml") { ant.format(type: "xml") } ant.current(outfile: "target/clover/report") { ant.format(type: "html") } } } } Regards Marek

            Aaron Long added a comment -

            @Marek - I'm happy to test a new snapshot build in our project if you want to attach it or send it to me. We are still using the 3.1.10 snapshot that you sent me a while back.

            Aaron Long added a comment - @Marek - I'm happy to test a new snapshot build in our project if you want to attach it or send it to me. We are still using the 3.1.10 snapshot that you sent me a while back.

            Marek Parfianowicz added a comment - - edited

            Problem analysis results:

            It seems that Grails compiles every domain class separately, as a consequence Clover sees this as a separate instrumentation session and generates a separate coverage recorder instance. As a consequence, at runtime hundreds of per-test recorder instances are running. Thus, during test execution every end of test method triggers flushing coverage data from all coverage recorders. In our case - 400 tests * 400 recorders for domain objects = 160'000 files.

            Workarounds:

            1) Disable instrumentation of domain classes, e.g.

            clover.excludes = "**/domain/**"
            

            2) Disable instrumentation of test classes, e.g.

            clover.excludes = "test/**"
            

            3) Disable per-test instrumentation.

            Use <testsources dir=".." enabled="false"/> ("enabled" is an undocumented attribute). This will cause that NoTestDetector will be used (which always returns false for isTestMethod, isTestClass).

            Bug: <testsources> attribute is not passed to groovyc wrapper right now (in instrumentation.ser) - see CLOV-1190 - fixed in 3.1.9-SNAPSHOT.

            4) Perform merge of database (to be verified)

            Database merge causes collation of per-test coverage data too. However, merging 600'000 files might take considerable amount of time (although possibly lower than during report generation).

            Possible final fix:

            Add extra option for <clover-setup/> and <clover-instr/> and for runtime, which will cause that a single, shared per-test coverage recorder will be used for all test classes, whenever the same initstring is used. Assumption is that

            • all coverage recorders created during instrumentation are cumulative (indexes in new one are superset of indexes in previous one for the same database) and
            • all coverage recorders with the same initstring use exactly the same database (in other words: we cannot have multi-module build with multiple clover datbases having the same relative initstring)

            However, this requires a growable size recorder (as the older recorders would have smaller arrays). Is should be safe to use such option for single-threaded tests (i.e. when tests are launched sequentially; do not confuse with a test of multi-threaded application).

            Marek Parfianowicz added a comment - - edited Problem analysis results: It seems that Grails compiles every domain class separately, as a consequence Clover sees this as a separate instrumentation session and generates a separate coverage recorder instance. As a consequence, at runtime hundreds of per-test recorder instances are running. Thus, during test execution every end of test method triggers flushing coverage data from all coverage recorders. In our case - 400 tests * 400 recorders for domain objects = 160'000 files. Workarounds: 1) Disable instrumentation of domain classes, e.g. clover.excludes = "**/domain/**" 2) Disable instrumentation of test classes, e.g. clover.excludes = "test/**" 3) Disable per-test instrumentation. Use <testsources dir=".." enabled="false"/> ("enabled" is an undocumented attribute). This will cause that NoTestDetector will be used (which always returns false for isTestMethod, isTestClass). Bug: <testsources> attribute is not passed to groovyc wrapper right now (in instrumentation.ser) - see CLOV-1190 - fixed in 3.1.9-SNAPSHOT. 4) Perform merge of database (to be verified) Database merge causes collation of per-test coverage data too. However, merging 600'000 files might take considerable amount of time (although possibly lower than during report generation). Possible final fix: Add extra option for <clover-setup/> and <clover-instr/> and for runtime, which will cause that a single, shared per-test coverage recorder will be used for all test classes, whenever the same initstring is used. Assumption is that all coverage recorders created during instrumentation are cumulative (indexes in new one are superset of indexes in previous one for the same database) and all coverage recorders with the same initstring use exactly the same database (in other words: we cannot have multi-module build with multiple clover datbases having the same relative initstring) However, this requires a growable size recorder (as the older recorders would have smaller arrays). Is should be safe to use such option for single-threaded tests (i.e. when tests are launched sequentially; do not confuse with a test of multi-threaded application).

            I wish we had 600,000 tests, but we don't. You can see from the logs that there are only 563 tests and no test* methods in the application code that would be executed. I also looked for any tests which call other tests and didn't see any.

            If you unzip the clover_loop.zip, you'll see that in the debug output that it's generating the same *.s files multiple times for the same tests, I'm not sure why. If you search for a test name (PhysicalTotalLossServiceTests, for example), you'll see it show up once and then about a minute later show up again, same lines...that just repeats forever.

            Aaron Long added a comment - I wish we had 600,000 tests, but we don't. You can see from the logs that there are only 563 tests and no test* methods in the application code that would be executed. I also looked for any tests which call other tests and didn't see any. If you unzip the clover_loop.zip, you'll see that in the debug output that it's generating the same *.s files multiple times for the same tests, I'm not sure why. If you search for a test name (PhysicalTotalLossServiceTests, for example), you'll see it show up once and then about a minute later show up again, same lines...that just repeats forever.

            Yes, sure. I'll raise a support ticket.

            Marek Parfianowicz added a comment - Yes, sure. I'll raise a support ticket.

            During the run, Clover generates an amazing number of files in the .clover/ directory (about 600,000 files *.s files)

            The *.s files are per-test coverage snapshot files. It means that Clover has detected 600'000 tests during the build (unit / integration test). Indeed, it's a huge number; it's uncommon to see more than 10'000 tests; no wonder why HTML report generation "hanged".

            I suppose that either you're calling the same set of tests multiple times or Clover default test detection algorithms found some application classes/methods which are actually not tests. I suggest to check following things first:

            • are there any "public void testXyz()" methods in application code
            • are there any test methods calling other test methods (recursive calls, in a loop, nested tests ?)

            Marek Parfianowicz added a comment - During the run, Clover generates an amazing number of files in the .clover/ directory (about 600,000 files *.s files) The *.s files are per-test coverage snapshot files. It means that Clover has detected 600'000 tests during the build (unit / integration test). Indeed, it's a huge number; it's uncommon to see more than 10'000 tests; no wonder why HTML report generation "hanged". I suppose that either you're calling the same set of tests multiple times or Clover default test detection algorithms found some application classes/methods which are actually not tests. I suggest to check following things first: are there any "public void testXyz()" methods in application code are there any test methods calling other test methods (recursive calls, in a loop, nested tests ?)

            Aaron Long added a comment -

            Yes, that makes sense as this is probably a support issue at this point. We are looking to purchase clover but this is a show stopper for us (thus the blocker).

            Can move the ticket to the CLV project for me?

            Aaron Long added a comment - Yes, that makes sense as this is probably a support issue at this point. We are looking to purchase clover but this is a show stopper for us (thus the blocker). Can move the ticket to the CLV project for me?

            Hi Aaron,

            I see that you have raised a Blocker - is there any chance that your intention was to create a support ticket, actually? The difference is:

            • CLOV project on jira.atlassian.com is for raising bugs and improvement requests, which are being handled by developers according to Atlassian Bug Fixing Policy, which means it can take some time until bug is solved
            • CLV project on support.atlassian.com is for raising support issues, which are being handled Atlassian Support team according to SLA

            Regards
            Marek

            Marek Parfianowicz added a comment - Hi Aaron, I see that you have raised a Blocker - is there any chance that your intention was to create a support ticket, actually? The difference is: CLOV project on jira.atlassian.com is for raising bugs and improvement requests, which are being handled by developers according to Atlassian Bug Fixing Policy , which means it can take some time until bug is solved CLV project on support.atlassian.com is for raising support issues, which are being handled Atlassian Support team according to SLA Regards Marek

              mparfianowicz Marek Parfianowicz
              e23cac2bea4b Aaron Long
              Affected customers:
              0 This affects my team
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: