search

friends-of-reactphp / mysql

Async MySQL database client for ReactPHP.
MIT License
334 stars 66 forks source link

Strange behavior while 'free memory' #168

Closed yyydevf closed 1 year ago

yyydevf commented 1 year ago

Hello.

I wanna to create like a cron job for my application: every second select some data from table and do something with them, looks good, but have some troubles;

php -v

PHP 8.1.8 (cli) (built: Jul 26 2022 02:04:15) (NTS)
Copyright (c) The PHP Group
Zend Engine v4.1.8, Copyright (c) Zend Technologies
    with Zend OPcache v8.1.8, Copyright (c), by Zend Technologies
    with Xdebug v3.1.5, Copyright (c) 2002-2022, by Derick Rethans

pecl list

Installed packages, channel pecl.php.net:
=========================================
Package        Version State
event          3.0.8   stable

Example: 

<?php

require_once 'vendor/autoload.php';

$loop = \React\EventLoop\Loop::get();
$factory = new \React\MySQL\Factory();
$connection = $factory->createLazyConnection('root:root@localhost:13306/db1');

$loop->addPeriodicTimer(
    1,
    fn() => $connection->query('SELECT 1')
        ->then(function (\React\MySQL\QueryResult $result) {
            echo count($result->resultRows) . PHP_EOL;
            //some other actions
        })
);

// for diagnostic
$loop->addPeriodicTimer(1, function () {
    echo sprintf(
        '[%s] Current usage %f mb, Max: %f mb' . PHP_EOL,
        (new \DateTime())->getTimestamp(),
        round(memory_get_usage() / 1024 / 1024, 2) . ' mb',
        round(memory_get_peak_usage() / 1024 / 1024, 2) . ' mb'
    );
});

$loop->run():

I do not query anything in database, just select 1, but memory increase per request Ill tested around a hour and can someone explain to me this behavior? Sometimes memory cleared. Whats the magic 450 seconds? Free memory after 450/900/1350/1800 seconds, not every 450 seconds, its arithmetic progression +450 per step

[1670340928] Current usage 3.850000 mb, Max: 4.480000 mb
[1670340929] Current usage 4.200000 mb, Max: 4.480000 mb
[1670340930] Current usage 4.220000 mb, Max: 4.480000 mb

....

[1670341379] Current usage 14.960000 mb, Max: 14.990000 mb
[1670341380] Current usage 14.990000 mb, Max: 15.010000 mb
// After 453 seconds
[1670341381] Current usage 4.360000 mb, Max: 15.060000 mb
[1670341382] Current usage 4.380000 mb, Max: 15.060000 mb

...

[1670342286] Current usage 25.850000 mb, Max: 25.880000 mb
[1670342287] Current usage 25.880000 mb, Max: 25.900000 mb
[1670342288] Current usage 25.900000 mb, Max: 25.930000 mb
// Again, after 900 seconds since last 'memory free'
[1670342289] Current usage 4.520000 mb, Max: 25.930000 mb
[1670342290] Current usage 4.540000 mb, Max: 25.930000 mb
[1670342291] Current usage 4.570000 mb, Max: 25.930000 mb

...

[1670343648] Current usage 36.640000 mb, Max: 36.660000 mb
[1670343649] Current usage 36.660000 mb, Max: 36.680000 mb
[1670343650] Current usage 36.680000 mb, Max: 36.710000 mb
// Again, after  1350 seconds since last 'memory free'
[1670343651] Current usage 4.600000 mb, Max: 36.720000 mb
[1670343652] Current usage 4.620000 mb, Max: 36.720000 mb
[1670343653] Current usage 4.640000 mb, Max: 36.720000 mb
SimonFrings commented 1 year ago

Hey @yyydevf ,thanks for bringing this up :+1:

We're currently not aware of any memory leaks and it's hard to see the time difference when only using the timestamp, but the behavior you're seeing sounds similar to the other ticket you opened in reactphp/http: https://github.com/reactphp/http/issues/477

Could this be the same case here?

