bug: AppiumFieldDecorator: Memory leak after moving from java-client 8.5.0 to 8.5.1 .... 9.1.0

amedvedjev commented 4 months ago

Do I have the most recent component updates?

[X] I use the most recent available driver/plugin and server versions

Is the component officially supported by the Appium team?

[X] I have verified the component repository is present under the Appium organization in GitHub

Is there an existing issue for this?

[X] I have searched the existing issues

Current Behavior

After increasing java client version from 8.5.0 to 8.5.1 ... 9.1.0 we have a huge memory leak while executing tests. Tests becoming very slow in few minutes.

A bit more details mentioned https://github.com/appium/appium/discussions/18860

Expected Behavior

No memory issues.

Minimal Reproducible Example

have at least 100 tests
execute tests in parallel 5-10
have java client 8.5.1 or higher
have Appium annotations while searching elements

Environment

Operating system: MacOS
Appium server version (output of appium --version): 2.x.x (was reproduced with many including latest)
Last component(s) version which did not exhibit the problem: java-client 8.5.0
Platform and version under test: any ios / android
Real device or emulator/simulator: real

Link to Appium Logs

No response

Further Information

also discussed here https://discuss.appium.io/t/appium-terminating-unexpectedly-not-receiving-commands/40782

valfirst commented 4 months ago

@amedvedjev do you have the project to reproduce the problem?

amedvedjev commented 4 months ago

@valfirst Need to write from zero. All projects I have are private. But bet we can reproduce using one thread/phone. Will try to write with Appium test app.

amedvedjev commented 4 months ago

@mykola-mokhnach @valfirst found easy way to reproduce issue with following test:

public void leaks_page_init() {
    for (int i = 0; i < 200; i++) {
        myApp().homePage().isHomePageLoaded(); // isHomePageLoaded should return new Page()
    }
}

public class MyApp {
    @Getter
    private final Page page;

    public MyApp(Page page) {
        this.page = page;
    }

    public AnimationPage animationPage() {
        return new AnimationPage(page);
    }

    public HomePage homePage() {
        return new HomePage(page);
    }
}

public class HomePage extends BasePage {

    @iOSXCUITFindBy(id = "TBD")
    @AndroidFindBy(uiAutomator = "new UiSelector().text(\"API Demos\")")
    private WebElement mainContainer;

    // header
    // body
    @iOSXCUITFindBy(id = "TBD")
    @AndroidFindBys(value = {
            @AndroidBy(className = "android.widget.ListView"),
            @AndroidBy(className = "android.widget.TextView")
    })
    private List<WebElement> optionItems;
    // footer

    // dialog on first start
    @iOSXCUITFindBy(id = "TBD")
    @AndroidFindBy(uiAutomator = "new UiSelector().text(\"OK\")")
    private WebElement okButton;

    public HomePage(Page page) {
        super(page);
    }

    public boolean isLoaded(int sec) {
        Logger.log("sec: '" + sec + "'");
        return super.isLoaded(mainContainer);
    }

    public HomePage isHomePageLoaded() {
        Assert.assertTrue(isLoaded(-1), createAssertionLog("'HomePage' NOT loaded"));
        return new HomePage(page); // this -> instead of `this` to increase new page numbers created in test
    }
}

public abstract class BasePage extends Base {

    @Getter
    final protected Page page;
    @Getter
    final private AppiumDriver driver;
    @Getter
    final private SoftAssert softAssert;
    final protected static int DEFAULT_WAIT_TIME = 20; // default look for elements
    final protected int DEFAULT_AFTER_TAP_TIME = 150; // msec
    final protected Boolean isIOS;
    final protected Boolean isAndroid;

    @iOSXCUITFindBy(iOSClassChain = "**/XCUIElementTypeKeyboard[1]/**/XCUIElementTypeButton[-1]")
    private WebElement keyBoardLastKey_iOS;

    @iOSXCUITFindBy(id = "TBD")
    @AndroidFindBy(id = "TBD")
    private WebElement someButton;

