[PATCH] Fix bug in arch_setup_free_memory

[Waldemar Kozaczuk]

The commit 97fe8aa3d2d8f2c938fcaa379c44ae5a80dfbf33 adjusted logic
in arch_setup_free_memory() to improve memory utilization
by making OSv use memory below kernel (<= 2MB).

Ironically the new logic introduced new bug which led to much bigger
waste of memory. Specifically it did not take into account
the case of memory region starting below 2MB and ending
above 1GB at the same time and make it skip the part above 1GB altogether.

This patch fixes this bug and makes issue reported below go away.

Fixes #1048

Signed-off-by: Waldemar Kozaczuk <jwkoz...@gmail.com>
---
arch/x64/arch-setup.cc | 12 ++++++++----
1 file changed, 8 insertions(+), 4 deletions(-)

diff --git a/arch/x64/arch-setup.cc b/arch/x64/arch-setup.cc
index e5fb7a6e..986a0928 100644
--- a/arch/x64/arch-setup.cc
+++ b/arch/x64/arch-setup.cc
@@ -175,11 +175,15 @@ void arch_setup_free_memory()
//
// Free the memory below elf_phys_start which we could not before
if (ent.addr < (u64)elf_phys_start) {
+ auto ent_below_kernel = ent;
if (ent.addr + ent.size >= (u64)elf_phys_start) {
- ent = truncate_above(ent, (u64) elf_phys_start);
+ ent_below_kernel = truncate_above(ent, (u64) elf_phys_start);
+ }
+ mmu::free_initial_memory_range(ent_below_kernel.addr, ent_below_kernel.size);
+ // If there is nothing left below elf_phys_start return
+ if (ent.addr + ent.size <= (u64)elf_phys_start) {
+ return;
}
- mmu::free_initial_memory_range(ent.addr, ent.size);
- return;
}
//
// Ignore memory already freed above
@@ -331,4 +335,4 @@ void reset_bootchart(osv_multiboot_info_type* mb_info)

mb_info->tsc_uncompress_done_hi = now_high;
mb_info->tsc_uncompress_done = now_low;
-}
\ No newline at end of file
+}
--
2.20.1

[Waldek Kozaczuk]

This patch definitely fixes an apparent bug I introduced myself in the past. I have tested that issue #1048 goes away with 4,5,6, 7 or 8GB of memory. I have also verified using cli module that free memory is reported properly now.

However, there is still 1 question and 1 issue outstanding:

1. I do not understand how this bug arch_setup_free_memory() would lead to a page fault reported by issue 1048 or other "read errors" with higher memory (8GB, end so). I would expect this bug lead to OSv missing to use the memory above 1GB in the e820 block but still be able to operate properly without the page fault. Is there another underlying bug that this patch actually covers?

2. After this patch the tst-huge.so does not pass - actually hangs or never completes. I have played with it a bit and discovered that it passes if I run it with the right amount of memory - 128M < m <= 1G, but fails with anything above 1GB (the deafult is 2GB). It could be that the test is flaky and has to have right amount of free memory to pass (?).

Here is the stacktrace of where it was stuck:

sched::thread::switch_to (this=this@entry=0xffff8000001ba040) at arch/x64/arch-switch.hh:108

#1  0x00000000403ff794 in sched::cpu::reschedule_from_interrupt (this=0xffff80000001d040, called_from_yield=called_from_yield@entry=false, 

    preempt_after=..., preempt_after@entry=...) at core/sched.cc:339

#2  0x00000000403ffc8c in sched::cpu::schedule () at include/osv/sched.hh:1310

#3  0x0000000040400372 in sched::thread::wait (this=this@entry=0xffff8000014a1040) at core/sched.cc:1214

#4  0x0000000040428072 in sched::thread::do_wait_for<lockfree::mutex, sched::wait_object<waitqueue> > (mtx=...) at include/osv/mutex.h:41

#5  sched::thread::wait_for<waitqueue&> (mtx=...) at include/osv/sched.hh:1220

#6  waitqueue::wait (this=this@entry=0x408ec550 <mmu::vma_list_mutex+48>, mtx=...) at core/waitqueue.cc:56

#7  0x00000000403e2d83 in rwlock::reader_wait_lockable (this=<optimized out>) at core/rwlock.cc:174

#8  rwlock::rlock (this=this@entry=0x408ec520 <mmu::vma_list_mutex>) at core/rwlock.cc:29

#9  0x000000004034ad98 in rwlock_for_read::lock (this=0x408ec520 <mmu::vma_list_mutex>) at include/osv/rwlock.h:113

#10 std::lock_guard<rwlock_for_read&>::lock_guard (__m=..., this=<synthetic pointer>) at /usr/include/c++/8/bits/std_mutex.h:162

#11 lock_guard_for_with_lock<rwlock_for_read&>::lock_guard_for_with_lock (lock=..., this=<synthetic pointer>) at include/osv/mutex.h:89

#12 mmu::vm_fault (addr=18446603337326391296, addr@entry=18446603337326395384, ef=ef@entry=0xffff8000014a6068) at core/mmu.cc:1334

#13 0x00000000403a746e in page_fault (ef=0xffff8000014a6068) at arch/x64/mmu.cc:38

#14 <signal handler called>

#15 0x00000000403f2114 in memory::page_range_allocator::insert<true> (this=this@entry=0x40904300 <memory::free_page_ranges>, pr=...)

    at core/mempool.cc:575

#16 0x00000000403ef83c in memory::page_range_allocator::<lambda(memory::page_range&)>::operator() (header=..., __closure=<synthetic pointer>)

    at core/mempool.cc:751

#17 memory::page_range_allocator::<lambda(memory::page_range&)>::operator() (header=..., __closure=<synthetic pointer>) at core/mempool.cc:736

#18 memory::page_range_allocator::for_each<memory::page_range_allocator::alloc_aligned(size_t, size_t, size_t, bool)::<lambda(memory::page_range&)> > (f=..., min_order=<optimized out>, this=0x40904300 <memory::free_page_ranges>) at core/mempool.cc:809

