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.

Sign up for GitHub

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

Jump to bottom

feat(runtime): debug print in host function call #5018

Merged
merged 3 commits into from
Oct 20, 2021
Merged

feat(runtime): debug print in host function call #5018

merged 3 commits into from
Oct 20, 2021

Conversation

ailisp
Copy link
Member

@ailisp ailisp commented Oct 15, 2021

Fix #4838

Test Plan

cargo build -p neard
target/debug/neard --verbose=host-function run

In another terminal:

export NEAR_ENV=local
near deploy --accountId test.near --wasmFile runtime/near-test-contracts/res/simple_state.wasm
near call test.near set_status --accountId test.near '{"message":"hello"}'

In neard window, will see:

...
Oct 15 14:45:06.384 DEBUG gas: host-function: enter
Oct 15 14:45:06.384 DEBUG gas: host-function: close time.busy=63.8µs time.idle=17.7µs
Oct 15 14:45:06.384 DEBUG log_utf8: host-function: enter
Oct 15 14:45:06.384 DEBUG log_utf8: host-function: close time.busy=114µs time.idle=11.7µs

@matklad
Copy link
Contributor

matklad commented Oct 18, 2021

@nikurt as the official "king of logging" ( :) ), could you take a look at these log statements? We'll be emitting an event for every host function call, which might be pretty chatty.

@matklad matklad requested a review from nikurt October 18, 2021 13:09
@nikurt
Copy link
Contributor

nikurt commented Oct 19, 2021

Seems to be a useful kind of logging.
If it proves to be too chatty, we can disable it. For example, nearup currently disables debug logging for actix.

@near-bulldozer near-bulldozer bot merged commit f6fb565 into master Oct 20, 2021
@near-bulldozer near-bulldozer bot deleted the debug-print-host-func branch October 20, 2021 02:26
bowenwang1996 added a commit that referenced this pull request Oct 21, 2021
@bowenwang1996
Revert "feat(runtime): debug print in host function call (#5018)"
585d7a9 
This reverts commit f6fb565.
@bowenwang1996 bowenwang1996 mentioned this pull request Oct 21, 2021
Merged
@mina86
Copy link
Contributor

mina86 commented Oct 21, 2021

RUST_LOG=host-function=info for those wondering how to disable it.

near-bulldozer bot pushed a commit that referenced this pull request Oct 22, 2021
@bowenwang1996
Revert "feat(runtime): debug print in host function call (#5018)" (#5062
d7ec1f3 
)

This reverts commit f6fb565.

#5018 caused too many logs on entering `gas` host function due to how our gas metering works and it slows down neard significantly

```
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=5.97µs time.idle=631ns
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=6.36µs time.idle=593ns
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.557 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=5.29µs time.idle=507ns
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=101µs time.idle=1.70µs
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: close time.busy=6.33µs time.idle=735ns
Oct 21 22:48:11 mainnet-canary0 sh[748906]: Oct 21 22:48:11.561 DEBUG Process block{#50773946}:process_state_update:Runtime::apply:Runtime::process_receipt:run_vm{vm_kind=Wasmer0}:run_wasmer:run_method:run_method/call:gas: host-function: enter
```

even when there is very little load
```
Oct 21 22:48:41 mainnet-canary0 sh[748906]: Oct 21 22:48:41.724  INFO stats: #50773947 Downloading blocks 99.99% (3248)  13/13/40 peers ⬇ 62.0kiB/s ⬆ 10.6kiB/s 0.05 bps 1.26 Tgas/s CPU: 32%, Mem: 808.2 MiB
Oct 21 22:48:56 mainnet-canary0 sh[748906]: Oct 21 22:48:56.188  INFO stats: #50773948 Downloading blocks 99.99% (3290)  13/13/40 peers ⬇ 65.8kiB/s ⬆ 11.0kiB/s 0.07 bps 859.43 Ggas/s CPU: 32%, Mem: 811.6 MiB
```
This caused canary nodes to be broken
@ailisp ailisp mentioned this pull request Oct 25, 2021
Merged
near-bulldozer bot pushed a commit that referenced this pull request Nov 3, 2021
@ailisp
feat(runtime): debug log host function call except gas (#5076)
00138f2 
This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly.

Test Plan
------------
same as #5018, this time the output doesn't have `gas`:
```
Oct 25 16:55:57.767  INFO stats: Server listening at ed25519:[email protected]:24567
Oct 25 16:56:01.702 DEBUG input: host-function: enter
Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs
Oct 25 16:56:01.702 DEBUG register_len: host-function: enter
Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs
Oct 25 16:56:01.702 DEBUG read_register: host-function: enter
Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs
Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter
Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs
Oct 25 16:56:01.703 DEBUG register_len: host-function: enter
Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs
Oct 25 16:56:01.703 DEBUG read_register: host-function: enter
Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG register_len: host-function: enter
Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs
Oct 25 16:56:01.704 DEBUG read_register: host-function: enter
Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter
Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs
Oct 25 16:56:07.820  INFO stats: #    3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1  0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B  
```

Also @mina86 is there a way to test performance as betanet node before merge it to master?
olonho pushed a commit that referenced this pull request Nov 4, 2021
@ailisp @olonho
feat(runtime): debug log host function call except gas (#5076)
05035d4 
This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly.

Test Plan
------------
same as #5018, this time the output doesn't have `gas`:
```
Oct 25 16:55:57.767  INFO stats: Server listening at ed25519:[email protected]:24567
Oct 25 16:56:01.702 DEBUG input: host-function: enter
Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs
Oct 25 16:56:01.702 DEBUG register_len: host-function: enter
Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs
Oct 25 16:56:01.702 DEBUG read_register: host-function: enter
Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs
Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter
Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs
Oct 25 16:56:01.703 DEBUG register_len: host-function: enter
Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs
Oct 25 16:56:01.703 DEBUG read_register: host-function: enter
Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG register_len: host-function: enter
Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs
Oct 25 16:56:01.704 DEBUG read_register: host-function: enter
Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter
Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs
Oct 25 16:56:07.820  INFO stats: #    3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1  0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B  
```

Also @mina86 is there a way to test performance as betanet node before merge it to master?
pmnoxx pushed a commit that referenced this pull request Nov 20, 2021
@ailisp @pmnoxx
feat(runtime): debug log host function call except gas (#5076)
0852101 
This fix the problem in #5062 by not logging gas function call. Logging `gas` was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly.

Test Plan
------------
same as #5018, this time the output doesn't have `gas`:
```
Oct 25 16:55:57.767  INFO stats: Server listening at ed25519:[email protected]:24567
Oct 25 16:56:01.702 DEBUG input: host-function: enter
Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs
Oct 25 16:56:01.702 DEBUG register_len: host-function: enter
Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs
Oct 25 16:56:01.702 DEBUG read_register: host-function: enter
Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs
Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter
Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs
Oct 25 16:56:01.703 DEBUG register_len: host-function: enter
Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs
Oct 25 16:56:01.703 DEBUG read_register: host-function: enter
Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG register_len: host-function: enter
Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs
Oct 25 16:56:01.704 DEBUG read_register: host-function: enter
Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter
Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs
Oct 25 16:56:07.820  INFO stats: #    3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1  0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B  
```

Also @mina86 is there a way to test performance as betanet node before merge it to master?
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@nikurt nikurt nikurt approved these changes

@matklad matklad matklad approved these changes

@olonho olonho Awaiting requested review from olonho

Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Add debug log to each host function
4 participants
@ailisp @matklad @nikurt @mina86