Hybris start up optimizations

Most part of long-running hybris projects has issues with hybris start up time. Below could be found tips on how to speed up platform start up.

Disable unused tenants in properties

Disabling everything except master tenant allows to save time on spring context creation for each tenant during start up.
1

installed.tenants=
Use more than 1 tomcat start up threads

By adjusting tomcat startStopThreads engine configuration property (/hybris/config/tomcat/conf/server.xml) could be increased amount of threads. You can read about it in tomcat documentation. Starting from Hybris 6.7 this option can be safely used on production system(startStopThreads=0 is OOTB configuration value). For lower version of Hybris it is not recommended to be used, due to it can lead to broken spring context due to non deterministic extension load order.
Exclude jars from tag library scanning

Check Hybris start up logs for messages like At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time. In case they are present, you should define which jars are scanned and add exclude them from scanning:
- Increase log level to output scanned jars by adding at the bottom of hybris/bin/platform/resources/tanukiwrapper/bin/jdk_logging.properties:
1 2

org.apache.catalina.startup.TldConfig.level=FINE org.apache.jasper.compiler.TldLocationsCache.level=FINE
- Run Hybris and get list of scanned jars from logs. Small .sh script can be used to automate things:
1

cat console.log | grep "Consider adding" | awk -F '!\/\]' '{print $1}' | awk -F '\/' '{print $NF",\\"}' | sort | uniq
- Result of the sh script should be inserted into /hybris/config/tomcat/conf/catalina.properties as value of property org.apache.catalina.startup.TldConfig.jarsToSkip.
Get rid of groovy classes in Hybris extensions (including testsrc)

During startup Hybris class loader load all classes in extensions (even test files). In case of groovy files class loader must firstly compile groovy into class file and load it after that. Compilation process is pretty slow. For example, removal of 200 groovy test classes speed up Hybris start up and ant unittests execution on 90 seconds.
Exclude test classes from ant production

During start up Hybris load all class files including the ones placed in testsrc. Removing test classes during ant production packaging will allow to save some time on production server. For example, it can be done by overriding extension_build_jar ant macrodef:
1 2 3 4 5

<jar destfile="@{destdir}/bin/@{extname}server.jar"> <fileset dir="${ext.@{extname}.path}/classes" > <exclude name="**/*Test.class" /> </fileset> </jar>
Disable task engine

On dev local environment (and on prod env in case of different node types deployments are supported by CI/CD pipiline) could be disabled task engine, which is responsible for tasks and cronjons execution.

1
2


cronjob.timertask.loadonstartup = false
task.engine.loadonstartup       = false

Disable backoffice warmup

Warming up the cache from backoffice can be switched off during startup time and loaded during first access.
1

backoffice.fill.typefacade.cache.on.startup=false
Remove unused extension from localextensions.xml
Ensure proper relation between extensions

Wrong relation between Hybris extensions can lead to slow start up in various ways.
- For example, acceleratorstorefrontcommons copies commonweb folder in all dependent extensions with webmodule. This folder contains taglib definitions, various classes etc., which are loaded during startup. In one of the projects, core extension was related to acceleratorstorefrontcommons and 4 none storefront web extensions was related to core. Changing dependencies in the way, when core extensions doesn’t require acceleratorstorefrontcommons and only storefront extension requires it, allowed to save around 20 sec of build time and 20 sec of start up time.
- In another case wrong dependency on addonsupport extension leads to slower startup (only storefront extensions must be depndend on addon/addonsupport extensions).
Disable/remove unused web modules for extensions
- Some of OOTB extensions are shipped with web module extensions, which, most probably, are not used in project. There is possibility to disable them via properties (or whitelist via aspects in case of dockerized deployments)
  1 2 3
  
  processing.webroot=<disabled> virtualjdbc.webroot=<disabled> mcc.webroot=<disabled>
- Custom extensions can have unused web modules (ant extgen default template generate extension with web module). In such cases just remove web folder and remove web extension definition from extensionsinfo.xml

Decrease time of spring bean creation

First of all enable spring debug log for spring bean creation factories:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16


log4j2.appender.jsonFile.name = BEANLOG

log4j2.appender.jsonFile.type = RollingFile
log4j2.appender.jsonFile.Append=false
log4j2.appender.jsonFile.filePattern = /tmp/bean_init-%d{yyyyMMdd}.log

log4j2.appender.jsonFile.policies.type = Policies
log4j2.appender.jsonFile.policies.time.type = TimeBasedTriggeringPolicy
log4j2.appender.jsonFile.policies.time.interval = 1

log4j2.appender.jsonFile.layout.type = PatternLayout
log4j2.appender.jsonFile.layout.pattern = %r %m%n

log4j2.logger.beans.name = org.springframework.beans.factory.support
log4j2.logger.beans.level = all
log4j2.logger.beans.appenderRef.stdout.ref = BEANLOG

Determine which beans take a lot of time for creation and check if it possible to get rid of them

