RejectedSoftware Forums

Sign up

Odd pauses when posting data

I've been working on creating a prototype restful web service
using vibe.d and it runs very fast on my tests except for when I
pass in documents that have a larger number of nested levels.
With those, I see a very noticeable pause, about 1 second, before
I get a response back with curl. Below is a sample file that
describes the structure I'm using. It's only when block5 exists
that the issue occurs. I have other combinations that work fine
and I even though it was my code, but after commenting it out, I
still saw the pause.

My current thought is that it has something to do with parsing
the JSON, but I could be wrong. Any thoughts on what this could
be? I'm not on the best environment, but I didn't have any other
processes running at the same time when I run this, so I'm very
certain that it's not an environment issue. My only other
thought is that there's an issue with Curl. However, I made a
different test case that didn't have block5 in it, but had
multiple entries in the block3 array, so it is similar in size,
perhaps larger, than the ones I'm having issues with and it works
perfectly.

{
      "block1":
      {
          "val1": "value",
          "val2": "value",
          "val3": "value",
          "val4": ["A", "B"],
          "block2":
          {
              "arr1":
              [
                  {
                      "val5": "C",
                      "val6": ["D"]
                  }
              ]
          }
      },
      "block3":
      [
          {
              "val7": "value",
              "block4":
              {
                  "val8": 0,
                  "val9": "E",
                  "val10": ["F"],
                  "val11": ["G"],
                  "block5":
                  {
                      "arr2":
                      [
                          {
                              "val12": "H",
                              "val13": ["I", "J", "K"]
                          }
                      ]
                  }
              }
          }
      ]
}

Re: Odd pauses when posting data

I just tested posting the JSON to this app:

import vibe.d;

static this()
{
	void handle(HttpServerRequest req, HttpServerResponse res)
	{
		static int cnt;
		res.writeBody(to!string(cnt++)~"\n"~req.json.toString()~"\n", "text/plain");
	}

	auto settings = new HttpServerSettings;
	settings.port = 8080;
	listenHttp(settings, &handle);
}

and the response is instantaneous. Is there anything else happening in your app? If not, does this simple app also show the delay for you?

Re: Odd pauses when posting data

Crap...it's on my end. I must not have simplified my test case enough and missed something. I rewrote the code to simply return the value of one of the elements and it was very fast as well.

Re: Odd pauses when posting data

Correction: I'm still seeing the slowdown. I created two test cases: one for the fake file I showed you and one for my real data. All I do is grab a value from the first block and return a string. Both files are similar in structure and size (1.5 real vs. 1.1 fake). For some reason, the real data has a pause and the fake doesn't. This is very weird. Any thoughts on why this would be happening?

FYI: I'm using the REST interface, so my code looks like this:

string postSample(Json block1, Json[] block3)
{

  return block1.val1.toString();

}

Is there a way for me to turn on code coverage to see where the delay may be?

Re: Odd pauses when posting data

Am 10/1/2012 3:25 PM, schrieb Casey Sybrandy:

Correction: I'm still seeing the slowdown. I created two test cases:
one for the fake file I showed you and one for my real data. All I do
is grab a value from the first block and return a string. Both files
are similar in structure and size (1.5 real vs. 1.1 fake). For some
reason, the real data has a pause and the fake doesn't. This is very
weird. Any thoughts on why this would be happening?

FYI: I'm using the REST interface, so my code looks like this:

string postSample(Json block1, Json[] block3)
{

  return block1.val1.toString();

}

Is there a way for me to turn on code coverage to see where the delay
may be?

You can use set DFLAGS=-profile -g before running vibe to enable
profiling, but I think you have to be lucky to get a meaningful result.

Maybe if all the strings have the same length as in the original data,
the pause can be reproduced?

Btw. while looking for something suspicious, I found and fixed a bug in
the JSON parser for unicode sequences (\uNNNN), but that shouldn't
make a real difference in execution time.

Re: Odd pauses when posting data

Interesting...first, I did a git pull in case that JSON fix made a difference.
No change. So, I modified my test case and now I'm getting a similar pause.
Here's the new test case:

