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

Integration tests stalled in Emmet tests #162295

Closed
deepak1556 opened this issue Sep 29, 2022 · 11 comments
Closed

Integration tests stalled in Emmet tests #162295

deepak1556 opened this issue Sep 29, 2022 · 11 comments
Assignees
Labels
bug Issue identified by VS Code Team member as probable bug emmet Emmet related issues integration-test-failure
Milestone

Comments

@deepak1556
Copy link
Collaborator

deepak1556 commented Sep 29, 2022

Refs https://dev.azure.com/monacotools/Monaco/_build/results?buildId=187079&view=results

2022-09-28T22:46:42.9418800Z �[0m  Tests for Expand Abbreviations (HTML)�[0m
2022-09-28T22:46:49.4683010Z [perf] Renderer reported VERY LONG TASK (2036ms), starting auto profiling session 'd3084e04-0003-4aa9-981d-e0f0c05fa75d'
2022-09-28T22:46:49.4856210Z �[90m[main 2022-09-28T22:46:49.479Z]�[0m UtilityProcess<1>: Enabling inspect port on extension host with pid 50077.
2022-09-28T22:46:49.5367540Z �[90m[main 2022-09-28T22:46:49.529Z]�[0m UtilityProcess<1>: Enabling inspect port on extension host with pid 50077.
2022-09-28T22:46:50.3958730Z �[93m[main 2022-09-28T22:46:50.386Z]�[0m [perf] started to EXPECT frequent heartbeat d3084e04-0003-4aa9-981d-e0f0c05fa75d
2022-09-28T22:46:50.9614880Z UNRESPONSIVE extension host: received responsive event and cancelling profiling session
2022-09-28T22:46:50.9724740Z �[93m[main 2022-09-28T22:46:50.954Z]�[0m [perf] MISSED heartbeat, trying to profile renderer d3084e04-0003-4aa9-981d-e0f0c05fa75d
2022-09-28T22:47:06.1583430Z �[93m[main 2022-09-28T22:47:06.156Z]�[0m [perf] profiling STARTED d3084e04-0003-4aa9-981d-e0f0c05fa75d
2022-09-28T22:47:07.4028550Z UNRESPONSIVE extension host: starting to profile NOW
2022-09-28T22:47:08.1738560Z   �[32m  ✔�[0m�[90m Expand snippets (HTML)�[0m�[31m (25192ms)�[0m
2022-09-28T22:47:09.6954890Z   �[32m  ✔�[0m�[90m Expand snippets in completion list (HTML)�[0m�[31m (1023ms)�[0m
2022-09-28T22:47:11.0071160Z [perf] STOPPING to send heartbeat
2022-09-28T22:47:12.4051350Z �[93m[main 2022-09-28T22:47:12.396Z]�[0m [perf] profiling DONE d3084e04-0003-4aa9-981d-e0f0c05fa75d
2022-09-28T22:47:12.9398800Z �[90m[main 2022-09-28T22:47:12.934Z]�[0m [perf] stored profile to DISK d3084e04-0003-4aa9-981d-e0f0c05fa75d /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/renderer-profile-1664405232398.cpuprofile
2022-09-28T22:47:13.0658290Z {
2022-09-28T22:47:13.0768040Z   sessionId: 'd3084e04-0003-4aa9-981d-e0f0c05fa75d',
2022-09-28T22:47:13.0879820Z   selfTime: 750.746,
2022-09-28T22:47:13.0989190Z   totalTime: 750.746,
2022-09-28T22:47:13.1093680Z   functionName: '(program)',
2022-09-28T22:47:13.1199470Z   callstack: '#(program)@-1:-1\n#(root)@-1:-1'
2022-09-28T22:47:13.1298670Z }
2022-09-28T22:47:13.1402610Z {
2022-09-28T22:47:13.1509000Z   sessionId: 'd3084e04-0003-4aa9-981d-e0f0c05fa75d',
2022-09-28T22:47:13.1609770Z   selfTime: 581.076,
2022-09-28T22:47:13.1713690Z   totalTime: 581.076,
2022-09-28T22:47:13.1825720Z   functionName: '(garbage collector)',
2022-09-28T22:47:13.1830630Z   callstack: '#(garbage collector)@-1:-1\n#(root)@-1:-1'
2022-09-28T22:47:13.1932380Z }
2022-09-28T22:47:13.2036110Z {
2022-09-28T22:47:13.2144180Z   sessionId: 'd3084e04-0003-4aa9-981d-e0f0c05fa75d',
2022-09-28T22:47:13.2243610Z   selfTime: 213.143,
2022-09-28T22:47:13.2347760Z   totalTime: 213.143,
2022-09-28T22:47:13.2453790Z   functionName: '(idle)',
2022-09-28T22:47:13.2560090Z   callstack: '#(idle)@-1:-1\n#(root)@-1:-1'
2022-09-28T22:47:13.2664270Z }
2022-09-28T22:47:13.2772190Z {
2022-09-28T22:47:13.2878330Z   sessionId: 'd3084e04-0003-4aa9-981d-e0f0c05fa75d',
2022-09-28T22:47:13.2982680Z   selfTime: 206.304,
2022-09-28T22:47:13.3086850Z   totalTime: 206.304,
2022-09-28T22:47:13.3201990Z   functionName: '_reveal',
2022-09-28T22:47:13.3317790Z   callstack: 'piiRemoved/workbench.desktop.main.js#_reveal@137:1137\n' +
2022-09-28T22:47:13.3425990Z     'piiRemoved/workbench.desktop.main.js#reveal@137:1070\n' +
2022-09-28T22:47:13.3532960Z     'piiRemoved/workbench.desktop.main.js#G@2142:38723\n' +
2022-09-28T22:47:13.3639620Z     'piiRemoved/workbench.desktop.main.js#invoke@82:126\n' +
2022-09-28T22:47:13.3740620Z     'piiRemoved/workbench.desktop.main.js#deliver@82:2193\n' +
2022-09-28T22:47:13.3842060Z     'piiRemoved/workbench.desktop.main.js#fire@82:1637\n' +
2022-09-28T22:47:13.3847090Z     'piiRemoved/workbench.desktop.main.js#@1985:16026\n' +
2022-09-28T22:47:13.3953650Z     'piiRemoved/workbench.desktop.main.js#invoke@82:126\n' +
2022-09-28T22:47:13.4134390Z     'piiRemoved/workbench.desktop.main.js#deliver@82:2193\n' +
2022-09-28T22:47:13.4246450Z     'piiRemoved/workbench.desktop.main.js#fire@82:1637\n' +
2022-09-28T22:47:13.4359590Z     'piiRemoved/workbench.desktop.main.js#_setOutlineModel@1985:23052\n' +
2022-09-28T22:47:13.4364420Z     'piiRemoved/workbench.desktop.main.js#_createOutline@1985:20534\n' +
2022-09-28T22:47:13.4461760Z     '#(root)@-1:-1'
2022-09-28T22:47:13.4571230Z }
2022-09-28T22:47:13.4673140Z {
2022-09-28T22:47:13.4785480Z   sessionId: 'd3084e04-0003-4aa9-981d-e0f0c05fa75d',
2022-09-28T22:47:13.4888270Z   selfTime: 154.696,
2022-09-28T22:47:13.4989310Z   totalTime: 154.696,
2022-09-28T22:47:13.5133970Z   functionName: '_reveal',
2022-09-28T22:47:13.5235160Z   callstack: 'piiRemoved/workbench.desktop.main.js#_reveal@137:1137\n' +
2022-09-28T22:47:13.5291850Z     'piiRemoved/workbench.desktop.main.js#reveal@137:1070\n' +
2022-09-28T22:47:13.5406550Z     'piiRemoved/workbench.desktop.main.js#G@2142:38723\n' +
2022-09-28T22:47:13.5525560Z     'piiRemoved/workbench.desktop.main.js#update@2142:37963\n' +
2022-09-28T22:47:13.5634640Z     'piiRemoved/workbench.desktop.main.js#handleOpenedEditors@2870:11265\n' +
2022-09-28T22:47:13.5744010Z     'piiRemoved/workbench.desktop.main.js#openEditor@2870:11173\n' +
2022-09-28T22:47:13.5854390Z     'piiRemoved/workbench.desktop.main.js#doShowEditor@2963:16746\n' +
2022-09-28T22:47:13.5970880Z     'piiRemoved/workbench.desktop.main.js#doOpenEditor@2963:15427\n' +
2022-09-28T22:47:13.6079600Z     'piiRemoved/workbench.desktop.main.js#openEditor@2963:15329\n' +
2022-09-28T22:47:13.6186940Z     'piiRemoved/workbench.desktop.main.js#openEditor@2769:24043\n' +
2022-09-28T22:47:13.6293190Z     '#(root)@-1:-1'
2022-09-28T22:47:13.6397870Z }
2022-09-28T22:47:13.6422670Z �[93m[main 2022-09-28T22:47:13.072Z]�[0m [perf] STOPPING to monitor renderer d3084e04-0003-4aa9-981d-e0f0c05fa75d

Looks like there are two items that need investigation,

  1. The long tasks reported by the auto profiler
  2. Does the profiler output interact negatively with integration tests
  3. Unrelated: should the auto profiler be enabled in CI ? Will it create noise in the telemetry ? If we want to keep the profiler enabled in CI should we then store the generated cpuprofile as pipeline artifacts.
@bpasero
Copy link
Member

bpasero commented Sep 29, 2022

Yeah I think the profiler should probably not run in our CI and/or tests.

What is more interesting is megabytes of logs being created as part of the run all containing this exception:

[2022-09-28 22:49:59.034] [main] [error] Error: write EPIPE
    at afterWriteDispatched (node:internal/stream_base_commons:160:15)
    at writeGeneric (node:internal/stream_base_commons:151:3)
    at Socket._writeGeneric (node:net:795:11)
    at Socket._write (node:net:807:8)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Writable.write (node:internal/streams/writable:334:10)
    at console.value (node:internal/console/constructor:286:16)
    at console.warn (node:internal/console/constructor:365:26)
    at d.error (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:38:3156)
    at C.error (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:38:5383)
    at Pt.onUnexpectedError (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:64412)
    at w.unexpectedErrorHandler (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:61599)
    at w.onUnexpectedError (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:7:354)
    at k (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:7:615)
    at process.<anonymous> (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:61680)
    at process.emit (node:events:538:35)
    at process._fatalException (node:internal/process/execution:167:25)

image

But it is hard to say if its caused by profiling or not.

@bpasero bpasero added this to the September 2022 milestone Sep 29, 2022
@jrieken
Copy link
Member

jrieken commented Sep 29, 2022

Will it create noise in the telemetry

There is a forgotten console.log-statement but the rest is using the log service and should be proper.

If we want to keep the profiler enabled in CI should we then store the generated cpuprofile as pipeline artifacts.

I kinda like that idea. I haven't seen an impact on runtime performance from profiling. Given we can store them as artifacts and given we can signal to the outside that this happened I see value in find issues quickly

@jrieken
Copy link
Member

jrieken commented Sep 29, 2022

Also note that we will disable automatic profiling for stable again

@bpasero
Copy link
Member

bpasero commented Sep 29, 2022

We store pipeline artefacts in the .build folder relative to the source root (logs, crash reports), so profiles could go there too, provided profiling does not make the CI more flaky.

A task to publish artefacts looks like this:

- task: PublishPipelineArtifact@0
inputs:
targetPath: .build/logs
${{ if and(eq(parameters.VSCODE_RUN_INTEGRATION_TESTS, true), eq(parameters.VSCODE_RUN_SMOKE_TESTS, false)) }}:
artifactName: logs-macos-$(VSCODE_ARCH)-integration-$(System.JobAttempt)
${{ elseif and(eq(parameters.VSCODE_RUN_INTEGRATION_TESTS, false), eq(parameters.VSCODE_RUN_SMOKE_TESTS, true)) }}:
artifactName: logs-macos-$(VSCODE_ARCH)-smoke-$(System.JobAttempt)
${{ else }}:
artifactName: logs-macos-$(VSCODE_ARCH)-$(System.JobAttempt)
displayName: "Publish Log Files"
continueOnError: true
condition: succeededOrFailed()

@deepak1556
Copy link
Collaborator Author

deepak1556 commented Sep 30, 2022

@bpasero bpasero modified the milestones: September 2022, October 2022 Sep 30, 2022
@jrieken jrieken removed their assignment Sep 30, 2022
@jrieken
Copy link
Member

jrieken commented Sep 30, 2022

i plead innocent, my changes are out: no more renderer profiling, no more lone console.log

@bpasero
Copy link
Member

bpasero commented Sep 30, 2022

Same ton of in the logs

[2022-09-29 16:14:41.562] [main] [error] Error: write EPIPE
    at afterWriteDispatched (node:internal/stream_base_commons:160:15)
    at writeGeneric (node:internal/stream_base_commons:151:3)
    at Socket._writeGeneric (node:net:795:11)
    at Socket._write (node:net:807:8)
    at writeOrBuffer (node:internal/streams/writable:389:12)
    at _write (node:internal/streams/writable:330:10)
    at Writable.write (node:internal/streams/writable:334:10)
    at console.value (node:internal/console/constructor:286:16)
    at console.warn (node:internal/console/constructor:365:26)
    at d.error (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:38:3156)
    at C.error (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:38:5383)
    at Pt.onUnexpectedError (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:64412)
    at w.unexpectedErrorHandler (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:61599)
    at w.onUnexpectedError (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:7:354)
    at k (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:7:615)
    at process.<anonymous> (/Users/runner/work/1/VSCode-darwin-x64/Visual Studio Code - Insiders.app/Contents/Resources/app/out/vs/code/electron-main/main.js:83:61680)
    at process.emit (node:events:538:35)
    at process._fatalException (node:internal/process/execution:167:25)

@jrieken
Copy link
Member

jrieken commented Sep 30, 2022

sorry, my PR to disable profiling go stuck in the pipeline (#162307). Second attempt is on its way

@SimonSiefke
Copy link
Contributor

@bpasero I believe the EPIPE error is happening because console.log/console.warn/console.error is writing to a closed stdout or a closed stderr stream.

I was having a similar error in my application (write EIO) and solved it by attaching error listeners to process.stdout and process.stderr:

const { createWriteStream } = require('fs')
const { tmpdir } = require('os')

let logger

const getOrCreateLogger = () => {
  if (!logger) {
    const tmpDir = tmpdir()
    logger = createWriteStream(`${tmpDir}/log.txt`)
  }
  return logger
}

process.stdout.on('error', (error) => {
  const logger = getOrCreateLogger()
  logger.write(`[main-process] stdout error: ${error.stack}`)
})

process.stderr.on('error', (error) => {
  const logger = getOrCreateLogger()
  logger.write(`[main-process] stderr error: ${error.stack}`)
})

This NodeJS issue helped me track down the problem: nodejs/node#831.

@rzhao271 rzhao271 added the bug Issue identified by VS Code Team member as probable bug label Dec 5, 2022
@rzhao271 rzhao271 modified the milestones: December 2022, January 2023 Dec 6, 2022
@rzhao271 rzhao271 added the emmet Emmet related issues label Dec 6, 2022
@rzhao271
Copy link
Contributor

rzhao271 commented Sep 8, 2023

@deepak1556 Is this issue still valid after #186717 got merged in?

@deepak1556
Copy link
Collaborator Author

Haven't seen this in while, can be closed.

@github-actions github-actions bot locked and limited conversation to collaborators Oct 26, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
bug Issue identified by VS Code Team member as probable bug emmet Emmet related issues integration-test-failure
Projects
None yet
Development

No branches or pull requests

5 participants