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 <javascript:>. > > 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.