Skip to content

Measure effect of tokio contention in event processing #926

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

Merged
merged 3 commits into from
May 10, 2019
Merged

Measure effect of tokio contention in event processing #926

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
56d5a62
Update Cargo.lock
leoyvens May 10, 2019
4e59ea6
runtime: Measure effect of tokio contention in event processing
leoyvens May 10, 2019
d217228
runtime: Add comment on `.wait()`
leoyvens May 10, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
84 changes: 42 additions & 42 deletions Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

27 changes: 13 additions & 14 deletions runtime/wasm/src/host.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,7 +86,7 @@ where
}
}

type MappingResponse = Result<BlockState, Error>;
type MappingResponse = (Result<BlockState, Error>, futures::Finished<Instant, Error>);

#[derive(Debug)]
struct MappingRequest {
Expand Down Expand Up @@ -275,7 +275,7 @@ impl RuntimeHost {
};

result_sender
.send(result)
.send((result, future::ok(Instant::now())))
Copy link
Contributor

Choose a reason for hiding this comment

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

Does this need to be a future?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Having this be IntoFuture lets us keep the rest of the code untouched, so the options were either Result<Instant, Error> (being always Ok) or futures::Finished<Instant, Error> which I went with. This log is a temporary thing anyhow, once we improve things and get less contention warnings, this will be overkill.

Copy link
Contributor

Choose a reason for hiding this comment

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

Makes sense. The reason I'm asking about the future is that I wonder if the wait later could add undesired extra time to the measurement.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Yhea .wait() sounds like it's waiting but that will actually be instant. I improved the comment.

.map_err(|_| err_msg("WASM module result receiver dropped."))
})
.wait()
Expand Down Expand Up @@ -610,14 +610,12 @@ impl RuntimeHostTrait for RuntimeHost {
format_err!("Mapping terminated before finishing to handle")
})
})
.and_then(move |result| {
.and_then(move |(result, _)| {
info!(
logger, "Done processing Ethereum call";
"function" => &call_handler.function,
"handler" => &call_handler.handler,
// Replace this when `as_millis` is stable.
"secs" => start_time.elapsed().as_secs(),
"ms" => start_time.elapsed().subsec_millis()
"ms" => start_time.elapsed().as_millis(),
);
result
}),
Expand Down Expand Up @@ -667,15 +665,13 @@ impl RuntimeHostTrait for RuntimeHost {
format_err!("Mapping terminated before finishing to handle block trigger")
})
})
.and_then(move |result| {
.and_then(move |(result, _)| {
info!(
logger, "Done processing Ethereum block";
"hash" => block.block.hash.unwrap().to_string(),
"number" => &block.block.number.unwrap().to_string(),
"handler" => &block_handler.handler,
// Replace this when `as_millis` is stable.
"secs" => start_time.elapsed().as_secs(),
"ms" => start_time.elapsed().subsec_millis()
"ms" => start_time.elapsed().as_millis(),
);
result
}),
Expand Down Expand Up @@ -773,14 +769,17 @@ impl RuntimeHostTrait for RuntimeHost {
)
})
})
.and_then(move |result| {
.and_then(move |(result, send_time)| {
info!(
logger, "Done processing Ethereum event";
"signature" => &event_handler.event,
"handler" => &event_handler.handler,
// Replace this when `as_millis` is stable.
"secs" => start_time.elapsed().as_secs(),
"ms" => start_time.elapsed().subsec_millis()
"total_ms" => start_time.elapsed().as_millis(),

// How much time the result spent in the channel,
// waiting in the tokio threadpool queue. Anything
// larger than 0 is bad here. The `.wait()` is instant.
"waiting_ms" => send_time.wait().unwrap().elapsed().as_millis(),
);
result
}),
Expand Down