{

  "block1":
  {
      "val1": "value",
      "val2asdf": "value",
      "val3asdf": "value",
      "val4asdf": ["A", "B"],
      "block2":
      {
          "arr1alsdfkjalsdfkj":
          [
              {
                  "val5asdfasdf": "CCC",
                  "val6asdfasdf": ["DDDD"]
              }
          ]
      }
  },
  "block3":
  [
      {
          "val7": "value",
          "block4":
          {
              "val8": 0,
              "val9": "E",
              "val10": ["F"],
              "val11": ["G"],
              "block5":
              {
                  "arr2":
                  [
                      {
                          "val12": "H",
                          "val13": ["I", "J", "K"]
                      }
                  ],
                  "arr3":
                  [
                      {
                          "val14": "H",
                          "val15": ["I", "J", "K"]
                      }
                  ]
              }
          }
      }
  ]

}

All I changed was two values and several field names in block1. Oddly enough,
I have test cases that don't involve block5, but similar sized data in block1
and it runs fast. Perhaps there's an issue with data over a certain size?
Here's what I'm getting with curl -v:

  • About to connect() to localhost port 8080 (#0)
  • Trying 127.0.0.1... connected
  • Connected to localhost (127.0.0.1) port 8080 (#0)

POST /sample HTTP/1.1
User-Agent: curl/7.21.0 (i486-pc-linux-gnu) libcurl/7.21.0 OpenSSL/0.9.8o zlib/1.2.3.4 libidn/1.15 libssh2/1.26
Host: localhost:8080
Accept: /
Content-Type: application/json
Content-Length: 1067
Expect: 100-continue

< HTTP/1.1 100 Continue

  • Done waiting for 100-continue
    < HTTP/1.1 500 Internal Server Error
    < Server: vibe.d/0.7.7
    < Date: Mon, 01 Oct 2012 15:08:58 GMT
    < Keep-Alive: timeout=10
    < Content-Type: text/plain
    < Transfer-Encoding: chunked
    0
  • transfer closed with outstanding read data remaining
  • Closing connection #0
    curl: (18) transfer closed with outstanding read data remaining

I did a quick trace as well and it looks like a lot of the time is spent in a
couple methods. Here's a subset of the output:

Calls Time Time Call

  1  6893740420  6893596406  6893596406     bool vibe.core.drivers.libevent2_tcp.Libevent2TcpConnection.waitForData(core.time.Duration)
  1  8355549309   765392259   765392259     extern (C) void vibe.core.drivers.libevent2_tcp.onConnect(int, short, void*).void ClientTask.execute()
 10   691300803   691275570    69127557     void vibe.stream.counting.LimitedInputStream.read(ubyte[])
383     6802911     5462917       14263     pure @safe bool std.exception.enforce!(bool).enforce(bool, lazy const(char)[], immutable(char)[], uint)
  1      391495      385249      385249     void vibe.crypto.ssl._sharedStaticCtor8()
 18      594246      327661       18203     int std.algorithm.countUntil!("a == b", immutable(char)[], immutable(char)[]).countUntil(immutable(char)[], immutable(char)[])

2522 487521 323526 128 void std.array.Appender!(immutable(char)[]).Appender.put!(char[]).put(char[])

  1      811591      282193      282193     immutable(char)[] vibe.utils.string.sanitizeUTF8(const(ubyte[]))

2576 165318 159657 61 void std.array.Appender!(immutable(char)[]).Appender.ensureAddable(uint)

  1      203911      148914      148914     vibe.core.drivers.libevent2.Libevent2Driver vibe.core.drivers.libevent2.Libevent2Driver.__ctor(vibe.core.driver.DriverCore)

As you can see, the top three are taking a lot of time.

Hope this helps. Outside of these pauses, I'm really liking this for
REST-related development, so I'm really hoping we can get this issue resolved.

Re: Odd pauses when posting data

Thanks, I can reproduce it with that JSON. Seems like too few bytes are
written and the connection times out at some point. I'll investigate...

Re: Odd pauses when posting data

OK got it. Curl sends an "Expect: 100-continue" header when the request
body has a certain minimum size. vibe.d has to respond with a 100 code
followed by two line breaks in that case. It responded, but with just
one line break. This caused curl to wait for one second because it
thought it may not continue sending the request. And then on top of
that, when it finally send the request body, the reponse body was also
interpreted in a weird way as partially a part of the response header.

Anyway, this is fixed now ;)

Re: Odd pauses when posting data

Thanks man! That made my day.