[COMMIT osv master] elf: refine logging

[Commit Bot]

From: Waldemar Kozaczuk <jwkoz...@gmail.com>
Committer: Waldemar Kozaczuk <jwkoz...@gmail.com>
Branch: master

elf: refine logging

This patch adds new build configuration option - `conf-debug_elf`,
intended to enable logging in dynamic linker logic.

It also refines/adds relevant comments.

Signed-off-by: Waldemar Kozaczuk <jwkoz...@gmail.com>

---
diff --git a/Makefile b/Makefile
--- a/Makefile
+++ b/Makefile
@@ -317,7 +317,7 @@ $(out)/bsd/%.o: INCLUDES += -isystem bsd/
# for machine/
$(out)/bsd/%.o: INCLUDES += -isystem bsd/$(arch)

-configuration-defines = conf-preempt conf-debug_memory conf-logger_debug
+configuration-defines = conf-preempt conf-debug_memory conf-logger_debug conf-debug_elf

configuration = $(foreach cf,$(configuration-defines), \
-D$(cf:conf-%=CONF_%)=$($(cf)))
diff --git a/arch/x64/arch-elf.cc b/arch/x64/arch-elf.cc
--- a/arch/x64/arch-elf.cc
+++ b/arch/x64/arch-elf.cc
@@ -10,6 +10,12 @@
#include <osv/elf.hh>
#include <osv/sched.hh>

+#if CONF_debug_elf
+#define elf_debug(format,...) kprintf("ELF [tid:%d, mod:%d, %s]: " format, sched::thread::current()->id(), _module_index, _pathname.c_str(), ##__VA_ARGS__)
+#else
+#define elf_debug(...)
+#endif
+
namespace elf {

// This function is solely used to relocate symbols in OSv kernel ELF
@@ -105,7 +111,7 @@ bool object::arch_relocate_rela(u32 type, u32 sym, void *addr,
// which provides dynamic access of thread local variable
// This calculates the module index of the ELF containing the variable
if (sym == STN_UNDEF) {
- // The thread-local variable being accessed is within
+ // The thread-local variable (most likely static) being accessed is within
// the SAME shared object as the caller
*static_cast<u64*>(addr) = _module_index;
// No need to calculate the offset to the beginning
@@ -114,11 +120,13 @@ bool object::arch_relocate_rela(u32 type, u32 sym, void *addr,
// in DIFFERENT shared object that the caller
*static_cast<u64*>(addr) = symbol(sym).obj->_module_index;
}
+ elf_debug("arch_relocate_rela, R_X86_64_DTPMOD64 for sym:%d, mod ID:%ld\n", sym, (*static_cast<u64*>(addr)));
break;
case R_X86_64_DTPOFF64:
// The thread-local variable being accessed is located
// in DIFFERENT shared object that the caller
*static_cast<u64*>(addr) = symbol(sym).symbol->st_value;
+ elf_debug("arch_relocate_rela, R_X86_64_DTPOFF64 for sym:%d, offset:%ld\n", sym, (*static_cast<u64*>(addr)));
break;
case R_X86_64_TPOFF64:
// This type is intended to resolve symbols of thread-local variables in static TLS
@@ -143,11 +151,13 @@ bool object::arch_relocate_rela(u32 type, u32 sym, void *addr,
}
*static_cast<u64*>(addr) = sm.symbol->st_value + addend - tls_offset;
} else {
- // TODO: Which case does this handle?
+ // The static (local to this module) thread-local variable/s being accessed within
+ // same module so we just need to set the offset for corresponding static TLS block
alloc_static_tls();
auto tls_offset = static_tls_end() + sched::kernel_tls_size();
*static_cast<u64*>(addr) = addend - tls_offset;
}
+ elf_debug("arch_relocate_rela, R_X86_64_TPOFF64 for sym:%d, TP offset:%ld\n", sym, (*static_cast<u64*>(addr)));
break;
default:
return false;
diff --git a/arch/x64/arch-switch.hh b/arch/x64/arch-switch.hh
--- a/arch/x64/arch-switch.hh
+++ b/arch/x64/arch-switch.hh
@@ -170,6 +170,10 @@ void thread::setup_tcb()
// (see arch/x64/loader.ld for specifics) with an extra buffer at
// the end of the kernel TLS to accommodate TLS block of pies and
// position-dependant executables.
+ //
+ // Please note that the TLS layout conforms to the variant II (2),
+ // which means for example that all variable offsets are negative.
+ // It also means that individual objects are laid out from the right to the left.

// (1) - TLS memory area layout with app shared library
// |-----|-----|-----|--------------|------|
diff --git a/conf/base.mk b/conf/base.mk
--- a/conf/base.mk
+++ b/conf/base.mk
@@ -9,3 +9,5 @@ conf-logger_debug=0
# This macro controls the NDEBUG macro that is used to identify the debug
# build variant in the code.
conf-DEBUG_BUILD=0
+
+conf-debug_elf=0
diff --git a/core/elf.cc b/core/elf.cc
--- a/core/elf.cc
+++ b/core/elf.cc
@@ -31,10 +31,8 @@

#include "arch.hh"

-#define ELF_DEBUG_ENABLED 0
-
-#if ELF_DEBUG_ENABLED
-#define elf_debug(format,...) kprintf("ELF [tid:%d, %s]: " format, sched::thread::current()->id(), _pathname.c_str(), ##__VA_ARGS__)
+#if CONF_debug_elf
+#define elf_debug(format,...) kprintf("ELF [tid:%d, mod:%d, %s]: " format, sched::thread::current()->id(), _module_index, _pathname.c_str(), ##__VA_ARGS__)
#else
#define elf_debug(...)
#endif
@@ -376,7 +374,7 @@ void object::set_base(void* base)
}

_end = _base + q->p_vaddr + q->p_memsz;
- elf_debug("The base set to: 0x%016x and end: 0x%016x\n", _base, _end);
+ elf_debug("The base set to: %018p and end: %018p\n", _base, _end);
}

