I have worked with BioModels as an enterprise application for nine years. I don’t remember when deploying times became too slow; it was a nightmare because it took more than 12 minutes to be ready. When it comes to employing CI/CD, I was genuinely frustrated having to wait about half an hour for two replicas of BioModels to deploy in Kubernetes. However, I successfully reduced the deploying time three times and I can redeploy BioModels more frequently. Now it takes around seven minutes more or less to complete the deployment. In this post, I am going to show you some ideas for inspecting bottlenecks in applications.

Logging services

The first approach I approached was to check every service or bean initialisation whether there were any blocks. The logging libraries always print out messages with timestamps to support checking how long a service or bean was instantiated. The logs below can be interpreted that there isn’t any issue during starting the services. The timestamps indicate clearly how quickly the services are instantiated.

2024-12-17 22:07:01,881 [localhost-startStop-1] DEBUG configuration.ConfigurationService - Jummp is loading the configuration file from the default location
2024-12-17 22:07:01,881 [localhost-startStop-1] DEBUG configuration.ConfigurationService - The app is loading the configuration file /Users/tnguyen/.jummp.properties
2024-12-17 22:07:01,924 [localhost-startStop-1] DEBUG redis.RedisService - Setting the configurations...
2024-12-17 22:07:01,994 [localhost-startStop-1] DEBUG redis.RedisService - Jedis Pool has been initialised successfully
2024-12-17 22:07:09,675 [localhost-startStop-1] INFO core.UserService - Finished the bean initialisation
2024-12-17 22:07:10,518 [localhost-startStop-1] INFO security.ContributorService - Finished the bean initialisation
2024-12-17 22:07:10,574 [localhost-startStop-1] DEBUG core.FileSystemService - Root folder for model repositories set to /Users/tnguyen/ownCloud/EBI/biomodels/jummp/data-folders/vcs/working
2024-12-17 22:07:10,642 [localhost-startStop-1] DEBUG core.FileSystemService - New model to be deposited in /Users/tnguyen/ownCloud/EBI/biomodels/jummp/data-folders/vcs/working/aaa
2024-12-17 22:07:10,642 [localhost-startStop-1] INFO core.FileSystemService - Finished the bean initialisation
2024-12-17 22:07:11,870 [localhost-startStop-1] DEBUG core.VcsService - Model Container Root: null
2024-12-17 22:07:11,910 [localhost-startStop-1] INFO core.VcsService - Finished the bean initialisation
2024-12-17 22:07:12,216 [localhost-startStop-1] INFO model.RepositoryFileService - Finished the bean initialisation
2024-12-17 22:07:12,247 [localhost-startStop-1] INFO model.ModelConversionService - Finished the bean initialisation
2024-12-17 22:07:12,433 [localhost-startStop-1] INFO core.DoiService - Finished the bean initialisation
2024-12-17 22:07:12,503 [localhost-startStop-1] INFO core.PubMedService - Finished the bean initialisation
2024-12-17 22:07:12,579 [localhost-startStop-1] INFO core.PublicationService - Finished the bean initialisation
2024-12-17 22:07:12,623 [localhost-startStop-1] INFO model.RepositoryFileService - Finished the bean initialisation
2024-12-17 22:07:13,085 [localhost-startStop-1] INFO core.MetadataService - Finished the bean initialisation
2024-12-17 22:07:13,224 [localhost-startStop-1] INFO biomodels.ModelTagService - Finished the bean initialisation
2024-12-17 22:07:13,242 [localhost-startStop-1] INFO core.MetadataDelegateService - Finished the bean initialisation
2024-12-17 22:07:13,953 [localhost-startStop-1] INFO biomodels.DecorationService - Finished the bean initialisation
2024-12-17 22:07:14,045 [localhost-startStop-1] INFO core.ModelFlagService - Finished the bean initialisation
2024-12-17 22:07:14,676 [localhost-startStop-1] INFO biomodels.ModelOfTheMonthService - Finished the bean initialisation
2024-12-17 22:07:14,700 [localhost-startStop-1] INFO biomodels.TagService - Finished the bean initialisation
2024-12-17 22:07:17,294 [localhost-startStop-1] INFO model.RepositoryFileService - Finished the bean initialisation
2024-12-17 22:07:17,295 [localhost-startStop-1] INFO model.ModelConversionService - Finished the bean initialisation
2024-12-17 22:07:17,417 [localhost-startStop-1] INFO core.SubmissionService - Finished the bean initialisation
2024-12-17 22:07:19,377 [localhost-startStop-1] INFO model.RepositoryFileService - Finished the bean initialisation
2024-12-17 22:07:19,378 [localhost-startStop-1] INFO model.ModelConversionService - Finished the bean initialisation
2024-12-17 22:07:19,382 [localhost-startStop-1] INFO omex.OmexService - Finished the bean initialisation
2024-12-17 22:07:19,854 [localhost-startStop-1] INFO sbml.SbmlService - Finished the bean initialisation
2024-12-17 22:07:22,455 [localhost-startStop-1] INFO core.NotificationService - Finished the bean initialisation
2024-12-17 22:07:25,671 [localhost-startStop-1] INFO biomodels.ClassifierConfigureService - Finished the bean initialisation
2024-12-17 22:07:25,685 [localhost-startStop-1] INFO biomodels.ModelClassService - Finished the bean initialisation
2024-12-17 22:07:26,072 [localhost-startStop-1] INFO core.FeedbackService - Finished the bean initialisation
2024-12-17 22:07:26,170 [localhost-startStop-1] INFO core.ReviewerAccountService - Finished the bean initialisation
2024-12-17 22:07:28,262 [localhost-startStop-1] INFO format.MatlabFormatService - Finished the bean initialisation
2024-12-17 22:07:28,487 [localhost-startStop-1] INFO core.SearchService - Finished the bean initialisation
2024-12-17 22:07:30,131 [localhost-startStop-1] DEBUG configuration.ConfigurationService - Jummp is loading the configuration file from the default location
2024-12-17 22:07:31,867 [localhost-startStop-1] INFO model.RepositoryFileService - Finished the bean initialisation
2024-12-17 22:07:40,317 [localhost-startStop-1] DEBUG support.SubmissionIdGeneratorInitializer - Most recent submission id is MODEL2412170001
2024-12-17 22:07:40,358 [localhost-startStop-1] DEBUG identifier.ModelIdentifierGeneratorFactoryBean - Seed: MODEL2412170001 --- type: from redis cache
2024-12-17 22:07:40,546 [localhost-startStop-1] INFO support.ModelIdentifierCursorPartitionRegistry - Processing partition MODEL for MODEL2412170001; width 5 (0 -> 4)
2024-12-17 22:07:40,550 [localhost-startStop-1] DEBUG support.ModelIdentifierCursorPartitionRegistry - Model identifier partition net.biomodels.jummp.core.model.identifier.support.LiteralModelIdentifierPartition@74fb693b has new value MODEL
2024-12-17 22:07:40,578 [localhost-startStop-1] INFO support.ModelIdentifierCursorPartitionRegistry - Processing partition 241217 for MODEL2412170001; width 6 (5 -> 10)
2024-12-17 22:07:40,578 [localhost-startStop-1] DEBUG support.ModelIdentifierCursorPartitionRegistry - Model identifier partition net.biomodels.jummp.core.model.identifier.support.DateModelIdentifierPartition@6042687b has new value 241217
2024-12-17 22:07:40,596 [localhost-startStop-1] INFO support.ModelIdentifierCursorPartitionRegistry - Processing partition 0000 for MODEL2412170001; width 4 (11 -> 14)
2024-12-17 22:07:40,597 [localhost-startStop-1] DEBUG support.ModelIdentifierCursorPartitionRegistry - Model identifier partition net.biomodels.jummp.core.model.identifier.support.NumericalModelIdentifierPartition@55b12133 has new value 0001
2024-12-17 22:07:40,691 [localhost-startStop-1] DEBUG decorator.FixedLiteralAppendingDecorator - Creating net.biomodels.jummp.core.model.identifier.decorator.FixedLiteralAppendingDecorator order: 0 nextValue: null with suffix MODEL
2024-12-17 22:07:40,713 [localhost-startStop-1] DEBUG decorator.DateAppendingDecorator - Creating net.biomodels.jummp.core.model.identifier.decorator.DateAppendingDecorator order: 1 nextValue: null that formats Tue Dec 17 22:07:40 GMT 2024 as 241217
2024-12-17 22:07:40,732 [localhost-startStop-1] DEBUG decorator.VariableDigitAppendingDecorator - Creating 4-digit net.biomodels.jummp.core.model.identifier.decorator.VariableDigitAppendingDecorator order: 2 nextValue: null
2024-12-17 22:07:40,802 [localhost-startStop-1] DEBUG identifier.ModelIdentifierGeneratorRegistryService - Searched for a generator named submissionIdGenerator and found net.biomodels.jummp.core.model.identifier.generator.DefaultModelIdentifierGenerator@33a833af.
2024-12-17 22:07:40,830 [localhost-startStop-1] DEBUG identifier.ModelIdentifierGeneratorFactoryBean - Seed: BIOMD0000000649 --- type: from redis cache
2024-12-17 22:07:40,831 [localhost-startStop-1] INFO support.ModelIdentifierCursorPartitionRegistry - Processing partition BIOMD for BIOMD0000000649; width 5 (0 -> 4)
2024-12-17 22:07:40,832 [localhost-startStop-1] DEBUG support.ModelIdentifierCursorPartitionRegistry - Model identifier partition net.biomodels.jummp.core.model.identifier.support.LiteralModelIdentifierPartition@25785131 has new value BIOMD
2024-12-17 22:07:40,832 [localhost-startStop-1] INFO support.ModelIdentifierCursorPartitionRegistry - Processing partition 0000000000 for BIOMD0000000649; width 10 (5 -> 14)
2024-12-17 22:07:40,833 [localhost-startStop-1] DEBUG support.ModelIdentifierCursorPartitionRegistry - Model identifier partition net.biomodels.jummp.core.model.identifier.support.NumericalModelIdentifierPartition@b238693d has new value 0000000649
2024-12-17 22:07:40,833 [localhost-startStop-1] DEBUG decorator.FixedLiteralAppendingDecorator - Creating net.biomodels.jummp.core.model.identifier.decorator.FixedLiteralAppendingDecorator order: 0 nextValue: null with suffix BIOMD
2024-12-17 22:07:40,833 [localhost-startStop-1] DEBUG decorator.VariableDigitAppendingDecorator - Creating 10-digit net.biomodels.jummp.core.model.identifier.decorator.VariableDigitAppendingDecorator order: 1 nextValue: null
2024-12-17 22:07:40,834 [localhost-startStop-1] DEBUG identifier.ModelIdentifierGeneratorRegistryService - Searched for a generator named publicationIdGenerator and found net.biomodels.jummp.core.model.identifier.generator.DefaultModelIdentifierGenerator@7ce8fdbc.

At least, this approach can show us the slow deployment issue doesn’t come from the initialisation of services.

Using profiling applications

One of the common profiling applications for Java-based stacks is Java VisualVM. It can be integrated with IntelliJ. I used it as the tool to inspect which parts of the BioModels platform are slowing down the startup. This snapshot was captured when BioModels Jummp started until finishing. It shows a lot of elastic search I/O workers. By running dependency-report, I found that the elasticsearch is one of Weceem’s plugins. Ultimately, I tried to purge the Weceem plugin completely and the app now takes less than three minutes to complete the deployment and to make the application be ready.

As shown in the screenshot above, loading I/O server boss causes a big bottleneck in starting the application.

Conclusion

When the startup of an application is slow, using the logging frameworks or profiling applications is supportive. Depending on the technical stacks used in your applications, the decision is various and different from case to case. I hope this post is useful for you.