#19 memory::page_range_allocator::alloc_aligned (this=this@entry=0x40904300 <memory::free_page_ranges>, size=size@entry=2097152, 

    offset=offset@entry=0, alignment=alignment@entry=2097152, fill=fill@entry=true) at core/mempool.cc:736

#20 0x00000000403f0164 in memory::alloc_huge_page (N=N@entry=2097152) at core/mempool.cc:1601

#21 0x000000004035030e in mmu::uninitialized_anonymous_page_provider::map (this=0x40873150 <mmu::page_allocator_init>, offset=83886080, 

    ptep=..., pte=..., write=<optimized out>) at include/osv/mmu-defs.hh:219

#22 0x0000000040355b94 in mmu::populate<(mmu::account_opt)1>::page<1> (offset=83886080, ptep=..., this=0x2000001ffd70)

    at include/osv/mmu-defs.hh:235

#23 mmu::page<mmu::populate<>, 1> (ptep=..., offset=83886080, pops=...) at core/mmu.cc:311

#24 mmu::map_level<mmu::populate<(mmu::account_opt)1>, 2>::operator() (base_virt=35185397596160, parent=..., this=<synthetic pointer>)

    at core/mmu.cc:437

#25 mmu::map_level<mmu::populate<(mmu::account_opt)1>, 3>::map_range<2> (this=<synthetic pointer>, ptep=..., base_virt=35184372088832, 

    slop=4096, page_mapper=..., size=132120576, vcur=<optimized out>) at core/mmu.cc:399

#26 mmu::map_level<mmu::populate<(mmu::account_opt)1>, 3>::operator() (base_virt=35184372088832, parent=..., this=<synthetic pointer>)

    at core/mmu.cc:449

#27 mmu::map_level<mmu::populate<(mmu::account_opt)1>, 4>::map_range<3> (this=<synthetic pointer>, ptep=..., base_virt=35184372088832, 

    slop=4096, page_mapper=..., size=134217728, vcur=<optimized out>) at core/mmu.cc:399

#28 mmu::map_level<mmu::populate<(mmu::account_opt)1>, 4>::operator() (base_virt=35184372088832, parent=..., this=<synthetic pointer>)

--Type <RET> for more, q to quit, c to continue without paging--

    at core/mmu.cc:449

#29 mmu::map_range<mmu::populate<(mmu::account_opt)1> > (vma_start=vma_start@entry=35185313710080, vstart=vstart@entry=35185313710080, 

    size=<optimized out>, page_mapper=..., slop=slop@entry=4096) at core/mmu.cc:354

#30 0x0000000040356385 in mmu::operate_range<mmu::populate<(mmu::account_opt)1> > (size=<optimized out>, start=0x200038200000, 

    vma_start=<optimized out>, mapper=...) at core/mmu.cc:801

#31 mmu::vma::operate_range<mmu::populate<(mmu::account_opt)1> > (size=3, addr=0x200038200000, mapper=..., this=0xffffa000012deb00)

    at core/mmu.cc:1412

#32 mmu::populate_vma<(mmu::account_opt)1> (vma=vma@entry=0xffffa000012deb00, v=v@entry=0x200038200000, size=size@entry=134217728, 

    write=write@entry=false) at core/mmu.cc:1206

#33 0x000000004034e8d2 in mmu::map_anon (addr=addr@entry=0x0, size=size@entry=134217728, flags=flags@entry=2, perm=perm@entry=3)

    at core/mmu.cc:1222

#34 0x000000004046503d in mmap (addr=addr@entry=0x0, length=length@entry=134217728, prot=prot@entry=3, flags=flags@entry=32802, 

    fd=fd@entry=-1, offset=offset@entry=0) at libc/mman.cc:156

#35 0x0000100000006624 in exhaust_memory (size=size@entry=134217728) at /home/wkozaczuk/projects/osv/tests/tst-huge.cc:31

#36 0x000010000000621e in main (argc=<optimized out>, argv=<optimized out>) at /home/wkozaczuk/projects/osv/tests/tst-huge.cc:99

#37 0x000000004043090d in osv::application::run_main (this=0xffffa00001130e10) at /usr/include/c++/8/bits/stl_vector.h:805

#38 0x0000000040226b51 in osv::application::main (this=0xffffa00001130e10) at core/app.cc:320

#39 0x0000000040430ab9 in osv::application::<lambda(void*)>::operator() (__closure=0x0, app=<optimized out>) at core/app.cc:233

#40 osv::application::<lambda(void*)>::_FUN(void *) () at core/app.cc:235

#41 0x000000004045eec6 in pthread_private::pthread::<lambda()>::operator() (__closure=0xffffa0000149c200) at libc/pthread.cc:114

#42 std::_Function_handler<void(), pthread_private::pthread::pthread(void* (*)(void*), void*, sigset_t, const pthread_private::thread_attr*)::<lambda()> >::_M_invoke(const std::_Any_data &) (__functor=...) at /usr/include/c++/8/bits/std_function.h:297

#43 0x0000000040401117 in sched::thread_main_c (t=0xffff8000014a1040) at arch/x64/arch-switch.hh:271

#44 0x00000000403a7263 in thread_main () at arch/x64/entry.S:113

Waldek

[Rick Payne]

Thanks for this - I was hitting a wierd page fault issue on our
application as we've recently moved from 0.52 to the latest OSv.
Something like this, which occurs early on in startup:

Assertion failed: ef->rflags & processor::rflags_if (arch/x64/mmu.cc:
page_fault: 34)

[backtrace]
0x00000000402298ea <__assert_fail+26>
0x000000004039aa30 <page_fault+240>
0x0000000040399826 <???+1077516326>
0x000000004039c0a8 <interrupt+232>
0x000000004039a779 <???+1077520249>
0x0000000040214ca1 <main_cont(int, char**)+193>
0x00000000403f9646 <thread_main_c+38>
0x000000004039a7a2 <???+1077520290>

On fixing the memory to 2GB in virsh, the problem was fixed. Applying
your patch also fixed it, it seems.

Rick

[Commit Bot]

From: Waldemar Kozaczuk <jwkoz...@gmail.com>
Committer: Nadav Har'El <n...@scylladb.com>
Branch: master

