Long execution times with jgit

[jiri-pejchal]

The revision goal takes 38 s in our project when using jgit. Because builds are tagged we have about 5000 tags in git repository so that may be the cause.

When the git binary is used:
<useNativeGit>true</useNativeGit>
instead of jgit the goal execution is down to 3.6 s.

 <plugin>
                <groupId>pl.project13.maven</groupId>
                <artifactId>git-commit-id-plugin</artifactId>
                <version>2.2.6</version>
                <executions>
                    <execution>
                        <goals>
                            <goal>revision</goal>
                        </goals>
                    </execution>
                </executions>
                <configuration>
                    <dotGitDirectory>${project.basedir}/.git</dotGitDirectory>
                    <generateGitPropertiesFile>true</generateGitPropertiesFile>
                    <failOnNoGitDirectory>false</failOnNoGitDirectory>
                    <generateGitPropertiesFile>false</generateGitPropertiesFile>
                    <dateFormat>yyyy-MM-dd HH:mm</dateFormat>
                    <gitDescribe>
                        <!-- don't generate the describe property -->
                        <skip>false</skip>
                        <!-- when the build is triggered while the repo is in "dirty state", append this suffix -->
                        <dirty>-DEV</dirty>
                        <tags>true</tags>
                        <!--
                             always print using the "tag-commits_from_tag-g_commit_id-maybe_dirty" format, even if "on" a tag.
                             The distance will always be 0 if you're "on" the tag.
                        -->
                        <forceLongFormat>false</forceLongFormat>
                    </gitDescribe>
                    <excludeProperties>
                        <excludeProperty>git.build.user.*</excludeProperty>
                        <excludeProperty>git.commit.message.*</excludeProperty>
                        <excludeProperty>git.commit.user</excludeProperty>
                        <excludeProperty>git.remote.origin.*</excludeProperty>
                    </excludeProperties>
                    <runOnlyOnce>true</runOnlyOnce>
                    <injectAllReactorProjects>true</injectAllReactorProjects>
                    <skipPoms>false</skipPoms>
                </configuration>

            </plugin>

$ java -version
java version "1.8.0_181"
Java(TM) SE Runtime Environment (build 1.8.0_181-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode)

$ mvn --version
Apache Maven 3.6.0 (97c98ec64a1fdfee7767ce5ffb20918da4f719f3; 2018-10-24T20:41:47+02:00)
Maven home: C:\software\apache-maven\bin\..
Java version: 1.8.0_181, vendor: Oracle Corporation, runtime: C:\Program Files\Java\jdk1.8.0_181\jre
Default locale: en_US, platform encoding: UTF-8
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"

[jiri-pejchal]

[TheSnoozer]

Hi,
thanks for reporting your issue and including more technical details.

Sadly I'd claim that this is currently expected behaviour and one of the main reasons why this plugin also allows to run with a native git binary.

Based on the documentation using the native git binary should usually give your build some performance boost, it may randomly break if you upgrade your git version and it decides to print information in a different format suddenly. As rule of thumb, keep using the default `jgit` implementation until you notice performance problems within your build

When the native git binary was introduced I also noticed the difference in build times (I guess it depends on the history of the git tree).

However I'm not so sure if we have any way in speeding-up the jgit implementation. This implementation is essentially a git reimplementation and thus may not have certain optimizations in place (or we simply use it wrong).

I'm actually not quite sure if we can do anything about this on our end....

[jiri-pejchal]

Ok, thanks. Also deleting all the tags helped. I'll use native git binary then.

[TheSnoozer]

Sounds good for me (so far I never had an issue with the native binary, but as the doc states changes are certainly out of our control). I'll take a look if there is any obvious that we could improve...

[TheSnoozer]