yyydevf commented 1 year ago

@SimonFrings Hello, thats not about memory leak, memory have free, but i'm trying to understand, whats the magic 450 seconds

it's hard to see the time difference when only using the timestamp

I have repeated the tests with normal dates, sorry for timestamps:

[14:08:11] Current usage 4.160000 mb, Max: 4.520000 mb
[14:08:12] Current usage 4.450000 mb, Max: 4.520000 mb
[14:08:13] Current usage 4.460000 mb, Max: 4.520000 mb

...

[14:17:53] Current usage 10.190000 mb, Max: 10.240000 mb
[14:17:54] Current usage 10.200000 mb, Max: 10.250000 mb
[14:17:55] Current usage 4.510000 mb, Max: 10.260000 mb
[14:17:56] Current usage 4.520000 mb, Max: 10.260000 mb

but the behavior you're seeing sounds similar to the other ticket you opened in reactphp/http: reactphp/http#477

Could this be the same case here?

Browser works fine.

Code:

<?php

declare(strict_types=1);

require_once 'vendor/autoload.php';

$loop = \React\EventLoop\Loop::get();
$browser = new \React\Http\Browser();

$loop->addPeriodicTimer(
    1,
    fn() => $browser->get('https://google.com')
        ->then(function ( $result) {
            //echo count($result->resultRows) . PHP_EOL;
            //some other actions
        })
);

$loop->addPeriodicTimer(1, function () {
    echo sprintf(
        '[%s] Current usage %f mb, Max: %f mb' . PHP_EOL,
        (new \DateTime())->format("G:i:s"),
        round(memory_get_usage() / 1024 / 1024, 2) . ' mb',
        round(memory_get_peak_usage() / 1024 / 1024, 2) . ' mb'
    );
});

$loop->run();

Log:

[14:15:30] Current usage 4.640000 mb, Max: 4.640000 mb
[14:15:31] Current usage 4.840000 mb, Max: 4.990000 mb
[14:15:32] Current usage 4.860000 mb, Max: 4.990000 mb
[14:15:33] Current usage 4.860000 mb, Max: 4.990000 mb
[14:15:34] Current usage 4.860000 mb, Max: 4.990000 mb
[14:15:35] Current usage 4.860000 mb, Max: 4.990000 mb
[14:15:36] Current usage 4.860000 mb, Max: 4.990000 mb

....

[14:36:05] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:06] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:07] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:08] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:09] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:10] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:11] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:12] Current usage 4.860000 mb, Max: 4.990000 mb
[14:36:13] Current usage 4.860000 mb, Max: 4.990000 mb
yyydevf commented 1 year ago

Can someone explain why free memory only after 10mb, not after every request?

Increasing number of queries have better result:

<?php

declare(strict_types=1);

require_once 'vendor/autoload.php';

$loop = \React\EventLoop\Loop::get();
$factory = new \React\MySQL\Factory();
$connection = $factory->createLazyConnection('root:root@localhost:13306/db1');

$loop->addPeriodicTimer(
    1,
    fn() => \React\Promise\all([
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
        $connection->query('SELECT 1'),
    ])->then(function ($result) {
        //echo count($result->resultRows) . PHP_EOL;
        //some other actions
    })
);

$loop->addPeriodicTimer(1, function () {
    echo sprintf(
        '[%s] Current usage %f mb, Max: %f mb' . PHP_EOL,
        (new \DateTime())->format("G:i:s"),
        round(memory_get_usage() / 1024 / 1024, 2) . ' mb',
        round(memory_get_peak_usage() / 1024 / 1024, 2) . ' mb'
    );
});

$loop->run();

Log

[14:29:56] Current usage 4.340000 mb, Max: 4.530000 mb
[14:29:57] Current usage 4.840000 mb, Max: 4.840000 mb
[14:29:58] Current usage 4.980000 mb, Max: 4.980000 mb

...

[14:30:33] Current usage 9.830000 mb, Max: 9.830000 mb
[14:30:34] Current usage 9.970000 mb, Max: 9.970000 mb
[14:30:35] Current usage 10.110000 mb, Max: 10.110000 mb
[14:30:36] Current usage 10.240000 mb, Max: 10.240000 mb
[14:30:37] Current usage 4.760000 mb, Max: 10.310000 mb
[14:30:38] Current usage 4.890000 mb, Max: 10.310000 mb
[14:30:39] Current usage 5.030000 mb, Max: 10.310000 mb

...

[14:31:13] Current usage 9.690000 mb, Max: 10.310000 mb
[14:31:14] Current usage 9.830000 mb, Max: 10.310000 mb
[14:31:15] Current usage 9.970000 mb, Max: 10.310000 mb
[14:31:16] Current usage 10.110000 mb, Max: 10.310000 mb
[14:31:17] Current usage 10.240000 mb, Max: 10.310000 mb
[14:31:18] Current usage 4.760000 mb, Max: 10.310000 mb
[14:31:19] Current usage 4.890000 mb, Max: 10.310000 mb
[14:31:20] Current usage 5.030000 mb, Max: 10.310000 mb
[14:31:21] Current usage 5.170000 mb, Max: 10.310000 mb

...

[14:31:55] Current usage 9.830000 mb, Max: 10.310000 mb
[14:31:56] Current usage 9.970000 mb, Max: 10.310000 mb
[14:31:57] Current usage 10.110000 mb, Max: 10.310000 mb
[14:31:58] Current usage 10.240000 mb, Max: 10.310000 mb
[14:31:59] Current usage 4.760000 mb, Max: 10.330000 mb
[14:32:00] Current usage 4.890000 mb, Max: 10.330000 mb
[14:32:01] Current usage 5.030000 mb, Max: 10.330000 mb

...

[14:32:36] Current usage 9.830000 mb, Max: 10.330000 mb
[14:32:37] Current usage 9.970000 mb, Max: 10.330000 mb
[14:32:38] Current usage 10.110000 mb, Max: 10.330000 mb
[14:32:39] Current usage 10.240000 mb, Max: 10.330000 mb
[14:32:40] Current usage 4.760000 mb, Max: 10.330000 mb
[14:32:41] Current usage 4.890000 mb, Max: 10.330000 mb
[14:32:42] Current usage 5.030000 mb, Max: 10.330000 mb
[14:32:43] Current usage 5.170000 mb, Max: 10.330000 mb
SimonFrings commented 1 year ago

I think what we see here might be PHP's behavior with cyclic references. As written in this article on php.net :

To avoid having to call the checking of garbage cycles with every possible decrease of a refcount, the algorithm instead puts all possible roots (zvals) in the "root buffer" (marking them "purple"). It also makes sure that each possible garbage root ends up in the buffer only once. Only when the root buffer is full does the collection mechanism start for all the different zvals inside. See step A in the figure above.

As far as I understand it, all cyclic references will be put in a buffer. When this buffer contains a certain number of garbage references PHP will start cleaning them. This is why your memory grows to 10.240000 mb and then drops back to 4.760000 mb, all references are being cleaned.

@clue invested a lot of time in reactphp/promise to get rid of these cyclic garbage references in https://github.com/reactphp/promise/pull/119, https://github.com/reactphp/promise/pull/118 and more. This is also why reactphp/http behaves normal. I don't know if mysql creates cyclic garbage references, this needs some further investigation, but it would explain the behavior you're seeing.

One thing I want to point out is that you're currently only looking at the resolved case when using the query() method, maybe there's an exception thrown but you never catch it, this could also lead to this behavior as described in https://github.com/reactphp/promise/pull/118. Maybe try this:

$loop->addPeriodicTimer(
    1,
    fn() => $connection->query('SELECT 1')->then(
        function (\React\MySQL\QueryResult $result) {
            echo count($result->resultRows) . PHP_EOL;
            //some other actions
        },
        function (Exception $error) {
            echo 'Error: ' . $error->getMessage() . PHP_EOL;
        })
);

I think this should answer your question, this is why I'll close this ticket for now.