Skip to content

Instantly share code, notes, and snippets.

@Fraser999

Fraser999/Branch 'EE-789-intobytes'

Created December 6, 2019 17:20
Show Gist options
  • Save Fraser999/ab8807d5fda946e9c9b043b03185a846 to your computer and use it in GitHub Desktop.
Save Fraser999/ab8807d5fda946e9c9b043b03185a846 to your computer and use it in GitHub Desktop.
Download ZIP
logging patch
Raw
Branch 'EE-789-intobytes'
tps/transfer_to_existing_account_multiple_execs/3
time: [299.34 ms 300.82 ms 304.37 ms]
thrpt: [9.8563 elem/s 9.9726 elem/s 10.022 elem/s]
change:
time: [+97.665% +101.15% +105.00%] (p = 0.00 < 0.05)
thrpt: [-51.218% -50.285% -49.409%]
Performance has regressed.
Benchmarking tps/transfer_to_existing_account_multiple_deploys_per_exec/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 15.9s or reduce sample count to 10
tps/transfer_to_existing_account_multiple_deploys_per_exec/3
time: [293.99 ms 294.62 ms 295.76 ms]
thrpt: [10.143 elem/s 10.182 elem/s 10.204 elem/s]
change:
time: [+111.77% +113.98% +116.68%] (p = 0.00 < 0.05)
thrpt: [-53.850% -53.267% -52.779%]
Performance has regressed.
Found 2 outliers among 10 measurements (20.00%)
1 (10.00%) high mild
1 (10.00%) high severe
Benchmarking tps/transfer_to_purse_multiple_execs/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 17.3s or reduce sample count to 10
tps/transfer_to_purse_multiple_execs/3
time: [311.25 ms 312.87 ms 315.67 ms]
thrpt: [9.5037 elem/s 9.5885 elem/s 9.6386 elem/s]
change:
time: [+101.89% +104.90% +108.00%] (p = 0.00 < 0.05)
thrpt: [-51.923% -51.195% -50.468%]
Performance has regressed.
Benchmarking tps/transfer_to_purse_multiple_deploys_per_exec/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 16.6s or reduce sample count to 10
tps/transfer_to_purse_multiple_deploys_per_exec/3
time: [294.50 ms 295.45 ms 296.48 ms]
thrpt: [10.119 elem/s 10.154 elem/s 10.187 elem/s]
change:
time: [+105.51% +106.96% +108.43%] (p = 0.00 < 0.05)
thrpt: [-52.023% -51.682% -51.339%]
Performance has regressed.
Raw
Branch 'into_bytes'
tps/transfer_to_existing_account_multiple_execs/3
time: [237.34 ms 239.03 ms 240.34 ms]
thrpt: [12.482 elem/s 12.551 elem/s 12.640 elem/s]
change:
time: [+55.912% +59.288% +63.560%] (p = 0.00 < 0.05)
thrpt: [-38.860% -37.221% -35.861%]
Performance has regressed.
Found 1 outliers among 10 measurements (10.00%)
1 (10.00%) high severe
Benchmarking tps/transfer_to_existing_account_multiple_deploys_per_exec/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 12.3s or reduce sample count to 10
tps/transfer_to_existing_account_multiple_deploys_per_exec/3
time: [232.74 ms 233.77 ms 235.23 ms]
thrpt: [12.753 elem/s 12.833 elem/s 12.890 elem/s]
change:
time: [+67.000% +68.340% +69.582%] (p = 0.00 < 0.05)
thrpt: [-41.032% -40.596% -40.120%]
Performance has regressed.
Found 2 outliers among 10 measurements (20.00%)
1 (10.00%) low mild
1 (10.00%) high mild
Benchmarking tps/transfer_to_purse_multiple_execs/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 13.3s or reduce sample count to 10
tps/transfer_to_purse_multiple_execs/3
time: [237.24 ms 240.86 ms 244.01 ms]
thrpt: [12.294 elem/s 12.456 elem/s 12.645 elem/s]
change:
time: [+54.837% +57.464% +60.013%] (p = 0.00 < 0.05)
thrpt: [-37.505% -36.493% -35.416%]
Performance has regressed.
Found 1 outliers among 10 measurements (10.00%)
1 (10.00%) low mild
Benchmarking tps/transfer_to_purse_multiple_deploys_per_exec/3: Warming up for 3.0000 s
Warning: Unable to complete 10 samples in 5.0s. You may wish to increase target time to 12.5s or reduce sample count to 10
tps/transfer_to_purse_multiple_deploys_per_exec/3
time: [231.64 ms 232.11 ms 232.87 ms]
thrpt: [12.883 elem/s 12.925 elem/s 12.951 elem/s]
change:
time: [+61.918% +63.143% +64.406%] (p = 0.00 < 0.05)
thrpt: [-39.175% -38.704% -38.240%]
Performance has regressed.
Raw
logging.patch
Index: execution-engine/engine-core/src/execution/executor.rs
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- execution-engine/engine-core/src/execution/executor.rs (revision 685cee368a5012cdca077a526195ccac583ec192)
+++ execution-engine/engine-core/src/execution/executor.rs (date 1575651328117)
@@ -2,6 +2,7 @@
cell::RefCell,
collections::{BTreeMap, BTreeSet},
rc::Rc,
+ time::Instant,
};
use parity_wasm::elements::Module;
@@ -89,6 +90,8 @@
R: StateReader<Key, StoredValue>,
R::Error: Into<Error>,
{
+ let start = Instant::now();
+
let (instance, memory) =
on_fail_charge!(instance_and_memory(parity_module.clone(), protocol_version));
@@ -143,12 +146,19 @@
);
let mut runtime = Runtime::new(system_contract_cache, memory, parity_module, context);
+
on_fail_charge!(
instance.invoke_export("call", &[], &mut runtime),
runtime.context().gas_counter(),
effects_snapshot
);
+ println!(
+ "exec: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
+
ExecutionResult::Success {
effect: runtime.context().effect(),
cost: runtime.context().gas_counter(),
@@ -177,6 +187,8 @@
R: StateReader<Key, StoredValue>,
R::Error: Into<Error>,
{
+ let start = Instant::now();
+
let mut named_keys = named_keys.clone();
let access_rights =
{
@@ -232,7 +244,9 @@
let mut runtime = Runtime::new(system_contract_cache, memory, parity_module, context);
- match instance.invoke_export("call", &[], &mut runtime) {
+ let t = instance.invoke_export("call", &[], &mut runtime);
+
+ let r = match t {
Ok(_) => ExecutionResult::Success {
effect: runtime.context().effect(),
cost: runtime.context().gas_counter(),
@@ -249,6 +263,11 @@
// TODO?: add ability to include extra_urefs and runtime.result to
// ExecutionResult::Success
+ println!(
+ "exec_direct: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
return ExecutionResult::Success {
effect: runtime.context().effect(),
cost: runtime.context().gas_counter(),
@@ -257,6 +276,11 @@
Error::Revert(status) => {
// Propagate revert as revert, instead of passing it as
// InterpreterError.
+ println!(
+ "exec_direct: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
return ExecutionResult::Failure {
error: Error::Revert(*status).into(),
effect: effects_snapshot,
@@ -273,7 +297,13 @@
cost: runtime.context().gas_counter(),
}
}
- }
+ };
+ println!(
+ "exec_direct: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
+ r
}
pub fn better_exec<R, T>(
@@ -300,6 +330,8 @@
R::Error: Into<Error>,
T: FromBytes + CLTyped,
{
+ let start = Instant::now();
+
let access_rights =
{
let mut keys: Vec<Key> = keys.values().cloned().collect();
@@ -341,7 +373,9 @@
let mut runtime = Runtime::new(system_contract_cache, memory, module, runtime_context);
- let return_error: wasmi::Error = match instance.invoke_export("call", &[], &mut runtime) {
+ let t = instance.invoke_export("call", &[], &mut runtime);
+
+ let return_error: wasmi::Error = match t {
Err(error) => error,
Ok(_) => {
// This duplicates the behavior of sub_call, but is admittedly rather questionable.
@@ -352,6 +386,11 @@
// which don't specify a return value.
let result = runtime.take_host_buf().unwrap_or(CLValue::from_t(())?);
let ret = result.to_t()?;
+ println!(
+ "better_exec: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
return Ok(ret);
}
};
@@ -361,11 +400,30 @@
.and_then(|host_error| host_error.downcast_ref::<Error>())
{
Some(Error::Ret(_)) => runtime.take_host_buf().ok_or(Error::ExpectedReturnValue)?,
- Some(Error::Revert(code)) => return Err(Error::Revert(*code)),
- _ => return Err(Error::Interpreter(return_error)),
+ Some(Error::Revert(code)) => {
+ println!(
+ "better_exec: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
+ return Err(Error::Revert(*code));
+ }
+ _ => {
+ println!(
+ "better_exec: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
+ return Err(Error::Interpreter(return_error));
+ }
};
let ret = return_value.to_t()?;
+ println!(
+ "better_exec: {:?} -- gas cost: {}",
+ start.elapsed(),
+ runtime.context().gas_counter()
+ );
Ok(ret)
}
}
Index: execution-engine/engine-core/src/execution/runtime/mod.rs
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- execution-engine/engine-core/src/execution/runtime/mod.rs (revision 685cee368a5012cdca077a526195ccac583ec192)
+++ execution-engine/engine-core/src/execution/runtime/mod.rs (date 1575651057612)
@@ -5,6 +5,7 @@
collections::{BTreeMap, HashMap, HashSet},
convert::TryFrom,
iter::IntoIterator,
+ time::Instant,
};
use itertools::Itertools;
@@ -815,6 +816,8 @@
target: PurseId,
amount: U512,
) -> Result<(), Error> {
+ let start = Instant::now();
+
let source_value: URef = source.value();
let target_value: URef = target.value();
@@ -830,6 +833,8 @@
let result = self.take_host_buf().unwrap();
let result: Result<(), mint::Error> = result.to_t()?;
+ println!("mint_transfer: {:?}", start.elapsed());
+
Ok(result.map_err(system_contracts::Error::from)?)
}
Index: execution-engine/engine-tests/src/profiling/simple_transfer.rs
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- execution-engine/engine-tests/src/profiling/simple_transfer.rs (revision 685cee368a5012cdca077a526195ccac583ec192)
+++ execution-engine/engine-tests/src/profiling/simple_transfer.rs (date 1575651057608)
@@ -7,7 +7,7 @@
//! By avoiding setting up global state as part of this executable, it will allow profiling to be
//! done only on meaningful code, rather than including test setup effort in the profile results.
-use std::{env, io, path::PathBuf};
+use std::{env, io, path::PathBuf, time::Instant};
use base16;
use clap::{crate_version, App, Arg};
@@ -89,6 +89,8 @@
}
fn main() {
+ let start = Instant::now();
+
let args = Args::new();
// If the required initial root hash wasn't passed as a command line arg, expect to read it in
@@ -125,4 +127,6 @@
if args.verbose {
println!("{:#?}", test_builder.get_transforms());
}
+
+ println!("Overall: {:?}", start.elapsed());
}
Raw
simple-transfer with logging
Branch 'dev'
mint_transfer: 6.770147ms
exec: 19.440583ms -- gas cost: 71275
mint_transfer: 5.792901ms
exec: 6.493408ms -- gas cost: 24439
mint_transfer: 7.141016ms
mint_transfer: 5.501281ms
exec_direct: 19.547753ms -- gas cost: 104112
Overall: 63.820841ms
Branch 'EE-789-CLValue'
mint_transfer: 10.794212ms
exec: 31.021464ms -- gas cost: 177172
mint_transfer: 8.861389ms
exec: 11.78672ms -- gas cost: 87991
mint_transfer: 10.629583ms
mint_transfer: 8.476972ms
exec_direct: 30.156788ms -- gas cost: 374264
Overall: 100.117587ms
Branch 'EE-789-intobytes'
mint_transfer: 13.866262ms
exec: 35.472809ms -- gas cost: 249308
mint_transfer: 13.526524ms
exec: 16.582614ms -- gas cost: 112845
mint_transfer: 13.993223ms
mint_transfer: 13.489544ms
exec_direct: 39.037976ms -- gas cost: 498845
Overall: 117.639378ms
Branch 'into_bytes'
mint_transfer: 8.54424ms
exec: 28.889151ms -- gas cost: 174473
mint_transfer: 10.517024ms
exec: 13.360455ms -- gas cost: 86931
mint_transfer: 10.416175ms
mint_transfer: 9.615597ms
exec_direct: 30.580765ms -- gas cost: 371198
Overall: 109.240478ms
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment