Application loads collection datasource really slow

Hello guys, I have a problem with a screen that retrieves entities based on a query and displays them in a table with 2 custom columns.

So, in the init method of the screen, I add a CollectionChangeListener that, based on the items currently in the datasource, retrieves some info from the db (this part is tested and for 50 entities, it takes ~0.2 seconds). In this listener, I log when the app enters and exits.

The interesting part comes here: looking in the logger, from when I load the screen until it actually executes the listener, it takes ALOT of time(~300 seconds). In my understanding, after the datasource loads the first batch of entities (50 entities), the CollectionChangeListener executes.

I ran the datasource query separate using JMX console and the query executes relatively fast ~3-4 seconds and retrieves ~14k entities.

The problem here is that it takes about 300 seconds to reach the listener and I can’t understand why this happens.

The frame init method:

@Override
public void init(Map<String, Object> params) {
    super.init(params);

    foodProductsDs.addCollectionChangeListener(e -> {
        Collection<UUID> foodProductIds = new ArrayList<>();
        foodProductIds.addAll(foodProductsDs.getItemIds());
        // logging happens in the productService.getNumberOfPackagedProductsWhichContainFoodProduct method
        numberOfPackagedProductsContainingFoodProduct = productService.getNumberOfPackagedProductsWhichContainFoodProduct(foodProductIds);
    });
}

The datasource query:

select e from fb$FoodProduct e
        inner join scope$Organization_Product op
        on op.to.id = e.id
        and op.from.id = :session$OrgId

This query does its job, so I assume that it isn’t the root of the problem, but I attached it for a better understanding.

At the end of the ready method I add 2 custom columns, but I just strip some information from the entities, so nothing too crazy in here too.

foodProductsTable.addGeneratedColumn("statusColumn", entity -> {
        Label field = (Label) componentsFactory.createComponent(Label.NAME);
        try {
            field.setValue(entity.getStatus().getType().getName());
        } catch (Exception e) {
            field.setValue(" - ");
        }
        return field;
    });

    foodProductsTable.addGeneratedColumn("numberOfPackagedProducts", entity -> {
        Label field = (Label) componentsFactory.createComponent(Label.NAME);
        if (numberOfPackagedProductsContainingFoodProduct.get(entity.getId()) != null)
            field.setValue(numberOfPackagedProductsContainingFoodProduct.get(entity.getId()));
        else
            field.setValue("0");
        return field;
    });

numberOfPackagedProductsContainingFoodProduct is a map that is calculated in the CollectionChangeListener.

I am literally out of solutions and I can see nothing wrong or brutally inefficient in my code.
This issue does not reproduce when I try to reproduce it when application runs on my machine, but happens on the live app, that runs on AWS and communicates with the DB that is hosted on another machine. I know there is some latency when communicating over network but 300 seconds is absurd.

Any input would be greatly appreciated.

Hi,
First, you should enable eclipselink sql logging in production system to get real SQL queries and timings. Maybe it’s actually a slow query.
Logback category and level for eclipselink sql are “eclipselink.sql” - DEBUG.

Second, if it’s possible, you can launch any profiler in production environment to understand where your application spends these 300 seconds.

For example, this is a simple profiling tool: GitHub - aragozin/jvm-tools: Small set of tools for JVM troublshooting, monitoring and profiling. (stcap + ssa).
Another way is to write a scheduled task inside the application which can be launched periodically to print thread dump to a file (or to a log).
This JMX bean is used to get thread dump: java.lang.management.ThreadMXBean.

Regards,

2 Likes

Thanks for the quick reply!

I’ve managed to figure out the issue. It seems that if a table has columns that contain properties that are not fetched by the datasource’s view the app will manually make individual queries to fetch that property for each and every property that’s missing.

The 300 seconds time has been reduced significantly to 3-4 seconds after some tweaks in the view of the datasource.