Open FabriceSalvaire opened 2 years ago
Hey @FabriceSalvaire, thanks for reporting. Please provide a simple code example and use case that generates this problem. Otherwise, we won't be able to reproduce it on our side.
Is there a way to trace what is going on ? I tried to look the Emacs lsp mode logging, but I don't have enough information.
Notice, it is not always easy for a user to make a docker image that reproduce a bug.
Please check the options of pylsp --help
to see how to get the logs generated by the server.
I have been experiencing the same thing for quite a while as well - I haven't been able to get lsp-mode to start pylsp with any other arguments (specifically '--verbose'). However I turned on IO logging and it looks like it's submitting a bunch of requests (one on every keypress?) for signature help (section of log below)
it then tries to cancel the previous request - however I get the following in the pylsp::stderr buffer
2022-09-09 15:57:52,238 EDT - WARNING - pylsp_jsonrpc.endpoint - Received cancel notification for unknown message id 2010
2022-09-09 15:57:52,518 EDT - WARNING - pylsp_jsonrpc.endpoint - Received cancel notification for unknown message id 2020
and then pylsp gets so caught up in fulfilling all these requests that it uses my entire CPU???
This server doesn't support cancelRequest
, so that should be the problem.
ah that's quite a bummer - is that something that could be in scope for the server? or is there a technical/design reason not to include it? As is with my (admittedly pretty large) project, it's mostly not usable :/.
@ccordoba12 just checking - do you think it'd be possible to add cancel Request support (maybe as a PR?) or technically is that not feasible in the implementation? If someone was interested in adding that support do you have any tips for how to get started?
I think that requires moving the server to use asyncio. Unfortunately, we don't have the resources to do it at the moment.
I am facing the same issue. I noticed it happens when scrolling through the lsp-ui-doc buffer.
I am experiencing something very similar with neovim, maybe this is not an emacs only issue?
When i start working on my project (a very small one: i am teaching myself python doing advent of code puzzles) the lsp log gets flooded with messages similar to what @compyman found out:
...
[ERROR][2022-12-04 16:06:20] .../vim/lsp/rpc.lua:733 "rpc" "pylsp" "stderr" "2022-12-04 16:06:20,770 +08 - WARNING - pylsp_jsonrpc.endpoint - Received cancel notification for unknown message id 2070\n"
...
I see i have one CPU at 100%, and in neovim, the lsp is acting up: diagnostics are out of date, not showing correctly, i get time outs when trying to format, etc.
After a while, the messages stop showing up in my log (unless i am typing) and things go back to normal.
Or is it a neovim issue?
Can you strace the hanging process? In my case it seems pylsp has decided to try and index all my build directories (which are under the source tree) of everything - including object files. No wonder it hangs:
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_net_can_can_kvaser_pci.c.o", {st_mode=S_IFREG|0644, st_size=68768, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_net_can_can_kvaser_pci.c.o", {st_mode=S_IFREG|0644, st_size=68768, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_intc_arm_gicv3_its.c.o", {st_mode=S_IFREG|0644, st_size=348968, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_intc_arm_gicv3_its.c.o", {st_mode=S_IFREG|0644, st_size=348968, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_intc_arm_gicv3_its.c.o", {st_mode=S_IFREG|0644, st_size=348968, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_intc_arm_gicv3_its.c.o", {st_mode=S_IFREG|0644, st_size=348968, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_intc_arm_gicv3_its.c.o", {st_mode=S_IFREG|0644, st_size=348968, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_arm_exynos4_boards.c.o", {st_mode=S_IFREG|0644, st_size=104248, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_arm_exynos4_boards.c.o", {st_mode=S_IFREG|0644, st_size=104248, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_arm_exynos4_boards.c.o", {st_mode=S_IFREG|0644, st_size=104248, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_arm_exynos4_boards.c.o", {st_mode=S_IFREG|0644, st_size=104248, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_arm_exynos4_boards.c.o", {st_mode=S_IFREG|0644, st_size=104248, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/ui_x_keymap.c.o", {st_mode=S_IFREG|0644, st_size=51392, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/ui_x_keymap.c.o", {st_mode=S_IFREG|0644, st_size=51392, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/ui_x_keymap.c.o", {st_mode=S_IFREG|0644, st_size=51392, ...}, AT_SYMLINK_NOFOLLOW) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/ui_x_keymap.c.o", {st_mode=S_IFREG|0644, st_size=51392, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/ui_x_keymap.c.o", {st_mode=S_IFREG|0644, st_size=51392, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_acpi_ghes.c.o", {st_mode=S_IFREG|0644, st_size=53728, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_acpi_ghes.c.o", {st_mode=S_IFREG|0644, st_size=53728, ...}, 0) = 0
newfstatat(AT_FDCWD, "/home/alex/lsrc/qemu.git/builds/bisect/libcommon.fa.p/hw_acpi_ghes.c.o", {st_mode=S_IFREG|0644, st_size=53728, ...}, AT_SYMLINK_NOFOLLOW) = 0
I managed to get a backtrace with gdb/py-bt:
(gdb) py-bt [32/875]
Traceback (most recent call first):
File "/usr/lib/python3/dist-packages/rope/base/resources.py", line 258, in does_match
if pattern.match(resource.path):
File "/usr/lib/python3/dist-packages/rope/base/project.py", line 280, in is_ignored
return self.ignored.does_match(resource)
File "/usr/lib/python3/dist-packages/rope/base/resources.py", line 180, in get_children
if not self.project.is_ignored(child):
File "/usr/lib/python3/dist-packages/rope/base/resources.py", line 216, in get_files
resource for resource in self.get_children() if not resource.is_folder()
File "/usr/lib/python3/dist-packages/rope/base/pycore.py", line 153, in _find_source_folders
for resource in folder.get_files():
File "/usr/lib/python3/dist-packages/rope/base/pycore.py", line 158, in _find_source_folders
result.extend(self._find_source_folders(resource))
File "/usr/lib/python3/dist-packages/rope/base/pycore.py", line 158, in _find_source_folders
result.extend(self._find_source_folders(resource))
File "/usr/lib/python3/dist-packages/rope/base/pycore.py", line 158, in _find_source_folders
result.extend(self._find_source_folders(resource))
File "/usr/lib/python3/dist-packages/rope/base/project.py", line 84, in get_source_folders
result.extend(self.pycore._find_source_folders(self.root))
File "/usr/lib/python3/dist-packages/rope/base/project.py", line 145, in find_module
for src in self.get_source_folders():
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/actions.py", line 52, in _get_relative_to_absolute_list
resource = self.project.find_module(name, folder=self.folder)
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/actions.py", line 33, in visitNormalImport
self.to_be_absolute.extend(self._get_relative_to_absolute_list(import_info))
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/actions.py", line 11, in dispatch
return method(import_, import_.import_info)
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/importinfo.py", line 61, in accept
return visitor.dispatch(self)
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/module_imports.py", line 270, in get_relative_to_absolute_list
import_stmt.accept(visitor)
File "/usr/lib/python3/dist-packages/rope/refactor/importutils/__init__.py", line 174, in relatives_to_absolutes
module_imports.get_relative_to_absolute_list()
File "/usr/lib/python3/dist-packages/rope/refactor/move.py", line 795, in moving_code_with_imports
source = import_tools.relatives_to_absolutes(pymodule)
File "/usr/lib/python3/dist-packages/rope/refactor/inline.py", line 110, in _init_imports
body, imports = move.moving_code_with_imports(self.project, self.resource, body)
File "/usr/lib/python3/dist-packages/rope/refactor/inline.py", line 106, in __init__
self._init_imports()
File "/usr/lib/python3/dist-packages/rope/refactor/inline.py", line 74, in create_inline
return InlineMethod(project, resource, offset)
File "/usr/lib/python3/dist-packages/pylsp_rope/refactoring.py", line 212, in validate
inline.create_inline(
File "/usr/lib/python3/dist-packages/pylsp_rope/refactoring.py", line 53, in is_valid
self.validate(info)
File "/usr/lib/python3/dist-packages/pylsp_rope/plugin.py", line 132, in <listcomp>
if cmd.is_valid(info)
File "/usr/lib/python3/dist-packages/pylsp_rope/plugin.py", line 129, in pylsp_code_actions
return [
File "/usr/lib/python3/dist-packages/pluggy/_callers.py", line 39, in _multicall
res = hook_impl.function(*args)
File "/usr/lib/python3/dist-packages/pluggy/_manager.py", line 324, in <lambda>
lambda: oldcall(hook_name, hook_impls, kwargs, firstresult)
File "/usr/lib/python3/dist-packages/pluggy/_result.py", line 33, in from_call
result = func()
File "/usr/lib/python3/dist-packages/pluggy/_manager.py", line 323, in traced_hookexec
outcome = _Result.from_call(
File "/usr/lib/python3/dist-packages/pylsp/config/config.py", line 33, in _hookexec
return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
File "/usr/lib/python3/dist-packages/pluggy/_hooks.py", line 265, in __call__
return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
File "/usr/lib/python3/dist-packages/pylsp/python_lsp.py", line 233, in _hook
return hook_handlers(config=self.config, workspace=workspace, document=doc, **kwargs)
File "/usr/lib/python3/dist-packages/pylsp/python_lsp.py", line 332, in code_actions
return flatten(self._hook('pylsp_code_actions', doc_uri, range=range, context=context))
File "/usr/lib/python3/dist-packages/pylsp/python_lsp.py", line 426, in m_text_document__code_action
return self.code_actions(textDocument['uri'], range, context)
File "/usr/lib/python3/dist-packages/pylsp_jsonrpc/dispatchers.py", line 25, in handler
return method(**(params or {}))
File "/usr/lib/python3/dist-packages/pylsp_jsonrpc/endpoint.py", line 185, in _handle_request
handler_result = handler(params)
File "/usr/lib/python3/dist-packages/pylsp_jsonrpc/endpoint.py", line 116, in consume
self._handle_request(message['id'], message['method'], message.get('params'))
File "/usr/lib/python3/dist-packages/pylsp_jsonrpc/streams.py", line 40, in listen
message_consumer(json.loads(request_str.decode('utf-8')))
File "/usr/lib/python3/dist-packages/pylsp/python_lsp.py", line 186, in start
self._jsonrpc_stream_reader.listen(self._endpoint.consume)
File "/usr/lib/python3/dist-packages/pylsp/python_lsp.py", line 92, in start_io_lang_server
server.start()
File "/usr/lib/python3/dist-packages/pylsp/__main__.py", line 84, in main
start_io_lang_server(stdin, stdout, args.check_parent_process,
File "/usr/bin/pylsp", line 8, in <module>
sys.exit(main())
So it looks like the underlying problem is with rope?
Using Emacs https://github.com/emacs-lsp/lsp-mode
I noticed it hangs too often to be usable, and the pyls process load the cpu to 100%.
I don't know how to debug that.