Sorry that this took so long, I wanted to finish the selective running feature (#185) before doing some more thoughtfull testing.
Overall I now ran a test with the 'old' 2.2.6 version and compared it with the latest local 3.0.0-SNAPSHOT with the improvements I have locally.

Some general observations:

• running the plugin with the native git implementaion can cut the execution time in almost half (e.g. running the gathering of properties against the tensorflow repository with 55278 commits yields a 7.22s execution time with the native binary VS a 11.37s execution time with jGIT) - somewhat obvious but the complexity and size of a repository can have a huge impact
• by comparing the two versions i noticed a hefty runtime difference that can be blamed to the new ahead_behind property which was introduced 365 set ahead and behind properties #395. To some extend this was expected since getting the right value of this properties performs a git fetch (sadly)
• the new upcomming selective running feature (Instead of determine all properties and then exclude properties why not choose selective running (native git) #185) somewhat mitigates the runtime impact of the new ahead_behind property and could yield in even faster execution than before (e.g. when only obtaining the git.commit)
• In summary the difference between native git and the jGIt implementation heavly depends on the size and shape of the underlying git-repo. By looking at the numbers using the JGIT implementation has a price, but thats why this plugin also ships with a native implementation that is expected to always perform better (JGit is a reimplementation in java and might not take some possible short cuts). As a result I'd claim that's fine for me and expected behaviour

For full transparency, here is the full comparison (including the script I used to gather the numbers). Execution time is measured in seconds and for all the Run with-tests the maven command was executed 10 times - the final resulting value is the mean of all those execution runs. In practice the time indicated is the time that an entire maven run took (slight overhead of maven is expected). However this can still be used as a rough indicator on how long the plugin needs to get the info's.

Comparison with new ahead_behind property:

before (commit d7af909)

=== Run test for /tmp/testing/PocketHub (commit count: 3451)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 1.7458910942077637
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 1.8617501258850098
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 2.1910812854766846
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 2.276075839996338
=== Run test for /tmp/testing/maven (commit count: 12357)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 1.7894320487976074
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 1.904515027999878
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 2.8245046138763428
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 3.00187087059021
=== Run test for /tmp/testing/tensorflow (commit count: 55278)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 3.999955892562866
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 4.2611799240112305
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 7.234072208404541
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 7.503699541091919

after (commit 64bff8f)

=== Run test for /tmp/testing/PocketHub (commit count: 3451)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 1.752915859222412
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 2.514976978302002
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 2.333421230316162
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 3.8971266746520996
=== Run test for /tmp/testing/maven (commit count: 12357)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 1.8299574851989746
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 2.449676752090454
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 2.793705940246582
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 4.646960496902466
=== Run test for /tmp/testing/tensorflow (commit count: 55278)
+++ git_commit_id_plugin_version 2.2.6 / use_native_git True / time: 4.004956245422363
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git True / time: 6.388733863830566
+++ git_commit_id_plugin_version 2.2.6 / use_native_git False / time: 7.212291240692139
+++ git_commit_id_plugin_version 3.0.0-SNAPSHOT / use_native_git False / time: 12.78350567817688

Run with all properties

Repository	Commit Count	use-native=True		use-native=False
		2.2.6	3.0.0-SNAPSHOT-187ea2f51	2.2.6	3.0.0-SNAPSHOT-187ea2f51
pockethub/PocketHub.git	3451	1.75	2.73	2.28	4.33
apache/maven.git	12357	1.77	2.95	2.97	5.61
apache/wicket.git	32769	2.7	3.58	5.43	7.44
netty/netty.git	14909	2.1	2.84	3.59	6.31
tensorflow/tensorflow.git	55281	4.29	7.22	7.74	11.37
angular/angular.js.git	12598	1.83	3.32	3.24	6.51
twbs/bootstrap.git	19565	2.34	4.4	3.44	5.56

Click to view raw data

=== Run test for /tmp/testing/PocketHub (commit count: 3451)
"2.2.6","True","1.75"
"3.0.0-SNAPSHOT-187ea2f51","True","2.73"
"2.2.6","False","2.28"
"3.0.0-SNAPSHOT-187ea2f51","False","4.33"
=== Run test for /tmp/testing/maven (commit count: 12357)
"2.2.6","True","1.77"
"3.0.0-SNAPSHOT-187ea2f51","True","2.95"
"2.2.6","False","2.97"
"3.0.0-SNAPSHOT-187ea2f51","False","5.61"
=== Run test for /tmp/testing/wicket (commit count: 32769)
"2.2.6","True","2.70"
"3.0.0-SNAPSHOT-187ea2f51","True","3.58"
"2.2.6","False","5.43"
"3.0.0-SNAPSHOT-187ea2f51","False","7.44"
=== Run test for /tmp/testing/netty (commit count: 14895)
"2.2.6","True","2.10"
"3.0.0-SNAPSHOT-187ea2f51","True","2.84"
"2.2.6","False","3.59"
"3.0.0-SNAPSHOT-187ea2f51","False","6.31"
=== Run test for /tmp/testing/tensorflow (commit count: 55278)
"2.2.6","True","4.29"
"3.0.0-SNAPSHOT-187ea2f51","True","7.22"
"2.2.6","False","7.74"
"3.0.0-SNAPSHOT-187ea2f51","False","11.37"
=== Run test for /tmp/testing/angular.js (commit count: 12598)
"2.2.6","True","1.83"
"3.0.0-SNAPSHOT-187ea2f51","True","3.32"
"2.2.6","False","3.24"
"3.0.0-SNAPSHOT-187ea2f51","False","6.51"
=== Run test for /tmp/testing/bootstrap (commit count: 19565)
"2.2.6","True","2.34"
"3.0.0-SNAPSHOT-187ea2f51","True","4.40"
"2.2.6","False","3.44"
"3.0.0-SNAPSHOT-187ea2f51","False","5.56" 

Run with includeOnlyProperty = ^git.commit.id$

<includeOnlyProperties>
  <includeOnlyProperty>^git.commit.id$</includeOnlyProperty>
</includeOnlyProperties>

Repository	Commit Count	use-native=True		use-native=False
		2.2.6	3.0.0-SNAPSHOT-187ea2f51	2.2.6	3.0.0-SNAPSHOT-187ea2f51
pockethub/PocketHub.git	3451	1.94	1.76	2.33	1.91
apache/maven.git	12357	1.92	1.77	3.02	1.98
apache/wicket.git	32769	2.55	1.86	5.84	2.05
netty/netty.git	14909	2.08	1.96	3.72	2.05
tensorflow/tensorflow.git	55281	4.31	1.77	7.79	2.07
angular/angular.js.git	12598	2.01	1.9	3.49	2.18
twbs/bootstrap.git	19565	2.61	1.99	3.88	2.09

Click to view raw data

=== Run test for /tmp/testing/PocketHub (commit count: 3451)
"2.2.6","True","1.94"
"3.0.0-SNAPSHOT-187ea2f51","True","1.76"
"2.2.6","False","2.33"
"3.0.0-SNAPSHOT-187ea2f51","False","1.91"
=== Run test for /tmp/testing/maven (commit count: 12357)
"2.2.6","True","1.92"
"3.0.0-SNAPSHOT-187ea2f51","True","1.77"
"2.2.6","False","3.02"
"3.0.0-SNAPSHOT-187ea2f51","False","1.98"
=== Run test for /tmp/testing/wicket (commit count: 32769)
"2.2.6","True","2.55"
"3.0.0-SNAPSHOT-187ea2f51","True","1.86"
"2.2.6","False","5.84"
"3.0.0-SNAPSHOT-187ea2f51","False","2.05"
=== Run test for /tmp/testing/netty (commit count: 14895)
"2.2.6","True","2.08"
"3.0.0-SNAPSHOT-187ea2f51","True","1.96"
"2.2.6","False","3.72"
"3.0.0-SNAPSHOT-187ea2f51","False","2.05"
=== Run test for /tmp/testing/tensorflow (commit count: 55278)
"2.2.6","True","4.31"
"3.0.0-SNAPSHOT-187ea2f51","True","1.77"
"2.2.6","False","7.79"
"3.0.0-SNAPSHOT-187ea2f51","False","2.07"
=== Run test for /tmp/testing/angular.js (commit count: 12598)
"2.2.6","True","2.01"
"3.0.0-SNAPSHOT-187ea2f51","True","1.90"
"2.2.6","False","3.49"
"3.0.0-SNAPSHOT-187ea2f51","False","2.18"
=== Run test for /tmp/testing/bootstrap (commit count: 19565)
"2.2.6","True","2.61"
"3.0.0-SNAPSHOT-187ea2f51","True","1.99"
"2.2.6","False","3.88"
"3.0.0-SNAPSHOT-187ea2f51","False","2.09" 

Run with excludeProperties = ^git.local.branch.*$

<excludeProperties>
  <excludeProperty>^git.local.branch.*$</excludeProperty>
</excludeProperties>

Repository	Commit Count	use-native=True		use-native=False
		2.2.6	3.0.0-SNAPSHOT-187ea2f51	2.2.6	3.0.0-SNAPSHOT-187ea2f51
pockethub/PocketHub.git	3451	1.79	1.86	2.16	2.3
apache/maven.git	12357	1.9	2.48	3.26	3.44
apache/wicket.git	32769	2.74	2.67	5.56	6.2
netty/netty.git	14909	2.11	2.04	3.69	4.04
tensorflow/tensorflow.git	55281	4.45	4.33	7.95	8.06
angular/angular.js.git	12598	1.85	1.9	3.06	3.1
twbs/bootstrap.git	19565	2.13	2.6	3.36	3.83

Click to view raw data

=== Run test for /tmp/testing/PocketHub (commit count: 3451)
"2.2.6","True","1.79"
"3.0.0-SNAPSHOT-187ea2f51","True","1.86"
"2.2.6","False","2.16"
"3.0.0-SNAPSHOT-187ea2f51","False","2.30"
=== Run test for /tmp/testing/maven (commit count: 12357)
"2.2.6","True","1.90"
"3.0.0-SNAPSHOT-187ea2f51","True","2.48"
"2.2.6","False","3.26"
"3.0.0-SNAPSHOT-187ea2f51","False","3.44"
=== Run test for /tmp/testing/wicket (commit count: 32769)
"2.2.6","True","2.74"
"3.0.0-SNAPSHOT-187ea2f51","True","2.67"
"2.2.6","False","5.56"
"3.0.0-SNAPSHOT-187ea2f51","False","6.20"
=== Run test for /tmp/testing/netty (commit count: 14909)
"2.2.6","True","2.11"
"3.0.0-SNAPSHOT-187ea2f51","True","2.04"
"2.2.6","False","3.69"
"3.0.0-SNAPSHOT-187ea2f51","False","4.04"
=== Run test for /tmp/testing/tensorflow (commit count: 55281)
"2.2.6","True","4.45"
"3.0.0-SNAPSHOT-187ea2f51","True","4.33"
"2.2.6","False","7.95"
"3.0.0-SNAPSHOT-187ea2f51","False","8.06"
=== Run test for /tmp/testing/angular.js (commit count: 12598)
"2.2.6","True","1.85"
"3.0.0-SNAPSHOT","True","1.90"
"2.2.6","False","3.06"
"3.0.0-SNAPSHOT","False","3.10"
=== Run test for /tmp/testing/bootstrap (commit count: 19565)
"2.2.6","True","2.13"
"3.0.0-SNAPSHOT-187ea2f51","True","2.60"
"2.2.6","False","3.36"
"3.0.0-SNAPSHOT-187ea2f51","False","3.83"

Testing script

Click to view

# python3.6 -m pip install GitPython

import os
import re
import git
import time
import subprocess
from git import RemoteProgress

TEST_DIR = '/tmp/testing'

GIT_URLS = [
    # git@github.com:torvalds/linux.git
    'git@github.com:pockethub/PocketHub.git',
    # 'git@github.com:cstamas/nexus-core-ng.git',
    'git@github.com:apache/maven.git',
    'git@github.com:apache/wicket.git',
    'git@github.com:netty/netty.git',
    'git@github.com:tensorflow/tensorflow.git',
    'git@github.com:angular/angular.js.git',
    'git@github.com:twbs/bootstrap.git'
]


class CustomProgress(RemoteProgress):
    def update(self, op_code, cur_count, max_count=None, message=''):
        if message:
            percent = cur_count / max_count
            print("{0:50}\t{1:.2%}".format(message, percent), end='\r')
            if op_code & RemoteProgress.END == RemoteProgress.END:
                print('')


def git_url_to_path(base_dir, git_url):
    repo_name = re.findall('/(.+?)\.git', git_url)[0]
    repo_path = os.path.join(base_dir, repo_name)
    return repo_path


def setup_testing_repos():
    os.makedirs(TEST_DIR, exist_ok=True)
    for git_url in GIT_URLS:
        repo_path = git_url_to_path(TEST_DIR, git_url)

        if not os.path.isdir(repo_path):
            print('Clone {0} into {1}'.format(git_url, repo_path))
            git.Repo.clone_from(git_url, repo_path, progress=CustomProgress())
        else:
            print('Nothing to-do for {0}'.format(git_url))


def setup_maven_benchmark_pom(tmp_dir_name):
    with open(os.path.join(tmp_dir_name, "pom.xml"), 'w') as mvn_pom:
        mvn_pom.write('''<?xml version="1.0" encoding="UTF-8"?>
            <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
                <modelVersion>4.0.0</modelVersion>
                <parent>
                    <groupId>org.sonatype.oss</groupId>
                    <artifactId>oss-parent</artifactId>
                    <version>9</version>
                </parent>
            
                <artifactId>naive-performance-test</artifactId>
                <version>0.0.3-SNAPSHOT</version>
            
                <properties>
                    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
                    <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
                    <git-commit-id-version>3.0.0-SNAPSHOT</git-commit-id-version>
                    <git-use-native>false</git-use-native>
                </properties>
            
                <build>
                    <plugins>
                        <plugin>
                            <groupId>pl.project13.maven</groupId>
                            <artifactId>git-commit-id-plugin</artifactId>
                            <version>${git-commit-id-version}</version>
                            <executions>
                                <execution>
                                    <id>get-the-git-infos</id>
                                    <goals>
                                        <goal>revision</goal>
                                    </goals>
                                    <phase>initialize</phase>
                                </execution>
                            </executions>
                            <configuration>
                                <prefix>git</prefix>
                                <verbose>true</verbose>
                                <useNativeGit>${git-use-native}</useNativeGit>
                                <skipPoms>false</skipPoms>
                                <!-- <nativeGitTimeoutInMs>3000</nativeGitTimeoutInMs> -->
                                <dotGitDirectory>${project.basedir}/.git</dotGitDirectory>
                                <generateGitPropertiesFile>true</generateGitPropertiesFile>
                                <evaluateOnCommit>HEAD</evaluateOnCommit>
                                <generateGitPropertiesFilename>${project.build.outputDirectory}/git.properties</generateGitPropertiesFilename>
                                <!--
                                <includeOnlyProperties>
                                    <includeOnlyProperty>^git.commit.id$</includeOnlyProperty>
                                </includeOnlyProperties>
                                -->
                                <excludeProperties>
                                    <excludeProperty>^git.local.branch.*$</excludeProperty>
                                </excludeProperties>
                            </configuration>
                        </plugin>
                        <!--
                        <plugin>
                            <artifactId>maven-antrun-plugin</artifactId>
                            <version>1.8</version>
                            <executions>
                                <execution>
                                    <id>echo-properties</id>
                                    <phase>initialize</phase>
                                    <goals>
                                        <goal>run</goal>
                                    </goals>
                                    <configuration>
                                        <target>
                                            <echo>git-evaluation-dir: ${git-evaluation-dir}</echo>
                                            <echo>git-use-native: ${git-use-native}</echo>
                                        </target>
                                    </configuration>
                                </execution>
                            </executions>
                        </plugin>
                        -->
                    </plugins>
                </build>
            </project>''')


def run_process(args, cwd):
    # print("start process: " + str(' '.join(args)))
    proc = subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.PIPE, cwd=cwd)
    stdout, _ = proc.communicate()
    if proc.returncode != 0:
        raise ValueError('Process failed with exit-code {0}.\nOutput: {1}'.format(proc.returncode, stdout))

    return stdout


def mean(numbers):
    return float(sum(numbers)) / max(len(numbers), 1)


setup_testing_repos()

for git_url in GIT_URLS:
    repo_path = git_url_to_path(TEST_DIR, git_url)
    actual_git_repo = os.path.join(repo_path, '.git')

    commit_count = run_process(['git', 'rev-list', '--all', '--count'], cwd=repo_path)
    commit_count = re.search(r'\d+', str(commit_count)).group()

    print(f"=== Run test for {repo_path} (commit count: {commit_count})")
    setup_maven_benchmark_pom(repo_path)

    for use_native_git in [True, False]:
        for git_commit_id_plugin_version in ['2.2.6', '3.0.0-SNAPSHOT']:
            max_attempts = 10
            execution_times = []
            for attempt in range(1, max_attempts + 1):
                print(f"Launching {attempt} / {max_attempts} for {git_commit_id_plugin_version},{use_native_git}",
                      end='\r', flush=True)
                start = time.time()
                run_process(
                    ['mvn',
                     'pl.project13.maven:git-commit-id-plugin:' + str(git_commit_id_plugin_version) + ':revision',
                     '-Dgit-use-native=' + str(use_native_git).lower()],
                    cwd=repo_path)

                total_time = time.time() - start
                execution_times.append(total_time)
            avg_execution_time = mean(execution_times)
            print(f"\"{git_commit_id_plugin_version}\",\"{use_native_git}\",\"{avg_execution_time:.2f}\"{100*' '}")

[TheSnoozer]

I'm closing this, since the execution times seem reasonable. If there is any specific pointer of a performance issue I certainly can look into it.