simplify DebugLog and implement sys_debuglog_read (#94)

pass DebugLogTest.WriteRead
`dlog` command is available
This commit is contained in:
Runji Wang 2020-07-07 18:55:04 +08:00 committed by GitHub
parent eb958cf5a5
commit c5707461fc
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 126 additions and 175 deletions

View File

@ -97,7 +97,6 @@ ExecutableTlsTest.StructureInitializerInThread
ExecutableTlsTest.StructureInitalizierInMain
ExecutableTlsTest.AlignmentInitializerInThread
ExecutableTlsTest.AlignmentInitializierInMain
ExecutableTlsTest.ArrayInitializerSpamThread
ExecutableTlsTest.ArrayInitializierSpamMain
EventPairTest.HandlesNotInvalid
EventPairTest.HandleRightsAreCorrect
@ -460,3 +459,4 @@ InterruptTest.UnBindPort
InterruptTest.VirtualInterrupts
InterruptTest.UnableToBindVirtualInterruptToVcpu
InterruptTest.NullOutputTimestamp
DebugLogTest.WriteRead

View File

@ -1,200 +1,118 @@
use {
super::*, crate::object::*, alloc::sync::Arc, core::convert::TryInto, kernel_hal::serial_write,
kernel_hal::timer_now, spin::Mutex,
super::*,
crate::object::*,
alloc::{sync::Arc, vec::Vec},
kernel_hal::timer_now,
lazy_static::lazy_static,
spin::Mutex,
};
static DLOG: Mutex<DlogBuffer> = Mutex::new(DlogBuffer::new());
#[cfg(not(test))]
const DLOG_SIZE: usize = 128usize * 1024usize;
#[cfg(test)]
const DLOG_SIZE: usize = 2usize * 1024usize;
const DLOG_MASK: usize = DLOG_SIZE - 1;
const DLOG_MIN_RECORD: usize = 32usize;
#[repr(C)]
struct DlogHeader {
header: u32,
datalen: u16,
flags: u16,
timestamp: u64,
pid: u64,
tid: u64,
lazy_static! {
static ref DLOG: Mutex<DlogBuffer> = Mutex::new(DlogBuffer {
buf: Vec::with_capacity(0x1000),
});
}
pub struct DebugLog {
base: KObjectBase,
flags: u32,
read_offset: Mutex<usize>,
}
struct DlogBuffer {
/// Append only buffer
buf: Vec<u8>,
}
impl_kobject!(DebugLog);
impl DebugLog {
/// Create a new `DebugLog`.
pub fn create(flags: u32) -> Arc<Self> {
Arc::new(DebugLog {
base: KObjectBase::new(),
flags,
read_offset: Default::default(),
})
}
pub fn write(&self, flags: u32, data: &str, tid: u64, pid: u64) -> ZxResult<usize> {
let flags = flags | self.flags;
DLOG.lock().write(flags, data.as_bytes(), tid, pid);
serial_write(data);
if data.as_bytes().last() != Some(&b'\n') {
serial_write("\n");
}
Ok(0)
/// Read a log, return the actual read size.
pub fn read(&self, buf: &mut [u8]) -> usize {
let mut offset = self.read_offset.lock();
let len = DLOG.lock().read_at(*offset, buf);
*offset += len;
len
}
/// Write a log.
pub fn write(&self, severity: Severity, flags: u32, tid: u64, pid: u64, data: &str) {
DLOG.lock()
.write(severity, flags | self.flags, tid, pid, data.as_bytes());
}
}
struct DlogBuffer {
buf: [u8; DLOG_SIZE],
head: usize,
tail: usize,
#[repr(C)]
#[derive(Debug)]
struct DlogHeader {
rollout: u32,
datalen: u16,
severity: Severity,
flags: u8,
timestamp: u64,
pid: u64,
tid: u64,
}
#[repr(u8)]
#[derive(Debug)]
pub enum Severity {
Trace = 0x10,
Debug = 0x20,
Info = 0x30,
Warning = 0x40,
Error = 0x50,
Fatal = 0x60,
}
const HEADER_SIZE: usize = core::mem::size_of::<DlogHeader>();
pub const DLOG_MAX_LEN: usize = 256;
#[allow(unsafe_code)]
impl DlogBuffer {
pub const fn new() -> Self {
DlogBuffer {
buf: [0u8; DLOG_SIZE],
head: 0usize,
tail: 0usize,
/// Read one record at offset.
#[allow(clippy::cast_ptr_alignment)]
fn read_at(&mut self, offset: usize, buf: &mut [u8]) -> usize {
assert!(buf.len() >= DLOG_MAX_LEN);
if offset == self.buf.len() {
return 0;
}
let header_buf = &self.buf[offset..offset + HEADER_SIZE];
buf[..HEADER_SIZE].copy_from_slice(header_buf);
let header = unsafe { &*(header_buf.as_ptr() as *const DlogHeader) };
let len = (header.rollout & 0xFFF) as usize;
buf[HEADER_SIZE..len].copy_from_slice(&self.buf[offset + HEADER_SIZE..offset + len]);
len
}
#[allow(unsafe_code)]
pub fn write(&mut self, flags: u32, data: &[u8], tid: u64, pid: u64) {
let wire_size = DLOG_MIN_RECORD + ((data.len() + 3) & !3);
let header_flag = (((DLOG_MIN_RECORD + data.len()) as u32 & 0xFFFu32) << 12)
| (wire_size as u32 & 0xFFFu32);
fn write(&mut self, severity: Severity, flags: u32, tid: u64, pid: u64, data: &[u8]) {
let wire_size = HEADER_SIZE + align_up_4(data.len());
let size = HEADER_SIZE + data.len();
let header = DlogHeader {
header: header_flag,
rollout: ((size as u32) << 12) | (wire_size as u32),
datalen: data.len() as u16,
flags: flags as u16,
timestamp: timer_now().as_secs(),
severity,
flags: flags as u8,
timestamp: timer_now().as_nanos() as u64,
pid,
tid,
};
let serde_header: [u8; core::mem::size_of::<DlogHeader>()] =
unsafe { core::mem::transmute(header) };
let head = self.head;
while (head - self.tail) > (DLOG_SIZE - wire_size) {
let tail_index = self.tail & DLOG_MASK;
let header: u32 =
u32::from_ne_bytes(self.buf[tail_index..tail_index + 4].try_into().unwrap());
self.tail += (header & 0xFFF) as usize;
}
let mut offset = head & DLOG_MASK;
let fifo_size = DLOG_SIZE - offset;
if fifo_size >= wire_size {
self.copy_and_write(offset, &serde_header);
self.copy_and_write(offset + DLOG_MIN_RECORD, data);
} else if fifo_size < DLOG_MIN_RECORD {
self.copy_and_write(offset, &serde_header[..fifo_size]);
self.copy_and_write(0, &serde_header[fifo_size..]);
self.copy_and_write(DLOG_MIN_RECORD - fifo_size, data);
} else {
self.copy_and_write(offset, &serde_header);
offset += DLOG_MIN_RECORD;
if offset < DLOG_SIZE {
let fifo_size = DLOG_SIZE - offset;
self.copy_and_write(offset, &data[..fifo_size]);
self.copy_and_write(0, &data[fifo_size..]);
} else {
self.copy_and_write(0, data);
}
}
self.head += wire_size;
}
fn copy_and_write(&mut self, start: usize, data: &[u8]) {
let end = start + data.len();
assert!(start < DLOG_SIZE);
assert!(end <= DLOG_SIZE);
assert!(start <= end);
if start < end {
self.buf[start..end].copy_from_slice(data);
}
}
#[cfg(test)]
pub fn get_head(&self) -> usize {
self.head & DLOG_MASK
}
#[cfg(test)]
pub fn get_tail(&self) -> usize {
self.tail & DLOG_MASK
}
#[cfg(test)]
pub fn check(&self, position: usize, value: u8) -> bool {
assert!(position < DLOG_SIZE);
assert_eq!(self.buf[position], value);
self.buf[position] == value
let header_buf: [u8; HEADER_SIZE] = unsafe { core::mem::transmute(header) };
self.buf.extend(header_buf.iter());
self.buf.extend(data);
self.buf.extend(&[0u8; 4][..wire_size - size]);
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn buffer_cover1() {
let mut buffer = DlogBuffer::new();
buffer.write(0u32, &[127u8; 100], 0, 0);
let head = buffer.get_head();
assert_eq!(head, 132usize);
let tail = buffer.get_tail();
assert_eq!(tail, 0usize);
buffer.write(0u32, &[255u8; 2000], 0, 0);
let head = buffer.get_head();
assert_eq!(head, 116usize);
let tail = buffer.get_tail();
assert_eq!(tail, 132usize);
}
#[test]
fn buffer_cover2() {
let mut buffer = DlogBuffer::new();
buffer.write(0u32, &[127u8; 2000], 0, 0);
for i in 32..2032 {
assert!(buffer.check(i, 127u8));
}
let head = buffer.get_head();
assert_eq!(head, 2032usize);
let tail = buffer.get_tail();
assert_eq!(tail, 0usize);
buffer.write(0u32, &[255u8; 101], 0, 0);
for i in 16..117 {
assert!(buffer.check(i, 255u8));
}
for i in 117..2032 {
assert!(buffer.check(i, 127u8));
}
let head = buffer.get_head();
assert_eq!(head, 120usize);
let tail = buffer.get_tail();
assert_eq!(tail, 2032usize);
}
#[test]
fn buffer_cover3() {
let mut buffer = DlogBuffer::new();
buffer.write(0u32, &[127u8; 1984], 0, 0);
buffer.write(0xdead_beafu32, &[255u8; 101], 0, 0);
for i in 0..101 {
assert!(buffer.check(i, 255u8));
}
for i in 102..2016 {
assert!(buffer.check(i, 127u8));
}
assert!(buffer.check(2022, 0xafu8));
assert!(buffer.check(2023, 0xbeu8));
let head = buffer.get_head();
assert_eq!(head, 104usize);
let tail = buffer.get_tail();
assert_eq!(tail, 2016usize);
}
fn align_up_4(x: usize) -> usize {
(x + 3) & !3
}

View File

@ -1,10 +1,8 @@
use {
super::*,
zircon_object::{debuglog::DebugLog, dev::*},
zircon_object::{debuglog::*, dev::*},
};
const FLAG_READABLE: u32 = 0x4000_0000u32;
impl Syscall<'_> {
pub fn sys_debuglog_create(
&self,
@ -22,6 +20,7 @@ impl Syscall<'_> {
.validate(ResourceKind::ROOT)?;
}
let dlog = DebugLog::create(options);
const FLAG_READABLE: u32 = 0x4000_0000u32;
let dlog_right = if options & FLAG_READABLE == 0 {
Rights::DEFAULT_DEBUGLOG
} else {
@ -35,22 +34,55 @@ impl Syscall<'_> {
pub fn sys_debuglog_write(
&self,
handle_value: HandleValue,
flags: u32,
options: u32,
buf: UserInPtr<u8>,
len: usize,
) -> ZxResult {
info!(
"debuglog.write: handle={:#x?}, flags={:#x?}, buf=({:#x?}; {:#x?})",
handle_value, flags, buf, len,
"debuglog.write: handle={:#x?}, options={:#x?}, buf=({:#x?}; {:#x?})",
handle_value, options, buf, len,
);
const LOG_FLAGS_MASK: u32 = 0x10;
if options & !LOG_FLAGS_MASK != 0 {
return Err(ZxError::INVALID_ARGS);
}
let datalen = len.min(224);
let data = buf.read_string(datalen as usize)?;
let thread = &self.thread;
let proc = thread.proc();
let tid = thread.id();
let pid = proc.id();
proc.get_object_with_rights::<DebugLog>(handle_value, Rights::WRITE)?
.write(flags, &data, tid, pid)?;
let proc = self.thread.proc();
let dlog = proc.get_object_with_rights::<DebugLog>(handle_value, Rights::WRITE)?;
dlog.write(Severity::Info, options, self.thread.id(), proc.id(), &data);
// print to kernel console
kernel_hal::serial_write(&data);
if data.as_bytes().last() != Some(&b'\n') {
kernel_hal::serial_write("\n");
}
Ok(())
}
#[allow(unsafe_code)]
pub fn sys_debuglog_read(
&self,
handle_value: HandleValue,
options: u32,
mut buf: UserOutPtr<u8>,
len: usize,
) -> ZxResult {
info!(
"debuglog.read: handle={:#x?}, options={:#x?}, buf=({:#x?}; {:#x?})",
handle_value, options, buf, len,
);
if options != 0 {
return Err(ZxError::INVALID_ARGS);
}
let proc = self.thread.proc();
let mut buffer = [0; DLOG_MAX_LEN];
let dlog = proc.get_object_with_rights::<DebugLog>(handle_value, Rights::READ)?;
let actual_len = dlog.read(&mut buffer).min(len);
if actual_len == 0 {
return Err(ZxError::SHOULD_WAIT);
}
buf.write_array(&buffer[..actual_len])?;
// special case: return actual_len as status
Err(unsafe { core::mem::transmute(actual_len as u32) })
}
}

View File

@ -245,6 +245,7 @@ impl Syscall<'_> {
Sys::DEBUG_WRITE => self.sys_debug_write(a0.into(), a1 as _),
Sys::DEBUGLOG_CREATE => self.sys_debuglog_create(a0 as _, a1 as _, a2.into()),
Sys::DEBUGLOG_WRITE => self.sys_debuglog_write(a0 as _, a1 as _, a2.into(), a3 as _),
Sys::DEBUGLOG_READ => self.sys_debuglog_read(a0 as _, a1 as _, a2.into(), a3 as _),
Sys::RESOURCE_CREATE => self.sys_resource_create(
a0 as _,
a1 as _,