Skip to content

feat: enable "how long did this thing run?" logging #4033

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

Merged
merged 1 commit into from
Mar 5, 2021

Conversation

matklad
Copy link
Contributor

@matklad matklad commented Mar 4, 2021

Tracing spans are a pairs of start/stop events, and can be used to
monitor how well the code is performing in production and, if it is
slow, which specific part is slow. To get this magic power, we need two
things:

  • actually use span! macros from tracing (we already do in contract
    runtime, this PR adds one more span right at the entry point, now that
    we have a single entry point)

  • ask tracing to please print this valuable info, as it is disabled by
    default.

@matklad
Copy link
Contributor Author

matklad commented Mar 4, 2021

Example output:

running 1 test
Mar 04 20:18:44.853  INFO run_vm_profiled:run_wasmer:run_wasmer/call: near_vm_runner::wasmer_runner: close time.busy=16.4µs time.idle=710ns
Mar 04 20:18:44.854  INFO run_vm_profiled:run_wasmer: near_vm_runner::wasmer_runner: close time.busy=18.2ms time.idle=300ns
Mar 04 20:18:44.854  INFO run_vm_profiled: near_vm_runner::runner: close time.busy=18.2ms time.idle=1.15µs
Mar 04 20:18:44.857  INFO run_vm_profiled:run_wasmer:run_wasmer/call: near_vm_runner::wasmer_runner: close time.busy=2.58µs time.idle=320ns
Mar 04 20:18:44.858  INFO run_vm_profiled:run_wasmer: near_vm_runner::wasmer_runner: close time.busy=4.03ms time.idle=200ns
Mar 04 20:18:44.858  INFO run_vm_profiled: near_vm_runner::runner: close time.busy=4.03ms time.idle=260ns
Mar 04 20:18:44.861  INFO run_vm_profiled:run_wasmer:run_wasmer/call: near_vm_runner::wasmer_runner: close time.busy=2.29µs time.idle=320ns
Mar 04 20:18:44.861  INFO run_vm_profiled:run_wasmer: near_vm_runner::wasmer_runner: close time.busy=3.77ms time.idle=180ns
Mar 04 20:18:44.861  INFO run_vm_profiled: near_vm_runner::runner: close time.busy=3.78ms time.idle=230ns
Mar 04 20:18:44.865  INFO run_vm_profiled:run_wasmer:run_wasmer/call: near_vm_runner::wasmer_runner: close time.busy=4.85µs time.idle=300ns
Mar 04 20:18:44.865  INFO run_vm_profiled:run_wasmer: near_vm_runner::wasmer_runner: close time.busy=3.63ms time.idle=180ns
Mar 04 20:18:44.865  INFO run_vm_profiled: near_vm_runner::runner: close time.busy=3.63ms time.idle=230ns

note the time.busy values

Copy link
Collaborator

@bowenwang1996 bowenwang1996 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@matklad I don't think we want to enable this by default?

Tracing spans are a pairs of start/stop events, and can be used to
monitor how well the code is performing in production and, if it is
slow, which specific part is slow. To get this magic power, we need two
things:

* actually use `span!` macros from tracing (we already do in contract
  runtime, this PR adds one more span right at the entry point, now that
  we have a single entry point)

* ask tracing to please print this valuable info, as it is disabled by
  default.
@matklad
Copy link
Contributor Author

matklad commented Mar 5, 2021

Yeah, makes sense. Left only .with_span_events, to have the the possibility of enabling this via env var.

It'd be cool though to figure out which things we should print by default. I'll see if I can up with "print all spans that took longer than 50ms". That definitelly should be possible with tracing, the question is, can I figure out how?

That is, I feel we should merge this PR.

@near-bulldozer near-bulldozer bot merged commit 25dbea3 into near:master Mar 5, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants