read_avail uses 100% CPU

[vmamidi]

For a short duration, ATS gets busier in read_avail and starts using 100% CPU. I do not have much information as of now but as the thread gets busier the requests that are handled by that thread timeout.

#0 Ptr::get (this=0x2aad05deab78) at ../../lib/ts/Ptr.h:150
#1 IOBufferReader::read_avail (this=) at ../../iocore/eventsystem/P_IOBuffer.h:633
#2 IOBufferReader::consume (n=, this=) at ../../iocore/eventsystem/P_IOBuffer.h:682
#3 UnixNetVConnection::load_buffer_and_write (this=, towrite=370501208, buf=..., total_written=, needs=) at UnixNetVConnection.cc:970
#4 0x00002aaaaaec81e9 in write_to_net_io (nh=nh@entry=0x2aaab3a11c80, vc=0x2aaacdd6a900, thread=) at UnixNetVConnection.cc:510
#5 0x00002aaaaaec91f3 in write_to_net (nh=nh@entry=0x2aaab3a11c80, vc=vc@entry=0x2aaacdd6a900, thread=) at UnixNetVConnection.cc:419
#6 0x00002aaaaaeaf888 in NetHandler::mainNetEvent (this=0x2aaab3a11c80, event=, e=) at UnixNet.cc:543
#7 0x00002aaaaaf07b1e in Continuation::handleEvent (data=0x2aaab1788fe0, event=5, this=) at I_Continuation.h:153
#8 EThread::process_event (calling_code=5, e=0x2aaab1788fe0, this=0x2aaab3a0de80) at UnixEThread.cc:143
#9 EThread::execute (this=0x2aaab3a0de80) at UnixEThread.cc:270
#10 0x00002aaaaaf066c6 in spawn_thread_internal (a=0x2aaab09c0c00) at Thread.cc:84
#11 0x00002aaaad73caa1 in start_thread (arg=0x2aaab6b0c700) at pthread_create.c:301
#12 0x00002aaaae5f393d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

[shinrich]

I have noticed spikes in read_avail several times in several different spots over the past year. Generally, we are able to rewrite the code to replace the read_avail with a cheaper read_avail_more_than.

Which version are you running? I'm not seeing a call to consume in my version of UnixNetVConnection::load_buffer_and_write at that line number.

[vmamidi]

ATS version is 7.0.0. I have thought about fixing read_avail similar to what's being done in read_avail_more_than but I was wondering how could the IOBufferBlock become so big such that read_avail becomes expensive.

[shinrich]

We noticed these read_avails causing us problem around the time we moved to openssl 1.0.2. It is a bit of a mystery to me too why the block lists suddenly became long enough for the read avails to become a significant performance issue.

[maskit]

I found large block lists on my local machine. What I did is just running h2load.

$ h2load -c 10 -n 1000 -m 1000 https://localhost:8443/bigfile

I used node-static as an origin server, and it was running on the same machine. The bigfile is 2GB.

I modified the code like below

diff --git a/iocore/eventsystem/P_IOBuffer.h b/iocore/eventsystem/P_IOBuffer.h
index dc299376a..574d6d1c2 100644
--- a/iocore/eventsystem/P_IOBuffer.h
+++ b/iocore/eventsystem/P_IOBuffer.h
@@ -627,10 +627,17 @@ IOBufferReader::read_avail()
 {
   int64_t t        = 0;
   IOBufferBlock *b = block.get();
+  int n = 0;
 
   while (b) {
     t += b->read_avail();
     b = b->next.get();
+    ++n;
+  }
+  if (n > 1) printf("-----------------> %d\n", n);
+  // ink_assert(n < 10000);
+  if (n > 10000) {
+    printf("");
   }
 
   t -= start_offset;

then I saw increasing numbers, and the buffer was allocated at Http2ClientSession.cc:184. It doesn't happen if I put --h1 option to h2load.

I couldn't have a time to dig in and I'm not sure whether the cause is the same but I hope it helps.