From f5ac51b7739041d63a9345f0f0d13ab77762d91a Mon Sep 17 00:00:00 2001 From: Friedel Ziegelmayer Date: Mon, 29 Jul 2019 15:13:43 +0200 Subject: [PATCH] feat: switch to log crate --- Cargo.toml | 1 - fil-proofs-tooling/.gitignore | 11 - fil-proofs-tooling/Cargo.toml | 22 - fil-proofs-tooling/LICENSE-APACHE | 7 - fil-proofs-tooling/LICENSE-MIT | 23 - fil-proofs-tooling/README.md | 1 - fil-proofs-tooling/release.toml | 4 - fil-proofs-tooling/src/bin/bencher.rs | 745 -------------------------- sector-builder-ffi/Cargo.toml | 7 +- sector-builder-ffi/src/api.rs | 45 +- sector-builder-ffi/src/lib.rs | 3 +- sector-builder-ffi/src/singletons.rs | 6 - sector-builder/Cargo.toml | 4 +- sector-builder/src/builder.rs | 5 +- sector-builder/src/lib.rs | 3 +- sector-builder/src/singletons.rs | 6 - 16 files changed, 46 insertions(+), 847 deletions(-) delete mode 100644 fil-proofs-tooling/.gitignore delete mode 100644 fil-proofs-tooling/Cargo.toml delete mode 100644 fil-proofs-tooling/LICENSE-APACHE delete mode 100644 fil-proofs-tooling/LICENSE-MIT delete mode 100644 fil-proofs-tooling/README.md delete mode 100644 fil-proofs-tooling/release.toml delete mode 100644 fil-proofs-tooling/src/bin/bencher.rs delete mode 100644 sector-builder-ffi/src/singletons.rs delete mode 100644 sector-builder/src/singletons.rs diff --git a/Cargo.toml b/Cargo.toml index 93558ca..9e68b60 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -2,6 +2,5 @@ members = [ "sector-builder", - "fil-proofs-tooling", "sector-builder-ffi" ] diff --git a/fil-proofs-tooling/.gitignore b/fil-proofs-tooling/.gitignore deleted file mode 100644 index 7042b1a..0000000 --- a/fil-proofs-tooling/.gitignore +++ /dev/null @@ -1,11 +0,0 @@ -/target -**/*.rs.bk -Cargo.lock -.criterion -**/*.h -heaptrack* -.bencher -logging-toolkit -*.profile -*.heap -rust-fil-proofs.config.toml diff --git a/fil-proofs-tooling/Cargo.toml b/fil-proofs-tooling/Cargo.toml deleted file mode 100644 index 80a5588..0000000 --- a/fil-proofs-tooling/Cargo.toml +++ /dev/null @@ -1,22 +0,0 @@ -[package] -name = "fil-proofs-tooling" -description = "Tooling for rust-fil-proofs" -version = "0.5.0" -authors = ["dignifiedquire "] -license = "MIT OR Apache-2.0" -publish = false -edition = "2018" -repository = "https://github.com/filecoin-project/rust-fil-proofs" -readme = "README.md" - -[dependencies] -clap = "2" -serde = { version = "1", features = ["derive"] } -serde_json = "1" -toml = "0.5" -failure = "0.1" -permutate = "0.3" -lazy_static = "1.2" -glob = "0.3" -human-size = "0.4" -prettytable-rs = "0.8" diff --git a/fil-proofs-tooling/LICENSE-APACHE b/fil-proofs-tooling/LICENSE-APACHE deleted file mode 100644 index 25d5a00..0000000 --- a/fil-proofs-tooling/LICENSE-APACHE +++ /dev/null @@ -1,7 +0,0 @@ - Copyright (c) 2018 Filecoin Project - -Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at - -http://www.apache.org/licenses/LICENSE-2.0 - -Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. diff --git a/fil-proofs-tooling/LICENSE-MIT b/fil-proofs-tooling/LICENSE-MIT deleted file mode 100644 index 468cd79..0000000 --- a/fil-proofs-tooling/LICENSE-MIT +++ /dev/null @@ -1,23 +0,0 @@ -Permission is hereby granted, free of charge, to any -person obtaining a copy of this software and associated -documentation files (the "Software"), to deal in the -Software without restriction, including without -limitation the rights to use, copy, modify, merge, -publish, distribute, sublicense, and/or sell copies of -the Software, and to permit persons to whom the Software -is furnished to do so, subject to the following -conditions: - -The above copyright notice and this permission notice -shall be included in all copies or substantial portions -of the Software. - -THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF -ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED -TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A -PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT -SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY -CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION -OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR -IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER -DEALINGS IN THE SOFTWARE. \ No newline at end of file diff --git a/fil-proofs-tooling/README.md b/fil-proofs-tooling/README.md deleted file mode 100644 index 7ec99ec..0000000 --- a/fil-proofs-tooling/README.md +++ /dev/null @@ -1 +0,0 @@ -# fil-proofs-tooling diff --git a/fil-proofs-tooling/release.toml b/fil-proofs-tooling/release.toml deleted file mode 100644 index 70d0688..0000000 --- a/fil-proofs-tooling/release.toml +++ /dev/null @@ -1,4 +0,0 @@ -disable-push = true -disable-publish = true -disable-tag = true -no-dev-version = true diff --git a/fil-proofs-tooling/src/bin/bencher.rs b/fil-proofs-tooling/src/bin/bencher.rs deleted file mode 100644 index 0dd3ff0..0000000 --- a/fil-proofs-tooling/src/bin/bencher.rs +++ /dev/null @@ -1,745 +0,0 @@ -#[macro_use] -extern crate serde; -#[macro_use] -extern crate failure; -#[macro_use] -extern crate lazy_static; - -use std::collections::HashMap; -use std::env; -use std::fmt; -use std::fs::{self, File}; -use std::io::prelude::*; -use std::process::Command; -use std::string::ToString; -use std::time::{Duration, SystemTime}; - -use clap::{App, Arg}; -use failure::Error; -use glob::glob; -use human_size::{Byte, Kibibyte, SpecificSize}; -use permutate::Permutator; -use prettytable::{format, Cell, Row, Table}; -use serde::de::{self, Deserialize, Deserializer, Visitor}; -use serde::ser::{Serialize, Serializer}; - -type Result = ::std::result::Result; - -#[derive(Debug, Deserialize)] -struct Case { - challenges: Vec, - size: Vec, - sloth: Vec, - m: Vec, - - command: Option, - expansion: Option>, - hasher: Option>, - layers: Option>, - partitions: Option>, - taper: Option>, - taper_layers: Option>, -} - -#[derive(Debug, Copy, Clone, PartialEq)] -struct Size(SpecificSize); - -impl Default for Size { - fn default() -> Self { - Size(SpecificSize::new(0, Byte).unwrap()) - } -} - -impl ToString for Size { - fn to_string(&self) -> String { - // return as KiB as that is what the examples expect - let kb: SpecificSize = self.0.into(); - kb.value().to_string() - } -} - -impl Serialize for Size { - fn serialize(&self, serializer: S) -> ::std::result::Result - where - S: Serializer, - { - serializer.serialize_str(&self.0.to_string()) - } -} - -impl<'de> Deserialize<'de> for Size { - fn deserialize(deserializer: D) -> ::std::result::Result - where - D: Deserializer<'de>, - { - struct SizeVisitor; - - impl<'de> Visitor<'de> for SizeVisitor { - type Value = Size; - - fn expecting(&self, f: &mut fmt::Formatter) -> fmt::Result { - f.write_str("user ID as a number or string") - } - - fn visit_u64(self, size: u64) -> ::std::result::Result - where - E: de::Error, - { - SpecificSize::new(size as f64, Byte) - .map(Size) - .map_err(de::Error::custom) - } - - fn visit_str(self, size: &str) -> ::std::result::Result - where - E: de::Error, - { - size.parse().map(Size).map_err(de::Error::custom) - } - } - - deserializer.deserialize_any(SizeVisitor) - } -} - -impl Case { - pub fn params(&self) -> Vec> { - let mut res = Vec::new(); - - res.push(self.challenges.iter().map(ToString::to_string).collect()); - res.push(self.size.iter().map(ToString::to_string).collect()); - res.push(self.sloth.iter().map(ToString::to_string).collect()); - res.push(self.m.iter().map(ToString::to_string).collect()); - - if let Some(ref hasher) = self.hasher { - res.push(hasher.iter().map(ToString::to_string).clone().collect()); - } - - if let Some(ref expansion) = self.expansion { - res.push(expansion.iter().map(ToString::to_string).clone().collect()); - } - - if let Some(ref layers) = self.layers { - res.push(layers.iter().map(ToString::to_string).clone().collect()); - } - - if let Some(ref partitions) = self.partitions { - res.push(partitions.iter().map(ToString::to_string).clone().collect()); - } - - if let Some(ref taper) = self.taper { - res.push(taper.iter().map(ToString::to_string).clone().collect()); - } - - if let Some(ref taper_layers) = self.taper_layers { - res.push( - taper_layers - .iter() - .map(ToString::to_string) - .clone() - .collect(), - ); - } - - res - } - - pub fn get_param_name(&self, i: usize) -> Result { - let params = self.get_param_names(); - if i > params.len() { - return Err(format_err!("invalid param index {}", i)); - } - - Ok(params[i].to_string()) - } - - pub fn get_param_names(&self) -> Vec { - let mut res = vec![ - "challenges".to_owned(), - "size".to_owned(), - "sloth".to_owned(), - "m".to_owned(), - ]; - - if self.hasher.is_some() { - res.push("hasher".to_owned()); - } - - if self.expansion.is_some() { - res.push("expansion".to_owned()); - } - - if self.layers.is_some() { - res.push("layers".to_owned()); - } - - if self.partitions.is_some() { - res.push("partitions".to_owned()); - } - - if self.taper.is_some() { - res.push("taper".to_owned()); - } - - if self.taper_layers.is_some() { - res.push("taper-layers".to_owned()); - } - - res - } -} - -#[cfg(not(target_os = "macos"))] -const TIME_CMD: &str = "/usr/bin/time"; - -#[cfg(target_os = "macos")] -const TIME_CMD: &str = "gtime"; - -/// The directory in which we expect the compiled binaries to be in. -const BINARY_DIR: &str = "target/release/examples"; - -/// The glob of which files to clear out before starting the run. -const CACHE_DIR: &str = "/tmp/filecoin-proofs-cache-*"; - -/// The directory in which the benchmark results will be stored. -const RESULT_DIR: &str = ".bencher"; - -lazy_static! { - static ref PRELUDE: Vec<(&'static str, Vec<&'static str>)> = - vec![("cargo", vec!["build", "--all", "--examples", "--release"]),]; - static ref MARKDOWN_TABLE_FORMAT: format::TableFormat = format::FormatBuilder::new() - .column_separator('|') - .borders('|') - .separators( - &[format::LinePosition::Title], - format::LineSeparator::new('-', '|', '|', '|'), - ) - .padding(1, 1) - .build(); -} - -fn combine<'a, T: ?Sized>(options: &'a [&'a [&'a T]]) -> Vec> { - Permutator::new(options).collect() -} - -fn run(config_path: &str, print_table: bool) -> Result<()> { - println!("reading config \"{}\"...", config_path); - - let mut f = File::open(config_path)?; - let mut contents = String::new(); - f.read_to_string(&mut contents)?; - - let config: HashMap = toml::from_str(&contents)?; - - println!("preparing..."); - - // make sure we are cleaning up the cache - for file in glob(CACHE_DIR)? { - fs::remove_file(file?)?; - } - - for (cmd, args) in &PRELUDE[..] { - let output = Command::new(cmd).args(args).output()?; - if !output.status.success() { - return Err(format_err!( - "failed to execute '{} {:?}': {} stdout: {}, stdout: {}", - cmd, - args, - output.status, - String::from_utf8_lossy(&output.stdout), - String::from_utf8_lossy(&output.stderr), - )); - } - } - - for (name, example) in config.iter() { - match run_benchmark(name, example) { - Ok(results) => { - if print_table { - print_result_table(name, example, &results); - } - } - Err(error) => { - eprintln!("error: {}", error); - } - } - } - - Ok(()) -} - -fn print_result_table(name: &str, example: &Case, results: &[BenchmarkResult]) { - let params = example.get_param_names(); - - let mut table = Table::new(); - table.set_format(*MARKDOWN_TABLE_FORMAT); - - let mut titles: Vec<&str> = vec![ - "name", - "size", - "proving", - "verifying", - "params gen", - "replication", - "max resident set size", - ]; - - titles.extend(params.iter().map(String::as_str)); - - table.set_titles(Row::new(titles.iter().map(|v| Cell::new(v)).collect())); - - for res in results { - let timing = res.time_res.max_resident_set_size.to_string(); - let mut values: Vec<&str> = vec![ - name, - &res.log_res - .config - .get("data_size") - .map(String::as_str) - .unwrap_or_else(|| ""), - &res.log_res - .stats - .get("avg_proving_time") - .map(String::as_str) - .unwrap_or_else(|| ""), - &res.log_res - .stats - .get("avg_verifying_time") - .map(String::as_str) - .unwrap_or_else(|| ""), - res.log_res - .stats - .get("params_generation_time") - .map(String::as_str) - .unwrap_or_else(|| ""), - res.log_res - .stats - .get("replication_time") - .map(String::as_str) - .unwrap_or_else(|| ""), - &timing, - ]; - values.extend(res.combination.iter().map(String::as_str)); - - table.add_row(Row::new(values.into_iter().map(Cell::new).collect())); - } - - println!("\n"); - table.printstd(); - println!("\n"); -} - -#[derive(Default, Debug, Serialize)] -struct TimeResult { - // Command being timed: "/Users/dignifiedquire/work/filecoin/rust-proofs/target/release/examples/drgporep-vanilla --challenges 1 --size 1 --sloth 0 --m 6 --hasher sha256" - command: String, - // User time (seconds): 118.33 - user_time: f64, - // System time (seconds): 1.07 - system_time: f64, - // Percent of CPU this job got: 959% - cpu: usize, - // Elapsed (wall clock) time (h:mm:ss or m:ss): 0:12.44 - elapsed_time: Duration, - // Average shared text size (kbytes): 0 - avg_shared_text_size: usize, - // Average unshared data size (kbytes): 0 - avg_unshared_data_size: usize, - // Average stack size (kbytes): 0 - avg_stack_size: usize, - // Average total size (kbytes): 0 - avg_total_size: usize, - // Maximum resident set size (kbytes): 117604 - max_resident_set_size: usize, - // Average resident set size (kbytes): 0 - avg_resident_set_size: usize, - // Major (requiring I/O) page faults: 0 - major_page_faults: usize, - // Minor (reclaiming a frame) page faults: 69788 - minor_page_faults: usize, - // Voluntary context switches: 7 - voluntary_context_switches: usize, - // Involuntary context switches: 70063 - involuntary_context_switches: usize, - // Swaps: 0 - swaps: usize, - // File system inputs: 0 - file_system_inputs: usize, - // File system outputs: 0 - file_system_outputs: usize, - // Socket messages sent: 0 - socket_messages_sent: usize, - // Socket messages received: 0 - socket_messages_received: usize, - // Signals delivered: 0 - signals_delivered: usize, - // Page size (bytes): 4096 - page_size: usize, - // Exit status: 0 - exit_status: usize, -} - -impl TimeResult { - fn from_str(raw: &str) -> Result { - let mut res = TimeResult::default(); - - for line in raw.trim().split('\n') { - let line = line.trim(); - let kv = line.split(": ").collect::>(); - let key = kv[0].trim(); - let value = kv[1].trim(); - - match key { - "Command being timed" => { - res.command = value.trim_matches('"').to_string(); - } - "User time (seconds)" => { - res.user_time = value.parse()?; - } - "System time (seconds)" => { - res.system_time = value.parse()?; - } - "Percent of CPU this job got" => { - res.cpu = value.replace('%', "").parse()?; - } - "Elapsed (wall clock) time (h:mm:ss or m:ss)" => { - let parts = value.split(':').collect::>(); - match parts.len() { - 2 => { - let minutes = Duration::from_secs(parts[0].parse::()? * 60); - let seconds = - Duration::from_millis((parts[1].parse::()? * 1000.0) as u64); - res.elapsed_time = minutes + seconds; - } - 3 => { - let hours = Duration::from_secs(parts[0].parse::()? * 60 * 60); - let minutes = Duration::from_secs(parts[1].parse::()? * 60); - let seconds = - Duration::from_millis((parts[2].parse::()? * 1000.0) as u64); - res.elapsed_time = hours + minutes + seconds; - } - _ => return Err(format_err!("invalid time format: '{}'", value)), - } - } - "Average shared text size (kbytes)" => { - res.avg_shared_text_size = value.parse()?; - } - "Average unshared data size (kbytes)" => { - res.avg_unshared_data_size = value.parse()?; - } - "Average stack size (kbytes)" => { - res.avg_stack_size = value.parse()?; - } - "Average total size (kbytes)" => { - res.avg_total_size = value.parse()?; - } - "Maximum resident set size (kbytes)" => { - res.max_resident_set_size = value.parse()?; - } - "Average resident set size (kbytes)" => { - res.avg_resident_set_size = value.parse()?; - } - "Major (requiring I/O) page faults" => { - res.major_page_faults = value.parse()?; - } - "Minor (reclaiming a frame) page faults" => { - res.minor_page_faults = value.parse()?; - } - "Voluntary context switches" => { - res.voluntary_context_switches = value.parse()?; - } - "Involuntary context switches" => { - res.involuntary_context_switches = value.parse()?; - } - "Swaps" => { - res.swaps = value.parse()?; - } - "File system inputs" => { - res.file_system_inputs = value.parse()?; - } - "File system outputs" => { - res.file_system_outputs = value.parse()?; - } - "Socket messages sent" => { - res.socket_messages_sent = value.parse()?; - } - "Socket messages received" => { - res.socket_messages_received = value.parse()?; - } - "Signals delivered" => { - res.signals_delivered = value.parse()?; - } - "Page size (bytes)" => { - res.page_size = value.parse()?; - } - "Exit status" => { - res.exit_status = value.parse()?; - } - _ => { - return Err(format_err!("unknown key: {}", key)); - } - } - } - - Ok(res) - } -} - -#[derive(Default, Debug, Serialize)] -struct BenchmarkResult { - combination: Vec, - stdout: String, - stderr: String, - time_res: TimeResult, - log_res: LogResult, -} - -impl BenchmarkResult { - pub fn new(combination: &[&str], stdout: &str, stderr: &str) -> Result { - // removes the annoying progress bar - let stderr = "Command being timed".to_owned() - + stderr.split("Command being timed").collect::>()[1]; - - let time_res = TimeResult::from_str(&stderr)?; - let log_res = LogResult::from_str(&stdout)?; - - Ok(BenchmarkResult { - combination: combination.iter().map(ToString::to_string).collect(), - stdout: stdout.to_owned(), - stderr, - time_res, - log_res, - }) - } -} - -#[derive(Default, Debug, Serialize)] -struct LogResult { - config: HashMap, - stats: HashMap, -} - -impl LogResult { - fn from_str(raw: &str) -> Result { - let lines = raw.trim().split('\n').filter_map(|l| { - if let Ok(parsed) = serde_json::from_str::>(l) { - let raw = &parsed["msg"]; - let system = parsed.get("target").cloned().unwrap_or_default(); - let kv = raw.trim().split(": ").collect::>(); - let key = kv[0].trim(); - let value = if kv.len() > 1 { kv[1].trim() } else { "" }; - - Some((system, String::from(key), String::from(value))) - } else { - None - } - }); - - let mut config = HashMap::new(); - let mut stats = HashMap::new(); - - for (system, key, value) in lines { - match system.as_ref() { - "config" => { - config.insert(key.to_owned(), value.to_owned()); - } - "stats" => { - stats.insert(key.to_owned(), value.to_owned()); - } - // ignoring unknown subsystems for now - _ => {} - } - } - - Ok(LogResult { config, stats }) - } -} - -fn run_benchmark(name: &str, config: &Case) -> Result> { - println!("benchmarking example: {}", name); - - // create dir to store results - let result_dir = env::current_dir()?.join(RESULT_DIR).join(name); - fs::create_dir_all(&result_dir)?; - - // the dance below is to avoid copies - let params = config.params(); - let tmp_1: Vec> = params - .iter() - .map(|list| list.iter().map(AsRef::as_ref).collect::>()) - .collect(); - let tmp_2: Vec<&[&str]> = tmp_1.iter().map(AsRef::as_ref).collect(); - - let combinations = combine(&tmp_2[..]); - - let binary_path = fs::canonicalize(BINARY_DIR)?.join(name); - - let mut results = Vec::with_capacity(combinations.len()); - - for combination in &combinations { - let mut cmd = Command::new(TIME_CMD); - cmd.arg("-v").arg(&binary_path); - - let mut print_comb = "\t".to_owned(); - for (i, param) in combination.iter().enumerate() { - let n = config.get_param_name(i)?; - cmd.arg(format!("--{}", n)).arg(param); - print_comb += &format!("{}: {}\t", n, param); - } - println!("{}", print_comb); - - if let Some(ref command) = config.command { - cmd.arg(command); - } - - let output = cmd.output()?; - let res = BenchmarkResult::new( - combination, - &String::from_utf8_lossy(&output.stdout), - &String::from_utf8_lossy(&output.stderr), - )?; - - match output.status.code() { - Some(code) => { - if code != 0 { - eprintln!("{}", &String::from_utf8_lossy(&output.stderr)); - return Err(format_err!("benchmark exited with non-zero status")); - } - } - None => { - return Err(format_err!("benchmark terminated by signal")); - } - } - - let mut data = serde_json::to_string(&res)?; - data.push('\n'); - results.push(res); - - // store result on disk - let timestamp = SystemTime::now().duration_since(SystemTime::UNIX_EPOCH)?; - let filename = result_dir.join(format!( - "{}-{}.json", - combination.join("-"), - timestamp.as_secs(), - )); - - fs::write(filename, data)?; - } - - Ok(results) -} - -fn main() { - // the bencher output-parsing code requires JSON, and an environment - // variable is the mechanism for enabling JSON-log support - std::env::set_var("FIL_PROOFS_LOG_JSON", "true"); - - let matches = App::new("Rust Proofs Bencher") - .version("1.0") - .about("Benchmark all the things") - .arg( - Arg::with_name("config") - .short("c") - .long("config") - .value_name("FILE") - .default_value("bench.config.toml") - .help("Sets a custom config file") - .takes_value(true), - ) - .arg( - Arg::with_name("table") - .long("table") - .takes_value(false) - .help("Print a summary as markdown table"), - ) - .get_matches(); - - let config = matches.value_of("config").unwrap(); - let print_table = matches.is_present("table"); - - ::std::process::exit(match run(config, print_table) { - Ok(_) => 0, - Err(err) => { - eprintln!("error: {:?}", err); - 1 - } - }); -} - -#[test] -fn test_combine() { - let input = vec![vec!["1", "2", "3"], vec!["4", "5"]]; - let refs: Vec<&[&str]> = input.iter().map(AsRef::as_ref).collect(); - assert_eq!( - combine(&refs[..]), - vec![ - vec!["1", "4"], - vec!["1", "5"], - vec!["2", "4"], - vec!["2", "5"], - vec!["3", "4"], - vec!["3", "5"] - ], - ); -} - -#[test] -fn test_time_result_from_str() { - let res = TimeResult::from_str(" - Command being timed: \"/Users/dignifiedquire/work/filecoin/rust-proofs/target/release/examples/drgporep-vanilla --challenges 1 --size 1 --sloth 0 --m 6 --hasher sha256\" - User time (seconds): 0.01 - System time (seconds): 0.01 - Percent of CPU this job got: 184% - Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.01 - Average shared text size (kbytes): 0 - Average unshared data size (kbytes): 0 - Average stack size (kbytes): 0 - Average total size (kbytes): 0 - Maximum resident set size (kbytes): 6932 - Average resident set size (kbytes): 0 - Major (requiring I/O) page faults: 0 - Minor (reclaiming a frame) page faults: 1932 - Voluntary context switches: 0 - Involuntary context switches: 889 - Swaps: 0 - File system inputs: 0 - File system outputs: 0 - Socket messages sent: 0 - Socket messages received: 0 - Signals delivered: 0 - Page size (bytes): 4096 - Exit status: 0 -").unwrap(); - - assert_eq!(res.command, "/Users/dignifiedquire/work/filecoin/rust-proofs/target/release/examples/drgporep-vanilla --challenges 1 --size 1 --sloth 0 --m 6 --hasher sha256"); - assert_eq!(res.user_time, 0.01); - assert_eq!(res.swaps, 0); - assert_eq!(res.involuntary_context_switches, 889); - assert_eq!(res.cpu, 184); - assert_eq!(res.elapsed_time, Duration::from_millis(10)); -} - -#[test] -fn test_log_results_str_json() { - let res = LogResult::from_str(" -{\"msg\":\"constraint system: Groth\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.315918-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:86 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"data_size: 1 kB\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.316948-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:87 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"challenge_count: 1\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.316961-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:88 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"m: 6\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.316970-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:89 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"sloth: 0\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.316978-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:90 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"tree_depth: 5\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.317011-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:91 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"config\"} -{\"msg\":\"reading groth params from cache: \\\"/tmp/filecoin-proofs-cache-multi-challenge merklepor-1024-1-6-0\\\"\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.317046-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:102 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"params\"} -{\"msg\":\"generating verification key\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:19.388725-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:123 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"params\"} -{\"msg\":\"avg_proving_time: 0.213533235 seconds\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:20.480250-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:180 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"stats\"} -{\"msg\":\"avg_verifying_time: 0.003935171 seconds\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:20.480273-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:181 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"stats\"} -{\"msg\":\"params_generation_time: 76.536768ms\",\"level\":\"INFO\",\"ts\":\"2018-12-14T13:57:20.480283-08:00\",\"place\":\"storage-proofs/src/example_helper.rs:182 storage_proofs::example_helper\",\"root\":\"storage-proofs\",\"target\":\"stats\"} - -").unwrap(); - - assert_eq!(res.config.get("constraint system").unwrap(), "Groth"); - assert_eq!(res.config.get("data_size").unwrap(), "1 kB",); - assert_eq!( - res.stats.get("avg_proving_time").unwrap(), - "0.213533235 seconds" - ); -} diff --git a/sector-builder-ffi/Cargo.toml b/sector-builder-ffi/Cargo.toml index 066d223..9d9234c 100644 --- a/sector-builder-ffi/Cargo.toml +++ b/sector-builder-ffi/Cargo.toml @@ -18,14 +18,13 @@ drop_struct_macro_derive = "0.3.0" ffi-toolkit = "0.3.0" filecoin-proofs = "0.5.0" filecoin-proofs-ffi = "0.6.0" -logging-toolkit = "0.5.0" sector-builder = { version = "^0.4", path = "../sector-builder" } storage-proofs = "0.5.0" - -slog = "2.4.1" failure = "0.1.5" libc = "0.2.58" -lazy_static = "1.3.0" +pretty_env_logger = "0.3.0" +log = "0.4.7" +once_cell = "0.2.4" [dev-dependencies] scopeguard = "1.0" diff --git a/sector-builder-ffi/src/api.rs b/sector-builder-ffi/src/api.rs index e7b5cd6..d5e3384 100644 --- a/sector-builder-ffi/src/api.rs +++ b/sector-builder-ffi/src/api.rs @@ -2,17 +2,15 @@ use std::mem; use std::ptr; use std::slice::from_raw_parts; -use libc; -use slog::*; - use ffi_toolkit::rust_str_to_c_str; use ffi_toolkit::{c_str_to_rust_str, raw_ptr}; +use libc; +use once_cell::sync::OnceCell; use sector_builder::{PieceMetadata, SealStatus, SecondsSinceEpoch, SectorBuilder}; use crate::responses::{ self, err_code_and_msg, FCPResponseStatus, FFIPieceMetadata, FFISealStatus, }; -use crate::singletons::FCP_LOG; #[repr(C)] pub struct FFISectorClass { @@ -32,6 +30,8 @@ pub unsafe extern "C" fn sector_builder_ffi_add_piece( piece_path: *const libc::c_char, store_until_utc_secs: u64, ) -> *mut responses::AddPieceResponse { + init_log(); + let piece_key = c_str_to_rust_str(piece_key); let piece_path = c_str_to_rust_str(piece_path); @@ -64,6 +64,8 @@ pub unsafe extern "C" fn sector_builder_ffi_add_piece( pub unsafe extern "C" fn sector_builder_ffi_get_max_user_bytes_per_staged_sector( sector_size: u64, ) -> u64 { + init_log(); + filecoin_proofs_ffi::api::get_max_user_bytes_per_staged_sector(sector_size) } @@ -76,6 +78,8 @@ pub unsafe extern "C" fn sector_builder_ffi_verify_piece_inclusion_proof( padded_piece_size: u64, sector_size: u64, ) -> *mut filecoin_proofs_ffi::responses::VerifyPieceInclusionProofResponse { + init_log(); + filecoin_proofs_ffi::api::verify_piece_inclusion_proof( comm_d, comm_p, @@ -92,6 +96,8 @@ pub unsafe extern "C" fn sector_builder_ffi_generate_piece_commitment( piece_path: *const libc::c_char, unpadded_piece_size: u64, ) -> *mut filecoin_proofs_ffi::responses::GeneratePieceCommitmentResponse { + init_log(); + filecoin_proofs_ffi::api::generate_piece_commitment(piece_path, unpadded_piece_size) } @@ -103,6 +109,8 @@ pub unsafe extern "C" fn sector_builder_ffi_get_seal_status( ptr: *mut SectorBuilder, sector_id: u64, ) -> *mut responses::GetSealStatusResponse { + init_log(); + let mut response: responses::GetSealStatusResponse = Default::default(); match (*ptr).get_seal_status(sector_id) { @@ -159,6 +167,7 @@ pub unsafe extern "C" fn sector_builder_ffi_get_seal_status( pub unsafe extern "C" fn sector_builder_ffi_get_sealed_sectors( ptr: *mut SectorBuilder, ) -> *mut responses::GetSealedSectorsResponse { + init_log(); let mut response: responses::GetSealedSectorsResponse = Default::default(); match (*ptr).get_sealed_sectors() { @@ -214,6 +223,7 @@ pub unsafe extern "C" fn sector_builder_ffi_get_sealed_sectors( pub unsafe extern "C" fn sector_builder_ffi_get_staged_sectors( ptr: *mut SectorBuilder, ) -> *mut responses::GetStagedSectorsResponse { + init_log(); let mut response: responses::GetStagedSectorsResponse = Default::default(); match (*ptr).get_staged_sectors() { @@ -284,7 +294,9 @@ pub unsafe extern "C" fn sector_builder_ffi_generate_post( flattened_comm_rs_len: libc::size_t, challenge_seed: &[u8; 32], ) -> *mut responses::GeneratePoStResponse { - info!(FCP_LOG, "generate_post: {}", "start"; "target" => "FFI"); + init_log(); + + info!("generate_post: {}", "start"); let comm_rs = into_commitments(flattened_comm_rs_ptr, flattened_comm_rs_len); @@ -324,7 +336,7 @@ pub unsafe extern "C" fn sector_builder_ffi_generate_post( } } - info!(FCP_LOG, "generate_post: {}", "finish"; "target" => "FFI"); + info!("generate_post: {}", "finish"); raw_ptr(response) } @@ -341,6 +353,8 @@ pub unsafe extern "C" fn sector_builder_ffi_init_sector_builder( staged_sector_dir: *const libc::c_char, max_num_staged_sectors: u8, ) -> *mut responses::InitSectorBuilderResponse { + init_log(); + let result = SectorBuilder::init_from_metadata( from_ffi_sector_class(sector_class), last_used_sector_id, @@ -375,6 +389,8 @@ pub unsafe extern "C" fn sector_builder_ffi_read_piece_from_sealed_sector( ptr: *mut SectorBuilder, piece_key: *const libc::c_char, ) -> *mut responses::ReadPieceFromSealedSectorResponse { + init_log(); + let mut response: responses::ReadPieceFromSealedSectorResponse = Default::default(); let piece_key = c_str_to_rust_str(piece_key); @@ -402,6 +418,8 @@ pub unsafe extern "C" fn sector_builder_ffi_read_piece_from_sealed_sector( pub unsafe extern "C" fn sector_builder_ffi_seal_all_staged_sectors( ptr: *mut SectorBuilder, ) -> *mut responses::SealAllStagedSectorsResponse { + init_log(); + let mut response: responses::SealAllStagedSectorsResponse = Default::default(); match (*ptr).seal_all_staged_sectors() { @@ -431,6 +449,8 @@ pub unsafe extern "C" fn sector_builder_ffi_verify_seal( proof_ptr: *const u8, proof_len: libc::size_t, ) -> *mut filecoin_proofs_ffi::responses::VerifySealResponse { + init_log(); + filecoin_proofs_ffi::api::verify_seal( sector_size, comm_r, @@ -457,6 +477,8 @@ pub unsafe extern "C" fn sector_builder_ffi_verify_post( faults_ptr: *const u64, faults_len: libc::size_t, ) -> *mut filecoin_proofs_ffi::responses::VerifyPoStResponse { + init_log(); + filecoin_proofs_ffi::api::verify_post( sector_size, proof_partitions, @@ -630,3 +652,14 @@ fn into_ffi_piece_metadata(piece_metadata: &PieceMetadata) -> FFIPieceMetadata { piece_inclusion_proof_ptr: ptr, } } + +/// Protects the init off the logger. +static LOG_INIT: OnceCell = OnceCell::new(); + +/// Ensures the logger is initialized. +fn init_log() { + LOG_INIT.get_or_init(|| { + let _ = pretty_env_logger::try_init_timed(); + true + }); +} diff --git a/sector-builder-ffi/src/lib.rs b/sector-builder-ffi/src/lib.rs index 836adb0..f1a9d9f 100644 --- a/sector-builder-ffi/src/lib.rs +++ b/sector-builder-ffi/src/lib.rs @@ -6,9 +6,8 @@ extern crate filecoin_proofs_ffi; extern crate sector_builder; #[macro_use] -extern crate lazy_static; +extern crate log; mod responses; -mod singletons; pub mod api; diff --git a/sector-builder-ffi/src/singletons.rs b/sector-builder-ffi/src/singletons.rs deleted file mode 100644 index 8690c1f..0000000 --- a/sector-builder-ffi/src/singletons.rs +++ /dev/null @@ -1,6 +0,0 @@ -use logging_toolkit::make_logger; -use slog::Logger; - -lazy_static! { - pub static ref FCP_LOG: Logger = make_logger("sector-builder-ffi"); -} diff --git a/sector-builder/Cargo.toml b/sector-builder/Cargo.toml index 65c2dac..f586276 100644 --- a/sector-builder/Cargo.toml +++ b/sector-builder/Cargo.toml @@ -14,16 +14,14 @@ failure = "0.1.5" itertools = "0.8" rand = "0.4" filecoin-proofs = "0.5.0" -logging-toolkit = "0.5.0" storage-proofs = "0.5.0" serde_cbor = "0.9.0" serde = { version = "1.0.92", features = ["rc", "derive"] } serde_json = "1.0" paired = "0.15" -lazy_static = "1.3.0" blake2b_simd = "0.5.1" byteorder = "1.3.1" -slog = "2.4.1" +log = "0.4.7" [dependencies.sled] version = "0.24" diff --git a/sector-builder/src/builder.rs b/sector-builder/src/builder.rs index 9ed797e..4e94da8 100644 --- a/sector-builder/src/builder.rs +++ b/sector-builder/src/builder.rs @@ -3,7 +3,6 @@ use std::sync::{mpsc, Arc, Mutex}; use filecoin_proofs::error::ExpectWithBacktrace; use filecoin_proofs::post_adapter::*; use filecoin_proofs::types::{PaddedBytesAmount, SectorClass}; -use slog::*; use crate::constants::*; use crate::disk_backed_storage::new_sector_store; @@ -12,7 +11,6 @@ use crate::kv_store::{KeyValueStore, SledKvs}; use crate::metadata::*; use crate::scheduler::{Request, Scheduler}; use crate::sealer::*; -use crate::singletons::FCP_LOG; pub type SectorId = u64; @@ -221,8 +219,7 @@ impl WrappedKeyValueStore { fn log_unrecov(result: Result) -> Result { if let Err(err) = &result { if let Some(SectorBuilderErr::Unrecoverable(err, backtrace)) = err.downcast_ref() { - let backtrace_string = format!("{:?}", backtrace); - error!(FCP_LOG, "unrecoverable error"; "backtrace" => backtrace_string, "error" => err); + error!("unrecoverable: {:?} - {:?}", err, backtrace); } } diff --git a/sector-builder/src/lib.rs b/sector-builder/src/lib.rs index 6fb78ba..7f32dae 100644 --- a/sector-builder/src/lib.rs +++ b/sector-builder/src/lib.rs @@ -3,7 +3,7 @@ #[macro_use] extern crate failure; #[macro_use] -extern crate lazy_static; +extern crate log; pub use filecoin_proofs::types::*; @@ -22,7 +22,6 @@ mod kv_store; mod metadata; mod scheduler; mod sealer; -mod singletons; mod state; mod store; mod util; diff --git a/sector-builder/src/singletons.rs b/sector-builder/src/singletons.rs deleted file mode 100644 index 4e93d43..0000000 --- a/sector-builder/src/singletons.rs +++ /dev/null @@ -1,6 +0,0 @@ -use logging_toolkit::make_logger; -use slog::Logger; - -lazy_static! { - pub static ref FCP_LOG: Logger = make_logger("sector-builder"); -}