diff --git a/hermit/arch/x86/kernel/apic.c b/hermit/arch/x86/kernel/apic.c index cacc23af1..3319b2c70 100644 --- a/hermit/arch/x86/kernel/apic.c +++ b/hermit/arch/x86/kernel/apic.c @@ -35,6 +35,7 @@ #include #include #include +#include #include #include #include @@ -201,7 +202,7 @@ static inline void x2apic_disable(void) msr = rdmsr(MSR_APIC_BASE); if (!(msr & MSR_X2APIC_ENABLE)) { - //kprintf("X2APIC already disabled!\n"); + LOG_WARNING("X2APIC already disabled!\n"); return; } @@ -209,7 +210,7 @@ static inline void x2apic_disable(void) wrmsr(MSR_APIC_BASE, msr & ~(MSR_X2APIC_ENABLE | MSR_XAPIC_ENABLE)); wrmsr(MSR_APIC_BASE, msr & ~MSR_X2APIC_ENABLE); - //kprintf("Disable X2APIC support\n"); + LOG_DEBUG("Disable X2APIC support\n"); lapic_read = lapic_read_default; lapic_write = lapic_write_default; } @@ -228,13 +229,13 @@ static inline void x2apic_enable(void) msr = rdmsr(MSR_APIC_BASE); if (msr & MSR_X2APIC_ENABLE) { - //kprintf("X2APIC already enabled!\n"); + LOG_WARNING("X2APIC already enabled!\n"); return; } wrmsr(MSR_APIC_BASE, msr | MSR_X2APIC_ENABLE); - //kprintf("Enable X2APIC support!\n"); + LOG_DEBUG("Enable X2APIC support!\n"); } /* @@ -327,8 +328,7 @@ int apic_timer_is_running(void) int apic_timer_deadline(uint32_t ticks) { if (BUILTIN_EXPECT(apic_is_enabled() && icr, 1)) { - //kprintf("timer oneshot %ld at core %d\n", ticks, CORE_ID); - + LOG_DEBUG("timer oneshot %ld at core %d\n", ticks, CORE_ID); lapic_timer_oneshot(); lapic_timer_set_counter(ticks * icr); @@ -420,7 +420,7 @@ static size_t search_ebda(void) { return 0; uint16_t addr = *((uint16_t*) (vptr+0x40E)); - kprintf("Found EBDA at 0x%x!\n", (uint32_t)addr); + LOG_INFO("Found EBDA at 0x%x!\n", (uint32_t)addr); // unmap page via mapping a zero page page_unmap(vptr, 1); @@ -467,30 +467,31 @@ static int lapic_reset(void) */ static int wakeup_ap(uint32_t start_eip, uint32_t id) { - static char* reset_vector = 0; - uint32_t i; + static char* reset_vector = 0; + uint32_t i; - kprintf("Wakeup application processor %d via IPI\n", id); + LOG_INFO("Wakeup application processor %d via IPI\n", id); - // set shutdown code to 0x0A - cmos_write(0x0F, 0x0A); + // set shutdown code to 0x0A + cmos_write(0x0F, 0x0A); if (!reset_vector) { reset_vector = (char*) vma_alloc(PAGE_SIZE, VMA_READ|VMA_WRITE); - page_map((size_t)reset_vector, 0x00, 1, PG_RW|PG_GLOBAL|PG_PCD); - reset_vector += 0x467; // add base address of the reset vector - kprintf("Map reset vector to %p\n", reset_vector); - } - *((volatile unsigned short *) (reset_vector+2)) = start_eip >> 4; - *((volatile unsigned short *) reset_vector) = 0x00; + page_map((size_t)reset_vector, 0x00, 1, PG_RW|PG_GLOBAL|PG_PCD); + reset_vector += 0x467; // add base address of the reset vector + LOG_INFO("Map reset vector to %p\n", reset_vector); + } - if (lapic_read(APIC_ICR1) & APIC_ICR_BUSY) { - kputs("ERROR: previous send not complete"); - return -EIO; - } + *((volatile unsigned short *) (reset_vector+2)) = start_eip >> 4; + *((volatile unsigned short *) reset_vector) = 0x00; + + if (lapic_read(APIC_ICR1) & APIC_ICR_BUSY) { + LOG_ERROR("Previous send not complete\n"); + return -EIO; + } - //kputs("Send IPI\n"); // send out INIT to AP + LOG_DEBUG("Send IPI\n"); if (has_x2apic()) { uint64_t dest = ((uint64_t)id << 32); @@ -518,7 +519,7 @@ static int wakeup_ap(uint32_t start_eip, uint32_t id) else udelay(10); - //kputs("IPI done...\n"); + LOG_DEBUG("IPI done...\n"); return 0; } else { @@ -549,7 +550,7 @@ static int wakeup_ap(uint32_t start_eip, uint32_t id) else udelay(10); - //kputs("IPI done...\n"); + LOG_DEBUG("IPI done...\n"); i = 0; while((lapic_read(APIC_ICR1) & APIC_ICR_BUSY) && (i < 1000)) @@ -567,7 +568,7 @@ int smp_init(void) if (ncores <= 1) return -EINVAL; - kprintf("CR0 of core %u: 0x%x\n", apic_cpu_id(), read_cr0()); + LOG_INFO("CR0 of core %u: 0x%x\n", apic_cpu_id(), read_cr0()); /* * dirty hack: Reserve memory for the bootup code. @@ -589,7 +590,7 @@ int smp_init(void) } } - //kprintf("size of the boot_code %d\n", sizeof(boot_code)); + LOG_DEBUG("size of the boot_code %d\n", sizeof(boot_code)); for(i=1; (i= atomic_int32_read(&cpu_online)) && (j < 1000); j++) udelay(1000); if (i >= atomic_int32_read(&cpu_online)) { - kprintf("Unable to wakeup processor %d, cpu_online %d\n", i, atomic_int32_read(&cpu_online)); + LOG_ERROR("Unable to wakeup processor %d, cpu_online %d\n", i, atomic_int32_read(&cpu_online)); return -EIO; } } - kprintf("%d cores online\n", atomic_int32_read(&cpu_online)); + LOG_INFO("%d cores online\n", atomic_int32_read(&cpu_online)); return 0; } @@ -658,7 +659,7 @@ int apic_calibration(void) lapic_reset(); - kprintf("APIC calibration determined an ICR of 0x%x\n", icr); + LOG_INFO("APIC calibration determined an ICR of 0x%x\n", icr); apic_initialized = 1; atomic_int32_inc(&cpu_online); @@ -716,7 +717,7 @@ static int apic_probe(void) found_mp: if (!apic_mp) { - kprintf("Didn't found MP config table\n"); + LOG_ERROR("Didn't find MP config table\n"); goto no_mp; } @@ -725,19 +726,19 @@ found_mp: isle = 0; } - kprintf("Found MP config table at 0x%x\n", apic_mp->mp_config); - kprintf("System uses Multiprocessing Specification 1.%u\n", apic_mp->version); - kprintf("MP features 1: %u\n", apic_mp->features[0]); + LOG_INFO("Found MP config table at 0x%x\n", apic_mp->mp_config); + LOG_INFO("System uses Multiprocessing Specification 1.%u\n", apic_mp->version); + LOG_INFO("MP features 1: %u\n", apic_mp->features[0]); if (apic_mp->features[0]) { - kputs("Currently, HermitCore supports only multiprocessing via the MP config tables!\n"); + LOG_ERROR("Currently, HermitCore supports only multiprocessing via the MP config tables!\n"); goto no_mp; } if (apic_mp->features[1] & 0x80) - kputs("PIC mode implemented\n"); + LOG_INFO("PIC mode implemented\n"); else - kputs("Virtual-Wire mode implemented\n"); + LOG_INFO("Virtual-Wire mode implemented\n"); apic_config = (apic_config_table_t*) ((size_t) apic_mp->mp_config); if (((size_t) apic_config & PAGE_MASK) != ((size_t) apic_mp & PAGE_MASK)) { @@ -746,7 +747,7 @@ found_mp: } if (!apic_config || strncmp((void*) &apic_config->signature, "PCMP", 4) !=0) { - kputs("Invalid MP config table\n"); + LOG_ERROR("Invalid MP config table\n"); goto no_mp; } @@ -803,29 +804,29 @@ found_mp: } else if (*((uint8_t*) addr) == 2) { // IO_APIC apic_io_entry_t* io_entry = (apic_io_entry_t*) addr; ioapic = (ioapic_t*) ((size_t) io_entry->addr); - kprintf("Found IOAPIC at 0x%x\n", ioapic); + LOG_INFO("Found IOAPIC at 0x%x\n", ioapic); if (is_single_kernel() && ioapic) { page_map(IOAPIC_ADDR, (size_t)ioapic & PAGE_MASK, 1, flags); vma_add(IOAPIC_ADDR, IOAPIC_ADDR + PAGE_SIZE, VMA_READ|VMA_WRITE); ioapic = (ioapic_t*) IOAPIC_ADDR; - kprintf("Map IOAPIC to 0x%x\n", ioapic); - kprintf("IOAPIC version: 0x%x\n", ioapic_version()); - kprintf("Max Redirection Entry: %u\n", ioapic_max_redirection_entry()); + LOG_INFO("Map IOAPIC to 0x%x\n", ioapic); + LOG_INFO("IOAPIC version: 0x%x\n", ioapic_version()); + LOG_INFO("Max Redirection Entry: %u\n", ioapic_max_redirection_entry()); } addr += 8; } else if (*((uint8_t*) addr) == 3) { // IO_INT apic_ioirq_entry_t* extint = (apic_ioirq_entry_t*) addr; if (extint->src_bus == isa_bus) { irq_redirect[extint->src_irq] = extint->dest_intin; - kprintf("Redirect irq %u -> %u\n", extint->src_irq, extint->dest_intin); + LOG_INFO("Redirect irq %u -> %u\n", extint->src_irq, extint->dest_intin); } addr += 8; } else addr += 8; } - kprintf("Found %u cores\n", count); + LOG_INFO("Found %u cores\n", count); if (count > MAX_CORES) { - kputs("Found too many cores! Increase the macro MAX_CORES!\n"); + LOG_ERROR("Found too many cores! Increase the macro MAX_CORES!\n"); goto no_mp; } ncores = count; @@ -840,33 +841,33 @@ check_lapic: if (!lapic) goto out; - kprintf("Found APIC at 0x%x\n", lapic); + LOG_INFO("Found APIC at 0x%x\n", lapic); if (has_x2apic()) { - kputs("Found and enable X2APIC\n"); + LOG_INFO("Found and enable X2APIC\n"); x2apic_enable(); } else { if (page_map(LAPIC_ADDR, (size_t)lapic & PAGE_MASK, 1, flags)) { - kprintf("Failed to map APIC to 0x%x\n", LAPIC_ADDR); + LOG_ERROR("Failed to map APIC to 0x%x\n", LAPIC_ADDR); goto out; } else { - kprintf("Mapped APIC 0x%x to 0x%x\n", lapic, LAPIC_ADDR); + LOG_INFO("Mapped APIC 0x%x to 0x%x\n", lapic, LAPIC_ADDR); vma_add(LAPIC_ADDR, LAPIC_ADDR + PAGE_SIZE, VMA_READ | VMA_WRITE); lapic = LAPIC_ADDR; } } - kprintf("Maximum LVT Entry: 0x%x\n", apic_lvt_entries()); - kprintf("APIC Version: 0x%x\n", apic_version()); - kprintf("EOI-broadcast: %s\n", (apic_broadcast()) ? "available" : "unavailable"); + LOG_INFO("Maximum LVT Entry: 0x%x\n", apic_lvt_entries()); + LOG_INFO("APIC Version: 0x%x\n", apic_version()); + LOG_INFO("EOI-broadcast: %s\n", (apic_broadcast()) ? "available" : "unavailable"); if (!((apic_version() >> 4))) { - kprintf("Currently, HermitCore didn't supports extern APICs!\n"); + LOG_ERROR("Currently, HermitCore doesn't support external APICs!\n"); goto out; } if (apic_lvt_entries() < 3) { - kprintf("LVT is too small\n"); + LOG_ERROR("LVT is too small\n"); goto out; } @@ -902,7 +903,7 @@ int smp_start(void) // reset APIC and set id lapic_reset(); - kprintf("Processor %d (local id %d) is entering its idle task\n", apic_cpu_id(), atomic_int32_read(¤t_boot_id)); + LOG_INFO("Processor %d (local id %d) is entering its idle task\n", apic_cpu_id(), atomic_int32_read(¤t_boot_id)); // use the same gdt like the boot processors gdt_flush(); @@ -919,7 +920,7 @@ int smp_start(void) // enable additional cpu features cpu_detection(); - //kprintf("CR0 of core %u: 0x%x\n", atomic_int32_read(¤t_boot_id), read_cr0()); + LOG_DEBUG("CR0 of core %u: 0x%x\n", atomic_int32_read(¤t_boot_id), read_cr0()); online[atomic_int32_read(¤t_boot_id)] = 1; // set task switched flag for the first FPU access @@ -953,13 +954,13 @@ int ipi_tlb_flush(void) if (!online[i]) continue; - //kprintf("Send IPI to %zd\n", i); + LOG_DEBUG("Send IPI to %zd\n", i); wrmsr(0x830, (i << 32)|APIC_INT_ASSERT|APIC_DM_FIXED|112); } irq_nested_enable(flags); } else { if (lapic_read(APIC_ICR1) & APIC_ICR_BUSY) { - kputs("ERROR: previous send not complete"); + LOG_ERROR("Previous send not complete"); return -EIO; } @@ -971,7 +972,7 @@ int ipi_tlb_flush(void) if (!online[i]) continue; - //kprintf("Send IPI to %zd\n", i); + LOG_DEBUG("Send IPI to %zd\n", i); set_ipi_dest(i); lapic_write(APIC_ICR1, APIC_INT_ASSERT|APIC_DM_FIXED|112); @@ -987,7 +988,7 @@ int ipi_tlb_flush(void) static void apic_tlb_handler(struct state *s) { - //kprintf("Receive IPI at core %d to flush the TLB\n", CORE_ID); + LOG_DEBUG("Receive IPI at core %d to flush the TLB\n", CORE_ID); write_cr3(read_cr3()); } #endif @@ -999,7 +1000,7 @@ int apic_send_ipi(uint64_t dest, uint8_t irq) if (has_x2apic()) { flags = irq_nested_disable(); - //kprintf("send IPI %d to %lld\n", (int)irq, dest); + LOG_DEBUG("send IPI %d to %lld\n", (int)irq, dest); wrmsr(0x830, (dest << 32)|APIC_INT_ASSERT|APIC_DM_FIXED|irq); irq_nested_enable(flags); } else { @@ -1009,7 +1010,7 @@ int apic_send_ipi(uint64_t dest, uint8_t irq) PAUSE; } - //kprintf("send IPI %d to %lld\n", (int)irq, dest); + LOG_DEBUG("send IPI %d to %lld\n", (int)irq, dest); set_ipi_dest((uint32_t)dest); lapic_write(APIC_ICR1, APIC_INT_ASSERT|APIC_DM_FIXED|irq); @@ -1027,7 +1028,7 @@ int apic_send_ipi(uint64_t dest, uint8_t irq) static void apic_err_handler(struct state *s) { - kprintf("Got APIC error 0x%x\n", lapic_read(APIC_ESR)); + LOG_ERROR("Got APIC error 0x%x\n", lapic_read(APIC_ESR)); } void shutdown_system(void) @@ -1037,7 +1038,7 @@ void shutdown_system(void) irq_disable(); if (if_bootprocessor) { - kprintf("Try to shutdown HermitCore\n"); + LOG_INFO("Try to shutdown HermitCore\n"); //vma_dump(); dump_pstate(); @@ -1047,13 +1048,13 @@ void shutdown_system(void) network_shutdown(); - kprintf("Disable APIC timer\n"); + LOG_INFO("Disable APIC timer\n"); } apic_disable_timer(); if (if_bootprocessor) - kprintf("Disable APIC\n"); + LOG_INFO("Disable APIC\n"); lapic_write(APIC_LVT_TSR, 0x10000); // disable thermal sensor interrupt lapic_write(APIC_LVT_PMC, 0x10000); // disable performance counter interrupt @@ -1065,7 +1066,7 @@ void shutdown_system(void) if (if_bootprocessor) { print_irq_stats(); - kprintf("System goes down...\n"); + LOG_INFO("System goes down...\n"); } flush_cache(); @@ -1082,13 +1083,13 @@ static void apic_shutdown(struct state * s) { go_down = 1; - //kputs("Receive shutdown interrupt\n"); + LOG_DEBUG("Receive shutdown interrupt\n"); } static void apic_lint0(struct state * s) { // Currently nothing to do - kputs("Receive LINT0 interrupt\n"); + LOG_INFO("Receive LINT0 interrupt\n"); } int apic_init(void) @@ -1107,9 +1108,9 @@ int apic_init(void) irq_install_handler(81+32, apic_shutdown); irq_install_handler(124, apic_lint0); if (apic_processors[boot_processor]) - kprintf("Boot processor %u (ID %u)\n", boot_processor, apic_processors[boot_processor]->id); + LOG_INFO("Boot processor %u (ID %u)\n", boot_processor, apic_processors[boot_processor]->id); else - kprintf("Boot processor %u\n", boot_processor); + LOG_INFO("Boot processor %u\n", boot_processor); online[boot_processor] = 1; return 0; @@ -1121,7 +1122,7 @@ int ioapic_inton(uint8_t irq, uint8_t apicid) uint32_t off; if (BUILTIN_EXPECT(irq > 24, 0)){ - kprintf("IOAPIC: trying to turn on irq %i which is too high\n", irq); + LOG_ERROR("IOAPIC: trying to turn on irq %i which is too high\n", irq); return -EINVAL; } @@ -1159,7 +1160,7 @@ int ioapic_intoff(uint8_t irq, uint8_t apicid) uint32_t off; if (BUILTIN_EXPECT(irq > 24, 0)){ - kprintf("IOAPIC: trying to turn on irq %i which is too high\n", irq); + LOG_ERROR("IOAPIC: trying to turn off irq %i which is too high\n", irq); return -EINVAL; } diff --git a/hermit/arch/x86/kernel/irq.c b/hermit/arch/x86/kernel/irq.c index f6621003a..d308d6b81 100644 --- a/hermit/arch/x86/kernel/irq.c +++ b/hermit/arch/x86/kernel/irq.c @@ -38,6 +38,7 @@ #include #include #include +#include #include #include #include @@ -290,7 +291,7 @@ size_t** irq_handler(struct state *s) size_t** ret = NULL; if(BUILTIN_EXPECT(s->int_no >= MAX_HANDLERS, 0)) { - kprintf("[%d] Invalid IRQ number %d\n", CORE_ID, s->int_no); + LOG_ERROR("Invalid IRQ number %d\n", s->int_no); return NULL; } @@ -303,7 +304,7 @@ size_t** irq_handler(struct state *s) if (handler) { handler(s); } else { - kprintf("[%d] Unhandled IRQ %d\n", CORE_ID, s->int_no); + LOG_ERROR("Unhandled IRQ %d\n", s->int_no); } // Check if timers have expired that would unblock tasks @@ -324,7 +325,7 @@ size_t** irq_handler(struct state *s) diff = rdtsc() - diff; if (diff > 15000) { - kprintf("Core %d, irq_no %d: %lld : %lld\n", CORE_ID, s->int_no, irq_counter[CORE_ID][s->int_no], diff); + LOG_INFO("Core %d, irq_no %d: %lld : %lld\n", CORE_ID, s->int_no, irq_counter[CORE_ID][s->int_no], diff); } } #endif @@ -349,7 +350,7 @@ void print_irq_stats(void) for(j=0; j #include #include +#include #include #include #include @@ -209,13 +210,13 @@ static void fault_handler(struct state *s) { if (s->int_no < 32) - kputs(exception_messages[s->int_no]); + LOG_INFO("%s", exception_messages[s->int_no]); else - kprintf("Unknown exception %d", s->int_no); + LOG_WARNING("Unknown exception %d", s->int_no); - kprintf(" Exception (%d) on core %d at %#x:%#lx, fs = %#lx, gs = %#lx, error code = 0x%#lx, task id = %u, rflags = %#x\n", + LOG_ERROR(" Exception (%d) on core %d at %#x:%#lx, fs = %#lx, gs = %#lx, error code = 0x%#lx, task id = %u, rflags = %#x\n", s->int_no, CORE_ID, s->cs, s->rip, s->fs, s->gs, s->error, per_core(current_task)->id, s->rflags); - kprintf("rax %#lx, rbx %#lx, rcx %#lx, rdx %#lx, rbp, %#lx, rsp %#lx rdi %#lx, rsi %#lx, r8 %#lx, r9 %#lx, r10 %#lx, r11 %#lx, r12 %#lx, r13 %#lx, r14 %#lx, r15 %#lx\n", + LOG_ERROR("rax %#lx, rbx %#lx, rcx %#lx, rdx %#lx, rbp, %#lx, rsp %#lx rdi %#lx, rsi %#lx, r8 %#lx, r9 %#lx, r10 %#lx, r11 %#lx, r12 %#lx, r13 %#lx, r14 %#lx, r15 %#lx\n", s->rax, s->rbx, s->rcx, s->rdx, s->rbp, s->rsp, s->rdi, s->rsi, s->r8, s->r9, s->r10, s->r11, s->r12, s->r13, s->r14, s->r15); apic_eoi(s->int_no); diff --git a/hermit/arch/x86/kernel/pci.c b/hermit/arch/x86/kernel/pci.c index e9a697241..79991b69f 100644 --- a/hermit/arch/x86/kernel/pci.c +++ b/hermit/arch/x86/kernel/pci.c @@ -28,6 +28,7 @@ #include #include #include +#include #include #include @@ -193,7 +194,7 @@ int print_pci_adapters(void) if (adapters[bus][slot] != -1) { counter++; - kprintf("%d) Vendor ID: 0x%x Device Id: 0x%x\n", + LOG_INFO("%d) Vendor ID: 0x%x Device Id: 0x%x\n", counter, adapters[bus][slot] & 0xffff, (adapters[bus][slot] & 0xffff0000) >> 16); @@ -201,7 +202,7 @@ int print_pci_adapters(void) for (i=0; i> 16) == PciDevTable[i].DevId) { - kprintf + LOG_INFO ("\tChip: %s ChipDesc: %s\n", PciDevTable[i].Chip, PciDevTable[i].ChipDesc); diff --git a/hermit/arch/x86/kernel/processor.c b/hermit/arch/x86/kernel/processor.c index 050bc9841..d97c942e9 100644 --- a/hermit/arch/x86/kernel/processor.c +++ b/hermit/arch/x86/kernel/processor.c @@ -31,6 +31,7 @@ #include #include #include +#include #include /* @@ -201,7 +202,7 @@ static uint32_t get_frequency_from_brand(void) cpuid(0x80000002, bint+0, bint+1, bint+2, bint+3); cpuid(0x80000003, bint+4, bint+5, bint+6, bint+7); cpuid(0x80000004, bint+8, bint+9, bint+10, bint+11); - kprintf("Processor: %s\n", brand); + LOG_INFO("Processor: %s\n", brand); for(index=0; index> 8) & 0xff); - kprintf("Sysenter instruction: %s\n", (cpu_info.feature1 & CPU_FEATURE_SEP) ? "available" : "unavailable"); - kprintf("Syscall instruction: %s\n", (cpu_info.feature3 & CPU_FEATURE_SYSCALL) ? "available" : "unavailable"); + LOG_INFO("Physical adress-width: %u bits\n", cpu_info.addr_width & 0xff); + LOG_INFO("Linear adress-width: %u bits\n", (cpu_info.addr_width >> 8) & 0xff); + LOG_INFO("Sysenter instruction: %s\n", (cpu_info.feature1 & CPU_FEATURE_SEP) ? "available" : "unavailable"); + LOG_INFO("Syscall instruction: %s\n", (cpu_info.feature3 & CPU_FEATURE_SYSCALL) ? "available" : "unavailable"); } //TODO: add check for SMEP and SMAP @@ -507,7 +508,7 @@ int cpu_detection(void) { xcr0 |= 0xE0; xsetbv(0, xcr0); - kprintf("Set XCR0 to 0x%llx\n", xgetbv(0)); + LOG_INFO("Set XCR0 to 0x%llx\n", xgetbv(0)); } // libos => currently no support of syscalls @@ -518,7 +519,7 @@ int cpu_detection(void) { wrmsr(MSR_LSTAR, (size_t) &isrsyscall); // clear IF flag during an interrupt wrmsr(MSR_SYSCALL_MASK, EFLAGS_TF|EFLAGS_DF|EFLAGS_IF|EFLAGS_AC|EFLAGS_NT); - } else kputs("Processor doesn't support syscalls\n"); + } else LOG_INFO("Processor doesn't support syscalls\n"); #endif if (has_nx()) @@ -535,15 +536,15 @@ int cpu_detection(void) { #endif wrmsr(MSR_KERNEL_GS_BASE, 0); - kprintf("Core %d set per_core offset to 0x%x\n", atomic_int32_read(¤t_boot_id), rdmsr(MSR_GS_BASE)); + LOG_INFO("Core %d set per_core offset to 0x%x\n", atomic_int32_read(¤t_boot_id), rdmsr(MSR_GS_BASE)); - /* set core id to the current boor id */ + /* set core id to the current boot id */ set_per_core(__core_id, atomic_int32_read(¤t_boot_id)); - kprintf("Core id is set to %d\n", CORE_ID); + LOG_INFO("Core id is set to %d\n", CORE_ID); if (has_fpu()) { if (first_time) - kputs("Found and initialized FPU!\n"); + LOG_INFO("Found and initialized FPU!\n"); asm volatile ("fninit"); } @@ -552,7 +553,7 @@ int cpu_detection(void) { a = b = c = d = 0; cpuid(1, &a, &b, &cpu_info.feature2, &cpu_info.feature1); - kprintf("CPU features: %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s\n", + LOG_INFO("CPU features: %s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s%s\n", has_sse() ? "SSE " : "", has_sse2() ? "SSE2 " : "", has_sse3() ? "SSE3 " : "", @@ -588,17 +589,17 @@ int cpu_detection(void) { a = b = d = 0; c = 2; cpuid(0xd, &a, &b, &c, &d); - kprintf("Ext_Save_Area_2: offset %d, size %d\n", b, a); + LOG_INFO("Ext_Save_Area_2: offset %d, size %d\n", b, a); a = b = d = 0; c = 3; cpuid(0xd, &a, &b, &c, &d); - kprintf("Ext_Save_Area_3: offset %d, size %d\n", b, a); + LOG_INFO("Ext_Save_Area_3: offset %d, size %d\n", b, a); a = b = d = 0; c = 4; cpuid(0xd, &a, &b, &c, &d); - kprintf("Ext_Save_Area_4: offset %d, size %d\n", b, a); + LOG_INFO("Ext_Save_Area_4: offset %d, size %d\n", b, a); save_fpu_state = save_fpu_state_xsave; restore_fpu_state = restore_fpu_state_xsave; @@ -616,7 +617,7 @@ int cpu_detection(void) { uint32_t c, d; char vendor_id[13]; - kprintf("HermitCore is running on a hypervisor!\n"); + LOG_INFO("HermitCore is running on a hypervisor!\n"); cpuid(0x40000000, &a, &b, &c, &d); memcpy(vendor_id, &b, 4); @@ -624,42 +625,42 @@ int cpu_detection(void) { memcpy(vendor_id + 8, &d, 4); vendor_id[12] = '\0'; - kprintf("Hypervisor Vendor Id: %s\n", vendor_id); - kprintf("Maximum input value for hypervisor: 0x%x\n", a); + LOG_INFO("Hypervisor Vendor Id: %s\n", vendor_id); + LOG_INFO("Maximum input value for hypervisor: 0x%x\n", a); } if (first_time) { - kprintf("CR0 0x%llx, CR4 0x%llx\n", read_cr0(), read_cr4()); - kprintf("size of xsave_t: %d\n", sizeof(xsave_t)); + LOG_INFO("CR0 0x%llx, CR4 0x%llx\n", read_cr0(), read_cr4()); + LOG_INFO("size of xsave_t: %d\n", sizeof(xsave_t)); if (has_msr()) { uint64_t msr; - kprintf("IA32_MISC_ENABLE 0x%llx\n", rdmsr(MSR_IA32_MISC_ENABLE)); - kprintf("IA32_PLATFORM_ID 0x%llx\n", rdmsr(MSR_IA32_PLATFORM_ID)); + LOG_INFO("IA32_MISC_ENABLE 0x%llx\n", rdmsr(MSR_IA32_MISC_ENABLE)); + LOG_INFO("IA32_PLATFORM_ID 0x%llx\n", rdmsr(MSR_IA32_PLATFORM_ID)); if (has_pat()) { msr = rdmsr(MSR_IA32_CR_PAT); - kprintf("IA32_CR_PAT 0x%llx\n", msr); - kprintf("PAT use per default %s\n", (msr & 0xF) == 0x6 ? "writeback." : "NO writeback!"); + LOG_INFO("IA32_CR_PAT 0x%llx\n", msr); + LOG_INFO("PAT use per default %s\n", (msr & 0xF) == 0x6 ? "writeback." : "NO writeback!"); } msr = rdmsr(MSR_MTRRdefType); - kprintf("MTRR is %s.\n", (msr & (1 << 11)) ? "enabled" : "disabled"); - kprintf("Fixed-range MTRR is %s.\n", (msr & (1 << 10)) ? "enabled" : "disabled"); - kprintf("MTRR used per default %s\n", (msr & 0xFF) == 0x6 ? "writeback." : "NO writeback!"); + LOG_INFO("MTRR is %s.\n", (msr & (1 << 11)) ? "enabled" : "disabled"); + LOG_INFO("Fixed-range MTRR is %s.\n", (msr & (1 << 10)) ? "enabled" : "disabled"); + LOG_INFO("MTRR used per default %s\n", (msr & 0xFF) == 0x6 ? "writeback." : "NO writeback!"); #if 0 if (msr & (1 << 10)) { - kprintf("MSR_MTRRfix64K_00000 0x%llx\n", rdmsr(MSR_MTRRfix64K_00000)); - kprintf("MSR_MTRRfix16K_80000 0x%llx\n", rdmsr(MSR_MTRRfix16K_80000)); - kprintf("MSR_MTRRfix16K_A0000 0x%llx\n", rdmsr(MSR_MTRRfix16K_A0000)); - kprintf("MSR_MTRRfix4K_C0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_C0000)); - kprintf("MSR_MTRRfix4K_C8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_C8000)); - kprintf("MSR_MTRRfix4K_D0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_D0000)); - kprintf("MSR_MTRRfix4K_D8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_D8000)); - kprintf("MSR_MTRRfix4K_E0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_E0000)); - kprintf("MSR_MTRRfix4K_E8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_E8000)); - kprintf("MSR_MTRRfix4K_F0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_F0000)); - kprintf("MSR_MTRRfix4K_F8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_F8000)); + LOG_INFO("MSR_MTRRfix64K_00000 0x%llx\n", rdmsr(MSR_MTRRfix64K_00000)); + LOG_INFO("MSR_MTRRfix16K_80000 0x%llx\n", rdmsr(MSR_MTRRfix16K_80000)); + LOG_INFO("MSR_MTRRfix16K_A0000 0x%llx\n", rdmsr(MSR_MTRRfix16K_A0000)); + LOG_INFO("MSR_MTRRfix4K_C0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_C0000)); + LOG_INFO("MSR_MTRRfix4K_C8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_C8000)); + LOG_INFO("MSR_MTRRfix4K_D0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_D0000)); + LOG_INFO("MSR_MTRRfix4K_D8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_D8000)); + LOG_INFO("MSR_MTRRfix4K_E0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_E0000)); + LOG_INFO("MSR_MTRRfix4K_E8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_E8000)); + LOG_INFO("MSR_MTRRfix4K_F0000 0x%llx\n", rdmsr(MSR_MTRRfix4K_F0000)); + LOG_INFO("MSR_MTRRfix4K_F8000 0x%llx\n", rdmsr(MSR_MTRRfix4K_F8000)); } #endif } diff --git a/hermit/arch/x86/kernel/syscall.c b/hermit/arch/x86/kernel/syscall.c index ffddee2c2..bf0152f87 100644 --- a/hermit/arch/x86/kernel/syscall.c +++ b/hermit/arch/x86/kernel/syscall.c @@ -30,6 +30,7 @@ #include #include #include +#include void __startcontext(void); @@ -40,7 +41,7 @@ void makecontext(ucontext_t *ucp, void (*func)(), int argc, ...) if (BUILTIN_EXPECT(!ucp, 0)) return; - //kprintf("sys_makecontext %p, func %p, stack 0x%zx, task %d\n", ucp, func, ucp->uc_stack.ss_sp, per_core(current_task)->id); + LOG_DEBUG("sys_makecontext %p, func %p, stack 0x%zx, task %d\n", ucp, func, ucp->uc_stack.ss_sp, per_core(current_task)->id); size_t* stack = (size_t*) ((size_t)ucp->uc_stack.ss_sp + ucp->uc_stack.ss_size); stack -= (argc > 6 ? argc - 6 : 0) + 1; @@ -93,6 +94,6 @@ int swapcontext(ucontext_t *oucp, const ucontext_t *ucp) { //TODO: implementation is missing - kprintf("WARNING: sys_swapcontext is currently not implemented: %p <=> %p\n", oucp, ucp); + LOG_WARNING("sys_swapcontext is currently not implemented: %p <=> %p\n", oucp, ucp); return -ENOSYS; } diff --git a/hermit/arch/x86/kernel/tasks.c b/hermit/arch/x86/kernel/tasks.c index 759753ec5..3bff78226 100644 --- a/hermit/arch/x86/kernel/tasks.c +++ b/hermit/arch/x86/kernel/tasks.c @@ -34,6 +34,7 @@ #include #include #include +#include #include #include @@ -88,8 +89,8 @@ int create_default_frame(task_t* task, entry_point_t ep, void* arg, uint32_t cor if (BUILTIN_EXPECT(!task->stack, 0)) return -EINVAL; - kprintf("Task %d uses memory region [%p - %p] as stack\n", task->id, task->stack, (char*) task->stack + KERNEL_STACK_SIZE - 1); - kprintf("Task %d uses memory region [%p - %p] as IST1\n", task->id, task->ist_addr, (char*) task->ist_addr + KERNEL_STACK_SIZE - 1); + LOG_INFO("Task %d uses memory region [%p - %p] as stack\n", task->id, task->stack, (char*) task->stack + KERNEL_STACK_SIZE - 1); + LOG_INFO("Task %d uses memory region [%p - %p] as IST1\n", task->id, task->ist_addr, (char*) task->ist_addr + KERNEL_STACK_SIZE - 1); memset(task->stack, 0xCD, DEFAULT_STACK_SIZE); diff --git a/hermit/arch/x86/kernel/timer.c b/hermit/arch/x86/kernel/timer.c index f3b70875d..f44b49f2e 100644 --- a/hermit/arch/x86/kernel/timer.c +++ b/hermit/arch/x86/kernel/timer.c @@ -32,6 +32,7 @@ #include #include #include +#include #include #include #include @@ -95,7 +96,7 @@ static void timer_handler(struct state *s) * display a message on the screen */ if (timer_ticks % TIMER_FREQ == 0) { - kprintf("One second has passed %d\n", CORE_ID); + LOG_INFO("One second has passed %d\n", CORE_ID); } #endif } diff --git a/hermit/arch/x86/kernel/uart.c b/hermit/arch/x86/kernel/uart.c index e1fd53140..3be2dbbf3 100644 --- a/hermit/arch/x86/kernel/uart.c +++ b/hermit/arch/x86/kernel/uart.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include #include @@ -298,11 +299,11 @@ Lsuccess: irq_install_handler(32+pci_info.irq, uart_handler); if (pci_info.type[0]) { mmio = 0; - kprintf("UART uses io address 0x%x\n", iobase); + LOG_INFO("UART uses io address 0x%x\n", iobase); } else { mmio = 1; page_map(iobase & PAGE_MASK, iobase & PAGE_MASK, 1, PG_GLOBAL | PG_ACCESSED | PG_DIRTY | PG_RW | PG_PCD); - kprintf("UART uses mmio address 0x%x\n", iobase); + LOG_INFO("UART uses mmio address 0x%x\n", iobase); vma_add(iobase, iobase + PAGE_SIZE, VMA_READ|VMA_WRITE); } diff --git a/hermit/arch/x86/mm/page.c b/hermit/arch/x86/mm/page.c index 68612d537..ed5446ae9 100644 --- a/hermit/arch/x86/mm/page.c +++ b/hermit/arch/x86/mm/page.c @@ -40,6 +40,7 @@ #include #include #include +#include #include #include @@ -258,7 +259,7 @@ void page_fault_handler(struct state *s) size_t phyaddr = expect_zeroed_pages ? get_zeroed_page() : get_page(); if (BUILTIN_EXPECT(!phyaddr, 0)) { - kprintf("out of memory: task = %u\n", task->id); + LOG_ERROR("out of memory: task = %u\n", task->id); goto default_handler; } @@ -268,7 +269,7 @@ void page_fault_handler(struct state *s) ret = __page_map(viraddr, phyaddr, 1, flags, 0); if (BUILTIN_EXPECT(ret, 0)) { - kprintf("map_region: could not map %#lx to %#lx, task = %u\n", phyaddr, viraddr, task->id); + LOG_ERROR("map_region: could not map %#lx to %#lx, task = %u\n", phyaddr, viraddr, task->id); put_page(phyaddr); goto default_handler; @@ -282,17 +283,17 @@ void page_fault_handler(struct state *s) default_handler: spinlock_irqsave_unlock(&page_lock); - kprintf("Page Fault Exception (%d) on core %d at cs:ip = %#x:%#lx, fs = %#lx, gs = %#lx, rflags 0x%lx, task = %u, addr = %#lx, error = %#x [ %s %s %s %s %s ]\n", + LOG_ERROR("Page Fault Exception (%d) on core %d at cs:ip = %#x:%#lx, fs = %#lx, gs = %#lx, rflags 0x%lx, task = %u, addr = %#lx, error = %#x [ %s %s %s %s %s ]\n", s->int_no, CORE_ID, s->cs, s->rip, s->fs, s->gs, s->rflags, task->id, viraddr, s->error, (s->error & 0x4) ? "user" : "supervisor", (s->error & 0x10) ? "instruction" : "data", (s->error & 0x2) ? "write" : ((s->error & 0x10) ? "fetch" : "read"), (s->error & 0x1) ? "protection" : "not present", (s->error & 0x8) ? "reserved bit" : "\b"); - kprintf("rax %#lx, rbx %#lx, rcx %#lx, rdx %#lx, rbp, %#lx, rsp %#lx rdi %#lx, rsi %#lx, r8 %#lx, r9 %#lx, r10 %#lx, r11 %#lx, r12 %#lx, r13 %#lx, r14 %#lx, r15 %#lx\n", + LOG_ERROR("rax %#lx, rbx %#lx, rcx %#lx, rdx %#lx, rbp, %#lx, rsp %#lx rdi %#lx, rsi %#lx, r8 %#lx, r9 %#lx, r10 %#lx, r11 %#lx, r12 %#lx, r13 %#lx, r14 %#lx, r15 %#lx\n", s->rax, s->rbx, s->rcx, s->rdx, s->rbp, s->rsp, s->rdi, s->rsi, s->r8, s->r9, s->r10, s->r11, s->r12, s->r13, s->r14, s->r15); if (task->heap) - kprintf("Heap 0x%llx - 0x%llx\n", task->heap->start, task->heap->end); + LOG_ERROR("Heap 0x%llx - 0x%llx\n", task->heap->start, task->heap->end); apic_eoi(s->int_no); //do_abort(); @@ -308,11 +309,11 @@ int page_init(void) // => Go expect zeroed pages => set zeroed_pages to true if (runtime_osinit) { expect_zeroed_pages = 1; - kputs("Detect Go runtime! Consequently, HermitCore zeroed heap.\n"); + LOG_INFO("Detect Go runtime! Consequently, HermitCore zeroed heap.\n"); } if (mb_info && ((mb_info->cmdline & PAGE_MASK) != ((size_t) mb_info & PAGE_MASK))) { - kprintf("Map multiboot cmdline 0x%x into the virtual address space\n", mb_info->cmdline); + LOG_INFO("Map multiboot cmdline 0x%x into the virtual address space\n", mb_info->cmdline); page_map((size_t) mb_info->cmdline & PAGE_MASK, mb_info->cmdline & PAGE_MASK, 1, PG_GLOBAL|PG_RW|PG_PRESENT); } diff --git a/hermit/drivers/net/e1000.c b/hermit/drivers/net/e1000.c index a2774947a..2ec19526f 100644 --- a/hermit/drivers/net/e1000.c +++ b/hermit/drivers/net/e1000.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include #include @@ -422,7 +423,7 @@ err_t e1000if_init(struct netif* netif) tmp32 &= ~(E1000_CTRL_VME|E1000_CTRL_FD|E1000_CTRL_ILOS|E1000_CTRL_PHY_RST|E1000_CTRL_LRST|E1000_CTRL_FRCSPD); e1000_write(e1000if->bar0, E1000_CTRL, tmp32 | E1000_CTRL_SLU | E1000_CTRL_ASDE); e1000_flush(e1000if->bar0); - kprintf("e1000if_init: Device Control Register 0x%x\n", e1000_read(e1000if->bar0, E1000_CTRL)); + LOG_INFO("e1000if_init: Device Control Register 0x%x\n", e1000_read(e1000if->bar0, E1000_CTRL)); /* make sure transmits are disabled while setting up the descriptors */ tmp32 = e1000_read(e1000if->bar0, E1000_TCTL); diff --git a/hermit/drivers/net/mmnif.c b/hermit/drivers/net/mmnif.c index 83659f1eb..fe496bd19 100644 --- a/hermit/drivers/net/mmnif.c +++ b/hermit/drivers/net/mmnif.c @@ -51,6 +51,7 @@ */ #include +#include #include /* lwip netif */ #include /* inteface stats */ @@ -241,18 +242,18 @@ static void mmnif_print_stats(void) if (!mmnif_dev) { - DEBUGPRINTF("mmnif_print_stats(): the device is not initialized yet.\n"); + LOG_INFO("mmnif_print_stats(): the device is not initialized yet.\n"); return; } mmnif = (mmnif_t *) mmnif_dev->state; - DEBUGPRINTF("/dev/mmnif - stats:\n"); - DEBUGPRINTF("Received: %d packets successfull\n", mmnif->stats.rx); - DEBUGPRINTF("Received: %d bytes\n", mmnif->stats.rx_bytes); - DEBUGPRINTF("Received: %d packets containuing errors\n", mmnif->stats.rx_err); - DEBUGPRINTF("Transmitted: %d packests successfull\n", mmnif->stats.tx); - DEBUGPRINTF("Transmitted: %d bytes\n", mmnif->stats.tx_bytes); - DEBUGPRINTF("Transmitted: %d packests were dropped due to errors\n", mmnif->stats.tx_err); + LOG_INFO("/dev/mmnif - stats:\n"); + LOG_INFO("Received: %d packets successfull\n", mmnif->stats.rx); + LOG_INFO("Received: %d bytes\n", mmnif->stats.rx_bytes); + LOG_INFO("Received: %d packets containuing errors\n", mmnif->stats.rx_err); + LOG_INFO("Transmitted: %d packests successfull\n", mmnif->stats.tx); + LOG_INFO("Transmitted: %d bytes\n", mmnif->stats.tx_bytes); + LOG_INFO("Transmitted: %d packests were dropped due to errors\n", mmnif->stats.tx_err); } /* mmnif_print_driver_status @@ -265,28 +266,28 @@ void mmnif_print_driver_status(void) if (!mmnif_dev) { - DEBUGPRINTF("mmnif_print_driver_status(): the device is not initialized yet.\n"); + LOG_ERROR("mmnif_print_driver_status(): the device is not initialized yet.\n"); return; } mmnif = (mmnif_t *) mmnif_dev->state; - DEBUGPRINTF("/dev/mmnif driver status: \n\n"); - DEBUGPRINTF("rx_buf: 0xp\n", mmnif->rx_buff); - DEBUGPRINTF("free descriptors : %d\n\n", mmnif->rx_buff->dcount); - DEBUGPRINTF("descriptor table: (only print descriptors in use)\n"); - DEBUGPRINTF("status\taddr\tsize\n"); + LOG_INFO("/dev/mmnif driver status: \n\n"); + LOG_INFO("rx_buf: 0xp\n", mmnif->rx_buff); + LOG_INFO("free descriptors : %d\n\n", mmnif->rx_buff->dcount); + LOG_INFO("descriptor table: (only print descriptors in use)\n"); + LOG_INFO("status\taddr\tsize\n"); for (i = 0; i < MMNIF_MAX_DESCRIPTORS; i++) { if (mmnif->rx_buff->desc_table[i].stat != 0) - DEBUGPRINTF("0x%.2X\t%p\t%X\t\n", + LOG_INFO("0x%.2X\t%p\t%X\t\n", mmnif->rx_buff->desc_table[i].stat, mmnif->rx_buff->desc_table[i].addr, mmnif->rx_buff->desc_table[i].len); } - DEBUGPRINTF("ring heap start addr: %p\n", mmnif->rx_buff + sizeof(mm_rx_buffer_t)); - DEBUGPRINTF("head: 0x%X\ttail: 0x%X\n", mmnif->rx_buff->head, mmnif->rx_buff->tail); + LOG_INFO("ring heap start addr: %p\n", mmnif->rx_buff + sizeof(mm_rx_buffer_t)); + LOG_INFO("head: 0x%X\ttail: 0x%X\n", mmnif->rx_buff->head, mmnif->rx_buff->tail); mmnif_print_stats(); } @@ -468,13 +469,13 @@ static err_t mmnif_tx(struct netif *netif, struct pbuf *p) /* check for over/underflow */ if (BUILTIN_EXPECT((p->tot_len < 20 /* IP header size */) || (p->tot_len > 1536), 0)) { - DEBUGPRINTF("mmnif_tx: illegal packet length %d => drop\n", p->tot_len); + LOG_ERROR("mmnif_tx: illegal packet length %d => drop\n", p->tot_len); goto drop_packet; } /* check destination ip */ if (BUILTIN_EXPECT((dest_ip < 1) || (dest_ip > MAX_ISLE), 0)) { - DEBUGPRINTF("mmnif_tx: invalid destination IP %d => drop\n", dest_ip); + LOG_ERROR("mmnif_tx: invalid destination IP %d => drop\n", dest_ip); goto drop_packet; } @@ -485,7 +486,7 @@ realloc: write_address = mmnif_rxbuff_alloc(dest_ip, p->tot_len); if (!write_address) { - //DEBUGPRINTF("mmnif_tx(): concurrency"); + LOG_DEBUG("mmnif_tx(): concurrency"); PAUSE; goto realloc; @@ -499,11 +500,11 @@ realloc: if (mmnif_commit_packet(dest_ip, write_address)) { - DEBUGPRINTF("mmnif_tx(): packet somehow lost during commit\n"); + LOG_WARNING("mmnif_tx(): packet somehow lost during commit\n"); } #ifdef DEBUG_MMNIF_PACKET -// DEBUGPRINTF("\n SEND %p with length: %d\n",(char*)heap_start_address + (dest_ip -1)*mpb_size + pos * 1792,p->tot_len +2); +// LOG_INFO("\n SEND %p with length: %d\n",(char*)heap_start_address + (dest_ip -1)*mpb_size + pos * 1792,p->tot_len +2); // hex_dump(p->tot_len, p->payload); #endif @@ -521,7 +522,7 @@ realloc: drop_packet: /* drop packet for one or another reason */ - DEBUGPRINTF("mmnif_tx(): packet dropped"); + LOG_ERROR("mmnif_tx(): packet dropped"); LINK_STATS_INC(link.drop); mmnif->stats.tx_err++; @@ -551,7 +552,7 @@ err_t mmnif_init(struct netif *netif) uint32_t nodes = possible_isles + 1; size_t flags; - DEBUGPRINTF("Initialize mmnif\n"); + LOG_INFO("Initialize mmnif\n"); mmnif_dev = netif; @@ -560,7 +561,7 @@ err_t mmnif_init(struct netif *netif) mmnif = kmalloc(sizeof(mmnif_t)); if (BUILTIN_EXPECT(!mmnif, 0)) { - DEBUGPRINTF("mmnif init():out of memory\n"); + LOG_ERROR("mmnif init():out of memory\n"); goto out; } memset(mmnif, 0x00, sizeof(mmnif_t)); @@ -569,32 +570,32 @@ err_t mmnif_init(struct netif *netif) */ if (BUILTIN_EXPECT(header_size < sizeof(mm_rx_buffer_t), 0)) { - DEBUGPRINTF("mmnif init(): header_size is too small\n"); + LOG_ERROR("mmnif init(): header_size is too small\n"); goto out; } if (BUILTIN_EXPECT(heap_size < MMNIF_RX_BUFFERLEN, 0)) { - DEBUGPRINTF("mmnif init(): heap_size is too small\n"); + LOG_ERROR("mmnif init(): heap_size is too small\n"); goto out; } - DEBUGPRINTF("mmnif_init() : size of mm_rx_buffer_t : %d\n", sizeof(mm_rx_buffer_t)); + LOG_INFO("mmnif_init() : size of mm_rx_buffer_t : %d\n", sizeof(mm_rx_buffer_t)); if (BUILTIN_EXPECT(!header_phy_start_address || !header_phy_start_address || !phy_isle_locks, 0)) { - DEBUGPRINTF("mmnif init(): invalid heap or header address\n"); + LOG_ERROR("mmnif init(): invalid heap or header address\n"); goto out; } if (BUILTIN_EXPECT(!header_start_address, 0)) { - DEBUGPRINTF("mmnif init(): vma_alloc failed\n"); + LOG_ERROR("mmnif init(): vma_alloc failed\n"); goto out; } err = vma_add((size_t)header_start_address, PAGE_FLOOR((size_t)header_start_address + ((nodes * header_size) >> PAGE_BITS)), VMA_READ|VMA_WRITE|VMA_CACHEABLE); if (BUILTIN_EXPECT(err, 0)) { - DEBUGPRINTF("mmnif init(): vma_add failed for header_start_address %p\n", header_start_address); + LOG_ERROR("mmnif init(): vma_add failed for header_start_address %p\n", header_start_address); goto out; } @@ -606,34 +607,34 @@ err_t mmnif_init(struct netif *netif) // map physical address in the virtual address space err = page_map((size_t) header_start_address, (size_t) header_phy_start_address, (nodes * header_size) >> PAGE_BITS, flags); if (BUILTIN_EXPECT(err, 0)) { - DEBUGPRINTF("mmnif init(): page_map failed\n"); + LOG_ERROR("mmnif init(): page_map failed\n"); goto out; } - DEBUGPRINTF("map header %p at %p\n", header_phy_start_address, header_start_address); + LOG_INFO("map header %p at %p\n", header_phy_start_address, header_start_address); mmnif->rx_buff = (mm_rx_buffer_t *) (header_start_address + header_size * (isle+1)); if (BUILTIN_EXPECT(!heap_start_address, 0)) { - DEBUGPRINTF("mmnif init(): vma_alloc failed\n"); + LOG_ERROR("mmnif init(): vma_alloc failed\n"); goto out; } err = vma_add((size_t)heap_start_address, PAGE_FLOOR((size_t)heap_start_address + ((nodes * heap_size) >> PAGE_BITS)), VMA_READ|VMA_WRITE|VMA_CACHEABLE); if (BUILTIN_EXPECT(!heap_start_address, 0)) { - DEBUGPRINTF("mmnif init(): vma_add failed for heap_start_address %p\n", heap_start_address); + LOG_ERROR("mmnif init(): vma_add failed for heap_start_address %p\n", heap_start_address); goto out; } // map physical address in the virtual address space err = page_map((size_t) heap_start_address, (size_t) heap_phy_start_address, (nodes * heap_size) >> PAGE_BITS, flags); if (BUILTIN_EXPECT(err, 0)) { - DEBUGPRINTF("mmnif init(): page_map failed\n"); + LOG_ERROR("mmnif init(): page_map failed\n"); goto out; } // map physical address in the virtual address space - DEBUGPRINTF("map heap %p at %p\n", heap_phy_start_address, heap_start_address); + LOG_INFO("map heap %p at %p\n", heap_phy_start_address, heap_start_address); mmnif->rx_heap = (uint8_t*) heap_start_address + heap_size * (isle+1); memset((void*)mmnif->rx_buff, 0x00, header_size); @@ -641,17 +642,17 @@ err_t mmnif_init(struct netif *netif) isle_locks = (islelock_t*) vma_alloc(((nodes + 1) * sizeof(islelock_t) + PAGE_SIZE - 1) & ~(PAGE_SIZE - 1), VMA_READ|VMA_WRITE|VMA_CACHEABLE); if (BUILTIN_EXPECT(!isle_locks, 0)) { - DEBUGPRINTF("mmnif init(): vma_alloc failed\n"); + LOG_ERROR("mmnif init(): vma_alloc failed\n"); goto out; } // map physical address in the virtual address space err = page_map((size_t) isle_locks, (size_t) phy_isle_locks, (((nodes+1) * sizeof(islelock_t) + PAGE_SIZE - 1) & ~(PAGE_SIZE - 1)) >> PAGE_BITS, flags); if (BUILTIN_EXPECT(err, 0)) { - DEBUGPRINTF("mmnif init(): page_map failed\n"); + LOG_ERROR("mmnif init(): page_map failed\n"); goto out; } - DEBUGPRINTF("map isle_locks %p at %p\n", phy_isle_locks, isle_locks); + LOG_INFO("map isle_locks %p at %p\n", phy_isle_locks, isle_locks); /* set initial values */ @@ -693,7 +694,7 @@ err_t mmnif_init(struct netif *netif) // set interrupt handler irq_install_handler(MMNIF_IRQ, mmnif_irqhandler); - DEBUGPRINTF("mmnif init complete\n"); + LOG_INFO("mmnif init complete\n"); return ERR_OK; @@ -767,14 +768,14 @@ anotherpacket: */ if (BUILTIN_EXPECT(length == 0, 0)) { - DEBUGPRINTF("mmnif_rx(): empty packet error\n"); + LOG_ERROR("mmnif_rx(): empty packet error\n"); goto out; } /* check for over/underflow */ if (BUILTIN_EXPECT((length < 20 /* IP header size */) || (length > 1536), 0)) { - DEBUGPRINTF("mmnif_rx(): illegal packet length %d => drop the packet\n", length); + LOG_ERROR("mmnif_rx(): illegal packet length %d => drop the packet\n", length); goto drop_packet; } @@ -782,7 +783,7 @@ anotherpacket: * has to be worked on */ #ifdef DEBUG_MMNIF_PACKET - DEBUGPRINTF("\n RECIEVED - %p with legth: %d\n", packet, length); + LOG_INFO("\n RECIEVED - %p with legth: %d\n", packet, length); hex_dump(length, packet); #endif @@ -792,7 +793,7 @@ anotherpacket: p = pbuf_alloc(PBUF_RAW, length, PBUF_POOL); if (BUILTIN_EXPECT(!p, 0)) { - DEBUGPRINTF("mmnif_rx(): low on mem - packet dropped\n"); + LOG_ERROR("mmnif_rx(): low on mem - packet dropped\n"); goto drop_packet; } @@ -820,7 +821,7 @@ anotherpacket: */ if ((err = mmnif_dev->input(p, mmnif_dev)) != ERR_OK) { - DEBUGPRINTF("mmnif_rx: IP input error\n"); + LOG_ERROR("mmnif_rx: IP input error\n"); pbuf_free(p); } @@ -849,7 +850,7 @@ static void mmnif_irqhandler(struct state* s) /* return if mmnif_dev is not yet initialized */ if (!mmnif_dev) { - DEBUGPRINTF("mmnif_irqhandler(): the driver is not initialized yet\n"); + LOG_ERROR("mmnif_irqhandler(): the driver is not initialized yet\n"); return; } @@ -862,7 +863,7 @@ static void mmnif_irqhandler(struct state* s) if (tcpip_callback_with_block((tcpip_callback_fn) mmnif_rx, (void*) mmnif_dev, 0) == ERR_OK) { mmnif->check_in_progress = 1; } else { - DEBUGPRINTF("mmnif_handler: unable to send a poll request to the tcpip thread\n"); + LOG_ERROR("mmnif_handler: unable to send a poll request to the tcpip thread\n"); } #endif } @@ -877,7 +878,7 @@ err_t mmnif_shutdown(void) err_t err; if (!mmnif_dev) { - DEBUGPRINTF("mmnif_shutdown(): you closed the device before it was properly initialized -.-* \n"); + LOG_ERROR("mmnif_shutdown(): you closed the device before it was properly initialized -.-* \n"); return ERR_MEM; } diff --git a/hermit/drivers/net/rtl8139.c b/hermit/drivers/net/rtl8139.c index 87392336a..aaa50bb2e 100644 --- a/hermit/drivers/net/rtl8139.c +++ b/hermit/drivers/net/rtl8139.c @@ -32,6 +32,7 @@ #include #include #include +#include #include #include #include @@ -93,22 +94,22 @@ static err_t rtl8139if_output(struct netif* netif, struct pbuf* p) struct pbuf *q; if (BUILTIN_EXPECT((rtl8139if->tx_queue - rtl8139if->tx_complete) > 3, 0)) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_output: too many packets at once\n")); + LOG_ERROR("rtl8139if_output: too many packets at once\n"); return ERR_IF; } if (BUILTIN_EXPECT(p->tot_len > 1792, 0)) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_output: packet is longer than 1792 bytes\n")); + LOG_ERROR("rtl8139if_output: packet is longer than 1792 bytes\n"); return ERR_IF; } if (rtl8139if->tx_inuse[transmitid] == 1) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_output: %i already inuse\n", transmitid)); + LOG_ERROR("rtl8139if_output: %i already inuse\n", transmitid); return ERR_IF; } if (inportb(rtl8139if->iobase + MSR) & MSR_LINKB) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_output: link failure\n")); + LOG_ERROR("rtl8139if_output: link failure\n"); return ERR_CONN; } @@ -181,7 +182,7 @@ static void rtl_rx_inthandler(struct netif* netif) // forward packet to LwIP netif->input(p, netif); } else { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_rx_inthandler: not enough memory!\n")); + LOG_ERROR("rtl8139if_rx_inthandler: not enough memory!\n"); rtl8139if->rx_pos += (rtl8139if->rx_pos + length) % RX_BUF_LEN; LINK_STATS_INC(link.memerr); LINK_STATS_INC(link.drop); @@ -191,7 +192,7 @@ static void rtl_rx_inthandler(struct netif* netif) rtl8139if->rx_pos = ((rtl8139if->rx_pos + 4 + 3) & ~0x3) % RX_BUF_LEN; outportw(rtl8139if->iobase + CAPR, rtl8139if->rx_pos - 0x10); } else { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_rx_inthandler: invalid header 0x%x, rx_pos %d\n", (uint32_t) header, rtl8139if->rx_pos)); + LOG_ERROR("rtl8139if_rx_inthandler: invalid header 0x%x, rx_pos %d\n", (uint32_t) header, rtl8139if->rx_pos); LINK_STATS_INC(link.drop); break; } @@ -220,12 +221,12 @@ static void rtl_tx_inthandler(struct netif* netif) return; if (txstatus & (TSD_TABT | TSD_OWC)) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139_tx_inthandler: major error\n")); + LOG_ERROR("rtl8139_tx_inthandler: major error\n"); continue; } if (txstatus & TSD_TUN) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139_tx_inthandler: transmit underrun\n")); + LOG_ERROR("rtl8139_tx_inthandler: transmit underrun\n"); } if (txstatus & TSD_TOK) { @@ -262,7 +263,7 @@ static void rtl8139if_handler(struct state* s) if (tcpip_callback_with_block(rtl8139if_poll, NULL, 0) == ERR_OK) { rtl8139if->polling = 1; } else { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_handler: unable to send a poll request to the tcpip thread\n")); + LOG_ERROR("rtl8139if_handler: unable to send a poll request to the tcpip thread\n"); } #endif } @@ -271,15 +272,15 @@ static void rtl8139if_handler(struct state* s) rtl_tx_inthandler(mynetif); if (isr_contents & ISR_RER) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_handler: RX error detected!\n")); + LOG_ERROR("rtl8139if_handler: RX error detected!\n"); } if (isr_contents & ISR_TER) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_handler: TX error detected!\n")); + LOG_ERROR("rtl8139if_handler: TX error detected!\n"); } if (isr_contents & ISR_RXOVW) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_handler: RX overflow detected!\n")); + LOG_ERROR("rtl8139if_handler: RX overflow detected!\n"); } outportw(rtl8139if->iobase + ISR, isr_contents & (ISR_RXOVW|ISR_TER|ISR_RER|ISR_TOK|ISR_ROK)); @@ -312,11 +313,11 @@ err_t rtl8139if_init(struct netif* netif) if (!board_tbl[tmp8].vendor_str) return ERR_ARG; - //kprintf("Found %s %s\n", board_tbl[tmp8].vendor_str, board_tbl[tmp8].device_str); + LOG_DEBUG("Found %s %s\n", board_tbl[tmp8].vendor_str, board_tbl[tmp8].device_str); rtl8139if = kmalloc(sizeof(rtl1839if_t)); if (!rtl8139if) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: out of memory\n")); + LOG_ERROR("rtl8139if_init: out of memory\n"); return ERR_MEM; } memset(rtl8139if, 0x00, sizeof(rtl1839if_t)); @@ -327,7 +328,7 @@ err_t rtl8139if_init(struct netif* netif) /* allocate the receive buffer */ rtl8139if->rx_buffer = page_alloc(RX_BUF_LEN + 16 /* header size */, VMA_READ|VMA_WRITE); if (!(rtl8139if->rx_buffer)) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: out of memory\n")); + LOG_ERROR("rtl8139if_init: out of memory\n"); kfree(rtl8139if); return ERR_MEM; } @@ -336,7 +337,7 @@ err_t rtl8139if_init(struct netif* netif) /* allocate the send buffers */ rtl8139if->tx_buffer[0] = page_alloc(4*TX_BUF_LEN, VMA_READ|VMA_WRITE); if (!(rtl8139if->tx_buffer[0])) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: out of memory\n")); + LOG_ERROR("rtl8139if_init: out of memory\n"); page_free(rtl8139if->rx_buffer, RX_BUF_LEN + 16); kfree(rtl8139if); return ERR_MEM; @@ -351,7 +352,7 @@ err_t rtl8139if_init(struct netif* netif) tmp32 = inportl(rtl8139if->iobase + TCR); if (tmp32 == 0xFFFFFF) { - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: ERROR\n")); + LOG_ERROR("rtl8139if_init: ERROR\n"); page_free(rtl8139if->rx_buffer, RX_BUF_LEN + 16); page_free(rtl8139if->tx_buffer[0], 4*TX_BUF_LEN); kfree(rtl8139if); @@ -369,8 +370,8 @@ err_t rtl8139if_init(struct netif* netif) /* hardware address length */ netif->hwaddr_len = ETHARP_HWADDR_LEN; - LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: Found %s at iobase 0x%x (irq %u)\n", board_tbl[tmp8].device_str, - rtl8139if->iobase, rtl8139if->irq)); + LOG_INFO("rtl8139if_init: Found %s at iobase 0x%x (irq %u)\n", board_tbl[tmp8].device_str, + rtl8139if->iobase, rtl8139if->irq); // determine the mac address of this card LWIP_DEBUGF(NETIF_DEBUG, ("rtl8139if_init: MAC address ")); for (tmp8=0; tmp8rx_buffer, RX_BUF_LEN + 16); page_free(rtl8139if->tx_buffer[0], 4*TX_BUF_LEN); kfree(rtl8139if); @@ -459,7 +460,7 @@ err_t rtl8139if_init(struct netif* netif) // Enable Receive and Transmitter outportb(rtl8139if->iobase + CR, CR_TE|CR_RE); // Sets the RE and TE bits high - kprintf("RTL8139: CR = 0x%x, ISR = 0x%x, speed = %u mbps\n", + LOG_INFO("RTL8139: CR = 0x%x, ISR = 0x%x, speed = %u mbps\n", inportb(rtl8139if->iobase + CR), inportw(rtl8139if->iobase + ISR), speed); /* diff --git a/hermit/drivers/net/util.c b/hermit/drivers/net/util.c index dc88de4af..a2de4de45 100644 --- a/hermit/drivers/net/util.c +++ b/hermit/drivers/net/util.c @@ -31,6 +31,7 @@ */ #include +#include #include "util.h" inline int isprint(unsigned char e) @@ -47,19 +48,19 @@ void hex_dump(unsigned n, const unsigned char *buf) while (n-- > 0) { - kprintf("%02X ", *buf++); + LOG_SAME_LINE(LOG_LEVEL_INFO, "%02X ", *buf++); on_this_line += 1; if (on_this_line == 16 || n == 0) { int i; - kputs(" "); + LOG_SAME_LINE(LOG_LEVEL_INFO, " "); for (i = on_this_line; i < 16; i++) - kputs(" "); + LOG_SAME_LINE(LOG_LEVEL_INFO, " "); for (i = on_this_line; i > 0; i--) - kputchar(isprint(buf[-i]) ? buf[-i] : '.'); - kputs("\n"); + LOG_SAME_LINE(LOG_LEVEL_INFO, "%c", isprint(buf[-i]) ? buf[-i] : '.'); + LOG_SAME_LINE(LOG_LEVEL_INFO, "\n"); on_this_line = 0; } } diff --git a/hermit/include/hermit/logging.h b/hermit/include/hermit/logging.h new file mode 100644 index 000000000..4ca3586fc --- /dev/null +++ b/hermit/include/hermit/logging.h @@ -0,0 +1,90 @@ +/* + * Copyright (c) 2016, Daniel Krebs, RWTH Aachen University + * All rights reserved. + * + * Redistribution and use in source and binary forms, with or without + * modification, are permitted provided that the following conditions are met: + * * Redistributions of source code must retain the above copyright + * notice, this list of conditions and the following disclaimer. + * * Redistributions in binary form must reproduce the above copyright + * notice, this list of conditions and the following disclaimer in the + * documentation and/or other materials provided with the distribution. + * * Neither the name of the University nor the names of its contributors + * may be used to endorse or promote products derived from this + * software without specific prior written permission. + * + * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" AND + * ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED + * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE + * DISCLAIMED. IN NO EVENT SHALL THE REGENTS OR CONTRIBUTORS BE LIABLE FOR ANY + * DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES + * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; + * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND + * ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT + * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF THIS + * SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. + */ + +#ifndef __HERMIT_LOGGING_H__ +#define __HERMIT_LOGGING_H__ + +#include +#include +#include + +enum { + LOG_LEVEL_DISABLED = 0, + LOG_LEVEL_ERROR, + LOG_LEVEL_WARNING, + LOG_LEVEL_INFO, + LOG_LEVEL_DEBUG, + LOG_LEVEL_VERBOSE +}; + +#define LOG_LEVEL_ERROR_PREFIX "ERROR" +#define LOG_LEVEL_WARNING_PREFIX "WARNING" +#define LOG_LEVEL_INFO_PREFIX "INFO" +#define LOG_LEVEL_DEBUG_PREFIX "DEBUG" +#define LOG_LEVEL_VERBOSE_PREFIX "VERBOSE" + +#ifndef LOG_LEVEL + #define LOG_LEVEL LOG_LEVEL_INFO +#endif + +// Gratefully taken from Leushenko @ http://stackoverflow.com/a/19017591 +#define CONC(a,b) a##_##b +#define IF(c, t, e) CONC(IF, c)(t, e) +#define IF_0(t, e) e +#define IF_1(t, e) t + +#define __LOG_FUNCTION(...) kprintf(__VA_ARGS__) + +// [timestamp][core:task][level] ... +#define __LOG_FORMAT_VERBOSE(level, fmt, ...) \ + "[%d.%03d][%d:%d][" CONC(level, PREFIX) "] " fmt, \ + (get_uptime() / 1000), (get_uptime() % 1000), \ + CORE_ID, sys_getpid(), \ + ##__VA_ARGS__ + +// don't add any formatting +#define __LOG_FORMAT_PASS(level, fmt, ...) fmt, ##__VA_ARGS__ + +// The compiler will optimize the if clause away since the condition can be +// evaluated at compile-time +#define __LOG(level, formatter, ...) do { \ + if(LOG_LEVEL >= level) { \ + __LOG_FUNCTION(formatter(level, __VA_ARGS__)); \ + } \ +} while(0) + +#define LOG_ERROR(...) __LOG(LOG_LEVEL_ERROR, __LOG_FORMAT_VERBOSE, __VA_ARGS__) +#define LOG_WARNING(...) __LOG(LOG_LEVEL_WARNING, __LOG_FORMAT_VERBOSE, __VA_ARGS__) +#define LOG_INFO(...) __LOG(LOG_LEVEL_INFO, __LOG_FORMAT_VERBOSE, __VA_ARGS__) +#define LOG_DEBUG(...) __LOG(LOG_LEVEL_DEBUG, __LOG_FORMAT_VERBOSE, __VA_ARGS__) +#define LOG_VERBOSE(...) __LOG(LOG_LEVEL_VERBOSE, __LOG_FORMAT_VERBOSE, __VA_ARGS__) + +// No formatting will be applied, so this can be used to expand the previous +// line. +#define LOG_SAME_LINE(level, ...) __LOG(level, __LOG_FORMAT_PASS, __VA_ARGS__) + +#endif // __HERMIT_LOGGING_H__ diff --git a/hermit/include/hermit/time.h b/hermit/include/hermit/time.h index 0e5d51df1..5ae042a3a 100644 --- a/hermit/include/hermit/time.h +++ b/hermit/include/hermit/time.h @@ -81,6 +81,10 @@ static inline uint64_t get_clock_tick(void) */ static inline void sleep(unsigned int sec) { timer_wait(sec*TIMER_FREQ); } +/** @brief Get milliseconds since system boot + */ +static inline uint64_t get_uptime() { return (get_clock_tick() * 1000) / TIMER_FREQ; } + static inline int timer_deadline(uint32_t t) { return apic_timer_deadline(t); } static inline void timer_disable(void) { apic_disable_timer(); } diff --git a/hermit/kernel/main.c b/hermit/kernel/main.c index 160cd2f20..c512fde6b 100644 --- a/hermit/kernel/main.c +++ b/hermit/kernel/main.c @@ -36,6 +36,7 @@ #include #include #include +#include #include #include #include @@ -58,7 +59,7 @@ #include #define HERMIT_PORT 0x494E -#define HEMRIT_MAGIC 0x7E317 +#define HERMIT_MAGIC 0x7E317 // set to one if the single-kernel version should use a DHCP server #define USE_DHCP 1 @@ -106,7 +107,7 @@ static int foo(void* arg) int i; for(i=0; i<5; i++) { - kprintf("hello from %s\n", (char*) arg); + LOG_INFO("hello from %s\n", (char*) arg); sleep(1); } @@ -146,7 +147,7 @@ static void print_status(void) static spinlock_t status_lock = SPINLOCK_INIT; spinlock_lock(&status_lock); - kprintf("CPU %d of isle %d is now online (CR0 0x%zx, CR4 0x%zx)\n", CORE_ID, isle, read_cr0(), read_cr4()); + LOG_INFO("CPU %d of isle %d is now online (CR0 0x%zx, CR4 0x%zx)\n", CORE_ID, isle, read_cr0(), read_cr4()); spinlock_unlock(&status_lock); } @@ -154,7 +155,7 @@ static void tcpip_init_done(void* arg) { sys_sem_t* sem = (sys_sem_t*)arg; - kprintf("LwIP's tcpip thread has task id %d\n", per_core(current_task)->id); + LOG_INFO("LwIP's tcpip thread has task id %d\n", per_core(current_task)->id); sys_sem_signal(sem); } @@ -175,7 +176,7 @@ static int init_netifs(void) tcpip_init(tcpip_init_done, &sem); sys_sem_wait(&sem); - kprintf("TCP/IP initialized.\n"); + LOG_INFO("TCP/IP initialized.\n"); sys_sem_free(&sem); if (!is_single_kernel()) @@ -203,7 +204,7 @@ static int init_netifs(void) if ((err = netifapi_netif_add(&default_netif, &ipaddr, &netmask, &gw, NULL, mmnif_init, ip_input)) != ERR_OK) #endif { - kprintf("Unable to add the intra network interface: err = %d\n", err); + LOG_ERROR("Unable to add the intra network interface: err = %d\n", err); return -ENODEV; } @@ -229,7 +230,7 @@ static int init_netifs(void) if ((err = netifapi_netif_add(&default_netif, &ipaddr, &netmask, &gw, NULL, e1000if_init, ethernet_input)) == ERR_OK) goto success; - kprintf("Unable to add the network interface: err = %d\n", err); + LOG_ERROR("Unable to add the network interface: err = %d\n", err); return -ENODEV; @@ -237,7 +238,7 @@ success: netifapi_netif_set_default(&default_netif); #if USE_DHCP - kprintf("Starting DHCPD...\n"); + LOG_INFO("Starting DHCPD...\n"); netifapi_dhcp_start(&default_netif); int mscnt = 0; @@ -273,7 +274,7 @@ success: int network_shutdown(void) { - kputs("Shutdown LwIP\n"); + LOG_INFO("Shutdown LwIP\n"); if (libc_sd >= 0) { int s = libc_sd; @@ -329,7 +330,7 @@ static int init_rcce(void) rcce_lock = (islelock_t*) addr; rcce_mpb = (rcce_mpb_t*) (addr + CACHE_LINE*(RCCE_MAXNP+1)); - kprintf("Map rcce_lock at %p and rcce_mpb at %p\n", rcce_lock, rcce_mpb); + LOG_INFO("Map rcce_lock at %p and rcce_mpb at %p\n", rcce_lock, rcce_mpb); return 0; } @@ -354,7 +355,7 @@ static void lock_test(void) end = rdtsc(); - kprintf("locks %lld (iterations %d)\n", end-start, i); + LOG_INFO("locks %lld (iterations %d)\n", end-start, i); start = rdtsc(); @@ -367,7 +368,7 @@ static void lock_test(void) end = rdtsc(); - kprintf("sem %lld (iterations %d)\n", end-start, i); + LOG_INFO("sem %lld (iterations %d)\n", end-start, i); } #endif @@ -387,14 +388,14 @@ static int initd(void* arg) char** argv = NULL; char **environ = NULL; - kputs("Initd is running\n"); + LOG_INFO("Initd is running\n"); // setup heap if (!curr_task->heap) curr_task->heap = (vma_t*) kmalloc(sizeof(vma_t)); if (BUILTIN_EXPECT(!curr_task->heap, 0)) { - kprintf("load_task: heap is missing!\n"); + LOG_ERROR("load_task: heap is missing!\n"); return -ENOMEM; } @@ -427,7 +428,7 @@ static int initd(void* arg) s = lwip_socket(PF_INET , SOCK_STREAM , 0); if (s < 0) { - kprintf("socket failed: %d\n", server); + LOG_ERROR("socket failed: %d\n", server); return -1; } @@ -439,31 +440,31 @@ static int initd(void* arg) if ((err = lwip_bind(s, (struct sockaddr *) &server, sizeof(server))) < 0) { - kprintf("bind failed: %d\n", errno); + LOG_ERROR("bind failed: %d\n", errno); lwip_close(s); return -1; } if ((err = lwip_listen(s, 2)) < 0) { - kprintf("listen failed: %d\n", errno); + LOG_ERROR("listen failed: %d\n", errno); lwip_close(s); return -1; } len = sizeof(struct sockaddr_in); - kprintf("Boot time: %d ms\n", (get_clock_tick() * 1000) / TIMER_FREQ); - kputs("TCP server is listening.\n"); + LOG_INFO("Boot time: %d ms\n", (get_clock_tick() * 1000) / TIMER_FREQ); + LOG_INFO("TCP server is listening.\n"); if ((c = lwip_accept(s, (struct sockaddr *)&client, (socklen_t*)&len)) < 0) { - kprintf("accept faild: %d\n", errno); + LOG_ERROR("accept faild: %d\n", errno); lwip_close(s); return -1; } - kputs("Establish IP connection\n"); + LOG_INFO("Establish IP connection\n"); lwip_setsockopt(c, SOL_SOCKET, SO_RCVBUF, (char *) &sobufsize, sizeof(sobufsize)); lwip_setsockopt(c, SOL_SOCKET, SO_SNDBUF, (char *) &sobufsize, sizeof(sobufsize)); @@ -474,9 +475,9 @@ static int initd(void* arg) magic = 0; lwip_read(c, &magic, sizeof(magic)); - if (magic != HEMRIT_MAGIC) + if (magic != HERMIT_MAGIC) { - kprintf("Invalid magic number %d\n", magic); + LOG_ERROR("Invalid magic number %d\n", magic); lwip_close(c); return -1; } @@ -577,20 +578,20 @@ int hermit_main(void) hermit_init(); system_calibration(); // enables also interrupts - kprintf("This is Hermit %s, build date %u\n", VERSION, &__DATE__); - kprintf("Isle %d of %d possible isles\n", isle, possible_isles); - kprintf("Kernel starts at %p and ends at %p\n", &kernel_start, &kernel_end); - kprintf("TLS image starts at %p and ends at %p\n", &tls_start, &tls_end); - kprintf("BBS starts at %p and ends at %p\n", &hbss_start, &kernel_end); - kprintf("Per core data starts at %p and ends at %p\n", &percore_start, &percore_end); - kprintf("Per core size 0x%zx\n", (size_t) &percore_end0 - (size_t) &percore_start); - kprintf("Processor frequency: %u MHz\n", get_cpu_frequency()); - kprintf("Total memory: %zd MiB\n", atomic_int64_read(&total_pages) * PAGE_SIZE / (1024ULL*1024ULL)); - kprintf("Current allocated memory: %zd KiB\n", atomic_int64_read(&total_allocated_pages) * PAGE_SIZE / 1024ULL); - kprintf("Current available memory: %zd MiB\n", atomic_int64_read(&total_available_pages) * PAGE_SIZE / (1024ULL*1024ULL)); - kprintf("Core %d is the boot processor\n", boot_processor); + LOG_INFO("This is Hermit %s, build date %u\n", VERSION, &__DATE__); + LOG_INFO("Isle %d of %d possible isles\n", isle, possible_isles); + LOG_INFO("Kernel starts at %p and ends at %p\n", &kernel_start, &kernel_end); + LOG_INFO("TLS image starts at %p and ends at %p\n", &tls_start, &tls_end); + LOG_INFO("BBS starts at %p and ends at %p\n", &hbss_start, &kernel_end); + LOG_INFO("Per core data starts at %p and ends at %p\n", &percore_start, &percore_end); + LOG_INFO("Per core size 0x%zx\n", (size_t) &percore_end0 - (size_t) &percore_start); + LOG_INFO("Processor frequency: %u MHz\n", get_cpu_frequency()); + LOG_INFO("Total memory: %zd MiB\n", atomic_int64_read(&total_pages) * PAGE_SIZE / (1024ULL*1024ULL)); + LOG_INFO("Current allocated memory: %zd KiB\n", atomic_int64_read(&total_allocated_pages) * PAGE_SIZE / 1024ULL); + LOG_INFO("Current available memory: %zd MiB\n", atomic_int64_read(&total_available_pages) * PAGE_SIZE / (1024ULL*1024ULL)); + LOG_INFO("Core %d is the boot processor\n", boot_processor); if (hbmem_base) - kprintf("Found high bandwidth memory at 0x%zx (size 0x%zx)\n", hbmem_base, hbmem_size); + LOG_INFO("Found high bandwidth memory at 0x%zx (size 0x%zx)\n", hbmem_base, hbmem_size); #if 0 print_pci_adapters(); diff --git a/hermit/kernel/signal.c b/hermit/kernel/signal.c index 4c010c72f..78faa4c33 100644 --- a/hermit/kernel/signal.c +++ b/hermit/kernel/signal.c @@ -4,15 +4,11 @@ #include #include #include +#include #include #include #include -#define ENABLE_DEBUG 0 -#if !ENABLE_DEBUG -#define kprintf(...) -#endif - #define SIGNAL_IRQ (32 + 82) #define SIGNAL_BUFFER_SIZE (16) @@ -22,26 +18,26 @@ static sig_t signal_buffer[MAX_CORES][SIGNAL_BUFFER_SIZE]; static void _signal_irq_handler(struct state* s) { - kprintf("Enter _signal_irq_handler() on core %d\n", CORE_ID); + LOG_DEBUG("Enter _signal_irq_handler() on core %d\n", CORE_ID); sig_t signal; task_t* dest_task; task_t* curr_task = per_core(current_task); while(dequeue_pop(&signal_queue[CORE_ID], &signal) == 0) { - kprintf(" Deliver signal %d\n", signal.signum); + LOG_DEBUG(" Deliver signal %d\n", signal.signum); if(get_task(signal.dest, &dest_task) == 0) { - kprintf(" Found valid task with ID %d\n", dest_task->id); + LOG_DEBUG(" Found valid task with ID %d\n", dest_task->id); // only service signals for tasks on this core if(dest_task->last_core != CORE_ID) { - kprintf(" Signal dispatched to wrong CPU! Dropping it ...\n"); + LOG_DEBUG(" Signal dispatched to wrong CPU! Dropping it ...\n"); continue; } if(dest_task->signal_handler) { - kprintf(" Has signal handler (%p)\n", dest_task->signal_handler); + LOG_DEBUG(" Has signal handler (%p)\n", dest_task->signal_handler); /* We will inject the signal handler into the control flow when * the task will continue it's exection the next time. There are @@ -82,7 +78,7 @@ static void _signal_irq_handler(struct state* s) struct state *task_state, *sighandler_state; const int task_is_running = dest_task == curr_task; - kprintf(" Task is%s running\n", task_is_running ? "" : " not"); + LOG_DEBUG(" Task is%s running\n", task_is_running ? "" : " not"); // location of task state depends of type of interruption task_state = (!task_is_running) ? @@ -93,7 +89,7 @@ static void _signal_irq_handler(struct state* s) const int state_on_task_stack = task_state->int_no == 0; if(state_on_task_stack) { - kprintf(" State is already on task stack\n"); + LOG_DEBUG(" State is already on task stack\n"); // stack pointer was saved by switch_context() after saving // task state to task stack task_stackptr = dest_task->last_stack_pointer; @@ -102,7 +98,7 @@ static void _signal_irq_handler(struct state* s) // interrupt stack task_stackptr = (size_t*) task_state->rsp; - kprintf(" Copy state to task stack\n"); + LOG_DEBUG(" Copy state to task stack\n"); task_stackptr -= sizeof(struct state) / sizeof(size_t); memcpy(task_stackptr, task_state, sizeof(struct state)); } @@ -114,7 +110,7 @@ static void _signal_irq_handler(struct state* s) size_t* sighandler_rsp = task_stackptr; if(state_on_task_stack) { - kprintf(" Craft state for signal handler on task stack\n"); + LOG_DEBUG(" Craft state for signal handler on task stack\n"); // we actually only care for ss, rflags, cs, fs and gs task_stackptr -= sizeof(struct state) / sizeof(size_t); @@ -125,7 +121,7 @@ static void _signal_irq_handler(struct state* s) // restored first dest_task->last_stack_pointer = (size_t*) sighandler_state; } else { - kprintf(" Reuse state on IST for signal handler\n"); + LOG_DEBUG(" Reuse state on IST for signal handler\n"); sighandler_state = task_state; } @@ -138,13 +134,13 @@ static void _signal_irq_handler(struct state* s) sighandler_state->rdi = (uint64_t) signal.signum; sighandler_state->rip = (uint64_t) dest_task->signal_handler; } else { - kprintf(" No signal handler installed\n"); + LOG_DEBUG(" No signal handler installed\n"); } } else { - kprintf(" Task %d has already died\n", signal.dest); + LOG_DEBUG(" Task %d has already died\n", signal.dest); } } - kprintf("Leave _signal_irq_handler() on core %d\n", CORE_ID); + LOG_DEBUG("Leave _signal_irq_handler() on core %d\n", CORE_ID); } int hermit_signal(signal_handler_t handler) @@ -159,17 +155,17 @@ int hermit_kill(tid_t dest, int signum) { task_t* task; if(BUILTIN_EXPECT(get_task(dest, &task), 0)) { - kprintf("Trying to send signal %d to invalid task %d\n", signum, dest); + LOG_ERROR("Trying to send signal %d to invalid task %d\n", signum, dest); return -ENOENT; } const tid_t dest_core = task->last_core; - kprintf("Send signal %d from task %d (core %d) to task %d (core %d)\n", + LOG_DEBUG("Send signal %d from task %d (core %d) to task %d (core %d)\n", signum, per_core(current_task)->id, CORE_ID, dest, dest_core); if(task == per_core(current_task)) { - kprintf(" Deliver signal to itself, call handler immediately\n"); + LOG_DEBUG(" Deliver signal to itself, call handler immediately\n"); if(task->signal_handler) { task->signal_handler(signum); @@ -179,12 +175,12 @@ int hermit_kill(tid_t dest, int signum) sig_t signal = {dest, signum}; if(dequeue_push(&signal_queue[dest_core], &signal)) { - kprintf(" Cannot push signal to task's signal queue, dropping it\n"); + LOG_ERROR(" Cannot push signal to task's signal queue, dropping it\n"); return -ENOMEM; } // send IPI to destination core - kprintf(" Send signal IPI (%d) to core %d\n", SIGNAL_IRQ, dest_core); + LOG_DEBUG(" Send signal IPI (%d) to core %d\n", SIGNAL_IRQ, dest_core); apic_send_ipi(dest_core, SIGNAL_IRQ); return 0; diff --git a/hermit/kernel/syscall.c b/hermit/kernel/syscall.c index 33e567081..db4d15513 100644 --- a/hermit/kernel/syscall.c +++ b/hermit/kernel/syscall.c @@ -36,6 +36,7 @@ #include #include #include +#include #include #include @@ -237,7 +238,7 @@ ssize_t sys_sbrk(ssize_t incr) static spinlock_t heap_lock = SPINLOCK_INIT; if (BUILTIN_EXPECT(!heap, 0)) { - kprintf("sys_sbrk: missing heap!\n"); + LOG_ERROR("sys_sbrk: missing heap!\n"); do_abort(); } @@ -508,7 +509,7 @@ int sys_rcce_init(int session_id) out: islelock_unlock(rcce_lock); - kprintf("Create MPB for session %d at 0x%zx, using of slot %d\n", session_id, paddr, i); + LOG_INFO("Create MPB for session %d at 0x%zx, using of slot %d\n", session_id, paddr, i); return err; } @@ -538,7 +539,7 @@ size_t sys_rcce_malloc(int session_id, int ue) } } while((i >= MAX_RCCE_SESSIONS) && (counter < 120)); - //kprintf("i = %d, counter = %d, max %d\n", i, counter, MAX_RCCE_SESSIONS); + LOG_DEBUG("i = %d, counter = %d, max %d\n", i, counter, MAX_RCCE_SESSIONS); // create new session if (i >= MAX_RCCE_SESSIONS) @@ -553,7 +554,7 @@ size_t sys_rcce_malloc(int session_id, int ue) goto out; } - kprintf("Map MPB of session %d at 0x%zx, using of slot %d, isle %d\n", session_id, vaddr, i, ue); + LOG_INFO("Map MPB of session %d at 0x%zx, using of slot %d, isle %d\n", session_id, vaddr, i, ue); if (isle == ue) memset((void*)vaddr, 0x0, RCCE_MPB_SIZE); @@ -561,7 +562,7 @@ size_t sys_rcce_malloc(int session_id, int ue) return vaddr; out: - kprintf("Didn't find a valid MPB for session %d, isle %d\n", session_id, ue); + LOG_ERROR("Didn't find a valid MPB for session %d, isle %d\n", session_id, ue); return 0; } diff --git a/hermit/kernel/tasks.c b/hermit/kernel/tasks.c index 982d7e9c7..0f0eda6ff 100644 --- a/hermit/kernel/tasks.c +++ b/hermit/kernel/tasks.c @@ -36,6 +36,7 @@ #include #include #include +#include #include #include @@ -214,7 +215,7 @@ void check_scheduling(void) const uint64_t cpu_freq_hz = 1000000ULL * (uint64_t) get_cpu_frequency(); if (((diff_cycles * (uint64_t) TIMER_FREQ) / cpu_freq_hz) > 0) { - //kprintf("Time slice expired for task %d on core %d. New task has priority %u.\n", curr_task->id, CORE_ID, prio); + LOG_DEBUG("Time slice expired for task %d on core %d. New task has priority %u.\n", curr_task->id, CORE_ID, prio); reschedule(); } #endif @@ -243,7 +244,7 @@ int multitasking_init(void) uint32_t core_id = CORE_ID; if (BUILTIN_EXPECT(task_table[0].status != TASK_IDLE, 0)) { - kputs("Task 0 is not an idle task\n"); + LOG_ERROR("Task 0 is not an idle task\n"); return -ENOMEM; } @@ -339,7 +340,7 @@ int init_tls(void) tls_addr = kmalloc(curr_task->tls_size + TLS_OFFSET); if (BUILTIN_EXPECT(!tls_addr, 0)) { - kprintf("load_task: heap is missing!\n"); + LOG_ERROR("load_task: heap is missing!\n"); return -ENOMEM; } @@ -347,7 +348,7 @@ int init_tls(void) // set fs register to the TLS segment set_tls((size_t) tls_addr + curr_task->tls_size + TLS_OFFSET); - kprintf("TLS of task %d on core %d starts at 0x%zx (TLS)\n", curr_task->id, CORE_ID, tls_addr + TLS_OFFSET); + LOG_INFO("TLS of task %d on core %d starts at 0x%zx (TLS)\n", curr_task->id, CORE_ID, tls_addr + TLS_OFFSET); } else set_tls(0); // no TLS => clear fs register return 0; @@ -367,7 +368,7 @@ void finish_task_switch(void) if (old->status == TASK_FINISHED) { /* cleanup task */ if (old->stack) { - kprintf("Release stack at 0x%zx\n", old->stack); + LOG_INFO("Release stack at 0x%zx\n", old->stack); destroy_stack(old->stack, DEFAULT_STACK_SIZE); old->stack = NULL; } @@ -405,7 +406,7 @@ void NORETURN do_exit(int arg) void* tls_addr = NULL; const uint32_t core_id = CORE_ID; - kprintf("Terminate task: %u, return value %d\n", curr_task->id, arg); + LOG_INFO("Terminate task: %u, return value %d\n", curr_task->id, arg); uint8_t flags = irq_nested_disable(); @@ -417,7 +418,7 @@ void NORETURN do_exit(int arg) // do we need to release the TLS? tls_addr = (void*)get_tls(); if (tls_addr) { - kprintf("Release TLS at %p\n", (char*)tls_addr - curr_task->tls_size); + LOG_INFO("Release TLS at %p\n", (char*)tls_addr - curr_task->tls_size); kfree((char*)tls_addr - curr_task->tls_size - TLS_OFFSET); } @@ -426,7 +427,7 @@ void NORETURN do_exit(int arg) irq_nested_enable(flags); - kprintf("Kernel panic: scheduler found no valid task\n"); + LOG_ERROR("Kernel panic: scheduler found no valid task\n"); while(1) { HALT; } @@ -462,7 +463,7 @@ static uint32_t get_next_core_id(void) break; if (BUILTIN_EXPECT(!readyqueues[core_id].idle, 0)) { - kprintf("BUG: no core available!\n"); + LOG_ERROR("BUG: no core available!\n"); return MAX_CORES; } @@ -555,7 +556,7 @@ int clone_task(tid_t* id, entry_point_t ep, void* arg, uint8_t prio) spinlock_irqsave_unlock(&table_lock); if (!ret) - kprintf("start new thread %d on core %d with stack address %p\n", i, core_id, stack); + LOG_INFO("start new thread %d on core %d with stack address %p\n", i, core_id, stack); out: if (ret) { @@ -631,7 +632,6 @@ int create_task(tid_t* id, entry_point_t ep, void* arg, uint8_t prio, uint32_t c if (id) *id = i; - //kprintf("Create task %d with pml4 at 0x%llx\n", i, task_table[i].page_map); ret = create_default_frame(task_table+i, ep, arg, core_id); if (ret) @@ -657,7 +657,7 @@ int create_task(tid_t* id, entry_point_t ep, void* arg, uint8_t prio, uint32_t c } if (!ret) - kprintf("start new task %d on core %d with stack address %p\n", i, core_id, stack); + LOG_INFO("start new task %d on core %d with stack address %p\n", i, core_id, stack); out: spinlock_irqsave_unlock(&table_lock); @@ -792,7 +792,7 @@ int set_timer(uint64_t deadline) ret = 0; } else { - kprintf("Task is already blocked. No timer will be set!\n"); + LOG_INFO("Task is already blocked. No timer will be set!\n"); } irq_nested_enable(flags); @@ -871,11 +871,11 @@ size_t** scheduler(void) curr_task = task_list_pop_front(&readyqueues[core_id].queue[prio-1]); if(BUILTIN_EXPECT(curr_task == NULL, 0)) { - kprintf("Kernel panic: No task in readyqueue\n"); + LOG_ERROR("Kernel panic: No task in readyqueue\n"); while(1); } if (BUILTIN_EXPECT(curr_task->status == TASK_INVALID, 0)) { - kprintf("Kernel panic: Got invalid task %d, orig task %d\n", + LOG_ERROR("Kernel panic: Got invalid task %d, orig task %d\n", curr_task->id, orig_task->id); while(1); } @@ -897,7 +897,7 @@ get_task_out: spinlock_irqsave_unlock(&readyqueues[core_id].lock); if (curr_task != orig_task) { - //kprintf("schedule on core %d from %u to %u with prio %u\n", core_id, orig_task->id, curr_task->id, (uint32_t)curr_task->prio); + LOG_DEBUG("schedule on core %d from %u to %u with prio %u\n", core_id, orig_task->id, curr_task->id, (uint32_t)curr_task->prio); return (size_t**) &(orig_task->last_stack_pointer); } diff --git a/hermit/mm/hbmemory.c b/hermit/mm/hbmemory.c index ed7d32ca8..fd54f435a 100644 --- a/hermit/mm/hbmemory.c +++ b/hermit/mm/hbmemory.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include @@ -85,7 +86,7 @@ size_t hbmem_get_pages(size_t npages) curr = curr->next; } out: - //kprintf("get_pages: ret 0%llx, curr->start 0x%llx, curr->end 0x%llx\n", ret, curr->start, curr->end); + LOG_DEBUG("get_pages: ret 0%llx, curr->start 0x%llx, curr->end 0x%llx\n", ret, curr->start, curr->end); spinlock_unlock(&list_lock); @@ -164,7 +165,7 @@ int hbmemory_init(void) init_list.start = hbmem_base; init_list.end = hbmem_base + hbmem_size; - kprintf("free list for hbmem starts at 0x%zx, limit 0x%zx\n", init_list.start, init_list.end); + LOG_INFO("free list for hbmem starts at 0x%zx, limit 0x%zx\n", init_list.start, init_list.end); return 0; } diff --git a/hermit/mm/malloc.c b/hermit/mm/malloc.c index 7de15cb67..9db7eee01 100644 --- a/hermit/mm/malloc.c +++ b/hermit/mm/malloc.c @@ -33,6 +33,7 @@ #include #include #include +#include #include /// A linked list for each binary size exponent @@ -120,14 +121,14 @@ void buddy_dump(void) int exp = i+BUDDY_MIN; if (buddy_lists[i]) - kprintf("buddy_list[%u] (exp=%u, size=%lu bytes):\n", i, exp, 1<next) { - kprintf(" %p -> %p \n", buddy, buddy->next); + LOG_INFO(" %p -> %p \n", buddy, buddy->next); free += 1<> PAGE_BITS; int err; - //kprintf("palloc(%lu) (%lu pages)\n", sz, npages); + LOG_DEBUG("palloc(%lu) (%lu pages)\n", sz, npages); // get free virtual address space viraddr = vma_alloc(PAGE_FLOOR(sz), flags); @@ -173,7 +174,7 @@ void* create_stack(size_t sz) uint32_t npages = PAGE_FLOOR(sz) >> PAGE_BITS; int err; - //kprintf("create_stack(0x%zx) (%lu pages)\n", DEFAULT_STACK_SIZE, npages); + LOG_DEBUG("create_stack(0x%zx) (%lu pages)\n", DEFAULT_STACK_SIZE, npages); if (BUILTIN_EXPECT(!sz, 0)) return NULL; @@ -211,7 +212,7 @@ int destroy_stack(void* viraddr, size_t sz) size_t phyaddr; uint32_t npages = PAGE_FLOOR(sz) >> PAGE_BITS; - //kprintf("destroy_stack(0x%zx) (size 0x%zx)\n", viraddr, DEFAULT_STACK_SIZE); + LOG_DEBUG("destroy_stack(0x%zx) (size 0x%zx)\n", viraddr, DEFAULT_STACK_SIZE); if (BUILTIN_EXPECT(!viraddr, 0)) return -EINVAL; @@ -250,7 +251,7 @@ void* kmalloc(size_t sz) buddy->prefix.magic = BUDDY_MAGIC; buddy->prefix.exponent = exp; - //kprintf("kmalloc(%lu) = %p\n", sz, buddy+1); + LOG_DEBUG("kmalloc(%lu) = %p\n", sz, buddy+1); // pointer arithmetic: we hide the prefix return buddy+1; @@ -261,7 +262,7 @@ void kfree(void *addr) if (BUILTIN_EXPECT(!addr, 0)) return; - //kprintf("kfree(%lu)\n", addr); + LOG_DEBUG("kfree(%lu)\n", addr); buddy_t* buddy = (buddy_t*) addr - 1; // get prefix diff --git a/hermit/mm/memory.c b/hermit/mm/memory.c index 281fddb70..3bf6b945c 100644 --- a/hermit/mm/memory.c +++ b/hermit/mm/memory.c @@ -31,6 +31,7 @@ #include #include #include +#include #include #include @@ -93,7 +94,7 @@ size_t get_pages(size_t npages) curr = curr->next; } out: - //kprintf("get_pages: ret 0%llx, curr->start 0x%llx, curr->end 0x%llx\n", ret, curr->start, curr->end); + LOG_DEBUG("get_pages: ret 0%llx, curr->start 0x%llx, curr->end 0x%llx\n", ret, curr->start, curr->end); spinlock_unlock(&list_lock); @@ -125,7 +126,7 @@ size_t get_zeroed_page(void) if (BUILTIN_EXPECT(!viraddr, 0)) goto novaddr; - //kprintf("Core %d uses 0x%zx as temporary address\n", CORE_ID, viraddr); + LOG_DEBUG("Core %d uses 0x%zx as temporary address\n", CORE_ID, viraddr); set_per_core(ztmp_addr, viraddr); } @@ -250,12 +251,12 @@ int memory_init(void) // enable paging and map Multiboot modules etc. ret = page_init(); if (BUILTIN_EXPECT(ret, 0)) { - kputs("Failed to initialize paging!\n"); + LOG_ERROR("Failed to initialize paging!\n"); return ret; } - kprintf("mb_info: 0x%zx\n", mb_info); - kprintf("memory_init: base 0x%zx, image_size 0x%zx, limit 0x%zx\n", base, image_size, limit); + LOG_INFO("mb_info: 0x%zx\n", mb_info); + LOG_INFO("memory_init: base 0x%zx, image_size 0x%zx, limit 0x%zx\n", base, image_size, limit); if (mb_info) { if (mb_info->flags & MULTIBOOT_INFO_MEM_MAP) { @@ -269,13 +270,13 @@ int memory_init(void) start_addr = PAGE_FLOOR(mmap->addr); end_addr = PAGE_CEIL(mmap->addr + mmap->len); - kprintf("Free region 0x%zx - 0x%zx\n", start_addr, end_addr); + LOG_INFO("Free region 0x%zx - 0x%zx\n", start_addr, end_addr); if ((start_addr <= base) && (end_addr >= PAGE_2M_FLOOR(base+image_size))) { init_list.start = PAGE_2M_FLOOR(base+image_size); init_list.end = end_addr; - kprintf("Add region 0x%zx - 0x%zx\n", init_list.start, init_list.end); + LOG_INFO("Add region 0x%zx - 0x%zx\n", init_list.start, init_list.end); } // determine available memory @@ -303,14 +304,14 @@ int memory_init(void) atomic_int64_add(&total_allocated_pages, PAGE_2M_FLOOR(image_size) >> PAGE_BITS); atomic_int64_sub(&total_available_pages, PAGE_2M_FLOOR(image_size) >> PAGE_BITS); - kprintf("free list starts at 0x%zx, limit 0x%zx\n", init_list.start, init_list.end); + LOG_INFO("free list starts at 0x%zx, limit 0x%zx\n", init_list.start, init_list.end); // init high bandwidth memory subsystem hbmemory_init(); ret = vma_init(); if (BUILTIN_EXPECT(ret, 0)) - kprintf("Failed to initialize VMA regions: %d\n", ret); + LOG_WARNING("Failed to initialize VMA regions: %d\n", ret); // add missing free regions if (mb_info) { @@ -341,7 +342,7 @@ int memory_init(void) if (BUILTIN_EXPECT(!last->next, 0)) goto oom; - kprintf("Add region 0x%zx - 0x%zx\n", start_addr, end_addr); + LOG_INFO("Add region 0x%zx - 0x%zx\n", start_addr, end_addr); last->next->prev = last; last = last->next; @@ -358,6 +359,6 @@ int memory_init(void) return ret; oom: - kprintf("BUG: Failed to init mm!\n"); + LOG_ERROR("BUG: Failed to init mm!\n"); while(1) {HALT; } } diff --git a/hermit/mm/vma.c b/hermit/mm/vma.c index b8bfcb97a..c1652794a 100644 --- a/hermit/mm/vma.c +++ b/hermit/mm/vma.c @@ -31,6 +31,7 @@ #include #include #include +#include #include /* @@ -56,7 +57,7 @@ int vma_init(void) { int ret; - kprintf("vma_init: reserve vma region 0x%llx - 0x%llx\n", + LOG_INFO("vma_init: reserve vma region 0x%llx - 0x%llx\n", PAGE_2M_CEIL((size_t) &kernel_start), PAGE_2M_FLOOR((size_t) &kernel_end)); @@ -95,7 +96,7 @@ size_t vma_alloc(size_t size, uint32_t flags) spinlock_irqsave_t* lock = &vma_lock; vma_t** list = &vma_list; - //kprintf("vma_alloc: size = %#lx, flags = %#x\n", size, flags); + LOG_DEBUG("vma_alloc: size = %#lx, flags = %#x\n", size, flags); // boundaries of free gaps size_t start, end; @@ -128,7 +129,7 @@ fail: found: if (pred && pred->flags == flags) { pred->end += size; // resize VMA - //kprintf("vma_alloc: resize vma, start 0x%zx, pred->start 0x%zx, pred->end 0x%zx\n", start, pred->start, pred->end); + LOG_DEBUG("vma_alloc: resize vma, start 0x%zx, pred->start 0x%zx, pred->end 0x%zx\n", start, pred->start, pred->end); } else { // insert new VMA vma_t* new = kmalloc(sizeof(vma_t)); @@ -160,7 +161,7 @@ int vma_free(size_t start, size_t end) vma_t* vma; vma_t** list = &vma_list; - //kprintf("vma_free: start = %#lx, end = %#lx\n", start, end); + LOG_DEBUG("vma_free: start = %#lx, end = %#lx\n", start, end); if (BUILTIN_EXPECT(start >= end, 0)) return -EINVAL; @@ -225,7 +226,7 @@ int vma_add(size_t start, size_t end, uint32_t flags) if (BUILTIN_EXPECT(start >= end, 0)) return -EINVAL; - //kprintf("vma_add: start = %#lx, end = %#lx, flags = %#x\n", start, end, flags); + LOG_DEBUG("vma_add: start = %#lx, end = %#lx, flags = %#x\n", start, end, flags); spinlock_irqsave_lock(lock); @@ -249,7 +250,7 @@ int vma_add(size_t start, size_t end, uint32_t flags) if (pred && (pred->end == start) && (pred->flags == flags)) { pred->end = end; // resize VMA - //kprintf("vma_alloc: resize vma, start 0x%zx, pred->start 0x%zx, pred->end 0x%zx\n", start, pred->start, pred->end); + LOG_DEBUG("vma_alloc: resize vma, start 0x%zx, pred->start 0x%zx, pred->end 0x%zx\n", start, pred->start, pred->end); } else { // insert new VMA vma_t* new = kmalloc(sizeof(vma_t)); @@ -282,7 +283,7 @@ void vma_dump(void) { void print_vma(vma_t *vma) { while (vma) { - kprintf("0x%lx - 0x%lx: size=0x%x, flags=%c%c%c%s\n", vma->start, vma->end, vma->end - vma->start, + LOG_INFO("0x%lx - 0x%lx: size=0x%x, flags=%c%c%c%s\n", vma->start, vma->end, vma->end - vma->start, (vma->flags & VMA_READ) ? 'r' : '-', (vma->flags & VMA_WRITE) ? 'w' : '-', (vma->flags & VMA_EXECUTE) ? 'x' : '-', @@ -291,7 +292,7 @@ void vma_dump(void) } } - kputs("VMAs:\n"); + LOG_INFO("VMAs:\n"); spinlock_irqsave_lock(&vma_lock); print_vma(&vma_boot); spinlock_irqsave_unlock(&vma_lock);