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.

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

Very slow performance of nested parenthesis #294

Closed
qgazq opened this issue Oct 17, 2014 · 19 comments
Closed

Very slow performance of nested parenthesis #294

qgazq opened this issue Oct 17, 2014 · 19 comments
Assignees
Labels
Milestone

Comments

@qgazq
Copy link

qgazq commented Oct 17, 2014

I don't know if this a known feature/limitation, or bug, but I haven't seen anything about it while searching.
I have seen various people complaining of the symptom, but haven't seen a solution. If I've missed one I apologize.

At work we've been having a problem where analysis seemed to "stop" at one point for 1h 40mins and then continue. During the stop the java process is at 100%.
After some playing I narrowed it down to one file, then one function, then one statement, and then eventually to the simplest example I could.
This evening I've just installed sonarqube and the plugin at home and recreated the sample and it still does it, so I can now post a simple example here, and run tests to get more information if necessary.

The problem is seen when doing this code
slow.cpp:

void aFunction()
{
        char *a = ((((((((((( "hi" )))))))))));
}

Actually this also shows it, but throws a com.sonar.sslr.api.RecognitionException

void aFunction()
{
        (((((((((((  )))))))))));
}

Obviously the real code has a reason for the nested parenthesis, but this is a simple example that shows the slowdown.

I've include the full console output (showing the command as well) below.
But for the example above it is taking the CxxSquidSensor 33150 ms (33.1s) to analyse the one line.
If I change the number of nested parenthesis the timing changes as follows:
7 sets parenthesis : 733 ms (0.7s)
8 sets parenthesis : 1586 ms (1.6s)
9 sets parenthesis : 4000 ms (4s)
10 sets parenthesis : 11506 ms (11.5s)
11 sets parenthesis : 33150 ms (33.1s)
12 sets parenthesis : 102547 ms (1.7m)
13 sets parenthesis : 305545 ms (5.1m)
14 sets parenthesis : 891094 ms (14.9m)

So it appears each set is worse than double the analysis, approximately 3 fold. This doesn't seem right to me.
The real code has quite a few, and has code in them which is taking it to the 1h 40m.
Is there any reason you know that could cause this to happen, or something I could try?
That is something to try other than re-factoring our code, which in this case is probably possible and I will look at doing on Monday.

Regards
Gary

The console output (with debug) is:

