Hi everyone, Just a note that I created a clean, minimal test example here: https://github.com/dhalperi/restlet-testing
Thanks, Dan On Fri, Feb 15, 2013 at 10:20 AM, Daniel Halperin < [email protected]> wrote: > 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=3048916
