Skip to content
This repository has been archived by the owner on Feb 5, 2024. It is now read-only.

Connection or reconnection strange behavior in response time #168

Closed
pulciux opened this issue Dec 12, 2013 · 18 comments
Closed

Connection or reconnection strange behavior in response time #168

pulciux opened this issue Dec 12, 2013 · 18 comments

Comments

@pulciux
Copy link

pulciux commented Dec 12, 2013

OreintDB 1.6.0
orientdb-odm: lastest master branch
PHP: 5.5.6
Linux x86_64 - OpenSuSE 12.3

Hi all.
I using orientdb-odm by few days now, in conjunction with OrientDB 1.6.0, and I've encountered a strange behavior in multiple db calls after a single connection to the server.
I mean, I guess it's a strange behavior but it may be I forgot some step.

After a db connection using
$parameters = new BindingParameters($this->host,$this->port,$this->user,$this->password,$this->dbname);
$this->oobj = new HttpBinding($parameters);

I call a query or a command method and I get a response in 0.004 seconds.

e.g.
$this->oobj->query("select expand(inE('isSysUsersRoleOfClass')) from #21:0");

If I call them a second or more times the response time increase dramatically: about 0.5 seconds per call or more.

But if before calling a query or a command method I rebind it to the server recreating a new HttpBinding object the response time it still closer to the real server performances.

$this->oobj = new HttpBinding($parameters);
$this->oobj->query("select expand(inE('isSysUsersRoleOfClass')) from #21:0");

$this->oobj = new HttpBinding($parameters);
$this->oobj->query("select expand(inE('isSysUsersRoleOfClass')) from #21:1");
...

That it means, every first call it's executed fast but any further more on the same HttpBinding object takes a lot of time.
I was expecting the opposite behavior.
Any advice?

@odino
Copy link
Member

odino commented Dec 12, 2013

hey @pulciux thanks for the report!

@nrk could this be a problem by re-using the curl handle?

@pulciux
Copy link
Author

pulciux commented Dec 12, 2013

Hi Alessandro.
Thank you for replying.
I've no idea. Have you some suggestion about how to check it out?
I might try to find empirically where is the piece of code causing the biggest loss of performance.

@odino
Copy link
Member

odino commented Dec 12, 2013

that'd be great! it was implemente in this pull request

@pulciux
Copy link
Author

pulciux commented Dec 12, 2013

You totally right!
I saw you can tell to the CurlClient object to reset itself each time you call its execute method.

So I changed my binding initialization that way:

$adapter = new Doctrine\OrientDB\Binding\Adapter\CurlClientAdapter(new CurlClient(true));
$parameters = new BindingParameters($this->host,$this->port,$this->user,$this->password,$this->dbname);
$this->oobj = new HttpBinding($parameters,$adapter);

and it works. No more additional delay.

I'm wondering. Is it a issue related to the culr library in PHP 5.5?

@odino
Copy link
Member

odino commented Dec 12, 2013

I honestly have no idea, especially because the library is only tested on php 5.3 and 5.4 :)

@odino
Copy link
Member

odino commented Dec 12, 2013

@nrk do you have any idea?

@pulciux
Copy link
Author

pulciux commented Dec 12, 2013

Nope.
I should give it a try on a different environment.
When I'll have enough time I'll set up a virtual machine for some test, exchanging components versions.
Thank you. :-)

@nrk
Copy link
Member

nrk commented Dec 12, 2013

@odino & @pulciux sorry I can't look into this until this weekend but I will definitely get back to you after trying to reproduce the same issue.

@pulciux
Copy link
Author

pulciux commented Dec 13, 2013

@nrk, thank you in advance.
If you need any additional info just ask, I'll try to produce it.

@nrk
Copy link
Member

nrk commented Dec 14, 2013

Just did a quick test against OrientDB 1.6.2 using PHP 5.4.17 and 5.5.6 under MacOS X 10.9 but I couldn't reproduce the reported issue: reusing or not the underlying cURL handle didn't make much difference, the observed timings were roughly the same (between 1ms and 4ms).

