Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Working with 1.18 with 2 playwrights when the 2 object gets closed it throws HeapSpace #827

Closed
cortizcuellar opened this issue Feb 25, 2022 · 20 comments
Labels

Comments

@cortizcuellar
Copy link

Here is the info

https://stackoverflow.com/questions/71242763/java-playwright-throws-java-lang-outofmemoryerror-java-heap-space-closing-a-pla?noredirect=1

And when we connect to a wsEndPoint the problem arises when we try to close Page and Browser objects but not with Playwright object as you can see here.

20:39:13.279 [Thread-16] WARN  c.p.h.HeadlessBrowserConfig$DataPerThread.close(219) - Closing [PageImpl] object:[838546035].
java.io.IOException: Stream closed
	at java.lang.ProcessBuilder$NullOutputStream.write(ProcessBuilder.java:433)
	at java.io.OutputStream.write(OutputStream.java:116)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	at com.microsoft.playwright.impl.WriterThread.run(PipeTransport.java:167)
java.io.IOException: Stream closed
	at java.lang.ProcessBuilder$NullOutputStream.write(ProcessBuilder.java:433)
	at java.io.OutputStream.write(OutputStream.java:116)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	at java.io.FilterOutputStream.close(FilterOutputStream.java:158)
	at com.microsoft.playwright.impl.PipeTransport.close(PipeTransport.java:93)
	at com.microsoft.playwright.impl.PipeTransport.poll(PipeTransport.java:71)
	at com.microsoft.playwright.impl.Connection.processOneMessage(Connection.java:159)
	at com.microsoft.playwright.impl.ChannelOwner.runUntil(ChannelOwner.java:101)
	at com.microsoft.playwright.impl.Connection.sendMessage(Connection.java:107)
	at com.microsoft.playwright.impl.ChannelOwner.sendMessage(ChannelOwner.java:94)
	at com.microsoft.playwright.impl.JsonPipe.send(JsonPipe.java:46)
	at com.microsoft.playwright.impl.Connection.internalSendMessage(Connection.java:135)
	at com.microsoft.playwright.impl.Connection.sendMessageAsync(Connection.java:111)
	at com.microsoft.playwright.impl.Connection.sendMessage(Connection.java:107)
	at com.microsoft.playwright.impl.ChannelOwner.sendMessage(ChannelOwner.java:94)
	at com.microsoft.playwright.impl.PageImpl.close(PageImpl.java:547)
	at com.microsoft.playwright.Page.close(Page.java:3237)
20:39:13.321 [Thread-16] WARN  c.p.h.HeadlessBrowserConfig$DataPerThread.close(223) - Exception [Failed to read message from driver, pipe closed.]Closing [PageImpl] object:[838546035].

@yury-s
Copy link
Member

yury-s commented Feb 28, 2022

You are running out of memory, looks like the machine doesn't have enough memory to run multiple playwrights on it. If you still think this is a bug in the playwright please provide a repro that we could run locally.

@yury-s yury-s closed this as completed Feb 28, 2022
@yury-s yury-s reopened this Feb 28, 2022
@cortizcuellar
Copy link
Author

I am running with -Xms3g -Xmx3g when the shutdown is call i am using like 800 mb later the Out of memory exception is thrown when i call shutdown on the second playwright i will test this the same scenario with more memory.

@cortizcuellar
Copy link
Author

Running with -Xms20g -Xmx20g with connecting to a wsEndPoint Browserless in this case. When trying to close Page object it throws

19:15:42.135 [Thread-16] DEBUG c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(220) - Page [2117799917] is closed [false] browser is connected:[true].
19:15:42.136 [Thread-16] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(238) - Closing [PageImpl] object:[2117799917].
java.io.IOException: Stream closed
	at java.lang.ProcessBuilder$NullOutputStream.write(ProcessBuilder.java:433)
	at java.io.OutputStream.write(OutputStream.java:116)
	at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
	at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
	at com.microsoft.playwright.impl.WriterThread.run(PipeTransport.java:167)

20 GB is a lot of memory.
Any clue.

