logging: provide tree-sitter parsing and query time

[matu3ba]

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.

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]

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

dariooddenino@2fd1ab1

[the-mikedavis]

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]

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.