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. clover_loop.zip
          904 kB
          Aaron Long
        2. CLOVER-CoverageRecorders-200313-0908-462.pdf
          145 kB
          Marek Parfianowicz
        3. grails-clover-3.1.11.zip
          11 kB
          Marek Parfianowicz
        4. stacktrace.txt
          55 kB
          Aaron Long

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

            Owen made changes -
            Workflow Original: New Clover Workflow [ 897306 ] New: New Clover Workflow - Restricted [ 1474617 ]
            Piotr Swiecicki made changes -
            Workflow Original: Clover Workflow [ 896052 ] New: New Clover Workflow [ 897306 ]
            Piotr Swiecicki made changes -
            Workflow Original: reviewflow [ 449024 ] New: Clover Workflow [ 896052 ]

            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?
            Marek Parfianowicz made changes -
            Status Original: Resolved [ 5 ] New: Closed [ 6 ]

            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 .

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

                Created:
                Updated:
                Resolved: