search

microsoft / playwright

Playwright is a framework for Web Testing and Automation. It allows testing Chromium, Firefox and WebKit with a single API.
https://playwright.dev
Apache License 2.0
66.64k stars 3.65k forks source link

[Bug]: UI seems to lock on Windows making tests time out #30875

Closed pbrzosko closed 3 months ago

pbrzosko commented 5 months ago

Version

1.42.1

Steps to reproduce

  1. Clone my repo at https://github.com/pbrzosko/playwright-lock-issue
  2. Run npm install
  3. Run npm run pw on a Windows machine
  4. Execute tests in the UI

Expected behavior

All tests should run similar amount of time and not time out. Here is a screenshot of them running on OSX: image

Actual behavior

On Windows, it seems like tests are locking each other on some resource. Thus they start to time out and run very slowly: image

Additional context

When run with one worker, it seems to work fine.

Environment

System:
    OS: Windows 10 10.0.19045
    CPU: (24) x64 12th Gen Intel(R) Core(TM) i7-12850HX
    Memory: 6.77 GB / 31.69 GB
  Binaries:
    Node: 18.12.0 - C:\Program Files\nodejs\node.EXE
    npm: 8.19.2 - C:\Program Files\nodejs\npm.CMD
  IDEs:
    VSCode: 1.87.2 - C:\Users\rgzc\AppData\Local\Programs\Microsoft VS Code\bin\code.CMD
  Languages:
    Bash: 5.0.17 - C:\Windows\System32\bash.EXE
  npmPackages:
    @playwright/experimental-ct-vue: ^1.42.1 => 1.42.1
pbrzosko commented 5 months ago

We have checked tracing impact, according to this comment: https://github.com/microsoft/playwright/issues/30629#issuecomment-2091735779, but I am not sure how that changes anything? It just confirms, that writing trace make tests run slower, but it does not explain timeouts for those tests in UI mode:

image

image

yury-s commented 5 months ago

Do you have any new findings since the previous bug was filed? I tried running the suite on windows and was not able to reproduce the issue, here is what I get:

image

The numbers are a higher but not as drastically as in your case:

image

You can try reducing the number of workers in the ui mode. I don't see what action we can take here based on the provided information.

pbrzosko commented 5 months ago

No I don't have anything new. But what I have are tests which run around 1s on OSX regardless whether it is one worker, multiple workers, console or UI mode. Then I have a windows machine where tests run around 1s with single worker in console or UI mode, and then are 5 times slower with multiple workers in the console and 10 times or more slower in the UI. And the problem seem to occur only if we introduce parallel mode. This basically means for us that we can not run tests in parallel for moste of the devs. So this slows down our development and that is an issue for us. Should I concvince my boss that the whole team needs to switch to OSX because otherwise they need to wait 10 times more for tests to finish? You have executed the repo on Windows. Please now check on Linux or OSX and see whether there is a difference.

pbrzosko commented 5 months ago

The processor that we run it on (i7-12850HX) has 16 cores and 24 threads. I have a feeling that this 80% worker setting in playwright is actually either resulting in 16 or more workers. Basically the more workers we have the worse is the issue. So this sounds like a lock problem, right?

If it wasn't then it wouldn't matter If I would use 5 workers or 15 workers - the time increase would be the same because of trace or something else that UI does. Buy this is not the case.

Maybe try to run it on a similar processor.

Not sure though why do I need to try to figure out ways to find the issue?

yury-s commented 5 months ago

