From 7cd1bdfd818a094a41bb55403c442423db6a53bf Mon Sep 17 00:00:00 2001 From: Andreas Kling Date: Sat, 29 Feb 2020 12:51:44 +0100 Subject: [PATCH] Kernel: Simplify some dbg() logging We don't have to log the process name/PID/TID, dbg() automatically adds that as a prefix to every line. Also we don't have to do .characters() on Strings passed to dbg() :^) --- Kernel/FileSystem/Ext2FileSystem.cpp | 10 ++++---- Kernel/Process.cpp | 34 ++++++++++++++-------------- Kernel/Scheduler.cpp | 14 ++++++------ Kernel/Thread.cpp | 6 ++--- Kernel/VM/Region.cpp | 17 +++++--------- 5 files changed, 38 insertions(+), 43 deletions(-) diff --git a/Kernel/FileSystem/Ext2FileSystem.cpp b/Kernel/FileSystem/Ext2FileSystem.cpp index 81f6337222..868859d781 100644 --- a/Kernel/FileSystem/Ext2FileSystem.cpp +++ b/Kernel/FileSystem/Ext2FileSystem.cpp @@ -245,8 +245,8 @@ bool Ext2FS::write_block_list_for_inode(InodeIndex inode_index, ext2_inode& e2in } if (inode_dirty) { #ifdef EXT2_DEBUG - dbg() << "Ext2FS: Writing " << min(EXT2_NDIR_BLOCKS, blocks.size()) << " direct block(s) to i_block array of inode " << inode_index; - for (int i = 0; i < min(EXT2_NDIR_BLOCKS, blocks.size()); ++i) + dbg() << "Ext2FS: Writing " << min((size_t)EXT2_NDIR_BLOCKS, blocks.size()) << " direct block(s) to i_block array of inode " << inode_index; + for (size_t i = 0; i < min((size_t)EXT2_NDIR_BLOCKS, blocks.size()); ++i) dbg() << " + " << blocks[i]; #endif write_ext2_inode(inode_index, e2inode); @@ -875,7 +875,7 @@ bool Ext2FSInode::traverse_as_directory(Functioninode != 0) { #ifdef EXT2_DEBUG - dbg() << "Ext2Inode::traverse_as_directory: " << entry->inode << ", name_len: " << entry->name_len << ", rec_len: " << entry->rec_len << ", file_type: " << entry->file_type << ", name: " << String(entry->name, entry->name_len).characters(); + dbg() << "Ext2Inode::traverse_as_directory: " << entry->inode << ", name_len: " << entry->name_len << ", rec_len: " << entry->rec_len << ", file_type: " << entry->file_type << ", name: " << String(entry->name, entry->name_len); #endif if (!callback({ entry->name, entry->name_len, { fsid(), entry->inode }, entry->file_type })) break; @@ -1384,7 +1384,7 @@ KResult Ext2FS::create_directory(InodeIdentifier parent_id, const String& name, auto& inode = inode_or_error.value(); #ifdef EXT2_DEBUG - dbg() << "Ext2FS: create_directory: created new directory named '" << name.characters() << "' with inode " << inode->identifier().index(); + dbg() << "Ext2FS: create_directory: created new directory named '" << name << "' with inode " << inode->identifier(); #endif Vector entries; @@ -1421,7 +1421,7 @@ KResultOr> Ext2FS::create_inode(InodeIdentifier parent_id, return KResult(-ENOENT); #ifdef EXT2_DEBUG - dbg() << "Ext2FS: Adding inode '" << name.characters() << "' (mode " << String::format("%o", mode) << ") to parent directory " << parent_inode->identifier().index(); + dbg() << "Ext2FS: Adding inode '" << name << "' (mode " << String::format("%o", mode) << ") to parent directory " << parent_inode->identifier(); #endif size_t needed_blocks = ceil_div(size, block_size()); diff --git a/Kernel/Process.cpp b/Kernel/Process.cpp index 70092e2e67..204b73fd4f 100644 --- a/Kernel/Process.cpp +++ b/Kernel/Process.cpp @@ -1093,14 +1093,14 @@ KResultOr> Process::find_elf_interpreter_for_exec auto elf_header = (Elf32_Ehdr*)first_page; if (!ELFImage::validate_elf_header(*elf_header, file_size)) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): File has invalid ELF header"; + dbg() << "exec(" << path << "): File has invalid ELF header"; return KResult(-ENOEXEC); } // Not using KResultOr here because we'll want to do the same thing in userspace in the RTLD String interpreter_path; if (!ELFImage::validate_program_headers(*elf_header, file_size, (u8*)first_page, nread, interpreter_path)) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): File has invalid ELF Program headers"; + dbg() << "exec(" << path << "): File has invalid ELF Program headers"; return KResult(-ENOEXEC); } @@ -1109,10 +1109,10 @@ KResultOr> Process::find_elf_interpreter_for_exec if (elf_header->e_type != ET_DYN) return KResult(-ENOEXEC); - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): Using program interpreter " << interpreter_path.characters(); + dbg() << "exec(" << path << "): Using program interpreter " << interpreter_path; auto interp_result = VFS::the().open(interpreter_path, O_EXEC, 0, current_directory()); if (interp_result.is_error()) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): Unable to open program interpreter " << interpreter_path.characters(); + dbg() << "exec(" << path << "): Unable to open program interpreter " << interpreter_path; return interp_result.error(); } auto interpreter_description = interp_result.value(); @@ -1133,19 +1133,19 @@ KResultOr> Process::find_elf_interpreter_for_exec elf_header = (Elf32_Ehdr*)first_page; if (!ELFImage::validate_elf_header(*elf_header, interp_metadata.size)) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): Interpreter (" << interpreter_description->absolute_path().characters() << ") has invalid ELF header"; + dbg() << "exec(" << path << "): Interpreter (" << interpreter_description->absolute_path() << ") has invalid ELF header"; return KResult(-ENOEXEC); } // Not using KResultOr here because we'll want to do the same thing in userspace in the RTLD String interpreter_interpreter_path; if (!ELFImage::validate_program_headers(*elf_header, interp_metadata.size, (u8*)first_page, nread, interpreter_interpreter_path)) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): Interpreter (" << interpreter_description->absolute_path().characters() << ") has invalid ELF Program headers"; + dbg() << "exec(" << path << "): Interpreter (" << interpreter_description->absolute_path() << ") has invalid ELF Program headers"; return KResult(-ENOEXEC); } if (!interpreter_interpreter_path.is_empty()) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): Interpreter (" << interpreter_description->absolute_path().characters() << ") has its own interpreter (" << interpreter_interpreter_path.characters() << ")! No thank you!"; + dbg() << "exec(" << path << "): Interpreter (" << interpreter_description->absolute_path() << ") has its own interpreter (" << interpreter_interpreter_path << ")! No thank you!"; return KResult(-ELOOP); } @@ -1165,7 +1165,7 @@ KResultOr> Process::find_elf_interpreter_for_exec int Process::exec(String path, Vector arguments, Vector environment, int recursion_depth) { if (recursion_depth > 2) { - dbg() << m_name.characters() << "(" << m_pid << ") exec(" << path.characters() << "): SHENANIGANS! recursed too far trying to find #! interpreter"; + dbg() << "exec(" << path << "): SHENANIGANS! recursed too far trying to find #! interpreter"; return -ELOOP; } @@ -1513,9 +1513,9 @@ void Process::crash(int signal, u32 eip) if (eip >= 0xc0000000 && ksyms_ready) { auto* ksym = ksymbolicate(eip); - dbg() << "\033[31;1m" << String::format("%p", eip) << " " << (ksym ? demangle(ksym->name).characters() : "(k?)") << " +" << (ksym ? eip - ksym->address : 0) << "\033[0m\n"; + dbg() << "\033[31;1m" << String::format("%p", eip) << " " << (ksym ? demangle(ksym->name) : "(k?)") << " +" << (ksym ? eip - ksym->address : 0) << "\033[0m\n"; } else if (m_elf_loader) { - dbg() << "\033[31;1m" << String::format("%p", eip) << " " << m_elf_loader->symbolicate(eip).characters() << "\033[0m\n"; + dbg() << "\033[31;1m" << String::format("%p", eip) << " " << m_elf_loader->symbolicate(eip) << "\033[0m\n"; } else { dbg() << "\033[31;1m" << String::format("%p", eip) << " (?)\033[0m\n"; } @@ -1683,7 +1683,7 @@ ssize_t Process::do_write(FileDescription& description, const u8* data, int data #endif if (!description.can_write()) { #ifdef IO_DEBUG - dbg() << "block write on " << description.absolute_path().characters(); + dbg() << "block write on " << description.absolute_path(); #endif if (Thread::current->block(description) != Thread::BlockResult::WokeNormally) { if (nwritten == 0) @@ -1716,7 +1716,7 @@ ssize_t Process::sys$write(int fd, const u8* data, ssize_t size) if (!validate_read(data, size)) return -EFAULT; #ifdef DEBUG_IO - dbg() << name().characters() << "(" << pid() << "): sys$write(" << fd << ", " << (void*)const_cast(data) << ", " << String::format("%u", size) << ")"; + dbg() << "sys$write(" << fd << ", " << (const void*)(data) << ", " << size << ")"; #endif auto description = file_description(fd); if (!description) @@ -1737,7 +1737,7 @@ ssize_t Process::sys$read(int fd, u8* buffer, ssize_t size) if (!validate_write(buffer, size)) return -EFAULT; #ifdef DEBUG_IO - dbg() << name().characters() << "(" << pid() << ") sys$read(" << fd << ", " << (void*)buffer << ", " << size << ")"; + dbg() << "sys$read(" << fd << ", " << (const void*)buffer << ", " << size << ")"; #endif auto description = file_description(fd); if (!description) @@ -1762,7 +1762,7 @@ int Process::sys$close(int fd) REQUIRE_PROMISE(stdio); auto description = file_description(fd); #ifdef DEBUG_IO - dbg() << name().characters() << "(" << pid() << ") sys$close(" << fd << ") " << description.ptr(); + dbg() << "sys$close(" << fd << ") " << description.ptr(); #endif if (!description) return -EBADF; @@ -2827,7 +2827,7 @@ int Process::sys$select(const Syscall::SC_select_params* params) return error; #if defined(DEBUG_IO) || defined(DEBUG_POLL_SELECT) - dbg() << name().characters() << "<" << pid() << "> selecting on (read:" << rfds.size() << ", write:" << wfds.size() << "), timeout=" << timeout; + dbg() << "selecting on (read:" << rfds.size() << ", write:" << wfds.size() << "), timeout=" << timeout; #endif if (!timeout || select_has_timeout) { @@ -2888,7 +2888,7 @@ int Process::sys$poll(pollfd* fds, int nfds, int timeout) } #if defined(DEBUG_IO) || defined(DEBUG_POLL_SELECT) - dbg() << name().characters() << "<" << pid() << "> polling on (read:" << rfds.size() << ", write:" << wfds.size() << "), timeout=" << timeout; + dbg() << "polling on (read:" << rfds.size() << ", write:" << wfds.size() << "), timeout=" << timeout; #endif if (has_timeout || timeout < 0) { @@ -3695,7 +3695,7 @@ void Process::terminate_due_to_signal(u8 signal) { ASSERT_INTERRUPTS_DISABLED(); ASSERT(signal < 32); - dbg() << "terminate_due_to_signal " << name().characters() << "(" << pid() << ") <- " << signal; + dbg() << "Terminating due to signal " << signal; m_termination_status = 0; m_termination_signal = signal; die(); diff --git a/Kernel/Scheduler.cpp b/Kernel/Scheduler.cpp index 0bbd4f5346..b9c2540202 100644 --- a/Kernel/Scheduler.cpp +++ b/Kernel/Scheduler.cpp @@ -343,7 +343,7 @@ bool Scheduler::pick_next() auto name = process.name(); auto pid = process.pid(); auto exit_status = Process::reap(process); - dbg() << "reaped unparented process " << name.characters() << "(" << pid << "), exit status: " << exit_status.si_status; + dbg() << "Scheduler: Reaped unparented process " << name << "(" << pid << "), exit status: " << exit_status.si_status; } return IterationDecision::Continue; } @@ -374,7 +374,7 @@ bool Scheduler::pick_next() if (thread.dispatch_one_pending_signal() == ShouldUnblockThread::No) return IterationDecision::Continue; if (was_blocked) { - dbg() << "Unblock " << thread.process().name().characters() << "(" << thread.pid() << ") due to signal"; + dbg() << "Unblock " << thread << " due to signal"; ASSERT(thread.m_blocker != nullptr); thread.m_blocker->set_interrupted_by_signal(); thread.unblock(); @@ -385,13 +385,13 @@ bool Scheduler::pick_next() #ifdef SCHEDULER_RUNNABLE_DEBUG dbg() << "Non-runnables:"; Scheduler::for_each_nonrunnable([](Thread& thread) -> IterationDecision { - dbg() << " " << String::format("%-12s", thread.state_string()) << " " << thread.name().characters() << "(" << thread.pid() << ":" << thread.tid() << ") @ " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); + dbg() << " " << String::format("%-12s", thread.state_string()) << " " << thread << " @ " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); return IterationDecision::Continue; }); dbg() << "Runnables:"; Scheduler::for_each_runnable([](Thread& thread) -> IterationDecision { - dbg() << " " << String::format("%3u", thread.effective_priority()) << "/" << String::format("%2u", thread.priority()) << " " << String::format("%-12s", thread.state_string()) << " " << thread.name().characters() << "(" << thread.pid() << ":" << thread.tid() << ") @ " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); + dbg() << " " << String::format("%3u", thread.effective_priority()) << "/" << String::format("%2u", thread.priority()) << " " << String::format("%-12s", thread.state_string()) << " " << thread << " @ " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); return IterationDecision::Continue; }); #endif @@ -426,7 +426,7 @@ bool Scheduler::pick_next() thread_to_schedule = g_colonel; #ifdef SCHEDULER_DEBUG - dbg() << "switch to " << thread_to_schedule->name().characters() << " (" << thread_to_schedule->pid() << ":" << thread_to_schedule->tid() << ") @ " << String::format("%w", thread_to_schedule->tss().cs) << ":" << String::format("%x", thread_to_schedule->tss().eip); + dbg() << "Scheduler: Switch to " << *thread_to_schedule << " @ " << String::format("%04x:%08x", thread_to_schedule->tss().cs, thread_to_schedule->tss().eip); #endif return context_switch(*thread_to_schedule); @@ -445,7 +445,7 @@ bool Scheduler::donate_to(Thread* beneficiary, const char* reason) unsigned ticks_to_donate = min(ticks_left - 1, time_slice_for(*beneficiary)); #ifdef SCHEDULER_DEBUG - dbg() << Process::current->name().characters() << "(" << Process::current->pid() << ":" << Thread::current->tid() << ") donating " << ticks_to_donate << " ticks to " << beneficiary->process().name().characters() << " (" << beneficiary->pid() << ":" << beneficiary->tid() << "), reason=" << reason; + dbg() << "Scheduler: Donating " << ticks_to_donate << " ticks to " << *beneficiary << ", reason=" << reason; #endif context_switch(*beneficiary); beneficiary->set_ticks_left(ticks_to_donate); @@ -496,7 +496,7 @@ bool Scheduler::context_switch(Thread& thread) : "=m"(Thread::current->fpu_state())); #ifdef LOG_EVERY_CONTEXT_SWITCH - dbg() << "Scheduler: " << Process::current->name().characters() << " (" << Process::current->pid() << ":" << Thread::current->tid() << ") -> " << thread.process().name().characters() << "(" << thread.process().pid() << ":" << thread.tid() << ") [" << thread.priority() << "] " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); + dbg() << "Scheduler: " << *Thread::current << " -> " << thread << " [" << thread.priority() << "] " << String::format("%w", thread.tss().cs) << ":" << String::format("%x", thread.tss().eip); #endif } diff --git a/Kernel/Thread.cpp b/Kernel/Thread.cpp index 4047a6d6d5..87412c557f 100644 --- a/Kernel/Thread.cpp +++ b/Kernel/Thread.cpp @@ -348,16 +348,16 @@ void Thread::send_signal(u8 signal, [[maybe_unused]] Process* sender) // FIXME: Figure out what to do for masked signals. Should we also ignore them here? if (should_ignore_signal(signal)) { #ifdef SIGNAL_DEBUG - dbg() << "signal " << signal << " was ignored by " << process(); + dbg() << "Signal " << signal << " was ignored by " << process(); #endif return; } #ifdef SIGNAL_DEBUG if (sender) - dbg() << "signal: " << sender->name().characters() << "(" << sender->pid() << ") sent " << signal << " to " << process().name().characters() << "(" << pid() << ")"; + dbg() << "Signal: " << *sender << " sent " << signal << " to " << process(); else - dbg() << "signal: kernel sent " << signal << " to " << process().name().characters() << "(" << pid() << ")"; + dbg() << "Signal: Kernel sent " << signal << " to " << process(); #endif m_pending_signals |= 1 << (signal - 1); diff --git a/Kernel/VM/Region.cpp b/Kernel/VM/Region.cpp index 752fb4e18a..574c860988 100644 --- a/Kernel/VM/Region.cpp +++ b/Kernel/VM/Region.cpp @@ -28,10 +28,10 @@ #include #include #include -#include #include #include #include +#include //#define MM_DEBUG //#define PAGE_FAULT_DEBUG @@ -80,7 +80,7 @@ NonnullOwnPtr Region::clone() if (m_shared || vmobject().is_inode()) { ASSERT(!m_stack); #ifdef MM_DEBUG - dbg() << Process::current->name().characters() << "<" << Process::current->pid() << "> Region::clone(): sharing " << m_name.characters() << " (V" << String::format("%p", vaddr().get()) << ")"; + dbg() << "Region::clone(): Sharing " << name() << " (" << vaddr() << ")"; #endif // Create a new region backed by the same VMObject. auto region = Region::create_user_accessible(m_range, m_vmobject, m_offset_in_vmobject, m_name, m_access); @@ -90,12 +90,10 @@ NonnullOwnPtr Region::clone() } #ifdef MM_DEBUG - // FIXME: If m_name.characters() is returning null pointer, the debug message will lead to a crash - // For now we use String::format() to mitigate that. - dbg() << Process::current->name().characters() << "<" << Process::current->pid() << "> Region::clone(): cowing " << String::format("%s", m_name.characters()) << " (V" << String::format("%p", vaddr().get()) << ")", + dbg() << "Region::clone(): CoWing " << name() << " (" << vaddr() << ")"; #endif - // Set up a COW region. The parent (this) region becomes COW as well! - ensure_cow_map().fill(true); + // Set up a COW region. The parent (this) region becomes COW as well! + ensure_cow_map().fill(true); remap(); auto clone_region = Region::create_user_accessible(m_range, m_vmobject->clone(), m_offset_in_vmobject, m_name, m_access); clone_region->ensure_cow_map(); @@ -114,7 +112,7 @@ bool Region::commit() { InterruptDisabler disabler; #ifdef MM_DEBUG - dbg() << "MM: commit " << vmobject().page_count() << " pages in Region " << this << " (VMO=" << &vmobject() << ") at V" << String::format("%p", vaddr().get()); + dbg() << "MM: Commit " << page_count() << " pages in Region " << this << " (VMO=" << &vmobject() << ") at " << vaddr(); #endif for (size_t i = 0; i < page_count(); ++i) { if (!commit(i)) @@ -127,9 +125,6 @@ bool Region::commit(size_t page_index) { ASSERT(vmobject().is_anonymous() || vmobject().is_purgeable()); InterruptDisabler disabler; -#ifdef MM_DEBUG - dbg() << "MM: commit single page" << String::format("%zu", page_index, vmobject().page_count()) << "in Region " << this << " (VMO=" << &vmobject() << ") at V" << String::format("%p", vaddr().get()); -#endif auto& vmobject_physical_page_entry = vmobject().physical_pages()[first_page_index() + page_index]; if (!vmobject_physical_page_entry.is_null() && !vmobject_physical_page_entry->is_shared_zero_page()) return true;