Fix bug in arch_setup_free_memory

The commit 97fe8aa3d2d8f2c938fcaa379c44ae5a80dfbf33 adjusted logic
in arch_setup_free_memory() to improve memory utilization
by making OSv use memory below kernel (<= 2MB).

Ironically the new logic introduced new bug which led to much bigger
waste of memory. Specifically it did not take into account
the case of memory region starting below 2MB and ending
above 1GB at the same time and make it skip the part above 1GB altogether.

This patch fixes this bug and makes issue reported below go away.

Fixes #1048

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

Message-Id: <20190821025311.8...@gmail.com>

---
diff --git a/arch/x64/arch-setup.cc b/arch/x64/arch-setup.cc

[Nadav Har'El]

On Wed, Aug 21, 2019 at 6:04 AM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

This patch definitely fixes an apparent bug I introduced myself in the past. I have tested that issue #1048 goes away with 4,5,6, 7 or 8GB of memory. I have also verified using cli module that free memory is reported properly now.

Thanks, I committed you patch, which indeed fixes that bug. But you are asking god questions:

However, there is still 1 question and 1 issue outstanding:

1. I do not understand how this bug arch_setup_free_memory() would lead to a page fault reported by issue 1048 or other "read errors" with higher memory (8GB, end so). I would expect this bug lead to OSv missing to use the memory above 1GB in the e820 block but still be able to operate properly without the page fault. Is there another underlying bug that this patch actually covers?

What I don't understand (I don't understand the details of this intialization code, unfortunately), is that if your code by mistake did not use the code above 1GB, how does changing the amount of memory from 2GB to 4GB, etc., make any difference at all

2. After this patch the tst-huge.so does not pass - actually hangs or never completes. I have played with it a bit and discovered that it passes if I run it with the right amount of memory - 128M < m <= 1G, but fails with anything above 1GB (the deafult is 2GB). It could be that the test is flaky and has to have right amount of free memory to pass (?).

I don't remember this test every being flaky. You can go back to an older version and see if it failed for different amounts of memory. But maybe it was, because:

Here is the stacktrace of where it was stuck:

sched::thread::switch_to (this=this@entry=0xffff8000001ba040) at arch/x64/arch-switch.hh:108

#1  0x00000000403ff794 in sched::cpu::reschedule_from_interrupt (this=0xffff80000001d040, called_from_yield=called_from_yield@entry=false, 

    preempt_after=..., preempt_after@entry=...) at core/sched.cc:339

#2  0x00000000403ffc8c in sched::cpu::schedule () at include/osv/sched.hh:1310

#3  0x0000000040400372 in sched::thread::wait (this=this@entry=0xffff8000014a1040) at core/sched.cc:1214

#4  0x0000000040428072 in sched::thread::do_wait_for<lockfree::mutex, sched::wait_object<waitqueue> > (mtx=...) at include/osv/mutex.h:41

#5  sched::thread::wait_for<waitqueue&> (mtx=...) at include/osv/sched.hh:1220

#6  waitqueue::wait (this=this@entry=0x408ec550 <mmu::vma_list_mutex+48>, mtx=...) at core/waitqueue.cc:56

#7  0x00000000403e2d83 in rwlock::reader_wait_lockable (this=<optimized out>) at core/rwlock.cc:174

#8  rwlock::rlock (this=this@entry=0x408ec520 <mmu::vma_list_mutex>) at core/rwlock.cc:29

#9  0x000000004034ad98 in rwlock_for_read::lock (this=0x408ec520 <mmu::vma_list_mutex>) at include/osv/rwlock.h:113

#10 std::lock_guard<rwlock_for_read&>::lock_guard (__m=..., this=<synthetic pointer>) at /usr/include/c++/8/bits/std_mutex.h:162

#11 lock_guard_for_with_lock<rwlock_for_read&>::lock_guard_for_with_lock (lock=..., this=<synthetic pointer>) at include/osv/mutex.h:89

#12 mmu::vm_fault (addr=18446603337326391296, addr@entry=18446603337326395384, ef=ef@entry=0xffff8000014a6068) at core/mmu.cc:1334

#13 0x00000000403a746e in page_fault (ef=0xffff8000014a6068) at arch/x64/mmu.cc:38

An interesting deadlock...

This thread is running map_anon() and holding vma_list_mutex for writing.

Then, during this code, a page fault happens, and the page fault needs vma_list_mutex for *reading*.

I am guessing (need to verify...) that our rwlock implementation is not recursive - a thread already holding the write lock needs to wait (forever) for the read lock. If this is true, this is an rwlock bug.

But the bigger question is why did we get a page fault in the first place. We shouldn't have, and I would start my debugging there.

Maybe there's a bug somewhere in the memory::page_range_allocator stuff, or some sort of memory corruption - e.g., something like that uninitalized memory bug which you fixed where earlier something was always 0 but now that we allocate all memory, gets random values. Or some messed up page table. But I have no idea what's going on without doing further debugging....

I see I can reproduce this issue myself, with the same backtrace as you got - a thread doing an allocation, getting a page fault in the middle of the allocation and hanging on the rwlock deadlock. A bit of debugging:

The page fault happens in:

#15 0x00000000403e5b64 in memory::page_range_allocator::insert<true> (
    this=this@entry=0x409bb300 <memory::free_page_ranges>, pr=...)
    at core/mempool.cc:575
