output logging

This commit is contained in:
Vasily Galkin 2022-07-18 15:10:21 +03:00
parent 3bf71058cd
commit 43ffe213d4
5 changed files with 327 additions and 21 deletions

1
.gitignore vendored
View File

@ -1 +1,2 @@
/target
memtest_vulkan.log

143
Cargo.lock generated
View File

@ -67,6 +67,19 @@ version = "1.0.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "baf1de4339761588bc0619e3cbc0120ee582ebb74b53b4efbf79117bd2da40fd"
[[package]]
name = "chrono"
version = "0.4.19"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "670ad68c9088c2a963aaa298cb369688cf3f9465ce5e2d4ca10e6e0098a1ce73"
dependencies = [
"libc",
"num-integer",
"num-traits",
"time",
"winapi",
]
[[package]]
name = "codespan-reporting"
version = "0.11.1"
@ -108,6 +121,27 @@ dependencies = [
"winapi",
]
[[package]]
name = "errno"
version = "0.2.8"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "f639046355ee4f37944e44f60642c6f3a7efa3cf6b78c78a0d989a8ce6c396a1"
dependencies = [
"errno-dragonfly",
"libc",
"winapi",
]
[[package]]
name = "errno-dragonfly"
version = "0.1.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "aa68f1b12764fab894d2755d2518754e71b4fd80ecfb822714a1206c2aab39bf"
dependencies = [
"cc",
"libc",
]
[[package]]
name = "erupt"
version = "0.22.0+204"
@ -125,6 +159,17 @@ version = "1.0.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "3f9eec918d3f24069decb9af1554cad7c880e2da24a9afd88aca000531ab82c1"
[[package]]
name = "fs4"
version = "0.6.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e9813c3dc174931eff4bd78609debba56465b7c1da888576d21636b601a46790"
dependencies = [
"libc",
"rustix",
"winapi",
]
[[package]]
name = "getrandom"
version = "0.1.16"
@ -169,6 +214,12 @@ dependencies = [
"hashbrown",
]
[[package]]
name = "io-lifetimes"
version = "0.7.2"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "24c3f4eff5495aee4c0399d7b6a0dc2b6e81be84242ffbfcf253ebacccc1d0cb"
[[package]]
name = "libc"
version = "0.2.126"
@ -185,6 +236,12 @@ dependencies = [
"winapi",
]
[[package]]
name = "linux-raw-sys"
version = "0.0.46"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d4d2456c373231a208ad294c33dc5bff30051eafd954cd4caae83a712b12854d"
[[package]]
name = "log"
version = "0.4.17"
@ -214,8 +271,10 @@ name = "memtest_vulkan"
version = "0.2.0"
dependencies = [
"byte-strings",
"chrono",
"ctrlc",
"erupt",
"fs4",
"memtest_vulkan_build",
"mortal",
]
@ -299,6 +358,16 @@ dependencies = [
"version_check",
]
[[package]]
name = "num-integer"
version = "0.1.45"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "225d3389fb3509a24c93f5c29eb6bde2586b98d9f016636dff58d7c6f7569cd9"
dependencies = [
"autocfg",
"num-traits",
]
[[package]]
name = "num-traits"
version = "0.2.15"
@ -447,6 +516,20 @@ version = "1.1.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "08d43f7aa6b08d49f382cde6a7982047c3426db949b1424bc4b7ec9ae12c6ce2"
[[package]]
name = "rustix"
version = "0.35.7"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d51cc38aa10f6bbb377ed28197aa052aa4e2b762c22be9d3153d01822587e787"
dependencies = [
"bitflags",
"errno",
"io-lifetimes",
"libc",
"linux-raw-sys",
"windows-sys",
]
[[package]]
name = "siphasher"
version = "0.3.10"
@ -531,6 +614,17 @@ dependencies = [
"syn",
]
[[package]]
name = "time"
version = "0.1.44"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "6db9e6914ab8b1ae1c260a4ae7a49b6c5611b40328a735b21862567685e73255"
dependencies = [
"libc",
"wasi 0.10.0+wasi-snapshot-preview1",
"winapi",
]
[[package]]
name = "tinyvec"
version = "1.6.0"
@ -585,6 +679,12 @@ version = "0.9.0+wasi-snapshot-preview1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "cccddf32554fecc6acb585f82a32a72e28b48f8c4c1883ddfeeeaa96f7d8e519"
[[package]]
name = "wasi"
version = "0.10.0+wasi-snapshot-preview1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "1a143597ca7c7793eff794def352d41792a93c481eb1042423ff7ff72ba2c31f"
[[package]]
name = "wasi"
version = "0.11.0+wasi-snapshot-preview1"
@ -621,3 +721,46 @@ name = "winapi-x86_64-pc-windows-gnu"
version = "0.4.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "712e227841d057c1ee1cd2fb22fa7e5a5461ae8e48fa2ca79ec42cfc1931183f"
[[package]]
name = "windows-sys"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "ea04155a16a59f9eab786fe12a4a450e75cdb175f9e0d80da1e17db09f55b8d2"
dependencies = [
"windows_aarch64_msvc",
"windows_i686_gnu",
"windows_i686_msvc",
"windows_x86_64_gnu",
"windows_x86_64_msvc",
]
[[package]]
name = "windows_aarch64_msvc"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "9bb8c3fd39ade2d67e9874ac4f3db21f0d710bee00fe7cab16949ec184eeaa47"
[[package]]
name = "windows_i686_gnu"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "180e6ccf01daf4c426b846dfc66db1fc518f074baa793aa7d9b9aaeffad6a3b6"
[[package]]
name = "windows_i686_msvc"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "e2e7917148b2812d1eeafaeb22a97e4813dfa60a3f8f78ebe204bcc88f12f024"
[[package]]
name = "windows_x86_64_gnu"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "4dcd171b8776c41b97521e5da127a2d86ad280114807d0b2ab1e462bc764d9e1"
[[package]]
name = "windows_x86_64_msvc"
version = "0.36.1"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "c811ca4a8c853ef420abd8592ba53ddbbac90410fab6903b3e79972a631f7680"