@yury-s
Copy link
Member

yury-s commented Mar 2, 2022

Can you share a repro that we could run locally?

@cortizcuellar
Copy link
Author

Can you share a repro that we could run locally?

I will try that today mate. :)

@cortizcuellar
Copy link
Author

When running the process with 20G of ram memory the 2 page object it hangs the process as you can see here it takes more than 10 minutes hang i have try even longer 2 or 3 hours and continues hanged.
You can see in the top of the image the arguments at Java process.
image

08:23:03.458 [Thread-13] WARN  c.p.w.ProxyConfigServiceImpl.shutdown(223) - HeadlessBrowserConfig:[1092398950]
08:23:03.462 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig.shutdown(388) - Closing resources[Start] in headlessBrowser [1092398950] object
08:23:03.462 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(219) - Shutdown process start at [269559688] with thread:[Thread-13].
08:23:03.463 [Thread-13] DEBUG c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(222) - Page [1641736644] is closed [false] browser is connected:[true].
08:23:03.463 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(240) - Closing [PageImpl] object:[1641736644] with free memory:[16071.636199951172].
08:23:03.474 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(244) - Closed [PageImpl] object:[1641736644]. Free---->16071.636199951172 [MB] took:[6] ms.
08:23:03.474 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(240) - Closing [BrowserImpl] object:[184488816] with free memory:[16071.636199951172].
08:23:03.474 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(244) - Closed [BrowserImpl] object:[184488816]. Free---->16071.636199951172 [MB] took:[0] ms.
08:23:03.474 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(240) - Closing [PlaywrightImpl] object:[1288055767] with free memory:[16071.636199951172].
08:23:03.713 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(244) - Closed [PlaywrightImpl] object:[1288055767]. Free---->15754.336112976074 [MB] took:[233] ms.
08:23:03.713 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(230) - Shutdown process end at [269559688] with thread:[Thread-13].
08:23:03.722 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(219) - Shutdown process start at [993683470] with thread:[Thread-13].
08:23:03.722 [Thread-13] DEBUG c.p.h.HeadlessBrowserConfig$DataPerThread.shutdown(222) - Page [1522931126] is closed [false] browser is connected:[true].
08:23:03.723 [Thread-13] INFO  c.p.h.HeadlessBrowserConfig$DataPerThread.close(240) - Closing [PageImpl] object:[1522931126] with free memory:[15754.336112976074].

As you can see the times of closing the 1 bunch of objects is just like **0 ms or 6 ms** the problem arises when we try the close the  objects created at 2 thread

Thanks a lot and God bless.


@cortizcuellar
Copy link
Author

cortizcuellar commented Mar 3, 2022

If i run with flag -XX:+PrintGCDetails i can see next and immediately after the call to the 2 Page object shutdown method the message

[GC (Allocation Failure) [PSYoungGen: 4633312K->67619K(6116864K)] 4682338K->1909903K(20098048K), 0.6676778 secs] [Times: user=1.06 sys=0.36, real=0.67 secs]

image

Using -XX:+UseG1GC the problem continues closes the first Page and hangs and first browser Object shutdown
image