575    void insert(page_range& pr) {
(gdb) l
570        return size;
571    }
572
573 private:
574    template<bool UseBitmap = true>
575    void insert(page_range& pr) {
576        auto addr = static_cast<void*>(&pr);
577        auto pr_end = static_cast<page_range**>(addr + pr.size - sizeof(page_range**));
578        *pr_end = &pr;

We have addr = 0xffff800002949000 and

pr.size = 1061908480 which is very large - a bit lower than 1 GB.

we calculate pr_end as 0xffff800041dffff8 and then dereferencing it fails.

I haven't continued to try to figure out why.

--
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/d929a80d-7bac-4db9-beb2-47e46fc695ef%40googlegroups.com.

[Nadav Har'El]

On Wed, Aug 21, 2019 at 10:09 AM Rick Payne <ri...@rossfell.co.uk> wrote:

Thanks for this - I was hitting a wierd page fault issue on our
application as we've recently moved from 0.52 to the latest OSv.
Something like this, which occurs early on in startup:

Assertion failed: ef->rflags & processor::rflags_if (arch/x64/mmu.cc:
page_fault: 34)

This is often not the problem itself, but rather a result of an earlier bug, which caused

us to want to print an error message and that generated another error, and so on.

I still see such a problem with 1.01 GB of memory - I opened https://github.com/cloudius-systems/osv/issues/1050

But I no longer have problems with other smaller or larger memory, after Waldek's latest patch.

--
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/6e20f4ba3085db676f28f9799cf2c7eb28fb94bf.camel%40rossfell.co.uk.

[Waldek Kozaczuk]

Hi,

Thanks for committing this patch. But unfortunately the tst-huge.so problem is going to make the unit tests fails.

I saw you opened the issue about it. Shall we disable the test until we fix it or somehow change setup and make this test run with 1GB memory instead?

Waldek

[Nadav Har'El]

On Wed, Aug 21, 2019 at 2:21 PM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

Hi,

Thanks for committing this patch. But unfortunately the tst-huge.so problem is going to make the unit tests fails.

As bad this is, better one unit failing than a lot of real use cases (which unfortunately none of the unit tests caught) failing.

Would be nice to have unit tests trying to run a simple test on a bunch of memory sizes (100MB, 1GB, 1.01 GB, 2GB, 4 GB). This would have caught the previous bugs.

I saw you opened the issue about it. Shall we disable the test until we fix it or somehow change setup and make this test run with 1GB memory instead?

I was hoping maybe you were planning to look into this issue, so it will only be a short term problem ;-)

If this will become a long-term problem we'll indeed need to do one of the things you suggested - I prefer blacklisting the test in test.py.

[Rick Payne]

On Wed, 2019-08-21 at 12:22 +0300, Nadav Har'El wrote:
> I am guessing (need to verify...) that our rwlock implementation is
> not recursive - a thread already holding the write lock needs to wait
> (forever) for the read lock. If this is true, this is an rwlock bug.

So I was puzzled a bit by the rwlock code. It handles recursive write
lock acquisitions by incrementing a counter:

// recursive write lock
if (_wowner == sched::thread::current()) {
_wrecurse++;
}

On the unlock side though, it does decrement the counter but then goes
on to wake a write_waiter - which seems wrong. Probably I am missing
something - but why is the second part not inside the else clause where
_wowner is set to nullptr?

void rwlock::wunlock()
{
WITH_LOCK(_mtx) {
assert(_wowner == sched::thread::current());

if (_wrecurse > 0) {
_wrecurse--;
} else {
_wowner = nullptr;
}

if (!_write_waiters.empty()) {
_write_waiters.wake_one(_mtx);
} else {
_read_waiters.wake_all(_mtx);
}
}
}

I think you're right that if you hold the write lock and then try and
readlock it will fail:

bool rwlock::read_lockable()
{
return ((!_wowner) && (_write_waiters.empty()));
}

Rick

[Waldek Kozaczuk]

On Wednesday, August 21, 2019 at 5:22:19 AM UTC-4, Nadav Har'El wrote:

On Wed, Aug 21, 2019 at 6:04 AM Waldek Kozaczuk <jwkoz...@gmail.com> wrote:

This patch definitely fixes an apparent bug I introduced myself in the past. I have tested that issue #1048 goes away with 4,5,6, 7 or 8GB of memory. I have also verified using cli module that free memory is reported properly now.

Thanks, I committed you patch, which indeed fixes that bug. But you are asking god questions:

However, there is still 1 question and 1 issue outstanding:

1. I do not understand how this bug arch_setup_free_memory() would lead to a page fault reported by issue 1048 or other "read errors" with higher memory (8GB, end so). I would expect this bug lead to OSv missing to use the memory above 1GB in the e820 block but still be able to operate properly without the page fault. Is there another underlying bug that this patch actually covers?

What I don't understand (I don't understand the details of this intialization code, unfortunately), is that if your code by mistake did not use the code above 1GB, how does changing the amount of memory from 2GB to 4GB, etc., make any difference at all

I have actually tried to run tst-huge.so at the point of the commit https://github.com/cloudius-systems/osv/commit/97fe8aa3d2d8f2c938fcaa379c44ae5a80dfbf33 with manually applied patch to correct > 1GB issue and the test exhibits the exact same behavior. I feared that some other commit after (like moving kernel code 1GB higher in virtual memory) introduced new bug causing this test to hang but more and more it looks like using memory below kernel has exposed some old existing bug.

I have also suspected that possibly this issue is similar to what I fixed with this commit - https://github.com/cloudius-systems/osv/commit/ef56fde773f71662d193de8c4e799ec5ae55bf4b - initializing memory in the 2nd MB where we uncompress lzloader.elf and has all that garbage. So I added manually the memset() calls to reset first 640K and next 1MB of memory but it did not help.

     mmu::linear_map(elf_start, elf_phys, elf_size, OSV_KERNEL_BASE);

     // get rid of the command line, before low memory is unmapped

     parse_cmdline(mb);

+    memset((void*)0x0, 0, 0x9fc00);

+    memset((void*)0x100000, 0, 0x100000);

     // now that we have some free memory, we can start mapping the rest

     mmu::switch_to_runtime_page_tables();

Also here are the examples of e820 segments passed to OSv with 1G, 2G, 3.5G, 4G and 8G:

1G)
start: 0x0000000000000000, size: 0x000000000009fc00

start: 0x0000000000100000, size: 0x000000003fede000

2G)
start: 0x0000000000000000, size: 0x000000000009fc00

start: 0x0000000000100000, size: 0x000000007fede000

3.5G)
start: 0x0000000000000000, size: 0x000000000009fc00

start: 0x0000000000100000, size: 0x00000000bfede000
start: 0x0000000100000000, size: 0x0000000020000000

4G)
start: 0x0000000000000000, size: 0x000000000009fc00

