Hi everyone,
I'm having some crazy timing properties related to RESTlet responses being
above or below 1024 bytes. The fact that this is a power of 2 makes me
think it's no coincidence!
[To start, here is some setup text copied from my previous mail.]
I'm just getting started with RESTlet (v.2.1.1, with
org.restlet.jee.ext.jackson & jee.ext.jaxrs), so I may be doing something
very wrong. However, basic things work well for me. For instance, if I
return POJOs from a function annotated with
@Produces(MediaType.APPLICATION_JSON), they seem to be returned properly.
Right now, I'm experimenting with implementing different handlers for
different Content-Types. I started with the simplest possible: echo JSON
input (converted to String) back as JSON:
/**
* Class that handles queries.
*
* @author dhalperi
*/
@Path("/echo")
public final class EchoResource {
/**
* For now, simply echoes back its input.
*
* @param input the payload of the POST request itself.
* @return the payload.
*/
@POST
@Produces(MediaType.APPLICATION_JSON)
@Consumes(MediaType.APPLICATION_JSON)
public String postNewQuery(final String input) {
return input;
}
}
[/copied text]
I just found a new, very strange effect. It seems that if the payload
returned by this function is <= 1024 bytes, the processing time is
near-imperceptible; a few hundred ms at most. But when it goes to 1025
bytes, it seems to take just about 1.06s or just about 2.04s to process.
Also, there's almost no variation from those two numbers.
I send json (and time the processing) like this: time curl -i -XPOST
localhost:8753/echo -H "Content-type: application/json" -d
@./single_join.json
Here are the contents of single_join.json
% cat single_join.json
{
"raw_datalog" : "testRelationJoin(x,y,y,z) :-
testRelation(x,y),testRelation(y,z).",
"logical_ra" : "INSERT(JOIN(SCAN1,SCAN2))",
"query_plan" : {
"1" : [[
{
"op_name" : "SCAN1",
"op_type" : "SQLiteScan",
"arg_user_name" : "test",
"arg_program_name" : "test",
"arg_relation_name" : "testRelation"
},
{
"op_name" : "SCAN2",
"op_type" : "SQLiteScan",
"arg_user_name" : "test",
"arg_program_name" : "test",
"arg_relation_name" : "testRelation"
},
{
"op_name" : "JOIN",
"op_type" : "LocalJoin",
"arg_child1" : "SCAN1",
"arg_columns1" : ["1"],
"arg_child2" : "SCAN2",
"arg_columns2" : ["0"],
"arg_select1" : ["0"],
"arg_select2" : ["1"]
},
{
"op_name" : "INSERT",
"op_type" : "SQLiteInsert",
"arg_child" : "JOIN",
"arg_user_name" : "test",
"arg_program_name" : "test",
"arg_relation_name" : "testRelationJoin",
"arg_overwrite_table" : "true"
}
]]
}
}
if I add another section, say by copying the "JOIN" map again, the (long)
timing does not change at all. If I remove a section, say by deleting the
"JOIN", it returns instantaneously. This happens independent of what I
remove, so it does not appear to be data-dependent (other than bigger or
smaller than some size threshold). I eventually started manually tweaking
the file to find the boundary, and it's 1024 bytes as shown below.
Here's a few traces for evidence. Note that the "Content-Length" flips from
1025 to 1024 when I remove a single byte from the request and processing
time goes from over 1 second to a few hundred ms.
*% time* curl -i -XPOST localhost:8753/echo -H "Content-type:
application/json" -d @./single_join.5.json
HTTP/1.1 200 OK
Date: Fri, 15 Feb 2013 18:16:18 GMT
Accept-Ranges: bytes
Server: Restlet-Framework/2.1.1
*Content-Length: 1025*
Content-Type: application/xml; charset=UTF-8
{ "logical_ra" : "INSERT(JOIN(SCAN1,SCAN2))", "query_plan" : { "1" :
[[ { "op_name" : "SCAN1", "arg_user_name" :
"test", "arg_rel*aaaaaaaaaaaaaaaaaaaaaaa*tion_name" :
"testRelation" }, { "op_name" : "SCAN2",
"op_type" : "SQLiteScan", "arg_user_name" : "test",
"arg_program_name" : "test", "arg_relation_name" : "testRelation"
}, { "op_name" : "JOIN", "op_type"
: "LocalJoin", "arg_child1" : "SCAN1", "arg_columns1" :
["1"], "arg_child2" : "SCAN2", "arg_columns2" : ["0"],
"arg_select1" : ["0"], "arg_select2" : ["1"] },
{ "op_name" : "INSERT", "op_type" :
"SQLiteInsert", "arg_child" : "JOIN", "arg_user_name" :
"test", "arg_program_name" : "test", "arg_relation_name"
: "testRelationJoin", "arg_overwrite_table" : "true" }
]] }}curl -i -XPOST localhost:8753/echo -H "Content-type:
application/json" -d *0.01s user 0.00s system 1% cpu 1.025 total*
*
*
When I remove a single 'a' from the underlined text above, it drops to a
few hundred ms.
*% time* curl -i -XPOST localhost:8753/echo -H "Content-type:
application/json" -d @./single_join.5.json
HTTP/1.1 200 OK
Date: Fri, 15 Feb 2013 18:17:10 GMT
Accept-Ranges: bytes
Server: Restlet-Framework/2.1.1
*Content-Length: 1024*
Content-Type: application/xml; charset=UTF-8
{ "logical_ra" : "INSERT(JOIN(SCAN1,SCAN2))", "query_plan" : { "1" :
[[ { "op_name" : "SCAN1", "arg_user_name" :
"test", "arg_rel*aaaaaaaaaaaaaaaaaaaaaa*tion_name" :
"testRelation" }, { "op_name" : "SCAN2",
"op_type" : "SQLiteScan", "arg_user_name" : "test",
"arg_program_name" : "test", "arg_relation_name" : "testRelation"
}, { "op_name" : "JOIN", "op_type"
: "LocalJoin", "arg_child1" : "SCAN1", "arg_columns1" :
["1"], "arg_child2" : "SCAN2", "arg_columns2" : ["0"],
"arg_select1" : ["0"], "arg_select2" : ["1"] },
{ "op_name" : "INSERT", "op_type" :
"SQLiteInsert", "arg_child" : "JOIN", "arg_user_name" :
"test", "arg_program_name" : "test", "arg_relation_name"
: "testRelationJoin", "arg_overwrite_table" : "true" }
]] }}curl -i -XPOST localhost:8753/echo -H "Content-type:
application/json" -d *0.01s user 0.01s system 40% cpu 0.028 total*
Does anyone have advice for how I should debug this?
Thanks!
Dan
------------------------------------------------------
http://restlet.tigris.org/ds/viewMessage.do?dsForumId=4447&dsMessageId=3048890