gst102@ziggy:~/slowtest$ /opt/sonar-runner/bin/sonar-runner -Dsonar.projectKey=net.qgazq.test1 -Dsonar.projectName=Test1 -Dsonar.projectVersion=Test1 -Dsonar.sources=. -Dsonar.language=c++ -X
SonarQube Runner 2.4
Java 1.7.0_65 Oracle Corporation (64-bit)
Linux 3.13.0-27-generic amd64
INFO: Error stacktraces are turned on.
INFO: Runner configuration file: /opt/sonar-runner/conf/sonar-runner.properties
INFO: Project configuration file: NONE
INFO: Default locale: "en_GB", source code encoding: "UTF-8" (analysis is platform dependent)
INFO: Work directory: /home/gst102/slowtest/./.sonar
INFO: SonarQube Server 4.5
18:06:39.584 INFO  - Load global referentials...
18:06:39.600 DEBUG - Download: http://localhost:9000/batch/global (no proxy)
18:06:39.719 INFO  - Load global referentials done: 138 ms
18:06:39.731 INFO  - User cache: /home/gst102/.sonar/cache
18:06:39.744 INFO  - Install plugins
18:06:39.744 DEBUG - Download index of plugins
18:06:39.744 DEBUG - Download: http://localhost:9000/deploy/plugins/index.txt (no proxy)
18:06:39.822 INFO  - Install JDBC driver
18:06:39.822 DEBUG - Download index of jdbc-driver
18:06:39.822 DEBUG - Download: http://localhost:9000/deploy/jdbc-driver.txt (no proxy)
18:06:39.831 INFO  - Create JDBC datasource for jdbc:mysql://localhost:3306/sonar?useUnicode=true&characterEncoding=utf8
18:06:40.181 DEBUG - Testing JDBC connection
18:06:41.760 DEBUG - Download: http://localhost:9000/api/server (no proxy)
18:06:41.788 INFO  - Initializing Hibernate
18:06:41.791 DEBUG - hibernate.generate_statistics: false
18:06:41.791 DEBUG - hibernate.dialect: org.sonar.core.persistence.dialect.MySql$MySqlWithDecimalDialect
18:06:41.791 DEBUG - hibernate.connection.provider_class: org.sonar.jpa.session.CustomHibernateConnectionProvider
18:06:43.428 DEBUG - Loaded 2637 properties from l10n bundles
18:06:43.866 INFO  - Load project referentials...
18:06:43.867 DEBUG - Download: http://localhost:9000/batch/project?key=net.qgazq.test1&preview=false (no proxy)
18:06:44.742 INFO  - Load project referentials done: 876 ms
18:06:44.743 INFO  - Load project settings
18:06:45.093 INFO  - Loading technical debt model...
18:06:45.117 INFO  - Loading technical debt model done: 24 ms
18:06:45.120 INFO  - Apply project exclusions
18:06:45.384 DEBUG - Acquire semaphore on project : org.sonar.api.resources.Project@3e4b2d80[id=1,key=net.qgazq.test1,qualifier=TRK], with key batch-net.qgazq.test1
18:06:45.403 INFO  - -------------  Scan Test1
18:06:45.410 INFO  - Load module settings
18:06:45.640 DEBUG - Available languages:
18:06:45.640 DEBUG -   * c++ => "c++"
18:06:45.640 DEBUG -   * Java => "java"
18:06:46.981 INFO  - Language is forced to c++
18:06:46.983 INFO  - Loading rules...
18:06:48.388 INFO  - Loading rules done: 1405 ms
18:06:48.415 INFO  - Configure Maven plugins
18:06:48.647 INFO  - Compare to previous analysis (2014-10-17)
18:06:48.676 INFO  - Compare over 30 days (2014-09-17, analysis of 2014-10-17 17:35:07.0)
18:06:48.677 INFO  - No quality gate is configured.
18:06:48.870 DEBUG - Initializers :
18:06:48.870 INFO  - Base dir: /home/gst102/slowtest/.
18:06:48.870 INFO  - Working dir: /home/gst102/slowtest/./.sonar
18:06:48.871 INFO  - Source paths: .
18:06:48.871 INFO  - Source encoding: UTF-8, default locale: en_GB
18:06:48.871 INFO  - Index files
18:06:48.876 DEBUG - Declared extensions of language org.sonar.batch.languages.Language@7a3aefcc were converted to sonar.lang.patterns.c++ : **/*.cxx,**/*.cpp,**/*.cc,**/*.c,**/*.hxx,**/*.hpp,**/*.hh,**/*.h
18:06:48.876 DEBUG - Declared extensions of language org.sonar.batch.languages.Language@335578c5 were converted to sonar.lang.patterns.java : **/*.java,**/*.jav
18:06:48.905 DEBUG - Language of file 'slow.cpp' is detected to be 'c++'
18:06:48.927 INFO  - 1 files indexed
18:06:48.983 INFO  - Quality profile for c++: Gaz way
18:06:48.999 DEBUG - Sensors : QProfileSensor -> CxxSquidSensor -> CxxRatsSensor -> CxxXunitSensor -> CxxCoverageSensor -> CxxCppCheckSensor -> CxxVeraxxSensor -> CxxValgrindSensor -> InitialOpenIssuesSensor -> ProjectLinksSensor -> VersionEventsSensor -> FileHashSensor -> CPD Sensor (wrapped)
18:06:48.999 INFO  - Sensor QProfileSensor...
18:06:49.007 INFO  - Sensor QProfileSensor done: 8 ms
18:06:49.007 INFO  - Sensor CxxSquidSensor...
18:06:55.397 DEBUG - Updating semaphore batch-net.qgazq.test1
18:07:05.400 DEBUG - Updating semaphore batch-net.qgazq.test1
18:07:15.404 DEBUG - Updating semaphore batch-net.qgazq.test1
18:07:22.118 DEBUG - finished preprocessing '/home/gst102/slowtest/slow.cpp'
18:07:22.157 INFO  - Sensor CxxSquidSensor done: 33150 ms
18:07:22.157 INFO  - Sensor CxxRatsSensor...
18:07:22.158 DEBUG - Using pattern 'rats-reports/rats-result-*.xml' to find reports
18:07:22.174 INFO  - Sensor CxxRatsSensor done: 17 ms
18:07:22.174 INFO  - Sensor CxxXunitSensor...
18:07:22.175 DEBUG - Using pattern 'xunit-reports/xunit-result-*.xml' to find reports
18:07:22.175 INFO  - Sensor CxxXunitSensor done: 1 ms
18:07:22.175 INFO  - Sensor CxxCoverageSensor...
18:07:22.175 DEBUG - Using pattern 'coverage-reports/coverage-*.xml' to find reports
18:07:22.176 DEBUG - Parsing coverage reports
18:07:22.176 DEBUG - Parsing integration test coverage reports
18:07:22.176 DEBUG - Using pattern 'coverage-reports/it-coverage-*.xml' to find reports
18:07:22.176 DEBUG - Parsing overall test coverage reports
18:07:22.176 DEBUG - Using pattern 'coverage-reports/overall-coverage-*.xml' to find reports
18:07:22.176 INFO  - Sensor CxxCoverageSensor done: 1 ms
18:07:22.176 INFO  - Sensor CxxCppCheckSensor...
18:07:22.176 DEBUG - Using pattern 'cppcheck-reports/cppcheck-result-*.xml' to find reports
18:07:22.176 INFO  - Sensor CxxCppCheckSensor done: 0 ms
18:07:22.176 INFO  - Sensor CxxVeraxxSensor...
18:07:22.177 DEBUG - Using pattern 'vera++-reports/vera++-result-*.xml' to find reports
18:07:22.177 INFO  - Sensor CxxVeraxxSensor done: 1 ms
18:07:22.177 INFO  - Sensor CxxValgrindSensor...
18:07:22.177 DEBUG - Using pattern 'valgrind-reports/valgrind-result-*.xml' to find reports
18:07:22.177 INFO  - Sensor CxxValgrindSensor done: 0 ms
18:07:22.177 INFO  - Sensor InitialOpenIssuesSensor...
18:07:22.195 INFO  - Sensor InitialOpenIssuesSensor done: 18 ms
18:07:22.195 INFO  - Sensor ProjectLinksSensor...
18:07:22.200 INFO  - Sensor ProjectLinksSensor done: 5 ms
18:07:22.201 INFO  - Sensor VersionEventsSensor...
18:07:22.216 INFO  - Sensor VersionEventsSensor done: 15 ms
18:07:22.216 INFO  - Sensor FileHashSensor...
18:07:22.219 INFO  - Sensor FileHashSensor done: 3 ms
18:07:22.219 INFO  - Sensor CPD Sensor (wrapped)...
18:07:22.220 INFO  - DefaultCpdEngine is used for c++
18:07:22.220 INFO  - Cross-project analysis disabled
18:07:22.225 DEBUG - Populating index from [relative=slow.cpp, abs=/home/gst102/slowtest/slow.cpp]
18:07:22.233 DEBUG - Detection of duplications for [relative=slow.cpp, abs=/home/gst102/slowtest/slow.cpp]
18:07:22.239 INFO  - Sensor CPD Sensor (wrapped) done: 20 ms
18:07:22.844 INFO  - Execute decorators...
18:07:22.844 DEBUG - Decorators: ManualMeasureDecorator -> QProfileEventsDecorator -> SumDuplicationsDecorator -> UnitTestDecorator -> org.sonar.plugins.core.security.ApplyProjectRolesDecorator@49401fe3 -> org.sonar.plugins.core.sensors.DirectoriesDecorator@3a870a33 -> org.sonar.plugins.core.sensors.FilesDecorator@77aeb849 -> org.sonar.plugins.core.timemachine.TimeMachineConfigurationPersister@211b8954 -> org.sonar.plugins.core.timemachine.NewCoverageFileAnalyzer@6fc4fe01 -> org.sonar.plugins.core.timemachine.NewItCoverageFileAnalyzer@6e002cfa -> org.sonar.plugins.core.timemachine.NewOverallCoverageFileAnalyzer@4d890981 -> org.sonar.plugins.core.timemachine.NewCoverageAggregator@5fcf1beb -> org.sonar.plugins.design.batch.ProjectDsmDecorator@16d4fac7 -> FileTangleIndexDecorator -> f(lines) -> f(generated_lines) -> f(ncloc) -> f(generated_ncloc) -> f(classes) -> f(packages) -> f(functions) -> f(accessors) -> f(statements) -> f(public_api) -> f(comment_lines) -> f(comment_blank_lines) -> f(public_undocumented_api) -> f(commented_out_code_lines) -> f(complexity) -> f(complexity_in_classes) -> f(complexity_in_functions) -> f(class_complexity_distribution) -> f(function_complexity_distribution) -> f(file_complexity_distribution) -> f(lines_to_cover) -> f(uncovered_lines) -> f(conditions_to_cover) -> f(uncovered_conditions) -> f(it_lines_to_cover) -> f(it_uncovered_lines) -> f(it_conditions_to_cover) -> f(it_uncovered_conditions) -> f(overall_lines_to_cover) -> f(overall_uncovered_lines) -> f(overall_conditions_to_cover) -> f(overall_uncovered_conditions) -> f(rfc) -> f(rfc_distribution) -> f(lcom4_distribution) -> f(package_cycles) -> f(package_tangles) -> f(package_feedback_edges) -> f(package_edges_weight) -> f(new_lines_to_cover) -> f(new_uncovered_lines) -> f(new_conditions_to_cover) -> f(new_uncovered_conditions) -> f(new_it_lines_to_cover) -> f(new_it_uncovered_lines) -> f(new_it_conditions_to_cover) -> f(new_it_uncovered_conditions) -> f(new_overall_lines_to_cover) -> f(new_overall_uncovered_lines) -> f(new_overall_conditions_to_cover) -> f(new_overall_uncovered_conditions) -> org.sonar.batch.language.LanguageDistributionDecorator@3d363a02 -> org.sonar.plugins.cpd.decorators.DuplicationDensityDecorator@1bff7859 -> CommentDensityDecorator -> PackageTangleIndexDecorator -> f(file_complexity) -> f(class_complexity) -> f(function_complexity) -> org.sonar.plugins.core.sensors.CoverageDecorator@1a94871e -> org.sonar.plugins.core.sensors.LineCoverageDecorator@d32d034 -> org.sonar.plugins.core.sensors.BranchCoverageDecorator@3030cb1 -> org.sonar.plugins.core.sensors.ItLineCoverageDecorator@5f52470b -> org.sonar.plugins.core.sensors.ItCoverageDecorator@12b65411 -> org.sonar.plugins.core.sensors.ItBranchCoverageDecorator@4931b0 -> org.sonar.plugins.core.sensors.OverallLineCoverageDecorator@455d19f5 -> org.sonar.plugins.core.sensors.OverallCoverageDecorator@63534766 -> org.sonar.plugins.core.sensors.OverallBranchCoverageDecorator@7074ac7b -> Common Rules for c++ -> org.sonar.plugins.core.issue.IssueTrackingDecorator@300aabb8 -> org.sonar.batch.debt.DebtDecorator@331a78b3 -> org.sonar.batch.debt.NewDebtDecorator@eea49fb -> CountUnresolvedIssuesDecorator -> CountFalsePositivesDecorator -> org.sonar.batch.debt.SqaleRatingDecorator@379f0563 -> org.sonar.plugins.core.timemachine.TendencyDecorator@5dfc0f9f -> VariationDecorator
18:07:23.234 DEBUG - Decorator time:
        ManualMeasureDecorator: 7ms
        QProfileEventsDecorator: 18ms
        SumDuplicationsDecorator: 2ms
        UnitTestDecorator: 0ms
        org.sonar.plugins.core.security.ApplyProjectRolesDecorator@49401fe3: 3ms
        org.sonar.plugins.core.sensors.DirectoriesDecorator@3a870a33: 0ms
        org.sonar.plugins.core.sensors.FilesDecorator@77aeb849: 0ms
        org.sonar.plugins.core.timemachine.TimeMachineConfigurationPersister@211b8954: 7ms
        org.sonar.plugins.core.timemachine.NewCoverageFileAnalyzer@6fc4fe01: 0ms
        org.sonar.plugins.core.timemachine.NewItCoverageFileAnalyzer@6e002cfa: 0ms
        org.sonar.plugins.core.timemachine.NewOverallCoverageFileAnalyzer@4d890981: 0ms
        org.sonar.plugins.core.timemachine.NewCoverageAggregator@5fcf1beb: 0ms
        org.sonar.plugins.design.batch.ProjectDsmDecorator@16d4fac7: 0ms
        FileTangleIndexDecorator: 0ms
        f(lines): 1ms
        f(generated_lines): 2ms
        f(ncloc): 0ms
        f(generated_ncloc): 0ms
        f(classes): 0ms
        f(packages): 0ms
        f(functions): 0ms
        f(accessors): 0ms
        f(statements): 0ms
        f(public_api): 0ms
        f(comment_lines): 0ms
        f(comment_blank_lines): 0ms
        f(public_undocumented_api): 0ms
        f(commented_out_code_lines): 0ms
        f(complexity): 0ms
        f(complexity_in_classes): 0ms
        f(complexity_in_functions): 0ms
        f(class_complexity_distribution): 0ms
        f(function_complexity_distribution): 4ms
        f(file_complexity_distribution): 0ms
        f(lines_to_cover): 0ms
        f(uncovered_lines): 0ms
        f(conditions_to_cover): 0ms
        f(uncovered_conditions): 0ms
        f(it_lines_to_cover): 1ms
        f(it_uncovered_lines): 0ms
        f(it_conditions_to_cover): 0ms
        f(it_uncovered_conditions): 0ms
        f(overall_lines_to_cover): 0ms
        f(overall_uncovered_lines): 0ms
        f(overall_conditions_to_cover): 0ms
        f(overall_uncovered_conditions): 0ms
        f(rfc): 0ms
        f(rfc_distribution): 0ms
        f(lcom4_distribution): 0ms
        f(package_cycles): 0ms
        f(package_tangles): 0ms
        f(package_feedback_edges): 0ms
        f(package_edges_weight): 0ms
        f(new_lines_to_cover): 0ms
        f(new_uncovered_lines): 0ms
        f(new_conditions_to_cover): 0ms
        f(new_uncovered_conditions): 0ms
        f(new_it_lines_to_cover): 1ms
        f(new_it_uncovered_lines): 0ms
        f(new_it_conditions_to_cover): 1ms
        f(new_it_uncovered_conditions): 0ms
        f(new_overall_lines_to_cover): 0ms
        f(new_overall_uncovered_lines): 0ms
        f(new_overall_conditions_to_cover): 0ms
        f(new_overall_uncovered_conditions): 0ms
        org.sonar.batch.language.LanguageDistributionDecorator@3d363a02: 0ms
        org.sonar.plugins.cpd.decorators.DuplicationDensityDecorator@1bff7859: 1ms
        CommentDensityDecorator: 0ms
        PackageTangleIndexDecorator: 0ms
        f(file_complexity): 0ms
        f(class_complexity): 0ms
        f(function_complexity): 0ms
        org.sonar.plugins.core.sensors.CoverageDecorator@1a94871e: 0ms
        org.sonar.plugins.core.sensors.LineCoverageDecorator@d32d034: 0ms
        org.sonar.plugins.core.sensors.BranchCoverageDecorator@3030cb1: 0ms
        org.sonar.plugins.core.sensors.ItLineCoverageDecorator@5f52470b: 0ms
        org.sonar.plugins.core.sensors.ItCoverageDecorator@12b65411: 0ms
        org.sonar.plugins.core.sensors.ItBranchCoverageDecorator@4931b0: 2ms
        org.sonar.plugins.core.sensors.OverallLineCoverageDecorator@455d19f5: 0ms
        org.sonar.plugins.core.sensors.OverallCoverageDecorator@63534766: 0ms
        org.sonar.plugins.core.sensors.OverallBranchCoverageDecorator@7074ac7b: 1ms
        Common Rules for c++: 1ms
        org.sonar.plugins.core.issue.IssueTrackingDecorator@300aabb8: 75ms
        org.sonar.batch.debt.DebtDecorator@331a78b3: 26ms
        org.sonar.batch.debt.NewDebtDecorator@eea49fb: 12ms
        CountUnresolvedIssuesDecorator: 44ms
        CountFalsePositivesDecorator: 9ms
        org.sonar.batch.debt.SqaleRatingDecorator@379f0563: 2ms
        org.sonar.plugins.core.timemachine.TendencyDecorator@5dfc0f9f: 84ms
        VariationDecorator: 28ms

18:07:23.235 INFO  - Store results in database
18:07:23.236 DEBUG - Execute org.sonar.batch.index.MeasurePersister
18:07:23.355 DEBUG - Execute org.sonar.batch.index.DuplicationPersister
18:07:23.356 DEBUG - Execute org.sonar.batch.index.ComponentDataPersister
18:07:23.358 DEBUG - Execute org.sonar.batch.issue.IssuePersister
18:07:23.379 DEBUG - Execute org.sonar.batch.phases.GraphPersister
18:07:23.423 INFO  - ANALYSIS SUCCESSFUL, you can browse http://localhost:9000/dashboard/index/net.qgazq.test1
18:07:23.423 DEBUG - Evict preview database
18:07:23.423 DEBUG - Download: http://localhost:9000/batch_bootstrap/evict?project=1 (no proxy)
18:07:23.464 DEBUG - Post-jobs : org.sonar.plugins.core.issue.notification.SendIssueNotificationsPostJob@26d57227 -> org.sonar.plugins.core.batch.IndexProjectPostJob@739725c -> org.sonar.plugins.dbcleaner.ProjectPurgePostJob@4c82f9b8
18:07:23.464 INFO  - Executing post-job class org.sonar.plugins.core.issue.notification.SendIssueNotificationsPostJob
18:07:23.480 INFO  - Executing post-job class org.sonar.plugins.core.batch.IndexProjectPostJob
18:07:23.493 INFO  - Executing post-job class org.sonar.plugins.dbcleaner.ProjectPurgePostJob
18:07:23.505 INFO  - -> Keep one snapshot per day between 2014-09-19 and 2014-10-16
18:07:23.507 INFO  - -> Keep one snapshot per week between 2013-10-18 and 2014-09-19
18:07:23.508 INFO  - -> Keep one snapshot per month between 2009-10-23 and 2013-10-18
18:07:23.510 INFO  - -> Delete data prior to: 2009-10-23
18:07:23.521 DEBUG - ==>  Preparing: select * from projects p where p.id=?
18:07:23.550 DEBUG - ==> Parameters: 1(Long)
18:07:23.568 DEBUG - <==      Total: 1
18:07:23.568 DEBUG - ==>  Preparing: select * from projects where scope='PRJ' and root_id=?
18:07:23.569 DEBUG - ==> Parameters: 1(Long)
18:07:23.569 DEBUG - <==      Total: 0
18:07:23.570 INFO  - -> Clean Test1 [id=1]
18:07:23.577 INFO  - <- Clean snapshot 154
18:07:23.637 DEBUG - Release semaphore on project : org.sonar.api.resources.Project@3e4b2d80[id=1,key=net.qgazq.test1,qualifier=TRK], with key batch-net.qgazq.test1
18:07:23.647 DEBUG - To prevent a memory leak, the JDBC Driver [com.mysql.jdbc.Driver] has been forcibly deregistered
INFO: ------------------------------------------------------------------------
INFO: EXECUTION SUCCESS
INFO: ------------------------------------------------------------------------
Total time: 44.851s
Final Memory: 14M/441M
INFO: ------------------------------------------------------------------------
@guwirth guwirth added the bug label Oct 19, 2014
@guwirth
Copy link
Collaborator