Performance difference on Mac for me is similar to Windows (https://github.com/microsoft/playwright/assets/9798949/94dd6273-55a9-4a3e-9877-1d2ec82f3bc8, https://github.com/microsoft/playwright/assets/9798949/9adafec5-6673-4f44-8b9f-5a394e0f0a88) Removing workers: '80%' setting from the config and using the default value makes the tests pass faster actually.

But what I have are tests which run around 1s on OSX regardless whether it is one worker, multiple workers, console or UI mode.

That does not match what I see, on macOS they are also at least 2x slower in parallel mode.

Then I have a windows machine where tests run around 1s with single worker in console or UI mode, and then are 5 times slower with multiple workers in the console and 10 times or more slower in the UI. And the problem seem to occur only if we introduce parallel mode.

Neither me nor @dgozman have been able to reproduce 10x difference, the tests run ~5x slower on Windows in UI mode. This is probably due to difference in the hardware (disk?) and system configuration.

The UI mode is expected to be slower than normal execution. The more parallel workers you run, the more contention that may cause. 10x slow down is too high, but it appears to be specific to your environment which we cannot reproduce locally.

pbrzosko commented 5 months ago

We have tried to narrow down the issue. The only thing we see in the UI that it is the browser setup that takes majority of time - like 9.5s when the test times out at 10. We tried various tools like "Process Monitor" on Windows to see what is happening, but there is not much there. We only see process creating files with trace for the UI. Do you maybe have some hints how can we narrow down the problem? We also did PWTEST_PROFILE_DIR and loaded result files in Chrome Dev Tools - majority of time spent is in idle state of the worker. So seems like it is waiting for something, but I would like to know for what? Do you have some hints?

dgozman commented 5 months ago

@pbrzosko I am not really sure how to help you. Perhaps launching a browser triggers some security checks on your Windows?

We did some general improvements to tracing performance that will be released in v1.45 release. I'll look into windows-specific issues more closely for the next v1.46 release as well.

pbrzosko commented 4 months ago

As a last resort we have gathered profiling data from playwright. Please have a look whether you see something suspicious - I don't see anything :( If not, I think you can close the ticket. profiles_osx_cmd.zip profiles_osx_ui.zip profiles_win_ui.zip profiles_win_cmd.zip

pbrzosko commented 4 months ago

@dgozman did you have a chance to take a look at those profiler files?

dgozman commented 4 months ago

@pbrzosko I looked at some profiles. The most suspicious are some filesystem writes, followed by a lot of "idle". This reinforces my thoughts that filesystem if the bottleneck. Could you try updating to the canary version and see whether anything changes? We've made some improvements in this specific area, but have not released them yet.

pbrzosko commented 4 months ago

hi, it seems like canary version has improved a lot. Tests went down from 15s to 5s. I will check with the developer that had biggest issues tomorrow, and I hope it will be the same. Will get back to you.

pbrzosko commented 4 months ago

So, we seem to have like twice as good performance, as it was. The only issue we see is that when the test fails, there is no timeline data and browser window is empty. I am not sure it is caused by the changes done within this issue: image

version: 1.46.0-alpha-2024-06-19

dgozman commented 4 months ago

So, we seem to have like twice as good performance, as it was.

Excellent!

The only issue we see is that when the test fails, there is no timeline data and browser window is empty. I am not sure it is caused by the changes done within this issue

Could you please file a separate issue with repro steps? There were some unrelated changes around timeline/snapshots, perhaps we can fix this right away.

dgozman commented 3 months ago

After some more testing on Windows, it seems more inline with other OSes, where UI mode is 1.25x-1.5x slower in general due to UI overhead and enabled live tracing. Given the positive improvements above, I'll close this issue as fixed.

Typical performance on Windows

Terminal:

Running 21 tests using 21 workers

  ✓  1 [chromium] › TestComponent.spec.ts:25:7 › TestComponent.vue › Should fill in form 2 (2.2s)
  ✓  2 [chromium] › TestComponent.spec.ts:17:7 › TestComponent.vue › Should fill in form (1.8s)
  ✓  3 [chromium] › TestComponent.spec.ts:41:7 › TestComponent.vue › Should fill in form 6 (1.5s)
  ✓  4 [chromium] › TestComponent.spec.ts:29:7 › TestComponent.vue › Should fill in form 3 (1.6s)
  ✓  5 [chromium] › TestComponent.spec.ts:21:7 › TestComponent.vue › Should fill in form 1 (1.9s)
  ✓  6 [chromium] › TestComponent.spec.ts:33:7 › TestComponent.vue › Should fill in form 4 (1.5s)
  ✓  7 [chromium] › TestComponent.spec.ts:45:7 › TestComponent.vue › Should fill in form 7 (1.6s)
  ✓  8 [chromium] › TestComponent.spec.ts:37:7 › TestComponent.vue › Should fill in form 5 (1.7s)
  ✓  9 [chromium] › TestComponent.spec.ts:57:7 › TestComponent.vue › Should fill in form 10 (1.7s)
  ✓  10 [chromium] › TestComponent.spec.ts:49:7 › TestComponent.vue › Should fill in form 8 (2.4s)
  ✓  11 [chromium] › TestComponent.spec.ts:61:7 › TestComponent.vue › Should fill in form 11 (1.4s)
  ✓  12 [chromium] › TestComponent.spec.ts:69:7 › TestComponent.vue › Should fill in form 13 (2.3s)
  ✓  13 [chromium] › TestComponent.spec.ts:53:7 › TestComponent.vue › Should fill in form 9 (2.3s)
  ✓  14 [chromium] › TestComponent.spec.ts:65:7 › TestComponent.vue › Should fill in form 12 (2.0s)
  ✓  15 [chromium] › TestComponent.spec.ts:81:7 › TestComponent.vue › Should fill in form 16 (2.2s)
  ✓  16 [chromium] › TestComponent.spec.ts:85:7 › TestComponent.vue › Should fill in form 17 (2.2s)
  ✓  17 [chromium] › TestComponent.spec.ts:97:7 › TestComponent.vue › Should fill in form 20 (2.1s)
  ✓  18 [chromium] › TestComponent.spec.ts:77:7 › TestComponent.vue › Should fill in form 15 (2.1s)
  ✓  19 [chromium] › TestComponent.spec.ts:73:7 › TestComponent.vue › Should fill in form 14 (2.1s)
  ✓  20 [chromium] › TestComponent.spec.ts:93:7 › TestComponent.vue › Should fill in form 19 (2.2s)
  ✓  21 [chromium] › TestComponent.spec.ts:89:7 › TestComponent.vue › Should fill in form 18 (2.1s)

  21 passed (4.8s)

UI mode:

Running 21 tests using 21 workers

  ✓  1 [chromium] › TestComponent.spec.ts:17:7 › TestComponent.vue › Should fill in form (3.3s)
  ✓  2 [chromium] › TestComponent.spec.ts:25:7 › TestComponent.vue › Should fill in form 2 (3.7s)
  ✓  3 [chromium] › TestComponent.spec.ts:29:7 › TestComponent.vue › Should fill in form 3 (1.6s)
  ✓  4 [chromium] › TestComponent.spec.ts:37:7 › TestComponent.vue › Should fill in form 5 (3.2s)
  ✓  5 [chromium] › TestComponent.spec.ts:41:7 › TestComponent.vue › Should fill in form 6 (2.4s)
  ✓  6 [chromium] › TestComponent.spec.ts:33:7 › TestComponent.vue › Should fill in form 4 (3.8s)
  ✓  7 [chromium] › TestComponent.spec.ts:21:7 › TestComponent.vue › Should fill in form 1 (3.0s)
  ✓  8 [chromium] › TestComponent.spec.ts:53:7 › TestComponent.vue › Should fill in form 9 (3.8s)
  ✓  9 [chromium] › TestComponent.spec.ts:45:7 › TestComponent.vue › Should fill in form 7 (3.2s)
  ✓  10 [chromium] › TestComponent.spec.ts:57:7 › TestComponent.vue › Should fill in form 10 (1.7s)
  ✓  11 [chromium] › TestComponent.spec.ts:49:7 › TestComponent.vue › Should fill in form 8 (3.8s)
  ✓  12 [chromium] › TestComponent.spec.ts:77:7 › TestComponent.vue › Should fill in form 15 (3.5s)
  ✓  13 [chromium] › TestComponent.spec.ts:69:7 › TestComponent.vue › Should fill in form 13 (3.6s)
  ✓  14 [chromium] › TestComponent.spec.ts:93:7 › TestComponent.vue › Should fill in form 19 (3.4s)
  ✓  15 [chromium] › TestComponent.spec.ts:65:7 › TestComponent.vue › Should fill in form 12 (3.7s)
  ✓  16 [chromium] › TestComponent.spec.ts:81:7 › TestComponent.vue › Should fill in form 16 (3.5s)
  ✓  17 [chromium] › TestComponent.spec.ts:85:7 › TestComponent.vue › Should fill in form 17 (3.6s)
  ✓  18 [chromium] › TestComponent.spec.ts:61:7 › TestComponent.vue › Should fill in form 11 (3.6s)
  ✓  19 [chromium] › TestComponent.spec.ts:89:7 › TestComponent.vue › Should fill in form 18 (3.5s)
  ✓  20 [chromium] › TestComponent.spec.ts:73:7 › TestComponent.vue › Should fill in form 14 (3.4s)
  ✓  21 [chromium] › TestComponent.spec.ts:97:7 › TestComponent.vue › Should fill in form 20 (3.6s)

  21 passed (6.9s)