    public BasePage(Page page) {
        this.page = page;
        this.driver = page.getDriver();
        this.isIOS = page.getIsIOS();
        this.isAndroid = page.getIsAndroid();
        this.softAssert = page.getSoftAssert();
        setDefaultTiming();
    }

    public void setLookTiming(int sec) {
        if (sec == -1) {
            setDefaultTiming();
        } else {
            PageFactory.initElements(new AppiumFieldDecorator(driver, Duration.ofSeconds(sec)), this);
        }
    }

    public void setDefaultTiming() {
        PageFactory.initElements(new AppiumFieldDecorator(driver, Duration.ofSeconds(DEFAULT_WAIT_TIME)), this);
    }

    // override in inherited classes
    public boolean isLoaded(int sec) {
        return false;
    }

    public boolean isLoaded(WebElement el) {
        boolean bool = false;
        try {
            bool = !((RemoteWebElement) el).getId().isEmpty(); // no matter enabled or not
        } catch (Exception e) {
        }
        setDefaultTiming();
        return bool;
    }
}

public class Base {
    // app builds and properties files path
    protected static final String USER_HOME = System.getProperty("user.home");
    protected static final String USER_DIR = System.getProperty("user.dir");
    protected final String APP_PATH = USER_DIR + "/Documents/test/app/";

    public static void sleep(int msec) {
        try {
            Thread.sleep(msec);
        } catch (Exception ignored) {
        }
    }
}

can upload all code to try.

Results on my machine

8.5.0
Execution time: 14sec
java max mem: 170Mb

8.5.1
Execution time: 49sec
java max mem: **880Mb**

9.1.0
Execution time: 50sec
java max mem: **720Mb**

amedvedjev commented 4 months ago

and another with even more simple code:

    for (int i = 0; i < 200; i++) {
        PageFactory.initElements(new AppiumFieldDecorator(page.getDriver(), Duration.ofSeconds(10)), this);
    }

    8.5.0
    java max mem: 80Mb

    8.5.1
    java max mem: 500Mb

mykola-mokhnach commented 4 months ago

I can observe one potential issue there: PageFactory.initElements is expected to only be called once upon object creation. Basically, page objects are supposed to be reusable and should not contain any business logic as their single purpose is to abstract interactions with the UI.

initElements internally goes through all annotated properties of the given instance and replaces them with proxies. These proxies have multiple connections to "external" objects and are very hard to debug as they are constructed in runtime. Which means they might still be kept in memory because of some implicit connections to their parent object even if this object gets replacement proxies. The only guarantee they are cleaned up is when the parent object gets cleaned up.

My advice would be to avoid calling the factory method multiple times on the same object and only have single initElements call in the constructor.

mykola-mokhnach commented 4 months ago

@valfirst Maybe we should explicitly deny such possibility in the decorator...

amedvedjev commented 4 months ago

@mykola-mokhnach it is huge disadvantage of calling initElements only once. In such case the ONLY way to do it is init all pages and use only this object. In my code it is MyApp class. This first problem. Now we need each page make singleton?

Second problem - we want make search of element often more convenient and thus comfortable code below produce leaks

    @Step("Tap optional 'Continue' button")
    public boolean tapOptionalContinue(int sec) {
        Logger.log("sec: '" + sec+ "'");
        setLookTiming(sec);
        boolean result = tap(continueButton);
        setDefaultTiming();
        return result;
    }

Third problem. Why with 8.5.0 and below we did not have such issues?

mykola-mokhnach commented 4 months ago

Now we need each page make singleton?

Not sure why it must be a singleton. The idea is to create a new page every time it needs to be accessed in the UI. Usually this should not happen very often unless the test script constantly switches between different pages.

we want make search of element often more convenient and thus comfortable code below produce leaks

Lets take a look at this code from the detailed perspective.

setLookTiming(sec);

Internally this call would iterate through declared fields of the current object and fields of all inherited superclasses, except of the Object.class and create new proxies for all matching ones, maybe overriding existing values

setDefaultTiming();

would do exactly the same one more time. And that's all is done to simply click one button. Doesn't it look like a bit of an overkill?

