search

helix-editor / helix

A post-modern modal text editor.
https://helix-editor.com
Mozilla Public License 2.0
32.93k stars 2.43k forks source link

logging: provide tree-sitter parsing and query time #940

Open matu3ba opened 2 years ago

matu3ba commented 2 years ago

Describe your feature request

Provide very simple logging for tree-sitter on INFO/-vvv, so users can estimate expections of tree-sitter performance: 1. parsing and query time can be printed separately. As of now, tree-sitter timings are not logged at all: hx -vvv ir.cpp of ir.cpp shows only content from helix_lsp::transport and mio::poll.

Details truncated to 125 symbols line length, because some stuff is giantic in output even on only opening files. The same output uncovered bug #941.

```txt 2021-10-30T14:04:31.296 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE | WRITABLE 2021-10-30T14:04:31.296 mio::poll [TRACE] registering event source with poller: token=Token(2), interests=READABLE | WRITABLE 2021-10-30T14:04:31.296 mio::poll [TRACE] registering event source with poller: token=Token(3), interests=READABLE | WRITABLE 2021-10-30T14:04:31.296 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"initialize","params":{"capabilities":{"text 2021-10-30T14:04:31.297 mio::poll [TRACE] registering event source with poller: token=Token(4), interests=READABLE | WRITABLE 2021-10-30T14:04:31.297 mio::poll [TRACE] registering event source with poller: token=Token(5), interests=READABLE | WRITABLE 2021-10-30T14:04:31.297 mio::poll [TRACE] registering event source with poller: token=Token(0), interests=READABLE 2021-10-30T14:04:31.297 mio::poll [TRACE] registering event source with poller: token=Token(1), interests=READABLE 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] clangd version 12.0.1\n" 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] PID: 805639\n" 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] Working directory: $HOME/dev/git/zig/zig/src/sta 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] argv[0]: clangd\n" 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] Starting LSP over stdin/stdout\n" 2021-10-30T14:04:31.309 helix_lsp::transport [ERROR] err <- "I[14:04:31.309] <-- initialize(0)\n" 2021-10-30T14:04:31.310 helix_lsp::transport [ERROR] err <- "I[14:04:31.310] --> reply:initialize(0) 0 ms\n" 2021-10-30T14:04:31.310 helix_lsp::transport [INFO] <- {"id":0,"jsonrpc":"2.0","result":{"capabilities":{"astProvider":true," 2021-10-30T14:04:31.310 helix_lsp::transport [INFO] <- {"capabilities":{"astProvider":true,"callHierarchyProvider":true,"code 2021-10-30T14:04:31.310 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"initialized","params":{}} 2021-10-30T14:04:31.310 helix_lsp::transport [ERROR] err <- "I[14:04:31.310] <-- initialized\n" 2021-10-30T14:04:31.313 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"textDocument/didOpen","params":{"textDocume 2021-10-30T14:04:31.320 helix_lsp::transport [ERROR] err <- "I[14:04:31.320] <-- textDocument/didOpen\n" 2021-10-30T14:04:31.323 helix_lsp::transport [ERROR] err <- "I[14:04:31.323] Failed to find compilation database for $HOME/de 2021-10-30T14:04:31.324 helix_lsp::transport [ERROR] err <- "I[14:04:31.324] ASTWorker building file $HOME/dev/git/zig/zig/sr 2021-10-30T14:04:31.324 helix_lsp::transport [ERROR] err <- "[$HOME/dev/git/zig/zig/src/stage1]\n" 2021-10-30T14:04:31.324 helix_lsp::transport [ERROR] err <- "/usr/bin/clang $HOME/dev/git/zig/zig/src/stage1/ir.cpp -fsyntax- 2021-10-30T14:04:32.289 helix_lsp::transport [ERROR] err <- "I[14:04:32.289] --> textDocument/publishDiagnostics\n" 2021-10-30T14:04:32.289 helix_lsp::transport [INFO] <- {"jsonrpc":"2.0","method":"textDocument/publishDiagnostics","params":{ 2021-10-30T14:04:36.395 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"shutdown","params":null,"id":1} 2021-10-30T14:04:36.395 helix_lsp::transport [INFO] <- {"id":1,"jsonrpc":"2.0","result":null} 2021-10-30T14:04:36.395 helix_lsp::transport [INFO] <- null 2021-10-30T14:04:36.395 helix_lsp::transport [ERROR] err <- "I[14:04:36.395] <-- shutdown(1)\n" 2021-10-30T14:04:36.396 helix_lsp::transport [ERROR] err <- "I[14:04:36.395] --> reply:shutdown(1) 0 ms\n" 2021-10-30T14:04:36.396 helix_lsp::transport [INFO] -> {"jsonrpc":"2.0","method":"exit","params":null} 2021-10-30T14:04:36.396 helix_lsp::transport [ERROR] err <- "I[14:04:36.396] <-- exit\n" 2021-10-30T14:04:36.396 helix_lsp::transport [ERROR] err <- "I[14:04:36.396] LSP finished, exiting with status 0\n" 2021-10-30T14:04:36.409 helix_lsp::transport [ERROR] err: <- StreamClosed 2021-10-30T14:04:36.409 mio::poll [TRACE] deregistering event source from poller 2021-10-30T14:04:36.409 helix_lsp::transport [ERROR] err: <- StreamClosed 2021-10-30T14:04:36.409 mio::poll [TRACE] deregistering event source from poller 2021-10-30T14:04:36.419 mio::poll [TRACE] deregistering event source from poller 2021-10-30T14:04:36.419 mio::poll [TRACE] deregistering event source from poller 2021-10-30T14:04:36.419 mio::poll [TRACE] deregistering event source from poller ```
dariooddenino commented 2 years ago

I'm not familiar with tree-sitter, so I'm very unsure of these log placements (especially the query one):

https://github.com/dariooddenino/helix/commit/2fd1ab1c18a4cd646ef969aae5ac7752dc1e53cb

the-mikedavis commented 2 years ago

I think the query one may be logging the query analysis time rather than the time it takes to run the query (though I'd have to dig further to confirm). You should consult the tree-sitter-cli code in the tree-sitter repo https://github.com/tree-sitter/tree-sitter/tree/1f1b1eb4501ed0a2d195d37f7de15f72aa10acd0 to see how it gathers the metrics.

dariooddenino commented 2 years ago

I think the query one may be logging the query analysis time rather than the time it takes to run the query (though I'd have to dig further to confirm). You should consult the tree-sitter-cli code in the tree-sitter repo https://github.com/tree-sitter/tree-sitter/tree/1f1b1eb4501ed0a2d195d37f7de15f72aa10acd0 to see how it gathers the metrics.

Yeah, I had a little more time to check how tree-sitter work and helix code, and that spot has nothing to do with the query execution time. Still need to pinpoint exactly the point, but I think Syntax::update is probably a good start.