For example, in project only in 1 place was used @Retry annotation from spring-retry library. Analysis of bean creation logs, shows that creation of retryConfiguration bean takes 16 seconds(it takes so long due to aspect implementation). Rewriting @Retry annotation in one place on simple for loop allows to save 16 seconds during start up.
Determine which beans have circular dependencies and get rid of it

P.S.: Python script which converts spring bean creation log into json, which is much easier to understand and analyze.

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160


import json
import sys


class LogAnalyzer:
    # 1000ms = 1s
    DURATION_THRESHOLD = 1000

    LOG_FILE_NAME = '/tmp/bean_init-20200128.log'
    OUTPUT_FILE_NAME = 'result.json'

    def analyze(self):
        # Default limit is too small for spring bean creation nesting
        sys.setrecursionlimit(100000)

        root_node = TreeUtils.create_empty_node()
        root_node["name"] = "ROOT"
        current_root_node = root_node

        with open(self.LOG_FILE_NAME, 'r') as log_file:
            for line in log_file:
                split_line = line.split(" ", 1)
                milliseconds_from_start = int(split_line[0])
                log_message = split_line[1]

                if log_message.startswith("Creating instance"):
                    bean_name = TreeUtils.get_bean_name(log_message)

                    node = TreeUtils.create_empty_node()
                    node["name"] = bean_name
                    node["parent"] = current_root_node["name"]
                    node["data"]["start_time"] = milliseconds_from_start

                    current_root_node["children"].append(node)
                    current_root_node = node

                elif log_message.startswith("Finished creating"):
                    bean_name = TreeUtils.get_bean_name(log_message)

                    if current_root_node["name"] == bean_name:
                        current_root_node["duration"] = milliseconds_from_start - current_root_node["data"][
                            "start_time"]
                        current_root_node = TreeUtils.find_node_by_id(root_node, current_root_node["parent"])
                    else:
                        explicit_find_node = TreeUtils.find_node_by_id(root_node, bean_name)
                        print("Something wrong with logs for bean: " + bean_name)
                        if explicit_find_node is not None:
                            explicit_find_node["duration"] = milliseconds_from_start - explicit_find_node["data"][
                                "start_time"]
                elif "a consequence of a circular reference" in log_message:
                    bean_name = TreeUtils.get_bean_name(log_message)
                    current_root_node["circular"].append(bean_name)

        TreeUtils.filter_nodes_with_default_spring_beans(root_node)
        TreeUtils.filter_nodes_by_duration_threshold(root_node, self.DURATION_THRESHOLD)
        TreeUtils.sort_nodes_by_duration(root_node)
        TreeUtils.restructure_tree_for_json_output(root_node)

        with open(self.OUTPUT_FILE_NAME, 'w') as result_file:
            result_file.write(json.dumps(root_node))


class TreeUtils:

    @staticmethod
    def get_bean_name(message):
        first = message.find('\'') + 1
        last = message.rfind('\'')
        return message[first:last]

    @staticmethod
    def find_node_by_id(start_node, node_id):
        if start_node["name"] == node_id:
            return start_node
        else:
            children = start_node["children"]
            if not children:
                return None
            for child in children:
                found_node = TreeUtils.find_node_by_id(child, node_id)
                if found_node is not None:
                    return found_node
            return None

    @staticmethod
    def sort_nodes_by_duration(start_node):
        children = start_node["children"]
        if children:
            children.sort(key=lambda k: k['duration'], reverse=True)
            for child in children:
                TreeUtils.sort_nodes_by_duration(child)

    @staticmethod
    def filter_nodes_by_duration_threshold(start_node, threshold):
        if start_node["duration"] < threshold:
            del start_node
        else:
            children = start_node["children"]
            if children:
                filtered_children = [x for x in children if x["duration"] > threshold]
                start_node["children"] = filtered_children

                for child in filtered_children:
                    TreeUtils.filter_nodes_by_duration_threshold(child, threshold)

    @staticmethod
    def filter_nodes_with_default_spring_beans(start_node):
        if start_node["name"].startswith("org.springframework."):
            del start_node
        else:
            children = start_node["children"]
            if children:
                filtered_children = [x for x in children if not x["name"].startswith("org.springframework.")]
                start_node["children"] = filtered_children

                for child in filtered_children:
                    TreeUtils.filter_nodes_with_default_spring_beans(child)

    @staticmethod
    def create_empty_node():
        return {
            "name": None,
            "parent": None,
            "children": [],
            "circular": [],
            "duration": 10000000,
            "data": {
                "start_time": None
            }
        }

    @staticmethod
    def restructure_tree_for_json_output(start_node):
        children = start_node["children"]

        if children:
            for child in children:
                TreeUtils.restructure_tree_for_json_output(child)

        node_name = start_node["name"]
        duration = start_node["duration"]

        start_node[node_name] = {
            "duration": duration
        }
        if children:
            start_node[node_name]["sub"] = children

        if not start_node["circular"]:
            del start_node["circular"]

        del start_node["parent"]
        del start_node["data"]
        del start_node["name"]
        del start_node["duration"]
        del start_node["children"]


if __name__ == "__main__":
    LogAnalyzer().analyze()