Deadlock: Multi-VU many iterations

[ankur22]

While running the following test script:

Test script

import { check } from 'k6';
import { browser } from 'k6/experimental/browser';

export const options = {
  scenarios: {
    ui: {
      executor: 'shared-iterations',
      vus: 5,
      iterations: 1000,
      maxDuration: '40m',
      options: {
        browser: {
          type: 'chromium',
        },
      },
    },
  },
  thresholds: {
    checks: ["rate==1.0"]
  }
}

export default async function () {
  const context = browser.newContext();
  const page = context.newPage();

  try {
    // Goto front page, find login link and click it
    await page.goto('https://test.k6.io/', { waitUntil: 'networkidle' });
    await Promise.all([
      page.waitForNavigation(),
      page.locator('a[href="/my_messages.php"]').click(),
    ]);
    // Enter login credentials and login
    page.locator('input[name="login"]').type('admin');
    page.locator('input[name="password"]').type('123');
    // We expect the form submission to trigger a navigation, so to prevent a
    // race condition, setup a waiter concurrently while waiting for the click
    // to resolve.
    await Promise.all([
      page.waitForNavigation(),
      page.locator('input[type="submit"]').click(),
    ]);
    check(page, {
      'header': page.locator('h2').textContent() == 'Welcome, admin!',
    });
  } finally {
    page.close();
  }
}

The test has to be aborted since it goes over the 40m limit. Investigate why this happens and resolve it.

This is the screenshot of the dashboard of the test run. It would seem that all but one of the VUs completed all the allotted iterations. One vu was stuck in a deadlock, which meant the test run was waiting for it to complete the iteration, which it never did, that eventually resulted in an abort.

---

Tasks

Beta Give feedback

1. Collect every instance of this issue occurring
2. Investigate the root cause
3. Fix
4. Test
5. Polish
6. Retest
7. Fix Multi VU deadlock by isolating browser contexts #1219
   browser context bug internal optimization performance remote +6
   

[ankur22]

Investigation

After profiling we found that the issue was related to evaluating the page hide when page.close is called. Looking at the stack trace of the live goroutines, it became evident that it wasn't a traditional deadlock, but rather a stuck asynchronous process waiting for a response from the chrome browser.

My theory was that at a certain point when chrome is under a lot of load, it stops responding to CDP requests and that is why we get timeouts in navigations and new page creations. I tested this theory by setting the timeout to one that is longer than the max test duration. Unfortunately, chrome does respond to these events but it just takes longer for it to do so.

As of now, we're unable to to identify the root cause, and we can only guess that:

1. We're not receiving the response from chrome for an unknown reason;
2. In some cases a response it's valid for chrome not to respond to evaluate CDP requests (especially ones where there is no expected return value);
3. We receive the response but it slips through the filters possibly due to it being malformed or structured differently to what we expect.

The current workaround for this "deadlock" issue is to have a timeout, but it doesn't help solve the root problem.

Unrelated find #1

Unrelated to this current issue, we also found that logging the goroutine ids were taking a lot of time (pprof), and so we removed this step completely in #977.

Unrelated find #2

While working on this theory, I was also able to determine that the compute resources given to the remote chrome instance affects the test (see full investigation results here). We need to ensure that the compute resources for all components are appropriately set so that non of them over utilise the compute resources, which will affect the outcome and make results inconclusive.

[ankur22]

A temporary fix can be found in #979.

[inancgumus]

Could there be a race in handling iteration events? 🤔

From the stack trace, it seems like both page.Close and closing/disconnecting from of the browser happens concurrently.

goroutine 56 [select]:
github.com/grafana/xk6-browser/common.(*Browser).Close(0xc00067bc80)
	github.com/grafana/xk6-browser@v1.0.0-rc0.0.20230711104523-a8ebe8cc24f6/common/browser.go:464 +0x313
github.com/grafana/xk6-browser/browser.(*browserRegistry).deleteBrowser(0xc001cb2c80, 0xc001cb2840?)
	github.com/grafana/xk6-browser@v1.0.0-rc0.0.20230711104523-a8ebe8cc24f6/browser/registry.go:310 +0x9c
github.com/grafana/xk6-browser/browser.(*browserRegistry).handleIterEvents(0xc001cb2c80, 0x1a0fea0?, 0xc001480d80)
	github.com/grafana/xk6-browser@v1.0.0-rc0.0.20230711104523-a8ebe8cc24f6/browser/registry.go:269 +0x1c5
created by github.com/grafana/xk6-browser/browser.newBrowserRegistry
	github.com/grafana/xk6-browser@v1.0.0-rc0.0.20230711104523-a8ebe8cc24f6/browser/registry.go:219 +0x311

I haven't looked into this deeply, just guessing. So please take it with a grain of salt.

cc: @ankur22 @ka3de

[ankur22]

From the stack trace, it seems like both page.Close and closing of the browser happens concurrently.

When running this test, it was running 5 VUs, so it's likely an iteration finishing on one VU, and a page.close occurring on a different VU.

[inancgumus]

Right. But, in the meantime, might we be closing/(update: or disconnecting from) the browser and this might be racing with page.Close? It's surprising to me that it occurs only on pagehide. I think it should happen elsewhere too. Why does it only happen there? :)

[ankur22]

Right. But, in the meantime, might we be closing the browser and this might be racing with page.Close? It's weird that it occurs only on pagehide. It should happen elsewhere too. Why only there? :)

I don't have the answer for why it's occurring in this scenario, I was hoping that it was due to the overloaded chrome instance, however other APIs (such as page.goto) they eventually receive a response when the default timeout is set very high, which would mean that chrome does indeed respond to CDP requests when it is under heavy load, and doesn't drop messages.

When the evaluate on pagehide event blocks waiting on the response from chrome, that VU is stuck indefinitely, and it's stuck on the "main thread" of that VU, putting a pause on the whole underlying JS event loop. At this point even if k6 were to signal an iterEnd, the stuck VU wouldn't be able to handle it. So I can't see how there could be a race condition between the browser closing and page closing 🤔

If the browser for that stuck VU were to close, wouldn't we get an error suggesting that the remote host closed the connection?

Actually, the browser shouldn't be closed since this was running against a remote browser 🤔 Actually, it's expected. It won't actually close the remote chrome instance.

[inancgumus]

It seems we need to look deeper into this issue since you have very good points and I don't have the best answer at this moment :(

[ankur22]

After working with this fix against a remote chrome instance, we've now been able to reproduce the issue with page.goto as well as with the evaluate on page.close. We did this by setting the page's defaultTimeout to a very high value (30mins), which confirmed the VU deadlocks waiting for a response from chrome. When the timeouts are left at 30secs, the timeouts occur as expected and we do not see deadlocks. As far as I can tell this still leaves us with the these possibilities for the root cause of the problem:

1. Chrome isn't returning a response for some of these CDP requests.
2. Chrome is returning a malformed request which we're not propagating to all listening handlers. I've looked at the code and it seems to be set up correctly here to catch malformed responses and seems to forward all other msgs correctly to all listening handlers.
3. We have a deadlock somewhere in xk6-browser.

One more point to make is that the remote chrome instances were not under a lot of load.

[inancgumus]

Fixed by #1219.