start: 0x0000000000100000, size: 0x00000000bfede000
start: 0x0000000100000000, size: 0x0000000040000000

8G)

start: 0x0000000000000000, size: 0x000000000009fc00

start: 0x0000000000100000, size: 0x00000000bfede000
start: 0x0000000100000000, size: 0x0000000140000000

 

As you can see with 3.5G and more OSv gets 3 ranges. 

I wonder if we have a bug where the order in which the free ranges get added using free_initial_memory_range() matters. In other words the fact that we add 0-640K and 1M-2B after we add kernel_end-1GB which happens first:

Examples with 2G memory passed (see 4 calls to free_initial_memory_range()): 

free_initial_memory_range, addr: 000000000093daf4

free_initial_memory_range, size: 000000003f6c250c

free_initial_memory_range, addr: 0000000000000000

free_initial_memory_range, size: 000000000009fc00

free_initial_memory_range, addr: 0000000000100000

free_initial_memory_range, size: 0000000000100000

free_initial_memory_range, addr: 0000000040000000

free_initial_memory_range, size: 000000003ffde000

with 1G there are only 3 calls:

free_initial_memory_range, addr: 000000000093daf4

free_initial_memory_range, size: 000000003f6c250c

free_initial_memory_range, addr: 0000000000000000

free_initial_memory_range, size: 000000000009fc00

free_initial_memory_range, addr: 0000000000100000

free_initial_memory_range, size: 0000000000100000

To unsubscribe from this group and stop receiving emails from it, send an email to osv...@googlegroups.com.

[Rick Payne]

On Wed, 2019-08-21 at 13:21 +0300, Nadav Har'El wrote:
>
> This is often not the problem itself, but rather a result of an
> earlier bug, which caused
> us to want to print an error message and that generated another
> error, and so on.

Understood.

Still working on testing 0.53, and I'm now seeing another page fault
issue:

page fault outsAssertion failed: sched::exception_depth <= 1
(core/sched.cc: reschedule_from_interrupt: 236)

[backtrace]


I get nothing more than that - no backtrace. Will work on getting a bit
more later. Could well be that I'm running this out of memory too...

Rick