guwirth commented Oct 19, 2014

Is there any reason you know that could cause this to happen, or something I could try?

Could you try the code snippet with the sslr toolkit. This is to validate if this is a parser issue.

@qgazq
Copy link
Author

qgazq commented Oct 19, 2014

I'm happy to give it a go, but could you point me in the right direction on how to do that?
Is there something I should download and run, or do I need to build a test harness?
I was able to download a jar file of it from http://search.maven.org/#browse%7C-269427911 but it doesn't seem to be a standalone tool.
From another thread I found this link http://dist.sonarsource.com/c/download/sslr-c-toolkit-1.8.jar that I could run and it opened the file without any delay. But I guess I probably want the sslr-toolkit for cxx from this project is that right?

@qgazq
Copy link
Author

qgazq commented Oct 19, 2014

I found a cxx version at http://mvnrepository.com/artifact/org.codehaus.sonar-plugins.cxx/sslr-cxx-toolkit/0.9
I'm not sure if that's what you meant or not, (and if its the right version given I'm using 0.91 of the plugin) but I ran using it anyway, and it again opens the file with no delay and gives an AST tree I can browse.

@guwirth
Copy link
Collaborator

guwirth commented Oct 19, 2014

If you are checking out the code and building it you will find sslr-cxx-toolkit-0.9.2-SNAPSHOT.jar in the folder ...\sonar-cxx\sslr-cxx-toolkit\target

@guwirth
Copy link
Collaborator

guwirth commented Oct 19, 2014

I did a test. It is also slow in the toolkit. Seems to be an issue somewhere here:

private static void expressions(LexerfulGrammarBuilder b) {
    b.rule(primaryExpression).is(
      b.firstOf(LITERAL,
                CxxKeyword.THIS,
                par_expression,
                idExpression,
                lambdaExpression,
                // EXTENSION: gcc's statement expression: a compound statement enclosed in parentheses may appear as an expression
                b.sequence("(", compoundStatement, ")"))
      ).skipIfOneChild();

    b.rule(par_expression).is(b.sequence("(", expression, ")"));

First suspicion: Has something to do with the gcc's statement expression?

@wenns
Copy link
Contributor

wenns commented Oct 20, 2014

What does make you think so?

@wenns
Copy link
Contributor

wenns commented Oct 20, 2014

Wow, thats slow... Worse, the runtime complexity is exponential, something like O(3^n).

@wenns
Copy link
Contributor

wenns commented Oct 20, 2014

Have made a couple of measurements trying the 'gcc-expressions theory'. Ive measured parsing of the function posted by the OP, the 11 nested parantheses case. On my machine it takes:

current trunk: 35 s
current trunk with f50c47f commit reverted: 30 s

so while it helps somewhat, it doesnt solve the problem. Id expect the running time somewhere in the tenths of milliseconds, maybe.

@wenns
Copy link
Contributor

wenns commented Oct 21, 2014

Ive tried tags 0.9.1. and 0.9. While 0.9.1 is has essentially the same behavior as trunk (running time for the test case above is 30s), the 0.9 parses this expression immediately. From the pure intuition having not looked at the commit in between, I'd intuitively suspect the builtin checkers.

@wenns
Copy link
Contributor

wenns commented Oct 21, 2014

Should be a case for git bisect. Starting with

$ git bisect bad cxx-0.9.1
$ git bisect good cxx-0.9

@dbolkensteyn
Copy link

Just as a quick note: You want to make sure that memoization is enabled on your grammar. It remembers the result of parsing something, if it already tried before. Without that, you can have exponentially growing parse time, for example : Add 1 level of parenthesis, multiply the parsing time by 2.

@wenns
Copy link
Contributor

wenns commented Oct 21, 2014

Bisecting finished with this:

git bisect good
d0152bf4bcbba86b4e38e1c4a13f9dea2187b51a is the first bad commit
commit d0152bf4bcbba86b4e38e1c4a13f9dea2187b51a
Author: Waleri Enns <wen@contact.de>
Date:   Fri Dec 20 14:39:41 2013 +0100

    Upgrading to SSLR 1.19 and the according squid bridge

:040000 040000 96fe614347d5b18acf8fffe44e7fc41f00fc7739 c31af29f5df9337f65ca9e8fe00826535299c4fa M  cxx-checks
:040000 040000 9e9f1cc27d39658fccdd5e9c5395eaa498558207 d084c4d39254e47d309e291cf2a9a78683c08a63 M  cxx-squid
:100644 100644 b9baf2e976e23a05baddc9200f7b769ab01b7a33 34377f693efaf74b058e67092e891f6a100b9a1f M  pom.xml
:040000 040000 df473ceed95970d6daafd1cb3855934e16032f05 a5e6e0d22109a7590caf46bf57a9814c7f893ea0 M  sonar-cxx-plugin
:040000 040000 ff6d804387d6ec5c11cb7607a2616e3e15e497ff beaef2a68622717e2300201d7d7e55a33fa20c54 M  sslr-cxx-toolkit

Which is not good news, as the behaviour is caused by the upgrade to a new SSLR version and is not directly in our hand... How to handle this? One option is to roll forward to either 0.19.2 or 0.20. The last one is AFAIR not exactly a drop-in replacement for 0.19.1 ...

@wenns
Copy link
Contributor

wenns commented Oct 21, 2014

@dbolkensteyn: Thanks for the hint. It sounds like a possible cause. I'll have a look.

@wenns
Copy link
Contributor

wenns commented Oct 21, 2014

@dbolkensteyn:
Call like this:

GrammarFunctions.enableMemoizationOfMatchesForAllRules(this);

should suffice, shoudnt it?
While we're at it, whats the plan regarding preprocessing in SSLR 0.20 and later? Preprocessor support is deprecated without replacements.

@francoisferrand
Copy link
Contributor

I just did a sample analysis after modifying CxxGrammarImpl.create() and CppGrammar.create() to call LexerfulGrammarBuilder.buildWithMemoizationOfMatchesForAllRules() instead of LexerfulGrammarBuilder.build(), and performance seems greatly improved: analysis time is down from 43minutes to 9minutes.

I can see CxxSquidSensor now takes just 2min 52s, but I don't have the detail on the time is took before the change, and the code under analysis and cxx plugin may have been slightly modified between the two: more tests would be needed to verify if/how much performance increases, as well as check there is no difference in the results of the analysis, but this looks quite promising!

Here is the simple patch I applied:

diff --git a/cxx-squid/src/main/java/org/sonar/cxx/parser/CxxGrammarImpl.java b/cxx-squid/src/main/java/org/s
index cf5a460..000026c 100644
--- a/cxx-squid/src/main/java/org/sonar/cxx/parser/CxxGrammarImpl.java
+++ b/cxx-squid/src/main/java/org/sonar/cxx/parser/CxxGrammarImpl.java
@@ -294,7 +294,7 @@ public enum CxxGrammarImpl implements GrammarRuleKey {

     b.setRootRule(translationUnit);

-    return b.build();
+    return b.buildWithMemoizationOfMatchesForAllRules();
   }


diff --git a/cxx-squid/src/main/java/org/sonar/cxx/preprocessor/CppGrammar.java b/cxx-squid/src/main/java/org
index 4ef216b..f135c84 100644
--- a/cxx-squid/src/main/java/org/sonar/cxx/preprocessor/CppGrammar.java
+++ b/cxx-squid/src/main/java/org/sonar/cxx/preprocessor/CppGrammar.java
@@ -111,7 +111,7 @@ public enum CppGrammar implements GrammarRuleKey {

     b.setRootRule(preprocessorLine);

-    return b.build();
+    return b.buildWithMemoizationOfMatchesForAllRules();
   }

@francoisferrand
Copy link
Contributor

More precisely, I get the following results for CxxSquidSensor:

    Before the patch : 27min 50s
    After the patch:    2min 3s

And it seems the analysis reports the same issues and metrics in both versions.

@francoisferrand
Copy link
Contributor

Patch here: #299

@wenns
Copy link
Contributor

wenns commented Oct 24, 2014

Thank for the patch, I see forward to testing it next week.

@wenns
Copy link
Contributor

wenns commented Oct 28, 2014

Fixed with #299

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Development

No branches or pull requests

5 participants