View File

@ -10,6 +10,8 @@ version = '0.2.0'
byte-strings = '0.2.2'
ctrlc = '3.2.2'
mortal = '0.2.3'
fs4 = '0.6.2'
chrono = '0.4.19'
[dependencies.erupt]
default-features = false

View File

@ -1,4 +1,5 @@
mod input;
mod output;
use byte_strings::c_str;
use core::cmp::{max, min};
@ -153,20 +154,26 @@ impl<const LEN: usize> fmt::Display for MostlyZeroArr<LEN> {
return Ok(());
}
for i in 0..LEN {
if i % 16 == 0 && i != 0 { write!(f, " 0x{:X}? ", i/16)?; }
if i % 16 == 0 && i != 0 {
write!(f, " 0x{:X}? ", i / 16)?;
}
let vali = self.0[i];
if vali > 999999u32 {
write!(f, "{:3}m", vali/1000000u32)?;
write!(f, "{:3}m", vali / 1000000u32)?;
} else if vali > 9999u32 {
write!(f, "{:3}k", vali/1000u32)?;
write!(f, "{:3}k", vali / 1000u32)?;
} else if vali > 0 {
write!(f, "{:4}", vali)?;
} else {
write!(f, " ")?; //zero
}
if i % 16 == 15 { writeln!(f, "")?; }
else if i % 4 == 3 { write!(f, "|")?; }
else if i % 4 == 1 { write!(f, " ")?; }
if i % 16 == 15 {
writeln!(f, "")?;
} else if i % 4 == 3 {
write!(f, "|")?;
} else if i % 4 == 1 {
write!(f, " ")?;
}
}
Ok(())
}
@ -197,13 +204,20 @@ struct IOBuf {
impl fmt::Display for IOBuf {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
writeln!(f, " 0x0 0x1 0x2 0x3| 0x4 0x5 0x6 0x7| 0x8 0x9 0xA 0xB| 0xC 0xD 0xE 0xF")?;
writeln!(
f,
" 0x0 0x1 0x2 0x3| 0x4 0x5 0x6 0x7| 0x8 0x9 0xA 0xB| 0xC 0xD 0xE 0xF"
)?;
write!(f, "Err1BIdx{}", self.err_bit1_idx)?;
write!(f, "ErrBiCnt{}", self.err_bitcount)?;
write!(f, "MemBiCnt{}", self.mem_bitcount)?;
writeln!(f, "actual_ff: {} actual_max: 0x{:08X} actual_min: 0x{:08X} done_iter_or_err:{} iter:{} calc_param 0x{:08X}",
self.actual_ff, self.actual_max, self.actual_min, self.done_iter_or_err, self.iter, self.calc_param)?;
write!(f, "idxs:{}-{} first_elem: {}", self.idx_min, self.idx_max, self.first_elem)?;
write!(
f,
"idxs:{}-{} first_elem: {}",
self.idx_min, self.idx_max, self.first_elem
)?;
Ok(())
}
}
@ -230,16 +244,18 @@ impl IOBuf {
}
fn get_error_addresses_and_count(
&self,
buf_offset: i64
buf_offset: i64,
) -> Option<(std::ops::RangeInclusive<U64HexDebug>, i64)> {
if self.done_iter_or_err == self.iter {
None
} else {
let total_errors = self.mem_bitcount.0.iter().sum::<u32>() as i64;
Some((std::ops::RangeInclusive::<U64HexDebug>::new(
U64HexDebug(buf_offset + self.idx_min as i64 * ELEMENT_SIZE),
U64HexDebug(buf_offset + (self.idx_max + 1) as i64 * ELEMENT_SIZE - 1)),
total_errors
Some((
std::ops::RangeInclusive::<U64HexDebug>::new(
U64HexDebug(buf_offset + self.idx_min as i64 * ELEMENT_SIZE),
U64HexDebug(buf_offset + (self.idx_max + 1) as i64 * ELEMENT_SIZE - 1),
),
total_errors,
))
}
}
@ -292,8 +308,22 @@ fn test_device(
physical_device: vk::PhysicalDevice,
queue_family_index: u32,
device_create_info: vk::DeviceCreateInfo,
name: String,
debug_mode: bool,
) -> Result<bool, Box<dyn std::error::Error>> {
const MAX_LOG_SIZE: u64 = 50 * 1024 * 1024;
//log is put in current directory. This is intentional - run from other dir to use another log
let mut log_dupler = output::LogDupler::new(
std::io::stdout(),
std::fs::OpenOptions::new()
.read(true)
.append(true)
.create(true)
.open("memtest_vulkan.log")
.ok(),
MAX_LOG_SIZE,
);
writeln!(log_dupler, "Testing {}", name)?;
let device = unsafe { DeviceLoader::new(&instance, physical_device, &device_create_info) }?;
let queue = unsafe { device.get_device_queue(queue_family_index, 0) };
@ -641,10 +671,12 @@ fn test_device(
unsafe {
last_buffer_out = std::ptr::read(mapped);
}
if let Some((error_range, total_errors)) = last_buffer_out.get_error_addresses_and_count(test_offset) {
if let Some((error_range, total_errors)) =
last_buffer_out.get_error_addresses_and_count(test_offset)
{
no_errors = false;
let test_elems = test_window_size/ELEMENT_SIZE;
print!(
let test_elems = test_window_size / ELEMENT_SIZE;
write!(log_dupler,
"Error found. Mode {}, total errors 0x{:X} out of 0x{:X} ({:2.8}%)\nErrors address range: {:?}",
if reread_mode_for_this_win {
"NEXT_RE_READ"
@ -655,8 +687,8 @@ fn test_device(
test_elems,
total_errors as f64/test_elems as f64 * 100.0f64,
error_range,
);
println!(" deatils:\n{}", last_buffer_out);
)?;
writeln!(log_dupler, " deatils:\n{}", last_buffer_out)?;
}
last_buffer_out.check_vec_first()?;
}
@ -671,7 +703,7 @@ fn test_device(
} else {
speed_gbps = 0f32;
}
println!("{:7} iteration. Since last report passed {:15?} written {:6.1}GB, read: {:6.1}GB {:6.1}GB/sec", iteration, elapsed, written_bytes as f32 / GB, read_bytes as f32 / GB, speed_gbps);
writeln!(log_dupler, "{:7} iteration. Since last report passed {:15?} written {:6.1}GB, read: {:6.1}GB {:6.1}GB/sec", iteration, elapsed, written_bytes as f32 / GB, read_bytes as f32 / GB, speed_gbps)?;
if debug_mode {
println!("{}", last_buffer_out);
}
@ -926,8 +958,6 @@ fn init_vk_and_check_no_errors(debug_mode: bool) -> Result<bool, Box<dyn std::er
.get(selected_index)
.ok_or("No device at given index")?);
println!("Testing {}", numbered_devices[selected_index]);
let queue_create_info = vec![vk::DeviceQueueCreateInfoBuilder::new()
.queue_family_index(queue_family)
.queue_priorities(&[1.0])];
@ -941,6 +971,7 @@ fn init_vk_and_check_no_errors(debug_mode: bool) -> Result<bool, Box<dyn std::er
physical_device,
queue_family,
*device_create_info,
numbered_devices.swap_remove(selected_index),
debug_mode,
)?;
} else {

129
src/output.rs Normal file
View File

@ -0,0 +1,129 @@
use core::fmt;
use fs4::FileExt;
use std::{
collections::VecDeque,
fs::File,
io,
io::{Read, Seek, SeekFrom, Write},
};
/// Wrapper over a file that calls [`FileExt::unlock`] at [dropping][`Drop`].
pub struct FileLock<'a>(pub &'a File);
impl<'a> FileLock<'a> {
pub fn wrap_exclusive(f: &'a File) -> io::Result<Self> {
f.lock_exclusive()?;
Ok(Self(f))
}
}
impl<'a> core::ops::Deref for FileLock<'a> {
type Target = &'a File;
fn deref(&self) -> &Self::Target {
&self.0
}
}
impl<'a> core::ops::DerefMut for FileLock<'a> {
fn deref_mut(&mut self) -> &mut Self::Target {
&mut self.0
}
}
impl<'a> Drop for FileLock<'a> {
fn drop(&mut self) {
let _ = self.0.unlock();
}
}
pub struct NowTime;
impl fmt::Display for NowTime {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
use chrono::{DateTime, SecondsFormat, Utc};
let now = std::time::SystemTime::now();
let now: DateTime<Utc> = now.into();
write!(f, "{}", now.to_rfc3339_opts(SecondsFormat::Micros, true))
}
}
pub struct LogDupler<Writer: io::Write> {
pub writer: Writer,
pub log_file: Option<File>,
pub max_size: u64,
pub unlogged_buffer: VecDeque<u8>,
}
impl<Writer: io::Write> LogDupler<Writer> {
pub fn new(writer: Writer, log_file: Option<File>, max_size: u64) -> Self {
let mut initial_buf: Vec<u8> = Default::default();
let _ = writeln!(&mut initial_buf, "logging started at {}", NowTime);
Self {
writer: writer,
log_file: log_file,
max_size: max_size,
unlogged_buffer: initial_buf.into(),
}
}
fn write_deq_start(&mut self, len: usize) {
if let Some(file) = &self.log_file {
if let Ok(mut locked) = FileLock::wrap_exclusive(&file) {
let _ = locked.write_all(&self.unlogged_buffer.make_contiguous()[..len]);
if let Ok(metadata) = locked.metadata() {
let current_len = metadata.len();
if current_len > self.max_size {
let cut_len = current_len - self.max_size / 2u64;
let mut kept_buf = Vec::<_>::new();
if locked.seek(SeekFrom::Start(cut_len)).is_ok()
&& locked.read_to_end(&mut kept_buf).is_ok()
&& locked.set_len(0).is_ok()
&& locked.rewind().is_ok()
&& write!(locked, "... earlier log truncated at {}", NowTime).is_ok()
{
let _ = {
if let Some(line_end_pos) =
kept_buf.iter().position(|c| c == &b'\n')
{
locked.write_all(&kept_buf[line_end_pos..])
} else {
writeln!(locked, "")
}
};
}
}
}
}
}
self.unlogged_buffer.drain(..len);
}
}
impl<Writer: io::Write> Drop for LogDupler<Writer> {
fn drop(&mut self) {
let mut final_buf: Vec<u8> = Default::default();
let _ = writeln!(&mut final_buf, "logging finished at {}", NowTime);
self.unlogged_buffer.extend(final_buf);
let _ = self.flush();
if let Some(file) = &self.log_file {
if let Ok(locked) = FileLock::wrap_exclusive(&file) {
let _ = locked.sync_all();
}
}
}
}
impl<Writer: io::Write> Write for LogDupler<Writer> {
fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
let _ = self.writer.write(buf);
self.unlogged_buffer.extend(buf);
if let Some(rev_position) = self.unlogged_buffer.iter().rev().position(|c| c == &b'\n') {
self.write_deq_start(self.unlogged_buffer.len() - rev_position);
}
Ok(buf.len())
}
fn flush(&mut self) -> io::Result<()> {
let _ = self.writer.flush();
self.write_deq_start(self.unlogged_buffer.len());
Ok(())
}
}