thr3ads.net - Eventmachine talk - [Eventmachine-talk] sequential calls to HttpClient, [Mar 2009]

If this information is useful, please help other people find it:
Share via:

Paolo Negri

2009-Mar-15 05:02 UTC

[Eventmachine-talk] sequential calls to HttpClient,

Hi Everyone

I have the following Sinatra app

#server.rb
require ''rubygems''
require ''sinatra''

get ''/hello'' do
  sleep 1
  ''hello world''
end
#eof server.rb

that basically  returns a page with content "hello world" after a
delay of 1 second.

Now, when I try to access my application with the following client code

#client.rb
require ''rubygems''
require ''eventmachine''

params = {:host => "127.0.0.1",
          :port => "4567",
          :request => "/hello"}
EM.run do
  1.upto(4) do
    k = EM::Protocols::HttpClient.request(params)
    k.callback { puts Time.now, EM.connection_count }
  end
end
#eof client.rb

I see something unexpected

The Sinatra log is the following

127.0.0.1 - - [15/Mar/2009 08:52:24] "GET /hello HTTP/1.1" 200 11
0.9991
127.0.0.1 - - [15/Mar/2009 08:52:25] "GET /hello HTTP/1.1" 200 11
0.9982
127.0.0.1 - - [15/Mar/2009 08:52:26] "GET /hello HTTP/1.1" 200 11
0.9989
127.0.0.1 - - [15/Mar/2009 08:52:27] "GET /hello HTTP/1.1" 200 11
0.9986

which looks ok, 4 responses, 1 response every second.

But the client output looks like that

Sun Mar 15 08:52:24 +0000 2009
4
Sun Mar 15 08:52:27 +0000 2009
3
Sun Mar 15 08:52:27 +0000 2009
3
Sun Mar 15 08:52:27 +0000 2009
3

So what happens is the thar first call acts as expected and after 1
second I get the output from the callback, but for all the calls after
the first, the callback is triggered only when the last call finishes.
Another interesting data is the connection_count which is the same for
the last 3 calls, as if the connection were hanging.

Just to explain better myself the output I''d expect from the client
would be


Sun Mar 15 08:52:24 +0000 2009
4
Sun Mar 15 08:52:25 +0000 2009
3
Sun Mar 15 08:52:26 +0000 2009
2
Sun Mar 15 08:52:27 +0000 2009
1

What am I missing?

Thanks

Paolo

Aman Gupta

2009-Mar-15 05:42 UTC

head link

[Eventmachine-talk] sequential calls to HttpClient,

Interesting.. can you try HttpClient2 or
http://github.com/igrigorik/em-http-request?

conn = EM::Protocols::HttpClient2.connect ''127.0.0.1'', 4567
req = conn.get(''/hello'')
req.callback{ puts Time.now}

require ''em-http''
http =
EventMachine::HttpRequest.new(''http://127.0.0.1:4567/hello'').get
http.callback{ puts Time.now }

  Aman

On Sun, Mar 15, 2009 at 3:02 AM, Paolo Negri <hungrylist at gmail.com>
wrote:> Hi Everyone
>
> I have the following Sinatra app
>
> #server.rb
> require ''rubygems''
> require ''sinatra''
>
> get ''/hello'' do
> ?sleep 1
> ?''hello world''
> end
> #eof server.rb
>
> that basically ?returns a page with content "hello world" after a
> delay of 1 second.
>
> Now, when I try to access my application with the following client code
>
> #client.rb
> require ''rubygems''
> require ''eventmachine''
>
> params = {:host => "127.0.0.1",
> ? ? ? ? ?:port => "4567",
> ? ? ? ? ?:request => "/hello"}
> EM.run do
> ?1.upto(4) do
> ? ?k = EM::Protocols::HttpClient.request(params)
> ? ?k.callback { puts Time.now, EM.connection_count }
> ?end
> end
> #eof client.rb
>
> I see something unexpected
>
> The Sinatra log is the following
>
> 127.0.0.1 - - [15/Mar/2009 08:52:24] "GET /hello HTTP/1.1" 200 11
0.9991
> 127.0.0.1 - - [15/Mar/2009 08:52:25] "GET /hello HTTP/1.1" 200 11
0.9982
> 127.0.0.1 - - [15/Mar/2009 08:52:26] "GET /hello HTTP/1.1" 200 11
0.9989
> 127.0.0.1 - - [15/Mar/2009 08:52:27] "GET /hello HTTP/1.1" 200 11
0.9986
>
> which looks ok, 4 responses, 1 response every second.
>
> But the client output looks like that
>
> Sun Mar 15 08:52:24 +0000 2009
> 4
> Sun Mar 15 08:52:27 +0000 2009
> 3
> Sun Mar 15 08:52:27 +0000 2009
> 3
> Sun Mar 15 08:52:27 +0000 2009
> 3
>
> So what happens is the thar first call acts as expected and after 1
> second I get the output from the callback, but for all the calls after
> the first, the callback is triggered only when the last call finishes.
> Another interesting data is the connection_count which is the same for
> the last 3 calls, as if the connection were hanging.
>
> Just to explain better myself the output I''d expect from the
client would be
>
>
> Sun Mar 15 08:52:24 +0000 2009
> 4
> Sun Mar 15 08:52:25 +0000 2009
> 3
> Sun Mar 15 08:52:26 +0000 2009
> 2
> Sun Mar 15 08:52:27 +0000 2009
> 1
>
> What am I missing?
>
> Thanks
>
> Paolo
> _______________________________________________
> Eventmachine-talk mailing list
> Eventmachine-talk at rubyforge.org
> http://rubyforge.org/mailman/listinfo/eventmachine-talk
>

Paolo Negri

2009-Mar-15 06:15 UTC

head link

[Eventmachine-talk] sequential calls to HttpClient,

Hi Aman

Thanks for the quick reply
I get exactly the same result with httpclient2 and em-http
I did try to inspect a bit what''s going on in httpclient and
that''s
what I''ve found

Here''s the sequence of method calls going on in httpclient

so post_init is called for all right at the start. looking good
connection completed happens instantly, good
send_request happens just after connection_completed, good
receiving_data is weird, it happens at the expected moment for the
first connection and only after the last request sends data for the
others

Please note I''ve added a printout of the content (which is hello world
+ timestamp) to check that all contents look ok, and they do.

post_init at Sun Mar 15 10:09:28 +0000 2009
post_init at Sun Mar 15 10:09:28 +0000 2009
post_init at Sun Mar 15 10:09:28 +0000 2009
post_init at Sun Mar 15 10:09:28 +0000 2009
connection_completed at Sun Mar 15 10:09:28 +0000 2009
send request at Sun Mar 15 10:09:28 +0000 2009
connection_completed at Sun Mar 15 10:09:28 +0000 2009
send request at Sun Mar 15 10:09:28 +0000 2009
connection_completed at Sun Mar 15 10:09:28 +0000 2009
send request at Sun Mar 15 10:09:28 +0000 2009
connection_completed at Sun Mar 15 10:09:28 +0000 2009
send request at Sun Mar 15 10:09:28 +0000 2009

receiving data at Sun Mar 15 10:09:29 +0000 2009
parse response line at Sun Mar 15 10:09:29 +0000 2009
content at Sun Mar 15 10:09:29 +0000 2009
hello world Sun Mar 15 10:09:29 +0000 2009
Sun Mar 15 10:09:29 +0000 2009
4
unbind Sun Mar 15 10:09:29 +0000 2009

receiving data at Sun Mar 15 10:09:32 +0000 2009
parse response line at Sun Mar 15 10:09:32 +0000 2009
content at Sun Mar 15 10:09:32 +0000 2009
hello world Sun Mar 15 10:09:30 +0000 2009
Sun Mar 15 10:09:32 +0000 2009
3
receiving data at Sun Mar 15 10:09:32 +0000 2009
parse response line at Sun Mar 15 10:09:32 +0000 2009
content at Sun Mar 15 10:09:32 +0000 2009
hello world Sun Mar 15 10:09:31 +0000 2009
Sun Mar 15 10:09:32 +0000 2009
3
receiving data at Sun Mar 15 10:09:32 +0000 2009
parse response line at Sun Mar 15 10:09:32 +0000 2009
content at Sun Mar 15 10:09:32 +0000 2009
hello world Sun Mar 15 10:09:32 +0000 2009
Sun Mar 15 10:09:32 +0000 2009
3
unbind Sun Mar 15 10:09:32 +0000 2009
unbind Sun Mar 15 10:09:32 +0000 2009
unbind Sun Mar 15 10:09:32 +0000 2009



2009/3/15 Aman Gupta <themastermind1 at
gmail.com>:> Interesting.. can you try HttpClient2 or
> http://github.com/igrigorik/em-http-request?
>
> conn = EM::Protocols::HttpClient2.connect ''127.0.0.1'',
4567
> req = conn.get(''/hello'')
> req.callback{ puts Time.now}
>
> require ''em-http''
> http =
EventMachine::HttpRequest.new(''http://127.0.0.1:4567/hello'').get
> http.callback{ puts Time.now }
>
> ?Aman
>
> On Sun, Mar 15, 2009 at 3:02 AM, Paolo Negri <hungrylist at
gmail.com> wrote:
>> Hi Everyone
>>
>> I have the following Sinatra app
>>
>> #server.rb
>> require ''rubygems''
>> require ''sinatra''
>>
>> get ''/hello'' do
>> ?sleep 1
>> ?''hello world''
>> end
>> #eof server.rb
>>
>> that basically ?returns a page with content "hello world"
after a
>> delay of 1 second.
>>
>> Now, when I try to access my application with the following client code
>>
>> #client.rb
>> require ''rubygems''
>> require ''eventmachine''
>>
>> params = {:host => "127.0.0.1",
>> ? ? ? ? ?:port => "4567",
>> ? ? ? ? ?:request => "/hello"}
>> EM.run do
>> ?1.upto(4) do
>> ? ?k = EM::Protocols::HttpClient.request(params)
>> ? ?k.callback { puts Time.now, EM.connection_count }
>> ?end
>> end
>> #eof client.rb
>>
>> I see something unexpected
>>
>> The Sinatra log is the following
>>
>> 127.0.0.1 - - [15/Mar/2009 08:52:24] "GET /hello HTTP/1.1"
200 11 0.9991
>> 127.0.0.1 - - [15/Mar/2009 08:52:25] "GET /hello HTTP/1.1"
200 11 0.9982
>> 127.0.0.1 - - [15/Mar/2009 08:52:26] "GET /hello HTTP/1.1"
200 11 0.9989
>> 127.0.0.1 - - [15/Mar/2009 08:52:27] "GET /hello HTTP/1.1"
200 11 0.9986
>>
>> which looks ok, 4 responses, 1 response every second.
>>
>> But the client output looks like that
>>
>> Sun Mar 15 08:52:24 +0000 2009
>> 4
>> Sun Mar 15 08:52:27 +0000 2009
>> 3
>> Sun Mar 15 08:52:27 +0000 2009
>> 3
>> Sun Mar 15 08:52:27 +0000 2009
>> 3
>>
>> So what happens is the thar first call acts as expected and after 1
>> second I get the output from the callback, but for all the calls after
>> the first, the callback is triggered only when the last call finishes.
>> Another interesting data is the connection_count which is the same for
>> the last 3 calls, as if the connection were hanging.
>>
>> Just to explain better myself the output I''d expect from the
client would be
>>
>>
>> Sun Mar 15 08:52:24 +0000 2009
>> 4
>> Sun Mar 15 08:52:25 +0000 2009
>> 3
>> Sun Mar 15 08:52:26 +0000 2009
>> 2
>> Sun Mar 15 08:52:27 +0000 2009
>> 1
>>
>> What am I missing?
>>
>> Thanks
>>
>> Paolo
>> _______________________________________________
>> Eventmachine-talk mailing list
>> Eventmachine-talk at rubyforge.org
>> http://rubyforge.org/mailman/listinfo/eventmachine-talk
>>
> _______________________________________________
> Eventmachine-talk mailing list
> Eventmachine-talk at rubyforge.org
> http://rubyforge.org/mailman/listinfo/eventmachine-talk
>

Eventmachine talk - Mar 2009 - sequential calls to HttpClient,

[Eventmachine-talk] sequential calls to HttpClient,

[Eventmachine-talk] sequential calls to HttpClient,

[Eventmachine-talk] sequential calls to HttpClient,