[Nadav Har'El]

On Wed, Aug 21, 2019 at 10:21 PM Rick Payne <ri...@rossfell.co.uk> wrote:

On Wed, 2019-08-21 at 12:22 +0300, Nadav Har'El wrote:
> I am guessing (need to verify...) that our rwlock implementation is
> not recursive - a thread already holding the write lock needs to wait
> (forever) for the read lock. If this is true, this is an rwlock bug.

So I was puzzled a bit by the rwlock code. It handles recursive write
lock acquisitions by incrementing a counter:

    // recursive write lock
    if (_wowner == sched::thread::current()) {
        _wrecurse++;
    }

Indeed - it appears that although write lock is recursive (the same thread can get the write lock again), a thread holding the write lock cannot get a read lock.

It's not completely obvious whether this is a feature, or a bug, though. It's a bug in the sense it (a thread holding a write lock asking for a read lock) causes a certain deadlock, which is always bad - it would have been even better to assert() than just silently hang. But it's "feature" in the sense that if the reader is expecting to see stable data, not in the middle of someone reading it, he is bound to be disappointed because we are in the middle of writing (even if on this thread).

I think it's clear here that we don't need to fix rwlock now: the problem we have is why we got the page fault in the first place - not why it deadlocked while handling it.

 

On the unlock side though, it does decrement the counter but then goes
on to wake a write_waiter - which seems wrong. Probably I am missing
something - but why is the second part not inside the else clause where
_wowner is set to nullptr?

You're right, it seems there's should be a "return" in the recursive case!

That being said, I think the spurious wakeup doesn't cause any harm,

because the wait code rwlock::writer_wait_lockable() loops, and if a thread

is woken while the lock is still taken, it just goes to sleep again. It will just lose it's good spot on the queue :-(

void rwlock::wunlock()
{
    WITH_LOCK(_mtx) {
        assert(_wowner == sched::thread::current());

        if (_wrecurse > 0) {
            _wrecurse--;
        } else {
            _wowner = nullptr;
        }

        if (!_write_waiters.empty()) {
            _write_waiters.wake_one(_mtx);
        } else {
            _read_waiters.wake_all(_mtx);
        }
    }
}

I think you're right that if you hold the write lock and then try and
readlock it will fail:

bool rwlock::read_lockable()
{
    return ((!_wowner) && (_write_waiters.empty()));
}

Rick

--
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/d75b970c54f9fe25cda79f2cc0aa0e7eaee3ec2f.camel%40rossfell.co.uk.

[Nadav Har'El]

Do you know how to get a backtrace from gdb?

These sort of failures are almost always some sort of nested failure - for example

we have a page fault and while handling this page fault we try to print a message

and get a second crash, or something like that. So the message you see doesn't

really tell you what was the first thing that went wrong. A backtrace from gdb is

usually more helpful.

Rick

[Rick Payne]

On Thu, 2019-08-22 at 10:47 +0300, Nadav Har'El wrote:
> Do you know how to get a backtrace from gdb?

Yes, see below. It wasn't running out of memory:

(gdb) osv mem
Total Memory: 8589392896 Bytes
Mmap Memory: 2231259136 Bytes (25.98%)
Free Memory: 7464316928 Bytes (86.90%)

This is the most recent one:

(gdb) bt
#0 0x000000004022987e in abort (fmt=fmt@entry=0x406738f2 "exception
nested too deeply") at runtime.cc:121
#1 0x0000000040397bf6 in sched::arch_cpu::enter_exception
(this=<optimized out>) at arch/x64/arch-cpu.cc:19
#2 sched::exception_guard::exception_guard (this=<optimized out>) at
arch/x64/arch-cpu.cc:37
#3 0x000000004039a97c in page_fault (ef=0xffff80000001c048) at
arch/x64/mmu.cc:22
#4 <signal handler called>
#5 0x0000000040397d3b in safe_load<void*> (data=@0xffff8001032b13d0:
0x0, potentially_bad_pointer=0x2000af800000) at arch/x64/safe-ptr.hh:33
#6 backtrace_safe (pc=pc@entry=0xffff8001032b1330, nr=nr@entry=128) at
arch/x64/backtrace.cc:26
#7 0x00000000402295a6 in print_backtrace () at runtime.cc:79
#8 0x000000004022987c in abort (fmt=fmt@entry=0x40644c28 "Assertion
failed: %s (%s: %s: %d)\n") at runtime.cc:121
#9 0x00000000402298eb in __assert_fail (expr=expr@entry=0x40658734
"current_id < rings.size()", file=file@entry=0x40658810
"include/lockfree/unordered_ring_mpsc.hh",
line=line@entry=111,
func=func@entry=0x40658840 <bool unordered_ring_mpsc<harvest,
1024u>::emplace<unsigned long&, void const*&, unsigned int&, unsigned
int&, esource&>(unsigned long&, void const*&, unsigned int&, unsigned
int&, esource&)::__func__> "emplace") at runtime.cc:139
#10 0x000000004029e027 in unordered_ring_mpsc<harvest,
1024u>::emplace<unsigned long&, void const*&, unsigned int&, unsigned
int&, esource&> (this=<optimized out>)
at include/lockfree/unordered_ring_mpsc.hh:111
#11 random_harvestq_internal (somecounter=<optimized out>,
entropy=<optimized out>, count=<optimized out>, bits=<optimized out>,
origin=<optimized out>)
at bsd/sys/dev/random/random_harvestq.cc:164
#12 0x000000004039c02b in harvest_interrupt_randomness
(frame=0xffff8001032b2068, irq=32) at include/osv/intr_random.hh:22
#13 interrupt (frame=0xffff8001032b2068) at arch/x64/exceptions.cc:259
#14 <signal handler called>
#15 console::isa_serial_console::putchar (ch=97 'a') at drivers/isa-
serial.cc:108
#16 console::isa_serial_console::write (this=<optimized out>,
str=0x409c00c3 <debug_ll::msg+35>
"ge_range_allocator::alloc_aligned(unsigned long, unsigned long,
unsigned long, bool)+550>\n", len=<optimized out>) at drivers/isa-
serial.cc:79
#17 0x00000000403431d8 in console::console_multiplexer::drivers_write
(len=1,
str=0x409c00c2 <debug_ll::msg+34>
"age_range_allocator::alloc_aligned(unsigned long, unsigned long,
unsigned long, bool)+550>\n", this=0x409a97e0 <console::mux>)
at drivers/console-multiplexer.cc:49
#18 console::console_multiplexer::<lambda(char const*,
size_t)>::operator() (len=1,
str=0x409c00c2 <debug_ll::msg+34>
"age_range_allocator::alloc_aligned(unsigned long, unsigned long,
unsigned long, bool)+550>\n", __closure=<optimized out>)
at drivers/console-multiplexer.cc:36
#19 std::_Function_handler<void(char const*, long unsigned int),
console::console_multiplexer::start()::<lambda(char const*, size_t)>
>::_M_invoke(const std::_Any_data &, const char *&&, unsigned long &&)
(__functor=..., __args#0=<optimized out>, __args#1=<optimized out>) at
/usr/include/c++/7/bits/std_function.h:316
#20 0x0000000040343d33 in std::function<void (char const*, unsigned
long)>::operator()(char const*, unsigned long) const
(__args#1=<optimized out>, __args#0=<optimized out>,
this=0x409a9840 <console::mux+96>) at
/usr/include/c++/7/bits/std_function.h:706
#21 console::LineDiscipline::write(char const*, unsigned long,
std::function<void (char const*, unsigned long)>&)
(this=0xffffa001017d9900,
str=0x409c00c3 <debug_ll::msg+35>
"ge_range_allocator::alloc_aligned(unsigned long, unsigned long,
unsigned long, bool)+550>\n", len=<optimized out>, writer=...)
at drivers/line-discipline.cc:179
#22 0x0000000040343571 in console::console_multiplexer::write_ll (
this=this@entry=0x409a97e0 <console::mux>, str=str@entry=0x409c00a0
<debug_ll::msg> "\n[backtrace]\n",
len=<optimized out>) at drivers/console-multiplexer.cc:71
#23 0x0000000040342e33 in console::write_ll (msg=msg@entry=0x409c00a0
<debug_ll::msg> "\n[backtrace]\n", len=<optimized out>) at
drivers/console.cc:63
#24 0x00000000403d9b68 in debug_ll (fmt=fmt@entry=0x406740d1 "RIP:
0x%016lx <%s>\n") at core/debug.cc:250
#25 0x000000004039e752 in dump_registers (ef=ef@entry=0xffff80000001b04
8) at arch/x64/dump.cc:20
#26 0x0000000040334a21 in mmu::vm_sigsegv (addr=<optimized out>,
ef=0xffff80000001b048) at core/mmu.cc:1314
#27 0x000000004033723a in mmu::vm_fault (addr=<optimized out>,
addr@entry=18446603337326395384, ef=ef@entry=0xffff80000001b048) at
core/mmu.cc:1337
#28 0x000000004039a9c1 in page_fault (ef=0xffff80000001b048) at
arch/x64/mmu.cc:38
#29 <signal handler called>
#30 memory::page_range_allocator::insert<true> (pr=..., this=0x409c1300
<memory::free_page_ranges>) at core/mempool.cc:578
#31

memory::page_range_allocator::<lambda(memory::page_range&)>::operator()

(header=..., __closure=<synthetic pointer>) at core/mempool.cc:751

#32

memory::page_range_allocator::for_each<memory::page_range_allocator::al
loc_aligned(size_t, size_t, size_t,
bool)::<lambda(memory::page_range&)> > (f=..., min_order=<optimized
out>,

this=0x409c1300 <memory::free_page_ranges>) at core/mempool.cc:809
#33 memory::page_range_allocator::alloc_aligned (this=this@entry=0x409c
1300 <memory::free_page_ranges>, size=size@entry=2097152,

offset=offset@entry=0, alignment=alignment@entry=2097152,
fill=fill@entry=true) at core/mempool.cc:736

