This Runs Slower than just running cURL to post logs to the HTTP Listener

[EliFinkelshteyn]

Benchmarking on 50 users with a 100 loop count, I get far worse results using this vs cURL. Whereas cURL consistently gives me response times of around 10ms total load time per page on a page where not much is happening, using fluent-logger-php instead immediately increases average load times to about 600ms (all goes well with 10ms response times until about the 200th sample, at which point response times erratically grow into the thousands of ms. I'm guessing this is a buffering issue?

[chobie]

sorry for late response.

(all goes well with 10ms response times until about the 200th sample, at which point response times erratically grow into the thousands of ms. I'm guessing this is a buffering issue?

did you use Fluent\Logger\FluentLogger right?
It will sleep thousand of ms when the socket can't write / read correctly. so this is not buffering issue i think.

https://github.com/fluent/fluent-logger-php/blob/master/src/Fluent/Logger/FluentLogger.php#L372

we are finding better way to handle socket on this project as PHP's socket has many limitations.
please let me us if you have a good idea. thanks

[EliFinkelshteyn]

Yeah, that's definitely what it is. It must be failing and sleeping for 1000ms before retrying. I'll roll it out as is onto a production server and a/b test to see how often that happens in the real world. My feeling is most people logging have at least two separate use cases for logging: business critical and not business critical. If it's the former, sleeping 1000ms and trying again makes sense. If it's the latter, I'd think it makes more sense to just drop that log and keep going to keep things fast. Would it make sense to make this a startup option? Maybe something like:

self::$_fluentLogger = new FluentLogger(array("host" => "localhost","port" => "24224", "retry_socket"=>1);

[chobie]

you are right. I'd like to support that use case. for now I added retry_socket option to above branch. but it might change the option key.

I'll test this and merge in this weekend.

[EliFinkelshteyn]

Sweet, thanks! Let me know if I can help.

[chobie]

@EliFinkelshteyn btw, can you tell me your fluentd structure (send messages to local fluentd or remote fluentd directly) and distribution?
I'd like to improve error handling regarding this issue so I'm taking a look about PHP's fwrite implementation.

[kzk]

@chobie could you merge the above change to master?

[chobie]

@kzk thanks pointing it. i'll test this today.

[repeatedly]

I tried fluent-logger-php with follwing simple code:

<?php
// you can choose your own AutoLoader
require_once __DIR__.'/src/Fluent/Autoloader.php';

use Fluent\Logger\FluentLogger;

Fluent\Autoloader::register();

$logger = new FluentLogger("localhost","24224");

$t = microtime(true);

for ($i = 0; $i < 100000; ++$i) {
    $logger->post("debug.test",array("hello"=>"world"));
}

echo (microtime(true) - $t)

?>

The result of each loops:

10,000 loops: 0.15141582489014 sec
20,000 loops: 1.0778098106384 sec
100,000 loops: 23.173148870468 sec

20000 and 100000 took toooo long time without errors.
What is the problem?

[repeatedly]

Sorry, this is the my local fluentd configuration mistake...orz

[chobie]

I merged some commits from retry_socket_opt branch and I'll check that behavior today (if I keep my guts. hehe)