RejectedSoftware Forums

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?

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?

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.

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 ;)