image

Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for windows-amd64 JRE (1.8.0_181-b13), built on Jul  7 2018 04:01:33 by "java_re" with MS VC++ 10.0 (VS2010)
Memory: 4k page, physical 66829096k(43322092k free), swap 87632988k(48322016k free)
CommandLine flags: -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=21474836480 -XX:MaxHeapSize=21474836480 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockCommercialFeatures -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:-UseLargePagesIndividualAllocation -XX:+UseParallelGC 
4.555: [GC (Metadata GC Threshold) [PSYoungGen: 3460646K->54963K(6116864K)] 3460646K->55051K(20098048K), 0.0298597 secs] [Times: user=0.14 sys=0.00, real=0.03 secs] 
4.585: [Full GC (Metadata GC Threshold) [PSYoungGen: 54963K->0K(6116864K)] [ParOldGen: 88K->51554K(13981184K)] 55051K->51554K(20098048K), [Metaspace: 21074K->21074K(1067008K)], 0.0419001 secs] [Times: user=0.31 sys=0.06, real=0.04 secs] 
5.665: [GC (Metadata GC Threshold) [PSYoungGen: 562473K->15549K(6116864K)] 614028K->67112K(20098048K), 0.0115794 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
5.677: [Full GC (Metadata GC Threshold) [PSYoungGen: 15549K->0K(6116864K)] [ParOldGen: 51562K->24900K(13981184K)] 67112K->24900K(20098048K), [Metaspace: 34762K->34762K(1079296K)], 0.0278415 secs] [Times: user=0.09 sys=0.00, real=0.03 secs] 
9.262: [GC (Metadata GC Threshold) [PSYoungGen: 592661K->37509K(6116864K)] 617561K->62456K(20098048K), 0.0122229 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
9.275: [Full GC (Metadata GC Threshold) [PSYoungGen: 37509K->0K(6116864K)] [ParOldGen: 24947K->49005K(13981184K)] 62456K->49005K(20098048K), [Metaspace: 58039K->58039K(1099776K)], 0.1155353 secs] [Times: user=0.47 sys=0.01, real=0.12 secs] 
225.878: [GC (Allocation Failure) [PSYoungGen: 5076063K->67377K(6116864K)] 5125069K->1909648K(20098048K), 0.6868276 secs] [Times: user=1.45 sys=0.36, real=0.68 secs] 

@cortizcuellar
Copy link
Author

Strangely inside IntellijIdea applying System.exit(0) with 10 playwrights with -Xmx:5g works like a charm. I will dive more on this.

image

@cortizcuellar
Copy link
Author

cortizcuellar commented Mar 15, 2022

I can reproduce with this sample of course the running code is harder and better designed but i think will reproduce it..

import com.microsoft.playwright.Browser;
import com.microsoft.playwright.BrowserType;
import com.microsoft.playwright.Page;
import com.microsoft.playwright.Playwright;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.util.ArrayList;
import java.util.Arrays;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

public class StreamClosed{

    private final List<DataPerThread>dataPerThreads = new ArrayList<>();

    private final CountDownLatch latch = new CountDownLatch(5);

    private static final double MB_VALUE = 1024 * 1024;

    private final List<String> urls = new ArrayList<>();//will be using only one in all 5 threads for the sake of simplicity

	interface ShutdownEvent {
		void shutdown();
	}

    public static void main(String[] args) throws Exception{
        final StreamClosed clazz = new StreamClosed();
        final Runnable hook = ()->clazz.dataPerThreads.forEach(DataPerThread::shutdown);//CTRL + C WAS PRESSED
        Runtime.getRuntime().addShutdownHook(new Thread(hook));
        ExecutorService service = Executors.newFixedThreadPool(5);
        for(final String url:clazz.urls){
            final ThreadCaller thread = clazz.new ThreadCaller("http://myexternalip.com/raw");
            System.out.println("Send work with thread: "+thread.getName());
            service.execute(thread);
        }
        clazz.waitForChildThreadsToComplete();
        service.shutdown();
        service.shutdownNow();
        System.out.println("Ends....");
        try {
            Thread.sleep(240_000);
            clazz.dataPerThreads.forEach(DataPerThread::shutdown);//IF HERE NOT CTRL+C WAS PRESSED
        }catch (final Exception e){
            e.printStackTrace();
        }
    }

    protected void waitForChildThreadsToComplete() {
        try {
            latch.await();
            System.out.println("All child threads have completed.");
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    private final class ThreadCaller extends Thread{
        private final String url;

        public ThreadCaller(final String url) {
            this.url = url;
        }

        @Override
        public void run() {
            new DataPerThread(url).run();
        }
    }

    private final class DataPerThread implements ShutdownEvent,Runnable {
        protected final Logger LOGGER = LoggerFactory.getLogger(DataPerThread.class);

        private final Playwright playwright;

        private final String url;
        private final BrowserType browserType;
        private Browser browser;
        private Page page;
        private final int playwrightHashCode;

        public DataPerThread(final String url) {
            LOGGER.info("Building DataPerThreadObject for Thread:[{}]",Thread.currentThread().getName());
            LOGGER.info("Creating playwright with thread [{}].",Thread.currentThread().getName());
            final long startPlayWright = System.currentTimeMillis();
            this.url = url;
            this.playwright = Playwright.create();
            dataPerThreads.add(this);
            this.playwrightHashCode = System.identityHashCode(this.playwright);
            LOGGER.info("Working with Playwright:[{}] took:[{}] ms.",this.playwrightHashCode,(System.currentTimeMillis()-startPlayWright));
            LOGGER.debug("Creating browserType [{}]",this.playwrightHashCode);
            final long creatingBrowsersInfo = System.currentTimeMillis();
            this.browserType = playwright.chromium();
            LOGGER.debug("Created browserType [{}] with Playwright:[{}]",System.identityHashCode(this.browserType),this.playwrightHashCode);
            fillPlayWrightProxy();
            LOGGER.info("Working with browsers objects :[{}] with Playwright [{}] took:[{}] ms.",System.identityHashCode(browserType),playwrightHashCode,(System.currentTimeMillis()-creatingBrowsersInfo));
            LOGGER.info("Builded DataPerThreadObject [{}] for Thread:[{}]",System.identityHashCode(this),Thread.currentThread().getName());
        }

        @Override
        public void run() {
            System.out.println("Connecting to: "+url+" with Thread:[{}]"+Thread.currentThread().getName());
            try {
                System.out.println("Requesting: "+url+" with page: "+(System.identityHashCode(page)));
                System.out.println(page.navigate(url).body().length);
            }catch(final Exception e){
                System.out.println(e.getLocalizedMessage());
            }
            latch.countDown();
            System.out.println("Left: "+latch.getCount());
        }

        private void fillPlayWrightProxy(){
            LOGGER.info("BrowserType: [{}]",System.identityHashCode(browserType));
            this.browser = browserType.connect("wss://chrome.browserless.io/playwright?token="+token);
            LOGGER.debug("Created pageProvider [{}] with BrowserType:[{}]",System.identityHashCode(this.browser),System.identityHashCode(this.browserType));
            this.page = newPage();
        }

        private Page newPage(){
            LOGGER.debug("Trying to open page with Playwright Object:[{}]",playwrightHashCode);
            final long start = System.currentTimeMillis();
            final Page localPage = this.browser.newPage();
            localPage.onClose(this::onClosePage);
            final long end = System.currentTimeMillis();
            LOGGER.debug("Building page [{}] for thread [{}] with playwright: [{}] took {} ms.",System.identityHashCode(localPage),Thread.currentThread().getName(),playwrightHashCode,(end - start));
            return localPage;
        }

        private void onClosePage(final Page page){
            LOGGER.debug("Page [{}] will be closed shutDownProcess started:[{}].",System.identityHashCode(page),false);
        }

        @Override
        public void shutdown() {
            final String threadName = Thread.currentThread().getName();
            final long hashcode = System.identityHashCode(this);
            LOGGER.info("Shutdown process start at [{}] with thread:[{}].",hashcode,threadName);
            final boolean pageIsClosed = page.isClosed();
            final boolean browserIsConnected = browser.isConnected();
            LOGGER.debug("Page [{}] is closed [{}] browser is connected:[{}] browserContext:[{}].",System.identityHashCode(page),pageIsClosed,browserIsConnected,System.identityHashCode(page.context()));
            if(!pageIsClosed && browserIsConnected){
                close(page);
            }
            if(browserIsConnected){
                close(browser);
            }
            close(playwright);
            LOGGER.info("Shutdown process end at [{}] with thread:[{}].",hashcode,threadName);
        }

        private double getFreeMemory(){
            return Runtime.getRuntime().freeMemory() / MB_VALUE;
        }

        private DataPerThread close(final AutoCloseable closeable){
            if(closeable == null){
                return this;
            }
            final String className = closeable.getClass().getSimpleName();
            final int hashcode = closeable.hashCode();
            try{
                LOGGER.info("Closing [{}] object:[{}] with free memory:[{}] MB.",className,hashcode,getFreeMemory());
                final long startTime = System.currentTimeMillis();
                closeable.close();
                final long endTime = System.currentTimeMillis();
                LOGGER.info("Closed [{}] object:[{}]. Free---->{} [MB] took:[{}] ms.",className,hashcode,getFreeMemory(),(endTime-startTime));
            }catch(final Exception e){
                LOGGER.warn("Exception [{}]Closing [{}] object:[{}].",e.getLocalizedMessage(),className,hashcode);
            }
            return this;
        }
    }
}

With 3GB and pressing [Ctrl+C] in sleep it throws
image

With 35 GB it hangs forever after [Ctrl+C].

image

@yury-s
Copy link
Member

yury-s commented Mar 15, 2022

Does it reproduce with local browsers instead of browserless ?

@cortizcuellar
Copy link
Author

Does it reproduce with local browsers instead of browserless ?

I will let you know tomorrow :)

@cortizcuellar
Copy link
Author

cortizcuellar commented Mar 17, 2022

In the previous snippet i was using browserless not using Browserless i mean instead of using

this.browser = browserType.connect("wss://chrome.browserless.io/playwright?token="+token);

Using

this.browser = browserType.launch();

With 3GB of ram it closes Page + Browser object but it throws heap closing the 1 playwright object.

image

Trying to understand the dump i see something like this.

image
image

With 35 GB it hangs closing the page of the second thread.

image

Please note that when the shutdown process started is the Thread-0 is the thread i think that will kill Java process.

As you can see in the code i put a .sleep this is mainly for see what happens when a Ctrl+C is call or if not how behave the code when a the regular flow is not interrupted.

If not CTRL+C is not pressed and the code flows normally even with 3GB of ram it closes Smoothly. As you can see here the thread is main instead of Thread-0

image

It seems it have what to do which Thread closes the objects :(

After all the work is done and calling System.exit(0); even on a 1GB ram it works smoothly even with [Thread-1]

image

It seems that playwright is suffering when Ctrl+C is call/pressed or when AWS shutdowns the machine killing the Java process

@yury-s
Copy link
Member

yury-s commented Mar 17, 2022

Try running it with BROWSER=pw:channel (and DEBUG=pw:browser if that doesn't give enough info) and see what messages are flowing from the driver to the client. My hunch is that the close operation may take longer (especially on Windows) because we try to delete some temp files and that takes a while. While this is happening, the playwright client may keep receiving events from the driver without being able to process them.

@cortizcuellar
Copy link
Author

Try running it with BROWSER=pw:channel (and DEBUG=pw:browser if that doesn't give enough info) and see what messages are flowing from the driver to the client. My hunch is that the close operation may take longer (especially on Windows) because we try to delete some temp files and that takes a while. While this is happening, the playwright client may keep receiving events from the driver without being able to process them.

Are this system properties o maven commands? we are using gradle..

@yury-s
Copy link
Member

yury-s commented Mar 18, 2022

Are this system properties o maven commands? we are using gradle..

These are environment variables.

@cortizcuellar
Copy link
Author

Are this system properties o maven commands? we are using gradle..

These are environment variables.

I will do this mate and i will let you my kid is in the hospital :(

@cortizcuellar
Copy link
Author

With 3GB ram OutOfMemoryException
image
With 10GB RAM OutOfMemoryException
image
With 15GB ram it hangs closing the page of the second thread.
image

@cortizcuellar
Copy link
Author

With Environment variables set.

@mxschmitt
Copy link
Member

mxschmitt commented May 30, 2022

We fixed a related bug in 1.22, could you try to reproduce it there? I'm closing it in the mean time, since its most likely fixed.

Please file a new issue if you still encounter such issues with a new repro, thanks, appreciate the effort!

@cortizcuellar
Copy link
Author

Hey mate with the latest Playwright version it works. 1.25 :)
image

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants