Foundationdb 6.2 - fdbserver going out of memory

Using FoundationDB
1

I have a 3 Node foundationdb test cluster running fdb 6.2.11 where I am observing fdbserver occasionally going Out Of Memory.

The backtrace during the crash looks likes below from 10.196.76.47

TraceEvent::backtrace(std::string const&) at ??:?
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.tcc:613
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> > std::operator+<char, std::char_traits<char>, std::allocator<char> >(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, char const*) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:5958
 (inlined by) TraceEvent::backtrace(std::string const&) at /opt/foundation/foundationdb/flow/Trace.cpp:938
TraceEvent::~TraceEvent() at ??:?
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3631
 (inlined by) TraceEvent::~TraceEvent() at /opt/foundation/foundationdb/flow/Trace.cpp:947
criticalError at /opt/foundation/foundationdb/flow/Platform.cpp:2512
platform::outOfMemory() at /opt/foundation/foundationdb/flow/Platform.cpp:2501
operator new(unsigned long) at ??:?
ArenaBlock::addUsed(int) at /opt/foundation/foundationdb/./flow/FastRef.h:75
 (inlined by) ArenaBlock::allocate(Reference<ArenaBlock>&, int) at /opt/foundation/foundationdb/./flow/Arena.h:216
 (inlined by) operator new[](unsigned long, Arena&) at /opt/foundation/foundationdb/./flow/Arena.h:337
VectorRef<unsigned char, (VecSerStrategy)0>::reallocate(Arena&, int) at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) VectorRef<unsigned char, (VecSerStrategy)0>::reserve(Arena&, int) at /opt/foundation/foundationdb/./flow/Arena.h:1036
 (inlined by) commitMessages(TLogData*, Reference<LogData>, long, std::vector<TagsAndMessage, std::allocator<TagsAndMessage> > const&) at /opt/foundation/foundationdb/fdbserver/TLogServer.actor.cpp:1091
Reference<LogData>::~Reference() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) commitMessages(TLogData*, Reference<LogData>, long, Arena, StringRef) at /opt/foundation/foundationdb/fdbserver/TLogServer.actor.cpp:1171
Reference<LogData>::~Reference() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1cont5 at /opt/foundation/foundationdb/fdbserver/TLogServer.actor.cpp:1766
 (inlined by) a_body1cont3break1 at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8330
 (inlined by) a_body1cont3loopBody1 at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8301
a_body1cont3loopHead1 at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1cont3 at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8159
 (inlined by) a_body1cont1 at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8109
a_body1when1 at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1 at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8066
 (inlined by) TLogCommitActor at /opt/foundation/foundationdb/.objs/fdbserver/TLogServer.actor.g.cpp:8494
 (inlined by) tLogCommit(TLogData* const&, TLogCommitRequest const&, Reference<LogData> const&, PromiseStream<Void> const&) at /opt/foundation/foundationdb/fdbserver/TLogServer.actor.cpp:1722
(anonymous namespace)::ServeTLogInterfaceActorState<(anonymous namespace)::ServeTLogInterfaceActor>::a_body1loopBody1when4(TLogCommitRequest const&, int) at /opt/foundation/foundationdb/./flow/flow.h:529
ReplyPromise<TLogCommitReply>::~ReplyPromise() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) TLogCommitRequest::~TLogCommitRequest() at /opt/foundation/foundationdb/./fdbserver/TLogInterface.h:232
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:1008
void NotifiedQueue<TLogCommitRequest>::send<TLogCommitRequest>(TLogCommitRequest&&) at /opt/boost_1_67_0/boost/variant/detail/forced_return.hpp:31
 (inlined by) NetNotifiedQueue<TLogCommitRequest>::receive(ArenaObjectReader&) at /opt/foundation/foundationdb/./fdbrpc/fdbrpc.h:253
Reference<ArenaBlock>::~Reference() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) Arena::~Arena() at /opt/foundation/foundationdb/./flow/Arena.h:92
 (inlined by) ArenaObjectReader::~ArenaObjectReader() at /opt/foundation/foundationdb/./flow/ObjectSerializer.h:117
 (inlined by) a_body1cont1 at /opt/foundation/foundationdb/fdbrpc/FlowTransport.actor.cpp:651
ActorCallback<(anonymous namespace)::DeliverActor, 0, Void>::fire(Void const&) at /opt/foundation/foundationdb/./flow/flow.h:529
void SAV<Void>::send<Void>(Void&&) at /opt/boost_1_67_0/boost/variant/detail/forced_return.hpp:31
Promise<Void>::~Promise() at /opt/foundation/foundationdb/flow/TDMetric.actor.h:1269
 (inlined by) N2::PromiseTask::~PromiseTask() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:475
 (inlined by) N2::PromiseTask::operator()() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:482
 (inlined by) N2::Net2::run() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:657
main at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3346

The trace files of the fdbserver from 10.196.76.47 is here.
Cluster Details is like below

Using cluster file `/etc/foundationdb/fdb.cluster'.

Configuration:
  Redundancy mode        - double
  Storage engine         - ssd-2
  Coordinators           - 3
  Desired Proxies        - 1
  Desired Logs           - 2

Cluster:
  FoundationDB processes - 6
  Zones                  - 3
  Machines               - 3
  Memory availability    - 7.5 GB per process on machine with least available
  Retransmissions rate   - 1 Hz
  Fault Tolerance        - 1 machine
  Server time            - 04/20/20 14:53:54

Data:
  Replication health     - Healthy
  Moving data            - 0.000 GB
  Sum of key-value sizes - 448.312 GB
  Disk space used        - 1.594 TB

Operating space:
  Storage server         - 469.4 GB free on most full server
  Log server             - 333.7 GB free on most full server

Workload:
  Read rate              - 1861 Hz
  Write rate             - 578 Hz
  Transactions started   - 778 Hz
  Transactions committed - 94 Hz
  Conflict rate          - 0 Hz

Backup and DR:
  Running backups        - 0
  Running DRs            - 0

Process performance details:
  10.196.76.47:4500      ( 26% cpu; 14% machine; 0.062 Gbps; 29% disk IO; 6.9 GB / 11.0 GB RAM  )
  10.196.76.47:4501      (  1% cpu; 14% machine; 0.062 Gbps; 29% disk IO; 0.2 GB / 11.0 GB RAM  )
  10.196.76.49:4500      ( 14% cpu; 15% machine; 0.067 Gbps; 22% disk IO; 6.8 GB / 7.5 GB RAM  )
  10.196.76.49:4501      ( 16% cpu; 15% machine; 0.067 Gbps; 18% disk IO; 0.4 GB / 7.5 GB RAM  )
  10.196.76.56:4500      ( 31% cpu; 18% machine; 0.065 Gbps; 39% disk IO; 6.8 GB / 10.4 GB RAM  )
  10.196.76.56:4501      (  2% cpu; 18% machine; 0.065 Gbps; 44% disk IO; 0.2 GB / 10.4 GB RAM  )

Coordination servers:
  10.196.76.47:4500  (reachable)
  10.196.76.49:4501  (reachable)
  10.196.76.56:4500  (reachable)

Client time: 04/20/20 14:53:54

Just before the crash, I am observing few Slow Tasks like below

<Event Severity="30" Time="1587096940.191483" Type="SlowTask" ID="0000000000000000" TaskID="20000" MClocks="530.525" Duration="0.241148" SampleRate="1" NumYields="0" Machine="10.196.76.47:4500" LogGroup="default" Roles="CD,SS,TL" />
<Event Severity="30" Time="1587097227.580954" Type="SlowTask" ID="0000000000000000" TaskID="20000" MClocks="514.249" Duration="0.23375" SampleRate="1" NumYields="0" Machine="10.196.76.47:4500" LogGroup="default" Roles="CD,SS,TL" />
<Event Severity="30" Time="1587097279.286559" Type="SlowTask" ID="0000000000000000" TaskID="20000" MClocks="882.94" Duration="0.401337" SampleRate="1" NumYields="2" Machine="10.196.76.47:4500" LogGroup="default" Roles="CD,SS,TL" />

I am observing the similar crash in 10.196.76.49 server also. The trace file is here.

Can someone help me understand the backtrace above and what could be happening here?

2

At higher load, our default settings assume that each role has 8GB of memory, because generally by the time that people are running full load against a cluster, it’s not a small/dev cluster. Maybe we should re-evaluate those default settings, but this is basically either that you need to give your processes more memory (and set --memory correspondingly), or run more processes so that you can separate your Transaction Log and Storage Server processes.

Alternatively, It’s odd that your :4500 processes are all using ~6.8GB of RAM, and your :4501 process are nearly unused. Do you know why that is? How are these process configured? Having the load spread across processes more might also fix this issue.

For the SlowTask, do you see any Net2SlowTaskTrace lines? Those would have backtraces, telling you what the slow task actually was.

3

Looking at your trace file, it appears that at the start of that file the process was already using nearly 8GB. The MemoryMetrics event, which reports memory from some of the known memory pools, is able to account for about 6GB of that, although it’s hard to tell more precisely where that has gone without some of the traces from earlier logs.

Are you by any changing doing any reverse range reads in your workload? There’s a known memory issue with those that is fixed in newer releases (try 6.2.19). There are also a couple other places that can build up memory if you saturate the cluster in certain ways, some of which have been fixed in newer releases. Is your workload ever saturating?

Increasing the memory available could certainly help if the amount of memory needed is bounded, but if we need to look more into it, then one option to do so is to look at a couple trace events GetMagazineSample and HugeArenaSample. It’s useful to look at these events being logged as the memory is growing, so it would probably need to cover a time prior to the trace log that you posted. Each includes a backtrace of the allocation that can be symbolicated if you have the debug symbols (which I think at the moment aren’t published, so it requires doing a build or submitting a trace file to us, etc.).

4

Thanks @alexmiller and @ajbeamon for replying.

@alexmiller

Alternatively, It’s odd that your :4500 processes are all using ~6.8GB of RAM, and your :4501 process are nearly unused. Do you know why that is? How are these process configured?

4501 is configured as stateless.

[fdbserver.4500]

[fdbserver.4501]
class = stateless

For the SlowTask, do you see any Net2SlowTaskTrace lines? Those would have backtraces, telling you what the slow task actually was.

Yes, I see Net2SlowTask. Traces look like below.

?? ??:0
?? ??:0
io_submit at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/stl_vector.h:827
 (inlined by) AsyncFileKAIO::launch() at /opt/foundation/foundationdb/fdbrpc/AsyncFileKAIO.actor.h:394
N2::Net2::run() at /opt/foundation/foundationdb/flow/TDMetric.actor.h:1269
main at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3346
?? ??:0
_start at ??:?

Any pointers on when io_submit can become slow? Is it waiting on some other synchronous operations? I have placed the trace file here.

@ajbeamon

Is your workload ever saturating?

Our workload is not ever saturating.

Increasing the memory available could certainly help if the amount of memory needed is bounded, but if we need to look more into it, then one option to do so is to look at a couple trace events GetMagazineSample and HugeArenaSample . It’s useful to look at these events being logged as the memory is growing

Traces with GetMagazineSample looks like below-

TraceEvent::backtrace(std::string const&) at ??:?
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.tcc:613
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> > std::operator+<char, std::char_traits<char>, std::allocator<char> >(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, char const*) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:5958
 (inlined by) TraceEvent::backtrace(std::string const&) at /opt/foundation/foundationdb/flow/Trace.cpp:938
std::string::_M_rep() const at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3313
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3631
 (inlined by) FastAllocator<256>::getMagazine() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:449
FastAllocator<256>::allocate() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:272
Future<TLogPeekReply> sendCanceler<TLogPeekReply>(ReplyPromise<TLogPeekReply> const&, ReliablePacket* const&, Endpoint const&) at ??:?
 (inlined by) SendCancelerActorState at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.h:202
 (inlined by) SendCancelerActor at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.g.h:2714
 (inlined by) Future<TLogPeekReply> sendCanceler<TLogPeekReply>(ReplyPromise<TLogPeekReply> const&, ReliablePacket* const&, Endpoint const&) at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.h:202
Future<decltype (((((getReplyPromise((fake<TLogPeekRequest>)())).getFuture)()).getValue)())> RequestStream<TLogPeekRequest>::getReply<TLogPeekRequest>(TLogPeekRequest const&) const at ??:?
 (inlined by) Future<decltype (((((getReplyPromise((fake<TLogPeekRequest>)())).getFuture)()).getValue)())> RequestStream<TLogPeekRequest>::getReply<TLogPeekRequest>(TLogPeekRequest const&) const at /opt/foundation/foundationdb/./fdbrpc/fdbrpc.h:286
(anonymous namespace)::ServerPeekGetMoreActorState<(anonymous namespace)::ServerPeekGetMoreActor>::a_body1cont1loopBody1(int) at /opt/foundation/foundationdb/./flow/flow.h:529
a_body1cont1loopHead1 at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1cont1 at /opt/foundation/foundationdb/.objs/fdbserver/LogSystemPeekCursor.actor.g.cpp:689
 (inlined by) a_body1 at /opt/foundation/foundationdb/.objs/fdbserver/LogSystemPeekCursor.actor.g.cpp:664
 (inlined by) ServerPeekGetMoreActor at /opt/foundation/foundationdb/.objs/fdbserver/LogSystemPeekCursor.actor.g.cpp:934
 (inlined by) serverPeekGetMore(ILogSystem::ServerPeekCursor* const&, TaskPriority const&) at /opt/foundation/foundationdb/fdbserver/LogSystemPeekCursor.actor.cpp:209
ILogSystem::ServerPeekCursor::getMore(TaskPriority) at /opt/foundation/foundationdb/./flow/flow.h:529
Future<Void>::Future(Future<Void> const&) at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) StrictFuture<Void>::StrictFuture(Future<Void> const&) at /opt/foundation/foundationdb/./flow/flow.h:765
 (inlined by) a_body1cont3loopBody1 at /opt/foundation/foundationdb/fdbserver/storageserver.actor.cpp:2588
a_body1cont3loopHead1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont3 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8075
 (inlined by) a_body1cont2break1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8111
 (inlined by) a_body1cont2loopBody1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8092
a_body1cont2loopHead1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont2 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:7966
 (inlined by) a_body1break1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8014
 (inlined by) a_body1loopBody1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:7983
a_body1loopHead1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:7891
 (inlined by) UpdateActor at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:9167
 (inlined by) update(StorageServer* const&, bool* const&) at /opt/foundation/foundationdb/fdbserver/storageserver.actor.cpp:2561
a_body1loopBody1when11 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_callback_fire at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:13589
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
SAV<Void>::finishSendAndDelPromiseRef() at /opt/foundation/foundationdb/./flow/flow.h:478
(anonymous namespace)::UpdateActorState<(anonymous namespace)::UpdateActor>::a_body1cont9loopBody1(int) at /opt/foundation/foundationdb/./flow/serialize.h:748
a_body1cont9loopHead1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont9 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8574
 (inlined by) a_body1cont7break1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8607
 (inlined by) a_body1cont7loopBody1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8591
 (inlined by) a_body1cont7loopHead1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8581
 (inlined by) a_body1cont7 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8387
 (inlined by) a_body1cont5break1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8500
 (inlined by) a_body1cont5loopBody1cont1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8516
a_body1cont5loopBody1when1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont5loopBody1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8488
a_body1cont5loopHead1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont5 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8310
a_body1cont4when1 at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) a_body1cont4 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8192
 (inlined by) a_body1cont3break1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8227
 (inlined by) a_body1cont3loopBody1cont1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8243
 (inlined by) a_body1cont3loopBody1when1 at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8251
 (inlined by) a_callback_fire at /opt/foundation/foundationdb/.objs/fdbserver/storageserver.actor.g.cpp:8265
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
SAV<Void>::finishSendAndDelPromiseRef() at /opt/foundation/foundationdb/./flow/flow.h:478
(anonymous namespace)::ServerPeekGetMoreActorState<(anonymous namespace)::ServerPeekGetMoreActor>::a_body1cont1loopBody1when1(TLogPeekReply const&, int) [clone .isra.930] at /opt/foundation/foundationdb/./flow/flow.h:529
Reference<ArenaBlock>::~Reference() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) Arena::~Arena() at /opt/foundation/foundationdb/./flow/Arena.h:92
 (inlined by) TLogPeekReply::~TLogPeekReply() at /opt/foundation/foundationdb/./fdbserver/TLogInterface.h:149
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
SAV<TLogPeekReply>::finishSendAndDelPromiseRef() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1cont2 at /opt/foundation/foundationdb/flow/genericactors.actor.g.h:11349
 (inlined by) a_body1when1 at /opt/foundation/foundationdb/flow/genericactors.actor.g.h:11356
 (inlined by) a_callback_fire at /opt/foundation/foundationdb/flow/genericactors.actor.g.h:11370
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
SAV<TLogPeekReply>::finishSendAndDelPromiseRef() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) a_body1cont2 at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.g.h:2648
 (inlined by) a_body1when1 at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.g.h:2655
 (inlined by) a_callback_fire at /opt/foundation/foundationdb/fdbrpc/genericactors.actor.g.h:2669
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
SAV<TLogPeekReply>::finishSendAndDelPromiseRef() at /opt/boost_1_67_0/boost/variant/detail/forced_return.hpp:31
 (inlined by) void SAV<TLogPeekReply>::sendAndDelPromiseRef<TLogPeekReply&>(TLogPeekReply&) at /opt/foundation/foundationdb/./flow/flow.h:472
 (inlined by) NetSAV<TLogPeekReply>::receive(ArenaObjectReader&) at /opt/foundation/foundationdb/./fdbrpc/fdbrpc.h:111
Reference<ArenaBlock>::~Reference() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) Arena::~Arena() at /opt/foundation/foundationdb/./flow/Arena.h:92
 (inlined by) ArenaObjectReader::~ArenaObjectReader() at /opt/foundation/foundationdb/./flow/ObjectSerializer.h:117
 (inlined by) a_body1cont1 at /opt/foundation/foundationdb/fdbrpc/FlowTransport.actor.cpp:651
ActorCallback<(anonymous namespace)::DeliverActor, 0, Void>::fire(Void const&) at /opt/foundation/foundationdb/./flow/flow.h:529
void SAV<Void>::send<Void>(Void&&) at /opt/boost_1_67_0/boost/variant/detail/forced_return.hpp:31
Promise<Void>::~Promise() at /opt/foundation/foundationdb/flow/TDMetric.actor.h:1269
 (inlined by) N2::PromiseTask::~PromiseTask() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:475
 (inlined by) N2::PromiseTask::operator()() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:482
 (inlined by) N2::Net2::run() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:657
main at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3346
?? ??

Traces with HugeArenaSample

 (inlined by) std::map<std::string, std::pair<int, int>, std::less<std::string>, std::allocator<std::pair<std::string const, std::pair<int, int> > > >::lower_bound(std::string const&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/stl_map.h:1240
 (inlined by) std::map<std::string, std::pair<int, int>, std::less<std::string>, std::allocator<std::pair<std::string const, std::pair<int, int> > > >::operator[](std::string&&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/stl_map.h:515
 (inlined by) hugeArenaSample(int) at /opt/foundation/foundationdb/flow/FastAlloc.cpp:92
std::__atomic_base<long>::fetch_add(long, std::memory_order) at /opt/foundation/foundationdb/./flow/Arena.h:262
 (inlined by) ArenaBlock::create(int, Reference<ArenaBlock>&) at /opt/foundation/foundationdb/./flow/Arena.h:262
ArenaBlock::addUsed(int) at /opt/foundation/foundationdb/./flow/FastRef.h:75
 (inlined by) ArenaBlock::allocate(Reference<ArenaBlock>&, int) at /opt/foundation/foundationdb/./flow/Arena.h:216
 (inlined by) operator new[](unsigned long, Arena&) at /opt/foundation/foundationdb/./flow/Arena.h:337
VectorRef<KeyValueRef, (VecSerStrategy)0>::reallocate(Arena&, int) at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) VectorRef<KeyValueRef, (VecSerStrategy)0>::push_back(Arena&, KeyValueRef const&) at /opt/foundation/foundationdb/./flow/Arena.h:985
 (inlined by) RawCursor::getRange(KeyRangeRef, int, int) at /opt/foundation/foundationdb/fdbserver/KeyValueStoreSQLite.actor.cpp:1105
KeyValueStoreSQLite::Reader::action(KeyValueStoreSQLite::Reader::ReadRangeAction&) at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) TypedAction<KeyValueStoreSQLite::Reader, KeyValueStoreSQLite::Reader::ReadRangeAction>::operator()(IThreadPoolReceiver*) at /opt/foundation/foundationdb/./flow/IThreadPool.h:74
yield(TaskPriority) at /opt/foundation/foundationdb/./flow/flow.h:1018
 (inlined by) WorkPool<Coroutine, ThreadUnsafeSpinLock, true>::Worker::run() at /opt/foundation/foundationdb/fdbserver/CoroFlow.actor.cpp:151
Coroutine::wrapRun() at /opt/foundation/foundationdb/./flow/flow.h:629
 (inlined by) Coroutine::entry(void*) at /opt/foundation/foundationdb/fdbserver/CoroFlow.actor.cpp:89
Coro_StartWithArg at /opt/foundation/foundationdb/fdbrpc/libcoroutine/Coro.c:277
?? ??

It is the same trace file which I posted above in this reply.

I will be upgrading this cluster to the latest 6.2.19 end of this week. Before that, I am trying to do understand this a bit more what is making the cluster land up in this situation.

5

I did see these samples in the trace file, but because the memory used at the start of this file is already very large, I don’t know that we can determine much from them. What we’d really want is to have samples from when the memory is really growing so we could see where it’s all gone. For that, we’d need earlier trace files in the run that show change in memory between the first and last ProcessMetrics events.

6

@ajbeamon - This is a trace file from 10.196.76.47 where I can see the memory jumped from ~2.5 GB to ~ 6.44 GB .

This is a trace file from another node, 10.196.76.49 in the same cluster which also went OutOfMemory , here the memory went from ~1.9 GB to 7 GB.

7

io_submit() is KAIO, which is the Linux Kernel’s async IO support. If io_submit() is blocking for 250ms-400ms for you. That would indicate that there’s something very strange going on between FDB and your hardware. What version of Linux are you running? What filesystem? Which Distro? What environment are you running FDB in? (Bare metal? Cloud? Which cloud?)

I think we’ve previously seen io_submit() start to have a bit of noticeable latency during high IO workloads, but I don’t recall seeing anything to this degree. You could also try running with --knob_disable_posix_kernel_aio=1 to use a threadpool for async IO instead.

8

@ajbeamon - Looking at the GetMagazineSample trace from 10.196.76.47 when the memory jumped from ~2.44 GB to ~6.8 GB. The below backtraces to be more common during this period.

TraceEvent::backtrace(std::string const&) at ??:?
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.tcc:613
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> > std::operator+<char, std::char_traits<char>, std::allocator<char> >(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, char const*) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:5958
 (inlined by) TraceEvent::backtrace(std::string const&) at /opt/foundation/foundationdb/flow/Trace.cpp:938
std::string::_M_rep() const at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3313
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3631
 (inlined by) FastAllocator<64>::getMagazine() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:449
FastAllocator<64>::allocate() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:272
IndexedSet<Standalone<StringRef>, long>::Node::Node<StringRef&, int>(StringRef&, int&&, IndexedSet<Standalone<StringRef>, long>::Node*) at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) IndexedSet<Standalone<StringRef>, long>::iterator IndexedSet<Standalone<StringRef>, long>::insert<StringRef&, int>(StringRef&, int&&, bool) at /opt/foundation/foundationdb/./flow/IndexedSet.h:635
(anonymous namespace)::ApplyByteSampleResultActorState<(anonymous namespace)::ApplyByteSampleResultActor>::a_body1loopBody1cont1(Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> > const&, int) at /opt/foundation/foundationdb/./flow/serialize.h:748
Reference<ArenaBlock>::~Reference() at /opt/foundation/foundationdb/./flow/serialize.h:748
 (inlined by) Arena::~Arena() at /opt/foundation/foundationdb/./flow/Arena.h:92
 (inlined by) Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> >::~Standalone() at /opt/foundation/foundationdb/./flow/Arena.h:479
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
void SAV<Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> > >::send<Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> >&>(Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> >&) at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) void Promise<Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> > >::send<Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> >&>(Standalone<VectorRef<KeyValueRef, (VecSerStrategy)0> >&) const at /opt/foundation/foundationdb/./flow/flow.h:778
 (inlined by) a_body1cont1 at /opt/foundation/foundationdb/flow/genericactors.actor.h:1202
 (inlined by) a_body1when1 at /opt/foundation/foundationdb/flow/genericactors.actor.g.h:11733
 (inlined by) a_callback_fire at /opt/foundation/foundationdb/flow/genericactors.actor.g.h:11747
 (inlined by) fire at /opt/foundation/foundationdb/./flow/flow.h:998
void SAV<Void>::send<Void>(Void&&) at /opt/boost_1_67_0/boost/variant/detail/forced_return.hpp:31
Promise<Void>::~Promise() at /opt/foundation/foundationdb/flow/TDMetric.actor.h:1269
 (inlined by) N2::PromiseTask::~PromiseTask() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:475
 (inlined by) N2::PromiseTask::operator()() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:482
 (inlined by) N2::Net2::run() at /opt/foundation/foundationdb/flow/Net2.actor.cpp:657
main at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3346
?? ??:0

I also see the below trace during this period which seems to be the fix you added in 6.2.19.

addr2line -e fdbserver.debug -p -C -f -i 0x194478f 0x190e413 0x190e651 0x186d545 0x1863dea 0x72b1c2 0x765327 0x76559a 0x7656f1 0x768701 0x768775 0x768858 0xb46cbf 0xb4ad97 0xa2ef82 0xa2c0f9 0x18500a6 0x7ff4a0c5f5d0
TraceEvent::backtrace(std::string const&) at ??:?
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::basic_string(std::string const&) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.tcc:613
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> > std::operator+<char, std::char_traits<char>, std::allocator<char> >(std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, char const*) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:5958
 (inlined by) TraceEvent::backtrace(std::string const&) at /opt/foundation/foundationdb/flow/Trace.cpp:938
std::string::_M_rep() const at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3313
 (inlined by) std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3631
 (inlined by) FastAllocator<4096>::getMagazine() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:449
FastAllocator<4096>::allocate() at /opt/foundation/foundationdb/flow/FastAlloc.cpp:272
EvictablePageCache::allocate(EvictablePage*) at /opt/foundation/foundationdb/fdbrpc/AsyncFileCached.actor.h:76
 (inlined by) AFCPage::AFCPage(AsyncFileCached*, long) at /opt/foundation/foundationdb/fdbrpc/AsyncFileCached.actor.h:576
AsyncFileCached::readZeroCopy(void**, int*, long) at /opt/foundation/foundationdb/./flow/FastAlloc.h:200
asyncReadZeroCopy(sqlite3_file*, void**, int, long long, int*) at /opt/rh/devtoolset-8/root/usr/include/c++/8/bits/basic_string.h:3346
readDbPage at /opt/foundation/foundationdb/fdbserver/sqlite/sqlite3.amalgamation.c:31953
sqlite3PagerAcquire at /opt/foundation/foundationdb/fdbserver/sqlite/sqlite3.amalgamation.c:34182
btreeGetPage at /opt/foundation/foundationdb/fdbserver/sqlite/btree.c:1567
getAndInitPage at /opt/foundation/foundationdb/fdbserver/sqlite/btree.c:1619
moveToChild at /opt/foundation/foundationdb/fdbserver/sqlite/btree.c:4188
moveToLeftmost at /opt/foundation/foundationdb/fdbserver/sqlite/btree.c:4349
RawCursor::moveNext() at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) RawCursor::DefragmentingReader::advance() at /opt/foundation/foundationdb/fdbserver/KeyValueStoreSQLite.actor.cpp:945
 (inlined by) RawCursor::DefragmentingReader::peek() at /opt/foundation/foundationdb/fdbserver/KeyValueStoreSQLite.actor.cpp:957
 (inlined by) RawCursor::getRange(KeyRangeRef, int, int) at /opt/foundation/foundationdb/fdbserver/KeyValueStoreSQLite.actor.cpp:1094
KeyValueStoreSQLite::Reader::action(KeyValueStoreSQLite::Reader::ReadRangeAction&) at /opt/foundation/foundationdb/./flow/flow.h:529
 (inlined by) TypedAction<KeyValueStoreSQLite::Reader, KeyValueStoreSQLite::Reader::ReadRangeAction>::operator()(IThreadPoolReceiver*) at /opt/foundation/foundationdb/./flow/IThreadPool.h:74
yield(TaskPriority) at /opt/foundation/foundationdb/./flow/flow.h:1018
 (inlined by) WorkPool<Coroutine, ThreadUnsafeSpinLock, true>::Worker::run() at /opt/foundation/foundationdb/fdbserver/CoroFlow.actor.cpp:151
Coroutine::wrapRun() at /opt/foundation/foundationdb/./flow/flow.h:629
 (inlined by) Coroutine::entry(void*) at /opt/foundation/foundationdb/fdbserver/CoroFlow.actor.cpp:89
Coro_StartWithArg at /opt/foundation/foundationdb/fdbrpc/libcoroutine/Coro.c:277
?? ??:0

Are these pointing to the same issue or there is some other thing important which I am missing?

io_submit() is KAIO, which is the Linux Kernel’s async IO support. If io_submit() is blocking for 250ms-400ms for you. That would indicate that there’s something very strange going on between FDB and your hardware. What version of Linux are you running? What filesystem? Which Distro? What environment are you running FDB in? (Bare metal? Cloud? Which cloud?)

@alexmiller - Ubuntu 16.04.6 running on ESXi 6.5.

From the trace file it seems io_submit started taking time when the process memory usage increased more than 5.3 GB. I don’t see this when the memory usage of the process was less. Also the frequency of this event is less. Is there a possibility that Net2SlowTaskTrace (pointing to io_submit taking time) a side effect of the high memory usage on the process?

9

Your cluster status says you have 7.5 GB per process on one host (so thus 15GB in total). Is this accurate, or is there 7.5GB in total on that host? If you’re running the entire machine nearly out of memory, then I could easily see where the slow tasks and weird performance would be coming from.

Otherwise, I’ll need to ponder more…

10

Yes it is per process. No the entire machine is not out of memory. Another thing the out of memory is happening only on the process running on port 4500.