Why with 8.5.0 and below we did not have such issues?

I cannot answer this question. Probably because there is some bug, which is hard to spot (or might not be found at all)

I appreciate your efforts in helping people that visit the Appium forum and thus I try to prioritise your issues. Nevertheless my point here is that it makes more sense to fix the obvious issue with the upstream code first.

amedvedjev commented 4 months ago

@mykola-mokhnach thanks for your really great support and work with Appium code! The code with 200 page init is just quick example to replicate issue. With our app we have 430 page objects. All code written mostly like:

   // 100% check on what screen we are before executing any actions
    @Step("Check 'BlockedAccountPage' loaded {sec}")
    public boolean isLoaded(int sec) {
        Logger.log("sec: '" + sec + "'");
        setLookTiming(sec);
        return super.isLoaded(mainContainer);
    }

    public BlockedAccountPage isBlockedAccountPageLoaded() {
        Assert.assertTrue(isLoaded(-1), createAssertionLog("'BlockedAccountPage' NOT loaded"));
        return this;
    }

    @Step("Tap 'Contact us' button")
    public ContactUsPage tapContactUsButton() {
        Logger.log();
        Assert.assertTrue(tap(contactUsButton), createAssertionLog("FAILED"));
        return new ContactUsPage(page);
    }
    // quite lots places
    @Step("Tap optional 'Continue' button")
    public boolean tapOptionalContinue(int sec) {
        Logger.log("sec: '" + sec+ "'");
        setLookTiming(sec);
        boolean result = tap(continueButton);
        setDefaultTiming();
        return result;
    }

   // and when we need check many objects on screen we use fast search to skip them faster if they not exists
    @Step("Get 'Account currency' text")
    public String getAccountCurrencyText() {
        Logger.log();
        setLookTiming(3);
        String result = getText(accountCurrencyText);
        setDefaultTiming();
        return result;
    }

This is all super convenient and you see we use quite lot of timing change to speedup.

As far as now we have a bit more clear picture where issue is I will try to optimise code a bit to eliminate unneeded switches while we already switched into needed time. Will write next week how it helps.

Thanks for any fix / advice how to continue keep code simple and fast!!!

PS some more real statistic I have while executing some test with Demo app

// test itself
    public void leaks() {
        HomePage homePage = myApp().homePage();
        AnimationPage animationPage = myApp().animationPage();

        // skip OK button on first start
        homePage.tapOkButton(2);

        homePage
                .isHomePageLoaded()
                .tapOption(1); // Animation
        for (int j = 0; j < 10; j++) { // repeat same steps 10 times
            for (int i = 0; i < 12; i++) { // open all animation options and return back
                homePage
                        .isHomePageLoaded()
                        .tapOption(i);
                animationPage
                        .isAnimationPageLoaded()
                        .pressKey_Android(AndroidKey.BACK);
            }
        }

        skipRetryAndSoftAssert();
    }

    8.5.0
    Execution time: 233sec
    java max mem: 150Mb
        -> after replace `return this` -> `return new Page()`
        Execution time: 266sec
        java max mem: 160Mb

    8.5.1
    Execution time: 245sec
    java max mem: 200Mb
        -> after replace `return this` -> `return new Page()`
        Execution time: 290sec
        java max mem: 400Mb

    9.1.0
    Execution time: 246sec
    java max mem: 200Mb
        -> after replace `return this` -> `return new Page()`
        Execution time: 277sec
        java max mem: 300Mb

mykola-mokhnach commented 4 months ago

I've spent some fun time debugging the stuff and got https://github.com/appium/java-client/pull/2129 as the result of my efforts. I hope there will be paradise after it's merged. Feel free to test it locally @amedvedjev

mykola-mokhnach commented 4 months ago

@amedvedjev Have you had a chance to verify the patch? Does it make sense to publish a new client version now that includes it?

Auto81 commented 2 weeks ago

Just want to add a thank you here!

I have a (large) test suite that was beginning to push 7Gb of RAM usage by the end of the run, since ByteBuddy was introduced originally.

This fix has reduced that back down to 100Mb

appium / java-client