void* object::base() const
@@ -417,7 +415,7 @@ void file::load_segment(const Elf64_Phdr& phdr)
mmu::map_anon(_base + vstart + filesz, memsz - filesz, flag, perm);
}
}
- elf_debug("Loaded and mapped PT_LOAD segment at: 0x%016x of size: 0x%x\n", _base + vstart, filesz); //TODO: Add memory?
+ elf_debug("Loaded and mapped PT_LOAD segment at: %018p of size: 0x%x\n", _base + vstart, filesz);
}

bool object::mlocked()
@@ -523,7 +521,7 @@ void object::process_headers()
_tls_init_size = phdr.p_filesz;
_tls_uninit_size = phdr.p_memsz - phdr.p_filesz;
_tls_alignment = phdr.p_align;
- elf_debug("Found TLS segment at 0x%016x of aligned size: %x\n", _tls_segment, get_aligned_tls_size());
+ elf_debug("Found TLS segment at %018p of aligned size: 0x%x\n", _tls_segment, get_aligned_tls_size());
break;
default:
abort("Unknown p_type in executable %s: %d\n", pathname(), phdr.p_type);
@@ -1211,7 +1209,7 @@ void object::alloc_static_tls()
if (!_static_tls && tls_size) {
_static_tls = true;
_static_tls_offset = _static_tls_alloc.fetch_add(tls_size, std::memory_order_relaxed);
- elf_debug("Allocated static TLS at 0x%016x of size: 0x%x\n", _static_tls_offset, tls_size);
+ elf_debug("Allocated static TLS at offset: 0x%x of size: 0x%x\n", _static_tls_offset, tls_size);
}
}

[Nadav Har'El]

On Fri, Oct 23, 2020 at 7:11 AM Commit Bot <b...@cloudius-systems.com> wrote:

From: Waldemar Kozaczuk <jwkoz...@gmail.com>
Committer: Waldemar Kozaczuk <jwkoz...@gmail.com>
Branch: master

elf: refine logging

This patch adds new build configuration option - `conf-debug_elf`,
intended to enable logging in dynamic linker logic.

It also refines/adds relevant comments.

Hi. I just wanted to note that in the past we developed tracepoints as an alternative to adding such debugging options.

The advantages of tracepoints compared to debugging options include:

1. Tracepoints are "local" in the code - to add a tracepoint to elf.cc, you add it there - no need to add mess to various centralized code, build files, etc.
2. Tracepoints can be easily turned on and off during runtime, not only during build time.
3. Tracepoints can be reasonably turned on even if they produce a lot of output (esp. if you only want to see the latest one).
4. A turned-off tracepoint is almost as cheap as being disabled during build (it only does a "NOP" instruction), so no real advantage for build-time configurations.

So I think in the long run, we should use more tracepoints and less "kprint" et al. But it's not urgent to change that now.

https://github.com/cloudius-systems/osv/wiki/Debugging-OSv#tracepoints contains a partial description of tracepoints, but feel free to ask if there is something that wasn't described there well.

--
You received this message because you are subscribed to the Google Groups "OSv Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to osv-dev+u...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/osv-dev/00000000000056385405b24ec55c%40google.com.