feat(log): 将内核日志统一为新的logger (#814)

This commit is contained in:
曾俊
2024-05-16 17:25:23 +08:00
committed by GitHub
parent 92deae638b
commit 2eab6dd743
181 changed files with 1321 additions and 1261 deletions

View File

@ -11,6 +11,7 @@ use alloc::{
vec::Vec,
};
use lazy_static::__Deref;
use log::{debug, info};
use system_error::SystemError;
use unified_init::macros::unified_init;
@ -18,7 +19,6 @@ use crate::{
arch::CurrentIrqArch,
exception::InterruptArch,
init::initcall::INITCALL_LATE,
kdebug, kinfo,
libs::spinlock::SpinLock,
process::{
kthread::{KernelThreadClosure, KernelThreadMechanism},
@ -378,7 +378,7 @@ impl dyn Clocksource {
.expect("register: failed to enqueue watchdog list");
// 选择一个最好的时钟源
clocksource_select();
kdebug!("clocksource_register successfully");
debug!("clocksource_register successfully");
return Ok(());
}
@ -398,7 +398,7 @@ impl dyn Clocksource {
let cs = self.clocksource();
list_guard.push_back(cs);
list_guard.append(&mut temp_list);
// kdebug!(
// debug!(
// "CLOCKSOURCE_LIST len = {:?},clocksource_enqueue sccessfully",
// list_guard.len()
// );
@ -473,10 +473,9 @@ impl dyn Clocksource {
pub fn set_unstable(&self, delta: i64) -> Result<i32, SystemError> {
let mut cs_data = self.clocksource_data();
// 打印出unstable的时钟源信息
kdebug!(
debug!(
"clocksource :{:?} is unstable, its delta is {:?}",
cs_data.name,
delta
cs_data.name, delta
);
cs_data.flags.remove(
ClocksourceFlags::CLOCK_SOURCE_VALID_FOR_HRES | ClocksourceFlags::CLOCK_SOURCE_WATCHDOG,
@ -740,7 +739,7 @@ pub fn clocksource_resume() {
match ele.resume() {
Ok(_) => continue,
Err(_) => {
kdebug!("clocksource {:?} resume failed", data.name);
debug!("clocksource {:?} resume failed", data.name);
}
}
}
@ -756,7 +755,7 @@ pub fn clocksource_suspend() {
match ele.suspend() {
Ok(_) => continue,
Err(_) => {
kdebug!("clocksource {:?} suspend failed", data.name);
debug!("clocksource {:?} suspend failed", data.name);
}
}
}
@ -770,11 +769,11 @@ pub fn clocksource_suspend() {
/// * `Err(SystemError)` - 错误码
pub fn clocksource_watchdog() -> Result<(), SystemError> {
let mut cs_watchdog = CLOCKSOUCE_WATCHDOG.lock_irqsave();
// kdebug!("clocksource_watchdog start");
// debug!("clocksource_watchdog start");
// watchdog没有在运行的话直接退出
if !cs_watchdog.is_running || cs_watchdog.watchdog.is_none() {
// kdebug!("is_running = {:?},watchdog = {:?}", cs_watchdog.is_running, cs_watchdog.watchdog);
// debug!("is_running = {:?},watchdog = {:?}", cs_watchdog.is_running, cs_watchdog.watchdog);
return Ok(());
}
let cur_watchdog = cs_watchdog.watchdog.as_ref().unwrap().clone();
@ -797,7 +796,7 @@ pub fn clocksource_watchdog() -> Result<(), SystemError> {
.flags
.contains(ClocksourceFlags::CLOCK_SOURCE_UNSTABLE)
{
// kdebug!("clocksource_watchdog unstable");
// debug!("clocksource_watchdog unstable");
// 启动watchdog_kthread
run_watchdog_kthread();
continue;
@ -810,7 +809,7 @@ pub fn clocksource_watchdog() -> Result<(), SystemError> {
.flags
.contains(ClocksourceFlags::CLOCK_SOURCE_WATCHDOG)
{
// kdebug!("clocksource_watchdog start watch");
// debug!("clocksource_watchdog start watch");
cs_data
.flags
.insert(ClocksourceFlags::CLOCK_SOURCE_WATCHDOG);
@ -819,7 +818,7 @@ pub fn clocksource_watchdog() -> Result<(), SystemError> {
cs.update_clocksource_data(cs_data.clone())?;
continue;
}
// kdebug!("cs_data.watchdog_last = {:?},cs_now_clock = {:?}", cs_data.watchdog_last, cs_now_clock);
// debug!("cs_data.watchdog_last = {:?},cs_now_clock = {:?}", cs_data.watchdog_last, cs_now_clock);
// 计算时钟源的误差
let cs_dev_nsec = clocksource_cyc2ns(
CycleNum(cs_now_clock.div(cs_data.watchdog_last).data() & cs_data.mask.bits),
@ -830,14 +829,14 @@ pub fn clocksource_watchdog() -> Result<(), SystemError> {
cs_data.watchdog_last = cs_now_clock;
cs.update_clocksource_data(cs_data.clone())?;
if cs_dev_nsec.abs_diff(wd_dev_nsec) > WATCHDOG_THRESHOLD.into() {
// kdebug!("set_unstable");
// debug!("set_unstable");
// 误差过大标记为unstable
kinfo!("cs_dev_nsec = {}", cs_dev_nsec);
kinfo!("wd_dev_nsec = {}", wd_dev_nsec);
info!("cs_dev_nsec = {}", cs_dev_nsec);
info!("wd_dev_nsec = {}", wd_dev_nsec);
cs.set_unstable((cs_dev_nsec - wd_dev_nsec).try_into().unwrap())?;
continue;
}
// kdebug!("clocksource_watchdog aaa");
// debug!("clocksource_watchdog aaa");
// 判断是否要切换为高精度模式
if !cs_data
@ -900,7 +899,7 @@ fn __clocksource_watchdog_kthread() {
clock.clocksource_change_rating(0);
let mut data = clock.clocksource_data();
data.watchdog_last = clock.read();
kdebug!("kthread: watchdog_last = {:?}", data.watchdog_last);
debug!("kthread: watchdog_last = {:?}", data.watchdog_last);
data.flags.remove(ClocksourceFlags::CLOCK_SOURCE_UNSTABLE);
clock
.update_clocksource_data(data)
@ -917,7 +916,7 @@ fn __clocksource_watchdog_kthread() {
pub fn clocksource_watchdog_kthread() -> i32 {
// return 0;
loop {
// kdebug!("clocksource_watchdog_kthread start");
// debug!("clocksource_watchdog_kthread start");
__clocksource_watchdog_kthread();
if KernelThreadMechanism::should_stop(&ProcessManager::current_pcb()) {
break;
@ -969,7 +968,7 @@ pub fn clocksource_select() {
let cur_clocksource = CUR_CLOCKSOURCE.lock().as_ref().unwrap().clone();
let best_name = &best.clocksource_data().name;
if cur_clocksource.clocksource_data().name.ne(best_name) {
kinfo!("Switching to the clocksource {:?}\n", best_name);
info!("Switching to the clocksource {:?}\n", best_name);
drop(cur_clocksource);
CUR_CLOCKSOURCE.lock().replace(best.clone());
// TODO 通知timerkeeping 切换了时间源
@ -978,7 +977,7 @@ pub fn clocksource_select() {
// 当前时钟源为空
CUR_CLOCKSOURCE.lock().replace(best.clone());
}
kdebug!("clocksource_select finish, CUR_CLOCKSOURCE = {best:?}");
debug!("clocksource_select finish, CUR_CLOCKSOURCE = {best:?}");
}
/// # clocksource模块加载完成
@ -988,7 +987,7 @@ pub fn clocksource_boot_finish() {
FINISHED_BOOTING.store(true, Ordering::Relaxed);
// 清除不稳定的时钟源
__clocksource_watchdog_kthread();
kdebug!("clocksource_boot_finish");
debug!("clocksource_boot_finish");
}
fn run_watchdog_kthread() {

View File

@ -2,9 +2,10 @@ use alloc::{
string::ToString,
sync::{Arc, Weak},
};
use log::{error, info};
use system_error::SystemError;
use crate::{arch::time::CLOCK_TICK_RATE, kerror, kinfo, libs::spinlock::SpinLock};
use crate::{arch::time::CLOCK_TICK_RATE, libs::spinlock::SpinLock};
use super::{
clocksource::{Clocksource, ClocksourceData, ClocksourceFlags, ClocksourceMask, CycleNum, HZ},
@ -96,10 +97,10 @@ pub fn jiffies_init() {
let jiffies = clocksource_default_clock() as Arc<dyn Clocksource>;
match jiffies.register(1, 0) {
Ok(_) => {
kinfo!("jiffies_init sccessfully");
info!("jiffies_init sccessfully");
}
Err(_) => {
kerror!("jiffies_init failed, no default clock running");
error!("jiffies_init failed, no default clock running");
}
};
}

View File

@ -3,6 +3,7 @@ use core::{
time::Duration,
};
use log::warn;
use num_traits::FromPrimitive;
use system_error::SystemError;
@ -138,7 +139,7 @@ impl Syscall {
pub fn clock_gettime(clock_id: c_int, tp: *mut PosixTimeSpec) -> Result<usize, SystemError> {
let clock_id = PosixClockID::try_from(clock_id)?;
if clock_id != PosixClockID::Realtime {
kwarn!("clock_gettime: currently only support Realtime clock, but got {:?}. Defaultly return realtime!!!\n", clock_id);
warn!("clock_gettime: currently only support Realtime clock, but got {:?}. Defaultly return realtime!!!\n", clock_id);
}
if tp.is_null() {
return Err(SystemError::EFAULT);

View File

@ -1,11 +1,11 @@
use alloc::sync::Arc;
use core::sync::atomic::{compiler_fence, AtomicBool, AtomicI64, AtomicUsize, Ordering};
use log::{debug, info};
use system_error::SystemError;
use crate::{
arch::{CurrentIrqArch, CurrentTimeArch},
exception::InterruptArch,
kdebug, kinfo,
libs::rwlock::{RwLock, RwLockReadGuard},
time::{
jiffies::{clocksource_default_clock, jiffies_init},
@ -120,7 +120,7 @@ impl Timekeeper {
let mut clock_data = clock.clocksource_data();
clock_data.watchdog_last = clock.read();
if clock.update_clocksource_data(clock_data).is_err() {
kdebug!("timekeeper_setup_internals:update_clocksource_data run failed");
debug!("timekeeper_setup_internals:update_clocksource_data run failed");
}
timekeeper.clock.replace(clock.clone());
@ -193,7 +193,7 @@ pub fn timekeeper_init() {
///
/// * 'TimeSpec' - 时间戳
pub fn getnstimeofday() -> PosixTimeSpec {
// kdebug!("enter getnstimeofday");
// debug!("enter getnstimeofday");
let nsecs;
let mut xtime: PosixTimeSpec;
@ -218,7 +218,7 @@ pub fn getnstimeofday() -> PosixTimeSpec {
xtime.tv_nsec += nsecs as i64;
xtime.tv_sec += xtime.tv_nsec / NSEC_PER_SEC as i64;
xtime.tv_nsec %= NSEC_PER_SEC as i64;
// kdebug!("getnstimeofday: xtime = {:?}, nsecs = {:}", xtime, nsecs);
// debug!("getnstimeofday: xtime = {:?}, nsecs = {:}", xtime, nsecs);
// TODO 将xtime和当前时间源的时间相加
@ -248,7 +248,7 @@ pub fn do_settimeofday64(time: PosixTimeSpec) -> Result<(), SystemError> {
/// # 初始化timekeeping模块
#[inline(never)]
pub fn timekeeping_init() {
kinfo!("Initializing timekeeping module...");
info!("Initializing timekeeping module...");
let irq_guard = unsafe { CurrentIrqArch::save_and_disable_irq() };
timekeeper_init();
@ -274,12 +274,12 @@ pub fn timekeeping_init() {
drop(irq_guard);
drop(timekeeper);
jiffies_init();
kinfo!("timekeeping_init successfully");
info!("timekeeping_init successfully");
}
/// # 使用当前时钟源增加wall time
pub fn update_wall_time(delta_us: i64) {
// kdebug!("enter update_wall_time, stack_use = {:}",stack_use);
// debug!("enter update_wall_time, stack_use = {:}",stack_use);
compiler_fence(Ordering::SeqCst);
let irq_guard = unsafe { CurrentIrqArch::save_and_disable_irq() };
// 如果在休眠那就不更新

View File

@ -10,6 +10,7 @@ use alloc::{
sync::{Arc, Weak},
vec::Vec,
};
use log::{error, info, warn};
use system_error::SystemError;
use crate::{
@ -18,7 +19,6 @@ use crate::{
softirq::{softirq_vectors, SoftirqNumber, SoftirqVec},
InterruptArch,
},
kerror, kinfo,
libs::spinlock::{SpinLock, SpinLockGuard},
process::{ProcessControlBlock, ProcessManager},
sched::{schedule, SchedMode},
@ -160,7 +160,7 @@ impl Timer {
let mut split_pos: usize = 0;
for (pos, elt) in timer_list.iter().enumerate() {
if Arc::ptr_eq(&self_arc, &elt.1) {
kwarn!("Timer already in list");
warn!("Timer already in list");
}
if elt.0 > expire_jiffies {
split_pos = pos;
@ -180,7 +180,7 @@ impl Timer {
drop(timer);
let r = func.map(|mut f| f.run()).unwrap_or(Ok(()));
if unlikely(r.is_err()) {
kerror!(
error!(
"Failed to run timer function: {self:?} {:?}",
r.as_ref().err().unwrap()
);
@ -246,7 +246,7 @@ impl SoftirqVec for DoTimerSoftirq {
}
// 最多只处理TIMER_RUN_CYCLE_THRESHOLD个计时器
for _ in 0..TIMER_RUN_CYCLE_THRESHOLD {
// kdebug!("DoTimerSoftirq run");
// debug!("DoTimerSoftirq run");
let timer_list = TIMER_LIST.try_lock_irqsave();
if timer_list.is_err() {
continue;
@ -258,7 +258,7 @@ impl SoftirqVec for DoTimerSoftirq {
}
let (front_jiffies, timer_list_front) = timer_list.first().unwrap().clone();
// kdebug!("to lock timer_list_front");
// debug!("to lock timer_list_front");
if front_jiffies >= TIMER_JIFFIES.load(Ordering::SeqCst) {
break;
@ -280,7 +280,7 @@ pub fn timer_init() {
softirq_vectors()
.register_softirq(SoftirqNumber::TIMER, do_timer_softirq)
.expect("Failed to register timer softirq");
kinfo!("timer initialized successfully");
info!("timer initialized successfully");
}
/// 计算接下来n毫秒对应的定时器时间片
@ -300,7 +300,7 @@ pub fn next_n_us_timer_jiffies(expire_us: u64) -> u64 {
///
/// @return Err(SystemError) 错误码
pub fn schedule_timeout(mut timeout: i64) -> Result<i64, SystemError> {
// kdebug!("schedule_timeout");
// debug!("schedule_timeout");
if timeout == MAX_TIMEOUT {
let irq_guard = unsafe { CurrentIrqArch::save_and_disable_irq() };
ProcessManager::mark_sleep(true).ok();
@ -308,7 +308,7 @@ pub fn schedule_timeout(mut timeout: i64) -> Result<i64, SystemError> {
schedule(SchedMode::SM_NONE);
return Ok(MAX_TIMEOUT);
} else if timeout < 0 {
kerror!("timeout can't less than 0");
error!("timeout can't less than 0");
return Err(SystemError::EINVAL);
} else {
// 禁用中断,防止在这段期间发生调度,造成死锁
@ -337,16 +337,16 @@ pub fn schedule_timeout(mut timeout: i64) -> Result<i64, SystemError> {
pub fn timer_get_first_expire() -> Result<u64, SystemError> {
// FIXME
// kdebug!("rs_timer_get_first_expire,timer_jif = {:?}", TIMER_JIFFIES);
// debug!("rs_timer_get_first_expire,timer_jif = {:?}", TIMER_JIFFIES);
for _ in 0..10 {
match TIMER_LIST.try_lock_irqsave() {
Ok(timer_list) => {
// kdebug!("rs_timer_get_first_expire TIMER_LIST lock successfully");
// debug!("rs_timer_get_first_expire TIMER_LIST lock successfully");
if timer_list.is_empty() {
// kdebug!("timer_list is empty");
// debug!("timer_list is empty");
return Ok(0);
} else {
// kdebug!("timer_list not empty");
// debug!("timer_list not empty");
return Ok(timer_list.first().unwrap().0);
}
}