@pulciux where is the OrientDB database instance running? Same host of your scripts or a remote host?

@pulciux
Copy link
Author

pulciux commented Dec 14, 2013

Same host, connected through remote protocol.

But that's interesting.
Yesterday I've migrated my under develop db from OrientDB 1.6 to 1.6.2 but I haven't tried to change binding setting for orientdb-odm. So I was using it without reusing curl handler.
After your reply I enabled it again and I tried it out. It works as expected. No delay experienced.
Then I've reactivated the older version of OrientDB and the additional delay went back.
So it's definitely related to the OrientDB version.

Here a comparison with curl handler reusing :

OrientDB 1.6.2

2013-12-14T12:28:13+01:00: objects list retrieved
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0051379203796387 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0030069351196289 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0028700828552246 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0036120414733887 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0034480094909668 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.0027210712432861 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1

OrientDB 1.6.0

2013-12-14T12:33:11+01:00: objects list retrieved
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.051347970962524 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.22251796722412 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.29134297370911 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.29687786102295 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.27451682090759 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.31422305107117 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:16 2013] [error] [client 192.168.1.129] PHP Notice: time: 0.35869193077087 in /home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1

@odino
Copy link
Member

odino commented Dec 14, 2013

Ping @lgarulli

On Dec 14, 2013 4:08 PM, "pulciux" notifications@github.com wrote:

Same host, connected through remote protocol.

But that's interesting.
Yesterday I've migrated my under develop db from OrientDB 1.6 to 1.6.2 but
I haven't tried to change binding setting for orientdb-odm. So I was using
it without reusing curl handler.
After your reply I enabled it again and I tried it out. It works as
expected. No delay experienced.
Then I've reactivated the older version of OrientDB and the additional
delay went back.
So it's definitely related to the OrientDB version.

Here a comparison with curl handler reusing :

OrientDB 1.6.2

2013-12-14T12:28:13+01:00: objects list retrieved
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0051379203796387 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0030069351196289 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0028700828552246 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0036120414733887 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0034480094909668 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:28:13 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.0027210712432861 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1

OrientDB 1.6.0

2013-12-14T12:33:11+01:00: objects list retrieved
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.051347970962524 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.22251796722412 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:14 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.29134297370911 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.29687786102295 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.27451682090759 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:15 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.31422305107117 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1
[Sat Dec 14 12:33:16 2013] [error] [client 192.168.1.129] PHP Notice:
time: 0.35869193077087 in
/home/gianluigi/onTheCluod/Work/www/jengine2.3p/jdb/orientdb-odm/src/Doctrine/OrientDB/Binding/Client/Http/CurlClient.php
on line 108, referer: http://192.168.1.133/joshua3/stage.php?nomewin=1


Reply to this email directly or view it on GitHubhttps://github.com//issues/168#issuecomment-30569418
.

@odino
Copy link
Member

odino commented Dec 14, 2013

ooops /cc @lvca

@lvca
Copy link

lvca commented Dec 14, 2013

OrientDB 1.6.2 has little enhancements on performance (and the upcoming 1.6.3 a little more), so I'm expecting it could be faster.

@nrk
Copy link
Member

nrk commented Dec 27, 2013

Considering that this issue seems to be specifically related to 1.6.0 and previous or later releases of OrientDB behave normally with our HTTP bindings, I'd be more inclined to close it and eventually put a note somewhere.

@odino
Copy link
Member

odino commented Dec 30, 2013

ok, thanks @lvca / @pulciux / @nrk for the feedback! For now we can close this!

BTW performance is pretty solid :)

@odino odino closed this as completed Dec 30, 2013
@lvca
Copy link

lvca commented Dec 30, 2013

Great!

@pulciux
Copy link
Author

pulciux commented Dec 31, 2013

Thanks :-)

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants