Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Out of memory #16734

Closed
OlafvdSpek opened this issue Mar 14, 2021 · 20 comments · Fixed by #16902
Closed

Out of memory #16734

OlafvdSpek opened this issue Mar 14, 2021 · 20 comments · Fixed by #16902
Assignees
Labels
Bug A problem or regression with an existing feature has-pr An issue that has a pull request pending that may fix this issue. The pull request may be incomplete help wanted
Projects
Milestone

Comments

@OlafvdSpek
Copy link

OlafvdSpek commented Mar 14, 2021

pMA 5.1.1-dev / PHP 8

When trying to browse a large table..

PHP Fatal error:  Allowed memory size of 134217728 bytes exhausted (tried to allocate 68502032 bytes) in libraries/classes/Dbal/DbiMysqli.php on line 244

    public function realQuery($query, $mysqli, $options)
    {
        if ($options == ($options | DatabaseInterface::QUERY_STORE)) {
            $method = MYSQLI_STORE_RESULT;
        } elseif ($options == ($options | DatabaseInterface::QUERY_UNBUFFERED)) {
            $method = MYSQLI_USE_RESULT;
        } else {
            $method = 0;
        }

        return $mysqli->query($query, $method); // 244
    }

($options == ($options | DatabaseInterface::QUERY_STORE)) also looks very curious.

2021-03-14 09:37:51: SET collation_connection = 'utf8mb4_unicode_ci';
2021-03-14 09:37:51: SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';
2021-03-14 09:37:51: SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';
2021-03-14 09:37:51: SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';
2021-03-14 09:37:51: SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';
2021-03-14 09:37:51: SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';
2021-03-14 09:37:51: SELECT DATABASE()
2021-03-14 09:37:51: select * from users where uid != 0 LIMIT 0, 100 
2021-03-14 09:37:51: select * from users where uid != 0    
2021-03-14 09:37:51: SHOW WARNINGS

The second query without limit is the culprit..
The repeated FOREIGN_KEY_CHECKS query looks sub-optimal too.

@williamdes williamdes added this to the 5.1.1 milestone Mar 14, 2021
@williamdes williamdes added Bug A problem or regression with an existing feature help wanted labels Mar 14, 2021
@williamdes williamdes added this to Needs triage in issues via automation Mar 14, 2021
@williamdes williamdes moved this from Needs triage to Medium priority in issues Mar 14, 2021
@williamdes williamdes modified the milestones: 5.1.1, 5.1.2 Apr 23, 2021
@williamdes
Copy link
Member

I could not confirm this, even using a Docker container with very little RAM
Could you help reproducing this issue ?

@OlafvdSpek
Copy link
Author

OlafvdSpek commented Apr 24, 2021

Are you using PHP 8.0 with memory_limit = 128M (the default)? The amount of RAM shouldn't matter.
How did you enable the query log? Do you see the second query without limit (select * from users where uid != 0 )?
Do you see the repeated SHOW SESSION VARIABLES LIKE 'FOREIGN_KEY_CHECKS';?

@williamdes
Copy link
Member

I am trying to debug this on QA but for now did not find any evidence.
Could you apply manually this patch ? (that will help understand the process)
And maybe post the logs here afterwards please :)

diff --git a/libraries/classes/DatabaseInterface.php b/libraries/classes/DatabaseInterface.php
index d05d86aee0..eafff3db6f 100644
--- a/libraries/classes/DatabaseInterface.php
+++ b/libraries/classes/DatabaseInterface.php
@@ -237,9 +237,15 @@ class DatabaseInterface implements DbalInterface
 
                 syslog(
                     LOG_INFO,
-                    'SQL[' . basename($_SERVER['SCRIPT_NAME']) . ']: '
+                    'SQL[' . basename($_SERVER['SCRIPT_NAME']) . '?route=' . Routing::getCurrentRoute() . ']: '
                     . sprintf('%0.3f', $time) . '(W:' . $warningsCount . ') > ' . $query
                 );
                 closelog();
             }
         }

@OlafvdSpek
Copy link
Author

OlafvdSpek commented Apr 24, 2021

route=/table/search I think

Where do these logs show up? I don't see them in /var/log/syslog on Debian. I don't see them in the regular PHP error log either.

@williamdes
Copy link
Member

Here is my current hack, they are hard to find but should be in a /var/log.
If you apply it, that should help debug even more. I added C for cached or not

                syslog(
                    LOG_INFO,
                    sprintf(
                        'SQL[%s?route=%s]: %0.3f(W:%s,C:%s,L:0x%02X) > %s',
                        basename($_SERVER['SCRIPT_NAME']),
                        Routing::getCurrentRoute(),
                        $time,
                        $warningsCount,
                        $cache_affected_rows ? 'y' : 'n',
                        $link,
                        $query
                    )
                );
                error_log(
                    sprintf(
                        'SQL[%s?route=%s]: %0.3f(W:%s,C:%s,L:0x%02X) > %s',
                        basename($_SERVER['SCRIPT_NAME']),
                        Routing::getCurrentRoute(),
                        $time,
                        $warningsCount,
                        $cache_affected_rows ? 'y' : 'n',
                        $link,
                        $query
                    ) . PHP_EOL,
                    3,
                    ROOT_PATH . '/build/sql-log.txt'
                );

@OlafvdSpek
Copy link
Author

OlafvdSpek commented Apr 24, 2021

if ($GLOBALS['cfg']['DBG']['sqllog']) { ;)

And if ($debug) {

This is ran after the query isn't it? So it won't run for the query that runs out of memory.

This might be the culprit:

libraries/classes/Controllers/Table/SearchController.php: 306
libraries/classes/Controllers/Table/SearchController.php: 224
libraries/classes/Routing.php: 186
index.php: 18

@williamdes
Copy link
Member

williamdes commented Apr 24, 2021

I have only one fix in mind that could cause such an issue, and it is the issue #15652
If you revert #16470 does it work ?

This is ran after the query isn't it? So it won't run for the query that runs out of memory.

Yeah, right

Sill trying to find the bug you reported :)

@OlafvdSpek
Copy link
Author

OlafvdSpek commented Apr 24, 2021

                $statement = $analyzed_sql_results['statement'];
                $token_list = $analyzed_sql_results['parser']->list;
                $replaces = [
                    // Remove ORDER BY to decrease unnecessary sorting time
                    [   
                        'ORDER BY',
                        '',
                    ],
                    // Removes LIMIT clause that might have been added
                    [   
                        'LIMIT',
                        '',
                    ],
                ];
                $count_query = Query::replaceClauses(
                    $statement,
                    $token_list,
                    $replaces
                );
                $unlim_num_rows = $this->dbi->numRows($this->dbi->tryQuery($count_query)); // this doesn't look right.

#16470 could certainly be the one.

@williamdes
Copy link
Member

I did some updates to my deploy container to be able to use it locally
https://github.com/sudo-bot/gh-deployer-container#skip-deploy-and-use-your-workspace-folder

I think I have reproduced it, depending on my research criteria it crashes or not the fpm thread

@williamdes
Copy link
Member

Reverting the #16470 fixes the issue

cc @ibennetch this issue is release blocking until fixed, working on it

@williamdes williamdes modified the milestones: 5.1.2, 5.1.1 Apr 24, 2021
@williamdes williamdes moved this from Medium priority to High priority in issues Apr 24, 2021
@williamdes
Copy link
Member

williamdes commented Apr 24, 2021

Hi @OlafvdSpek
I think I have a fix, could you try it please ?
(6433180#diff-e3cad2512d97f55197190835c1aefdeee841ba0998bbd83d1b2449a6f6768637)

williamdes added a commit that referenced this issue Apr 24, 2021
Signed-off-by: William Desportes <williamdes@wdes.fr>
@OlafvdSpek
Copy link
Author

If the original query is like select count(*) from users, the result set size is 1, but wouldn't your query return something different?

issues automation moved this from High priority to Closed Apr 24, 2021
@williamdes
Copy link
Member

If the original query is like select count(*) from users, the result set size is 1, but wouldn't your query return something different?

It should not, the replacing will give the same query as the input and count

The snapshots are up to date, let me know if you find something I missed

@williamdes williamdes self-assigned this Apr 24, 2021
@williamdes williamdes reopened this Apr 25, 2021
issues automation moved this from Closed to Needs triage Apr 25, 2021
@williamdes
Copy link
Member

Should be: (4.9 output)
Screenshot_20210425_101731_com brave browser
Screenshot_20210425_101209_com brave browser

@williamdes
Copy link
Member

I think I have an idea on how to patch this

SELECT COUNT(*) FROM (SELECT * from help_category group by help_category_id) as cnt

The would give the maximum rows in an easy way
As far as I can think that would be a solution for all queries

@williamdes
Copy link
Member

@ibennetch could you give some advice on this one please ?

@williamdes
Copy link
Member

williamdes commented May 12, 2021

See: #16902

I applied this and it works fine

@williamdes
Copy link
Member

@ibennetch this is the last issue blocking the release, what do you think about my patch ?

@williamdes
Copy link
Member

Should be fixed by #16902

@williamdes williamdes added the has-pr An issue that has a pull request pending that may fix this issue. The pull request may be incomplete label May 14, 2021
@williamdes williamdes linked a pull request May 14, 2021 that will close this issue
williamdes added a commit that referenced this issue May 29, 2021
Pull-request: #16902
Fixes: #16734
Signed-off-by: William Desportes <williamdes@wdes.fr>
issues automation moved this from Needs triage to Closed May 29, 2021
@github-actions github-actions bot locked as resolved and limited conversation to collaborators May 30, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Bug A problem or regression with an existing feature has-pr An issue that has a pull request pending that may fix this issue. The pull request may be incomplete help wanted
Projects
issues
  
Closed
Development

Successfully merging a pull request may close this issue.

2 participants