So we've been trying with a debug image (with the tcp kassert
disabled). We do not get an OOM crash, but after some time (24hrs or
more) all cores just hit idle and never recover. It stops responding to
TCP connections and when you attached gdb, you see this:
Thread 1 received signal SIGINT, Interrupt.
processor::sti_hlt () at arch/x64/processor.hh:252
252 arch/x64/processor.hh: No such file or directory.
(gdb) info thread
Id Target Id Frame
* 1 Thread 1 (CPU#0 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
2 Thread 2 (CPU#1 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
3 Thread 3 (CPU#2 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
4 Thread 4 (CPU#3 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
5 Thread 5 (CPU#4 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
6 Thread 6 (CPU#5 [halted ]) processor::sti_hlt () at
arch/x64/processor.hh:252
The threads themselves look liks this:
(gdb) bt
#0 processor::sti_hlt () at arch/x64/processor.hh:252
#1 0x00000000405e4016 in arch::wait_for_interrupt () at
arch/x64/arch.hh:43
#2 0x00000000405d7f10 in sched::cpu::do_idle (this=0xffff80000001b040)
at core/sched.cc:404
#3 0x00000000405d7fc1 in sched::cpu::idle (this=0xffff80000001b040) at
core/sched.cc:423
#4 0x00000000405d73ef in sched::cpu::<lambda()>::operator()(void)
const (__closure=0xffff800100156070)
at core/sched.cc:165
#5 0x00000000405e0b57 in std::_Function_handler<void(),
sched::cpu::init_idle_thread()::<lambda()> >::_M_invoke(const
std::_Any_data &) (__functor=...) at
/usr/include/c++/9/bits/std_function.h:300
#6 0x0000000040496206 in std::function<void ()>::operator()() const
(this=0xffff800100156070)
at /usr/include/c++/9/bits/std_function.h:690
#7 0x00000000405db386 in sched::thread::main (this=0xffff800100156040)
at core/sched.cc:1210
#8 0x00000000405d7173 in sched::thread_main_c (t=0xffff800100156040)
at arch/x64/arch-switch.hh:321
#9 0x00000000404911b3 in thread_main () at arch/x64/entry.S:113
I tried the 'osv waiters' command but jsut get:
(gdb) osv waiters
waiters:
Python Exception <class 'gdb.MemoryError'> Cannot access memory at
address 0x42c00020880a9010:
Error occurred in Python command: Cannot access memory at address
0x42c00020880a9010
I think we'll go back to a 'release' image and see if we get the oom
with a few more clues...
Rick
On Wed, 2020-03-11 at 08:07 -0700, Waldek Kozaczuk wrote:
>
>
> On Tuesday, March 10, 2020 at 10:53:17 PM UTC-4, rickp wrote:
> > I've not found a way to reproduce this other than in production
> > yet,
> > which is annoying. I've built an image with this patch, and will
> > see if
> > we can run it with gdb too.
> >
> > What should I be looking for if it hits?
>
> In case of oom() this patch should show a list of threads (waiters)
> along with amount of memory requested. I am hoping it will give
> better clues where the problem is.
> > Note, the 'osv pagetable walk' command (and a few others) seem not
> > to
> > work for me:
> >
> > (gdb) osv pagetable walk
> > Python Exception <class 'gdb.error'> Argument required (expression
> > to
> > compute).:
> > Error occurred in Python: Argument required (expression to
> > compute).
>
> I will look into it.
> > Rick
> >
> > On Tue, 2020-03-10 at 11:21 -0700, Waldek Kozaczuk wrote:
> > > Is there a way to have a reproducible test app? If not I was
> > > wondering if this patch enabling some extra logging would help:
> > >
> > > diff --git a/core/mempool.cc b/core/mempool.cc
> > > index d902eea8..ace28b38 100644
> > > --- a/core/mempool.cc
> > > +++ b/core/mempool.cc
> > > @@ -501,9 +501,9 @@ ssize_t
> > reclaimer::bytes_until_normal(pressure
> > > curr)
> > > }
> > > }
> > >
> > > -void oom()
> > > +void oom(ssize_t target)
> > > {
> > > - abort("Out of memory: could not reclaim any further.
> > Current
> > > memory: %d Kb", stats::free() >> 10);
> > > + abort("Out of memory: could not reclaim any further.
> > Current
> > > memory: %d Kb, target: %d Kb", stats::free() >> 10, target >>
> > 10);
> > > }
> > >
> > > void reclaimer::wait_for_minimum_memory()
> > > @@ -924,6 +924,17 @@ bool reclaimer_waiters::wake_waiters()
> > > return woken;
> > > }
> > >
> > > +void reclaimer_waiters::print_waiters()
> > > +{
> > > + auto it = _waiters.begin();
> > > + while (it != _waiters.end()) {
> > > + auto& wr = *it;
> > > + it++;
> > > +
> > > + printf( "Waiter: %s, bytes: %ld\n", wr.owner->name(),
> > > wr.bytes);
> > > + }
> > > +}
> > > +
> > > // Note for callers: Ideally, we would not only wake, but
> > already
> > > allocate
> > > // memory here and pass it back to the waiter. However, memory
> > is
> > > not always
> > > // allocated the same way (ex: refill_page_buffer is completely
> > > different from
> > > @@ -943,7 +954,7 @@ void reclaimer_waiters::wait(size_t bytes)
> > >
> > > // Wait for whom?
> > > if (curr == reclaimer_thread._thread.get()) {
> > > - oom();
> > > + oom(bytes);
> > > }
> > >
> > > wait_node wr;
> > > @@ -1027,7 +1038,8 @@ void reclaimer::_do_reclaim()
> > > // Wake up all waiters that are waiting and now
> > have
> > > a chance to succeed.
> > > // If we could not wake any, there is nothing
> > really
> > > we can do.
> > > if (!_oom_blocked.wake_waiters()) {
> > > - oom();
> > > + _oom_blocked.print_waiters();
> > > + oom(target);
> > > }
> > > }
> > >
> > > diff --git a/include/osv/mempool.hh b/include/osv/mempool.hh
> > > index 10fe5602..620f1a5b 100644
> > > --- a/include/osv/mempool.hh
> > > +++ b/include/osv/mempool.hh
> > > @@ -137,6 +137,7 @@ public:
> > > bool wake_waiters();
> > > void wait(size_t bytes);
> > > bool has_waiters() { return !_waiters.empty(); }
> > > + void print_waiters();
> > > private:
> > > struct wait_node: boost::intrusive::list_base_hook<> {
> > > sched::thread* owner;
> > >
> > > Waldek
> > >
> > > On Tuesday, March 10, 2020 at 12:26:54 PM UTC-4, Waldek Kozaczuk
> > > wrote:
> > > > Well I found this commit changing original "> 0 " to ">= 0" -
> > > >
> > https://github.com/cloudius-systems/osv/commit/f888c39d744c38cf6fa2f7568c04cea3a7217dca
> >
> > > > - with some explanation. So maybe my theory is wrong. Also I
> > am
> > > > not sure calling bytes_until_normal() before that "if" would
> > change
> > > > anything then.
> > > >
> > > > On Tuesday, March 10, 2020 at 12:04:27 PM UTC-4, Waldek
> > Kozaczuk
> > > > wrote:
> > > > > So here is full code of of _do_reclaim():
> > > > >
> > > > > 1001 void reclaimer::_do_reclaim()
> > > > > 1002 {
> > > > > 1003 ssize_t target;
> > > > > 1004 emergency_alloc_level = 1;
> > > > > 1005
> > > > > 1006 while (true) {
> > > > > 1007 WITH_LOCK(free_page_ranges_lock) {
> > > > > 1008 _blocked.wait(free_page_ranges_lock);
> > > > > 1009 target = bytes_until_normal();
> > > > > 1010 }
> > > > > 1011
> > > > > 1012 // This means that we are currently ballooning,
> > we
> > > > > should
> > > > > 1013 // try to serve the waiters from temporary
> > memory
> > > > > without
> > > > > 1014 // going on hard mode. A big batch of more
> > memory is
> > > > > likely
> > > > > 1015 // in its way.
> > > > > 1016 if (_oom_blocked.has_waiters() &&
> > > > > throttling_needed()) {
> > > > > 1017 _shrinker_loop(target, [] { return false;
> > });
> > > > > 1018 WITH_LOCK(free_page_ranges_lock) {
> > > > > 1019 if (_oom_blocked.wake_waiters()) {
> > > > > 1020 continue;
> > > > > 1021 }
> > > > > 1022 }
> > > > > 1023 }
> > > > > 1024
> > > > > 1025 _shrinker_loop(target, [this] { return
> > > > > _oom_blocked.has_waiters(); });
> > > > > 1026
> > > > > 1027 WITH_LOCK(free_page_ranges_lock) {
> > > > > 1028 if (target >= 0) {
> > > > > 1029 // Wake up all waiters that are waiting
> > and
> > > > > now have a chance to succeed.
> > > > > 1030 // If we could not wake any, there is
> > > > > nothing really we can do.
> > > > > 1031 if (!_oom_blocked.wake_waiters()) {
> > > > > 1032 oom();
> > > > > 1033 }
> > > > > 1034 }
> > > > > 1035
> > > > > 1036 if (balloon_api) {
> > > > > 1037 balloon_api->voluntary_return();
> > > > > 1038 }
> > > > > 1039 }
> > > > > 1040 }
> > > > > 1041 }
> > > > >
> > > > > We got oom() because target was '>= 0'. Now the target is
> > > > > calculated as the result of bytes_until_normal().
> > > > >
> > > > > 495 ssize_t reclaimer::bytes_until_normal(pressure curr)
> > > > > 496 {
> > > > > 497 assert(mutex_owned(&free_page_ranges_lock));
> > > > > 498 if (curr == pressure::PRESSURE) {
> > > > > 499 return watermark_lo - stats::free();
> > > > > 500 } else {
> > > > > 501 return 0;
> > > > > 502 }
> > > > > 503 }
> > > > >
> > > > > which seems to indicate that when 0 is returned there no need
> > to
> > > > > reclaim any memory.
> > > > >
> > > > > So here are two things that might be wrong:
> > > > >
> > > > > 1. Shouldn't if (target >= 0) be changed to if (target > 0)
> > {?
> > > > >
> > > > > 2. Shouldn't we re-read the target in second WITH_LOCK
> > instead of
> > > > > comparing the original value in the beginning of the body of
> > the
> > > > > loop? The line before - _shrinker_loop(target, [this] {
> > return
> > > > > _oom_blocked.has_waiters(); }); - might have just released
> > enough
> > > > > memory to bring target below 0, right?
> > > > >
> > > > > In any case it would be useful to print the value of the
> > target
> > > > > before oom():
> > > > >
> > > > > if (!_oom_blocked.wake_waiters()) {
> > > > >
> > > > > printf("--> Target: %ld\n", target);
> > > > >
> > > > > oom();
> > > > >
> > > > > }
> > > > >
> > > > >
> > > > > On Monday, March 9, 2020 at 10:51:02 PM UTC-4, rickp wrote:
> > > > > > We're pretty close to current on OSv, but it also happens
> > on an
> > > > > > older
> > > > > > image. We have changed some stuff in our app, but I think
> > that
> > > > > > may just
> > > > > > be provking the bug. Certainly from gdb, I can see that
> > both
> > > > > > mmaped and
> > > > > > normal memory fluctuate up and down but eveything looks
> > sane.
> > > > > >
> > > > > > More debug in wake_waiters would be useful, but I'm losing
> > the
> > > > > > argument
> > > > > > to continue with OSv at the moment which makes testing this
> > a
> > > > > > bit
> > > > > > 'political'.
> > > > > >
> > > > > > btw - when we do run the system out of memory, it seems to
> > hang
> > > > > > rather
> > > > > > than generate an oom. Have you tried it?
> > > > > >
> > > > > > The tcp_do_segment one has been mentioned before (by
> > someone
> > > > > > else). The
> > > > > > issue is that the kassert only has effect in the debug
> > build.
> > > > > > I'd guess
> > > > > > that the socket is being closed, but still has segments
> > that
> > > > > > have not
> > > > > > been processed, or something like that. I'll try and narrow
> > it
> > > > > > down a
> > > > > > bit if I get time.
> > > > > >
> > > > > > Rick
> > > > > >
> > > > > > On Mon, 2020-03-09 at 22:32 -0400, Waldek Kozaczuk wrote:
> > > > > > > Does it happen with the very latest OSv code? Did it
> > start
> > > > > > happening
> > > > > > > at some point more often?
> > > > > > >
> > > > > > > I wonder if we could add some helpful printouts in
> > > > > > wake_waiters().
> > > > > > >
> > > > > > > Btw that assert() failure in tcp_do_segment() rings a
> > bell.
> > > > > > >
> > > > > > > On Mon, Mar 9, 2020 at 22:25 Rick Payne <
> > ri...@rossfell.co.uk
> > > > > > > wrote:
> > > > > > > > I can't add much other than I doubt its fragmentation.
> > > > > > Sometimes
> > > > > > > > this
> > > > > > > > happens within a few minutes of the system starting. At
> > no
> > > > > > point do
> > > > > > > > I
> > > > > > > > think we're using more than 2GB of ram (of the 12GB)
> > > > > > either.
> > > > > > > >
> > > > > > > > I did compile up a debug verison of OSv and built the
> > > > > > system with
> > > > > > > > that,
> > > > > > > > but I've been unable to trigger the oom(). Worse, I hit
> > a
> > > > > > kassert
> > > > > > > > in
> > > > > > > > the netchannel code that seems to be ignored in the
> > > > > > 'release'
> > > > > > > > build,
> > > > > > > > but panics in the debug build:
> > > > > > > >
> > > > > > > > [E/384 bsd-kassert]: tcp_do_segment: TCPS_LISTEN
> > > > > > > > Assertion failed: tp->get_state() > 1
> > > > > > > > (bsd/sys/netinet/tcp_input.cc:
> > > > > > > > tcp_do_segment: 1076)
> > > > > > > >
> > > > > > > > [backtrace]
> > > > > > > > 0x0000000040221330 <abort(char const*, ...)+280>
> > > > > > > > 0x0000000040221399 <__assert_fail+64>
> > > > > > > > 0x00000000402a4798 <???+1076512664>
> > > > > > > > 0x00000000402a97c2 <???+1076533186>
> > > > > > > > 0x00000000402a98a1 <???+1076533409>
> > > > > > > > 0x00000000402aa448 <???+1076536392>
> > > > > > > > 0x0000000040656a9a <std::function<void
> > > > > > (mbuf*)>::operator()(mbuf*)
> > > > > > > > const+76>
> > > > > > > > 0x0000000040655855 <net_channel::process_queue()+61>
> > > > > > > > 0x000000004023b165 <???+1076080997>
> > > > > > > > 0x000000004023b4d7 <soclose+878>
> > > > > > > > 0x000000004024cd21 <socket_file::close()+51>
> > > > > > > > 0x00000000406a6a10 <fdrop+151>
> > > > > > > > 0x00000000406a64f7 <fdclose(int)+184>
> > > > > > > > 0x000000004067cd42 <close+41>
> > > > > > > >
> > > > > > > > So at the moment, I'm a bit stuck with getting any
> > more
> > > > > > info...
> > > > > > > >
> > > > > > > > Rick
> > > > > > > >
> > > > > > > > On Mon, 2020-03-09 at 08:52 -0700, Waldek Kozaczuk
> > wrote:
> > > > > > > > > As I understand this stack trace the oom() was
> > called
> > > > > > here as
> > > > > > > > part of
> > > > > > > > > _do_reclaim():
> > > > > > > > >
> > > > > > > > > 1025 WITH_LOCK(free_page_ranges_lock) {
> > > > > > > > > 1026 if (target >= 0) {
> > > > > > > > > 1027 // Wake up all waiters that are
> > > > > > waiting and
> > > > > > > > now
> > > > > > > > > have a chance to succeed.
> > > > > > > > > 1028 // If we could not wake any,
> > there
> > > > > > is
> > > > > > > > nothing
> > > > > > > > > really we can do.
> > > > > > > > > 1029 if
> > (!_oom_blocked.wake_waiters()) {
> > > > > > > > > 1030 oom();
> > > > > > > > > 1031 }
> > > > > > > > > 1032 }
> > > > > > > > > 1033
> > > > > > > > > 1034 if (balloon_api) {
> > > > > > > > > 1035 balloon_api-
> > >voluntary_return();
> > > > > > > > > 1036 }
> > > > > > > > > 1037 }
> > > > > > > > >
> > > > > > > > > so it seems wake_waiters() returned false. I wonder
> > if
> > > > > > the memory
> > > > > > > > was
> > > > > > > > > heavily fragmented or there is some logical bug in
> > there.
> > > > > > This
> > > > > > > > method
> > > > > > > > > is called from two places and I wonder if this part
> > of
> > > > > > > > wake_waiters()
> > > > > > > > > is correct:
> > > > > > > > >
> > > > > > > > > 921 if (!_waiters.empty()) {
> > > > > > > > > 922 reclaimer_thread.wake();
> > > > > > > > > 923 }
> > > > > > > > > 924 return woken;
> > > > > > > > >
> > > > > > > > >
> > > > > > > > > should this if also set woken to true?
> > > > > > > > >
> > > > > > > > > Also could we also enhance the oom() logic to print
> > out
> > > > > > more
> > > > > > > > useful
> > > > > > > > > information if this happens once again?
> > > > > > > > >
> > > > > > > > > On Tuesday, March 3, 2020 at 2:21:40 AM UTC-5, rickp
> > > > > > wrote:
> > > > > > > > > > Had a crash on a system that I don't understand.
> > Its a
> > > > > > VM with
> > > > > > > > > > 12GB
> > > > > > > > > > allocated, we were running without about 10.5GB
> > free
> > > > > > according
> > > > > > > > to
> > > > > > > > > > the
> > > > > > > > > > API.
> > > > > > > > > >
> > > > > > > > > > Out of the blue, we had a panic:
> > > > > > > > > >
> > > > > > > > > > Out of memory: could not reclaim any further.
> > Current
> > > > > > memory:
> > > > > > > > > > 10954988
> > > > > > > > > > Kb
> > > > > > > > > > [backtrace]
> > > > > > > > > > 0x00000000403f6320 <memory::oom()+32>
> > > > > > > > > > 0x00000000403f71cc
> > > > > > <memory::reclaimer::_do_reclaim()+380>
> > > > > > > > > > 0x00000000403f722f <???+1077899823>
> > > > > > > > > > 0x000000004040f29b <thread_main_c+43>
> > > > > > > > > > 0x00000000403ae412 <???+1077601298>
> > > > > > > > > >
> > > > > > > > > > The 'Out of memory' message seems to print
> > > > > > stats::free() and
> > > > > > > > that
> > > > > > > > > > number suggests we have plenty of free ram.
> > > > > > > > > >
> > > > > > > > > > Have I misunderstood, or is there something I need
> > to
> > > > > > be
> > > > > > > > looking
> > > > > > > > > > at?
> > > > > > > > > >
> > > > > > > > > > Cheers,
> > > > > > > > > > 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...@googlegroups.com.
> > > > > > > > > To view this discussion on the web visit
> > > > > > > > >
> > > > > > > >
> > > > > >
> > https://groups.google.com/d/msgid/osv-dev/8f7e00a5-edfe-4487-aa5a-5072a560c6e3%40googlegroups.com
> >
> > > > > >
> > > > > > > > > .
> > > > > > > >
> > > > > >
> > >
> > > --
> > > 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...@googlegroups.com.
> > > To view this discussion on the web visit
> > >
> > https://groups.google.com/d/msgid/osv-dev/b8a57083-2882-4878-8668-f510eaceff84%40googlegroups.com
> >
> > > .
> >
>
> --
> 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+unsubscr...@googlegroups.com.
> To view this discussion on the web visit
> https://groups.google.com/d/msgid/osv-dev/79e94c93-f832-4ed9-935e-0ffd9a1a4ec6%40googlegroups.com
> .
--
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+unsubscr...@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/osv-dev/6bfe6f36061690e36caea65aa1339af21c6e5686.camel%40rossfell.co.uk.