#34 0x00000000403e7414 in memory::alloc_huge_page (N=N@entry=2097152)
at core/mempool.cc:1601
#35 0x000000004033c5ee in
mmu::uninitialized_anonymous_page_provider::map (this=0x40930030
<mmu::page_allocator_init>, offset=56623104, ptep=..., pte=...,
write=<optimized out>)
---Type <return> to continue, or q <return> to quit---
at core/mmu.cc:1037
#36 0x000000004033b919 in mmu::populate<(mmu::account_opt)0>::page<1>
(offset=56623104, ptep=..., this=0xffff8001032b5ba0) at core/mmu.cc:532
#37 mmu::page<mmu::populate<(mmu::account_opt)0>, 1> (offset=56623104,
ptep=..., pops=...) at core/mmu.cc:311
#38 mmu::map_level<mmu::populate<(mmu::account_opt)0>, 2>::operator()
(base_virt=35187316490240, parent=..., this=<synthetic pointer>) at
core/mmu.cc:437
#39 mmu::map_level<mmu::populate<(mmu::account_opt)0>, 3>::map_range<2>
(this=<synthetic pointer>, base_virt=35186519572480, ptep=...,
slop=4096, page_mapper=..., size=2097152,

vcur=<optimized out>) at core/mmu.cc:399

#40 mmu::map_level<mmu::populate<(mmu::account_opt)0>, 3>::operator()
(base_virt=35186519572480, parent=..., this=<synthetic pointer>) at
core/mmu.cc:449
#41 mmu::map_level<mmu::populate<(mmu::account_opt)0>, 4>::map_range<3>
(this=<synthetic pointer>, base_virt=35184372088832, ptep=...,
slop=4096, page_mapper=..., size=2097152,

vcur=<optimized out>) at core/mmu.cc:399

#42 mmu::map_level<mmu::populate<(mmu::account_opt)0>, 4>::operator()
(base_virt=35184372088832, parent=..., this=<synthetic pointer>) at
core/mmu.cc:449
#43 mmu::map_range<mmu::populate<(mmu::account_opt)0> > (slop=4096,
page_mapper=..., size=<optimized out>, vstart=<optimized out>,
vma_start=<optimized out>) at core/mmu.cc:354
#44 mmu::operate_range<mmu::populate<(mmu::account_opt)0> >
(size=<optimized out>, start=<optimized out>, vma_start=<optimized
out>, mapper=...) at core/mmu.cc:806
#45 mmu::vma::operate_range<mmu::populate<(mmu::account_opt)0> >
(size=<optimized out>, addr=<optimized out>, mapper=...,
this=0xffffa00105ad2c00) at core/mmu.cc:1412
#46 mmu::populate_vma<(mmu::account_opt)0> (write=<optimized out>,
size=<optimized out>, v=<optimized out>, vma=0xffffa00105ad2c00) at
core/mmu.cc:1206
#47 mmu::vma::fault (this=0xffffa00105ad2c00, addr=<optimized out>,
ef=<optimized out>) at core/mmu.cc:1439
#48 0x00000000403373e1 in mmu::vm_fault (addr=<optimized out>,
addr@entry=35187316490240, ef=ef@entry=0xffff8001032b6068) at
core/mmu.cc:1341
#49 0x000000004039a9c1 in page_fault (ef=0xffff8001032b6068) at
arch/x64/mmu.cc:38
#50 <signal handler called>
#51 0x0000100005bc6d43 in ?? ()
#52 0x00002000494ae438 in ?? ()
#53 0x00000000061ec000 in ?? ()
#54 0x0000200040f55ab0 in ?? ()
#55 0x0000200040f55a98 in ?? ()
#56 0x0000200040f55aa0 in ?? ()

[Rick Payne]

On Thu, 2019-08-22 at 10:33 +0300, Nadav Har'El wrote:
> You're right, it seems there's should be a "return" in the recursive
> case!
> That being said, I think the spurious wakeup doesn't cause any harm,
> because the wait code rwlock::writer_wait_lockable() loops, and if a
> thread
> is woken while the lock is still taken, it just goes to sleep again.
> It will just lose it's good spot on the queue :-(

I wasn't sure that was the case. I put an assert in
writer_wait_lockable() (see below) and I was able to trigger it by
having 1 thread take the write lock twice, then a second thread attempt
to take the write lock. When the first thread released, the second
thread triggers the assert.

void rwlock::writer_wait_lockable()
{
while (true) {
if (write_lockable()) {
return;
}

_write_waiters.wait(_mtx);
assert((_wowner == sched::thread::current()) ||
(_wowner == nullptr));

}
}

Rick

[Nadav Har'El]

So, we have a page_fault here, and most of the lines above are not interesting, additional bugs while printing the strack trace :-( It would be nice if we fixed those issues too, but it's less important than fixing the real bug.

#50 <signal handler called>
#51 0x0000100005bc6d43 in ?? ()

Please run "osv syms" to allow gdb to find your application object files, and show lines there. Perhaps it's a segfault inside your application, not the kernel?

[Nadav Har'El]

Yes, *this* assert will trigger, but it doesn't matter for correctness - because what will happen next is that the loop will continue, and the code will check write_lockable() again, and only if that is true, it will return. This is what I said - this will be a spurious wakeup, and a waste of time, but will not compromise correctness. At least according to my understanding.

    }
}

Rick

[Rick Payne]

On Thu, 2019-08-22 at 12:30 +0300, Nadav Har'El wrote:

> Please run "osv syms" to allow gdb to find your application object
> files, and show lines there. Perhaps it's a segfault inside your
> application, not the kernel?

I had, but I had forgotten to add our stuff to the usr.manifest so the
tool could find them. I think this is better (from a different run,
apologies):

#44 <signal handler called>
#45 0x0000100005a67675 in process_main ()
#46 0x0000100005a714e9 in sched_thread_func ()
#47 0x0000100005cbab5d in thr_wrapper ()
#48 0x0000000040461c96 in

pthread_private::pthread::<lambda()>::operator() (

__closure=0xffffa0007fea4200) at libc/pthread.cc:114
#49 std::_Function_handler<void(),

pthread_private::pthread::pthread(void* (*)(void*), void*, sigset_t,
const pthread_private::thread_attr*)::<lambda()> >::_M_invoke(const
std::_Any_data &) (__functor=...) at

/usr/include/c++/7/bits/std_function.h:316
#50 0x00000000403f9647 in sched::thread_main_c (t=0xffff80007f4a3040)
at arch/x64/arch-switch.hh:271
#51 0x000000004039a793 in thread_main () at arch/x64/entry.S:113

process_main is something inside the beam/ERTS (which isn't compiled
with debug unfortunately). I'd guess its unlikely that its a bug in
there as the code is very widely tested.

Rick

[Rick Payne]

On Thu, 2019-08-22 at 21:49 +1100, Rick Payne wrote:
> On Thu, 2019-08-22 at 12:30 +0300, Nadav Har'El wrote:
>
> > Please run "osv syms" to allow gdb to find your application object
> > files, and show lines there. Perhaps it's a segfault inside your
> > application, not the kernel?
>
> I had, but I had forgotten to add our stuff to the usr.manifest so
> the
> tool could find them. I think this is better (from a different run,
> apologies):

Ok, with a debug build of the ERTS, it seems to be failing in the
garbage collector for the beam. At this point its probably allocating
memory and moving objects around - so I'm a bit suspicious of the
changes in OSv in this area:

#44 <signal handler called>
#45 0x0000100005bfa75e in move_boxed (ptr=0x20006c2016e0, hdr=128,
hpp=0x200040f55738,
orig=0x20005fbffcc0) at beam/erl_gc.h:91
#46 0x0000100005c00014 in sweep (src_size=0, src=0x0, ohsz=0,
oh=0x20005f000028 "@\002",
type=ErtsSweepNewHeap, n_htop=0x20005fbffff0, n_hp=0x20005fbffcc8)
at beam/erl_gc.c:2184

---Type <return> to continue, or q <return> to quit---

#47 sweep_new_heap (n_hp=0x20005f000028, n_htop=0x20005f001a58,
old_heap=0x20005f000028 "@\002", old_heap_size=0) at
beam/erl_gc.c:2237
#48 0x0000100005bff060 in do_minor (p=0x20004943dd78,
live_hf_end=0xfffffffffffffff8,
mature=0x20006b600028 "\200", mature_size=14266416,
new_sz=2072833,
objv=0x20004943de28, nobj=3) at beam/erl_gc.c:1678
#49 0x0000100005bfe1b4 in minor_collection (p=0x20004943dd78,
live_hf_end=0xfffffffffffffff8, need=0, objv=0x20004943de28,
nobj=3,
ygen_usage=1835980, recl=0x200040f55cf8) at beam/erl_gc.c:1426
#50 0x0000100005bfc2cf in garbage_collect (p=0x20004943dd78,
live_hf_end=0xfffffffffffffff8, need=0, objv=0x20004943de28,
nobj=3, fcalls=4000,
max_young_gen_usage=0) at beam/erl_gc.c:746
#51 0x0000100005bfc937 in erts_garbage_collect_nobump
(p=0x20004943dd78, need=0,
objv=0x20004943de28, nobj=3, fcalls=4000) at beam/erl_gc.c:882
#52 0x0000100005a8ecda in erts_execute_dirty_system_task
(c_p=0x20004943dd78)
at beam/erl_process.c:10543
#53 0x0000100005a714bf in erts_dirty_process_main
(esdp=0xffff80007fc75d00)
at beam/beam_emu.c:1201
#54 0x0000100005a8ac04 in sched_dirty_cpu_thread_func
(vesdp=0xffff80007fc75d00)
at beam/erl_process.c:8512
#55 0x0000100005d0c7e8 in thr_wrapper (vtwd=0x2000002fea50) at
pthread/ethread.c:118
#56 0x0000000040461c96 in

pthread_private::pthread::<lambda()>::operator() (

__closure=0xffffa0007f896a00) at libc/pthread.cc:114
#57 std::_Function_handler<void(),

pthread_private::pthread::pthread(void* (*)(void*), void*, sigset_t,
const pthread_private::thread_attr*)::<lambda()> >::_M_invoke(const

std::_Any_data---Type <return> to continue, or q <return> to quit---

&) (__functor=...) at /usr/include/c++/7/bits/std_function.h:316

#58 0x00000000403f9647 in sched::thread_main_c (t=0xffff800003579040)
at arch/x64/arch-switch.hh:271
#59 0x000000004039a793 in thread_main () at arch/x64/entry.S:113
(gdb)

Like I said, it could be the erlang ERTS but I think thats pretty
unlikely.

Rick

[Waldek Kozaczuk]

Rick,

Does this error happen with specific memory configuration? Or is more generic? I have lost track if in this email thread we are still talking about error related to the change in memory allocation I made to use memory below kernel? Also are you using the latest master or 0.53 specifically?

I thought we are talking about error when one passes 1.01 or 1.02 GB as memory size. Is it true?

I understand we have found slew of possible other bugs. 

Sorry I am a bit confused,

Waldek

--
You received this message because you are subscribed to a topic in the Google Groups "OSv Development" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/osv-dev/N5Knl4HE25o/unsubscribe.
To unsubscribe from this group and all its topics, 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/8d0280c9332d190ec647129e1a2afb30db2629db.camel%40rossfell.co.uk.

[Rick Payne]

Hi Waldek,

Our tree is up to date with f7b6bee552b41f56a55, plus I manually
applied your patch from this thread (as at the time it wasn't
committed).

Error seems to happen regardless of memory size I specify - but we
can't go below 2GB for memory reasons (btw - we seem to just freeze
when we run out of memory?).

Happens whether we use SMP or not.

We do have some modifications to OSv (mainly - do not use DHCP as we're
specifying the IP addresses in the cloudinit file, and some other hooks
into the network code that we're not actually using in this instance).
We've been using those changes for quite a while now - and I doubt this
is related. Again, its hard for me to try with a stock OSv due to the
complexity of the setup (multiple interfaces, talking to database
server etc).

We're keen to keep moving forward with the OSv version due to the
number of very useful fixes you've found (that may be causing some of
the crashes we see in production).

Cheers,
Rick