Hi @crosfield,
I’m hoping to determine what part of that request is taking a long time – is it the comprehensive query, which fetches information about the entire list of users? Or is it the follow-up queries, which fetch data about each user in the list? If you can tell me how long the first query takes to execute, it’ll help narrow down the cause.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
The first part of the query (from the empty window to the first part of the debug log) takes about 2 minutes:
(mysql): SELECT * FROM sessions WHERE session_id = '[session hash]'
(mysql): SELECT * FROM users WHERE user_id = 1
(mysql): SELECT * FROM user_settings WHERE user_id = '1'
(mysql): SELECT * FROM journals WHERE path = 'vestnik'
(mysql): SELECT * FROM journal_settings WHERE journal_id = '1'
(mysql): SELECT * FROM site
(mysql): SET time_zone = '+3:00'
(mysql): SELECT v.* FROM versions v LEFT JOIN plugin_settings ps ON lower(v.product_class_name) = ps.plugin_name AND ps.setting_name = 'enabled' AND (context_id = '1' OR v.sitewide = 1) WHERE v.current = 1 AND (ps.setting_value = '1' OR v.lazy_load <> 1)
(mysql): SELECT ug.* FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE uug.user_id = 1
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '1'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '2'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '3'
(mysql): SELECT count(*) FROM notifications WHERE user_id = 1 AND date_read IS NULL AND level = 3
(mysql): SELECT * FROM journals WHERE path = 'vestnik'
(mysql): SELECT * FROM journal_settings WHERE journal_id = '1'
(mysql): SELECT setting_name, setting_value, setting_type FROM plugin_settings WHERE plugin_name = 'defaultthemeplugin' AND context_id = 1
(mysql): SELECT setting_name, setting_value, setting_type FROM plugin_settings WHERE plugin_name = 'defaultmanuscriptchildthemeplugin' AND context_id = 1
(mysql): SELECT * FROM notifications WHERE user_id = 1 AND level = 1 ORDER BY date_created DESC
(mysql): SELECT c.* FROM journals c WHERE c.enabled = 1 OR c.journal_id IN (SELECT DISTINCT ug.context_id FROM user_groups ug JOIN user_user_groups uug ON (ug.user_group_id = uug.user_group_id) WHERE uug.user_id = 1) OR 1 IN (SELECT user_id FROM user_groups ug JOIN user_user_groups uug ON (ug.user_group_id = uug.user_group_id) WHERE ug.role_id = 1) ORDER BY seq
(mysql): SELECT ug.* FROM user_groups ug WHERE ug.context_id = 1
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '2'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '3'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '4'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '5'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '6'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '7'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '8'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '9'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '10'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '11'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '12'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '13'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '14'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '15'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '16'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '17'
(mysql): SELECT * FROM user_group_settings WHERE user_group_id = '18'
(mysql): SELECT COUNT(*) FROM (SELECT DISTINCT u.* FROM users AS u LEFT JOIN user_settings us ON (us.user_id = u.user_id AND us.setting_name = 'affiliation') LEFT JOIN user_interests ui ON (u.user_id = ui.user_id) LEFT JOIN controlled_vocab_entry_settings cves ON (ui.controlled_vocab_entry_id = cves.controlled_vocab_entry_id) LEFT JOIN user_user_groups uug ON (uug.user_id = u.user_id) LEFT JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id) LEFT JOIN user_settings usf ON (usf.user_id = u.user_id AND usf.setting_name = 'firstName' AND usf.locale = 'en_US' ) LEFT JOIN user_settings usl ON (usl.user_id = u.user_id AND usl.setting_name = 'lastName' AND usl.locale = 'en_US') WHERE 1=1 AND ug.context_id = 1 ) _ADODB_ALIAS_ LIMIT 1
(mysql): SELECT DISTINCT u.* FROM users AS u LEFT JOIN user_settings us ON (us.user_id = u.user_id AND us.setting_name = 'affiliation') LEFT JOIN user_interests ui ON (u.user_id = ui.user_id) LEFT JOIN controlled_vocab_entry_settings cves ON (ui.controlled_vocab_entry_id = cves.controlled_vocab_entry_id) LEFT JOIN user_user_groups uug ON (uug.user_id = u.user_id) LEFT JOIN user_groups ug ON (ug.user_group_id = uug.user_group_id) LEFT JOIN user_settings usf ON (usf.user_id = u.user_id AND usf.setting_name = 'firstName' AND usf.locale = 'en_US' ) LEFT JOIN user_settings usl ON (usl.user_id = u.user_id AND usl.setting_name = 'lastName' AND usl.locale = 'en_US') WHERE 1=1 AND ug.context_id = 1 ORDER BY usl.setting_value, usf.setting_value LIMIT 0,25
(mysql): SELECT * FROM user_settings WHERE user_id = '18'
(mysql): SELECT * FROM user_settings WHERE user_id = '20'
(mysql): SELECT * FROM user_settings WHERE user_id = '21'
(mysql): SELECT * FROM user_settings WHERE user_id = '27'
(mysql): SELECT * FROM user_settings WHERE user_id = '31'
(mysql): SELECT * FROM user_settings WHERE user_id = '32'
(mysql): SELECT * FROM user_settings WHERE user_id = '35'
(mysql): SELECT * FROM user_settings WHERE user_id = '37'
(mysql): SELECT * FROM user_settings WHERE user_id = '39'
(mysql): SELECT * FROM user_settings WHERE user_id = '43'
(mysql): SELECT * FROM user_settings WHERE user_id = '57'
(mysql): SELECT * FROM user_settings WHERE user_id = '1'
(mysql): SELECT * FROM user_settings WHERE user_id = '10'
(mysql): SELECT * FROM user_settings WHERE user_id = '16'
(mysql): SELECT * FROM user_settings WHERE user_id = '17'
(mysql): SELECT * FROM user_settings WHERE user_id = '9'
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 18 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 20 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 21 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 27 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 31 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 32 AND ug.role_id = 1
The remaining 3-4 minutes take the rest of the queries to complete:
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 35 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 37 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 39 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 43 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 57 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 10 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 16 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 17 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 9 AND ug.role_id = 1
(mysql): SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = 1 AND ug.role_id = 1
{"status":true,"content":"\n\n
Hi @crosfield,
Both halves seem to be taking unusually long. I’d suggest working with these in a MySQL client directly, to see which are slowest; they should all execute more or less instantaneously, so anything that takes a second or two is already suspect.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
I understand this OJS behavior is very strange. And at first I thought that we have a slow server or MySQL database is sending data slowly, but the rest of the frontend and backend interface works quite quickly. And phpMyAdmin displays data very quickly.
In addition, Submissions table is displayed fairly quickly. I know that it is displayed using AJAX, but then AJAX also performs requests to the same MySQL database.
Hi @crosfield,
My best guess is that one of your tables is missing an index, or that you have an unusually large amount of data in one (e.g. out-of-control spam registrations or something). Running some of those queries via the MySQL client directly to determine which is running slowly would be the next step in getting it debugged.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
Roughly understandable, thank you. Say please, 200 KB of response data when getting 16 users is a lot? And how to check what table is missing the index?
Hi @crosfield,
My load of 25 users (the paging limit) takes 1.90 seconds on my laptop (not a speed demon). That should be fairly typical.
Identifying a slow query would be a good start in identifying missing indexes – once we know where to look, we can start checking for missing definitions. But I think it’s more likely that you have some runaway data, as opposed to a missing index.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @crosfield,
By “runaway data”, I mean an unusual amount of data. For example, an account that stuffs the “reviewer interest” field with tens of thousands of entries.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
Thanks for the explanation. I doubt my database contains such data (since the total amount of uncompressed database (about 800 articles) is about 19 MB), but I check every search query. How can I interpret the lack of data for a SQL queries:
SELECT count(*) FROM notifications WHERE user_id = 1 AND date_read IS NULL AND level = 3,
SELECT setting_name, setting_value, setting_type FROM plugin_settings WHERE plugin_name = 'defaultthemeplugin' AND context_id = 1,
SELECT setting_name, setting_value, setting_type FROM plugin_settings WHERE plugin_name = 'defaultmanuscriptchildthemeplugin' AND context_id = 1 and by template like SELECT count(*) FROM user_groups ug JOIN user_user_groups uug ON ug.user_group_id = uug.user_group_id WHERE ug.context_id = 0 AND uug.user_id = <some.number> AND ug.role_id = 1? Everywhere in these queries phpMyAdmin responds “This table does not contain a unique column”. But the queries themselves were successful.
All of requests are executed in a thousandth of a second.
Hi @crosfield,
It’s odd that everything executes in thousandths of a second (that’s the way these queries should be, but it’s hard to explain why the full page doesn’t perform similarly).
The user_user_groups table is not supposed to have a unique column; it associates user_group entries with user entries, and has a unique index on (user_group_id, user_id). So that’s not a problem.
I’d suggest seeing if you can configure a slow query log in your MySQL settings.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
I have already applied to support the computer center of our University. They refused to give me access to MySQL settings or logs. I can only get access to the HTTP logs. From their point of view “our database works perfectly with whole other university sites, deal with your scripts yourself”.
And In HTTP logs I see strange errors like:
[Mon Oct 15 20:32:01.884790 2018] [:error] [pid 8808] [client <IP.address>] PHP Warning: Cannot modify header information - headers already sent by (output started at /http/<user_name>/<domain.name>/html/lib/pkp/lib/adodb/adodb.inc.php:519) in /http/<user_name>/<domain.name>/html/lib/pkp/classes/template/PKPTemplateManager.inc.php on line 864, referer: http://<domain.name>/management/settings/access
[Mon Oct 15 20:32:02.242001 2018] [:error] [pid 7581] [client <IP.address>] PHP Notice: Undefined index: en_US in /http/<user_name>/<domain.name>/html/lib/pkp/classes/controllers/grid/DataObjectGridCellProvider.inc.php on line 68, referer: http://<domain.name>/management/settings/access
What are the methods to understand where in the OJS code execution delays occur?
/lib/pkp/lib/adodb/adodb.inc.php:
519 if (isset($_SERVER['HTTP_USER_AGENT']) || !$newline) echo $msg;
520 else echo strip_tags($msg);
/lib/pkp/classes/template/PKPTemplateManager.inc.php:
863 header('Content-Type: text/html; charset=' . Config::getVar('i18n', 'client_charset'));
864 header('Cache-Control: ' . $this->_cacheability);
/lib/pkp/classes/controllers/grid/DataObjectGridCellProvider.inc.php:
67 // If it's localized, fetch the value in the current locale.
68 if (is_array($data)) $data=$data[$this->getLocale()];Hi @crosfield,
Neither of those warnings would explain the loading behavior (and the “Cannot modify header information” warning is a side-effect of using the Debug setting). If you don’t have enough access to debug this on your server, then I’d suggest getting a local copy running. If it doesn’t exhibit the same behavior, that’ll be useful information (though hard to debug); if it does, then you’ll be able to explore the situation without hitting the limits of your service provider.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
I moved the site and DB to the local machine and analyzed MySQL log. It’s filled with warnings like “InnoDB: Table mysql/innodb_index_stats has length mismatch in the column name table_name. Please run mysql_upgrade” (I use MAMP Pro for MacOS and obviously this is an internal MAMP problem). However, all tables with users are displayed almost instantly.
And I don’t know how to interpret the results of this experiment.
Hi @crosfield,
Hmm, interesting. So between the queries operating quickly on your server when executed through a MySQL client, and the whole thing working quickly on your home system, I’d make a few tentative conclusions…
The most common cause of performance problems is usually experienced in MySQL but that seems not to be the case for you. If you have access to a process list on your server, you could try running that to see if it helps to indicate – you should either see a MySQL process draining a large number of resources, or a PHP process. If you see neither, it might indicate process quotas, or a network wait of some kind.
Regards,
Alec Smecher
Public Knowledge Project Team
Hi @asmecher,
Unfortunately, I do not have access to the list of processes on the University server. The only thing I have is the code and the database. That is why I ask for help in debugging. In this case, I need some kind of tool to localize a piece of code that is “running slowly.” I’m sure of course that everything works fast enough, but 1) maybe some http requests work incorrectly in the server environment, for example, on the server they “knock” into the wrong places: 2) there is a difference in the behavior of PHP versions of Oracle and on my Mac, although it seems to me incredible. Perhaps there are some other reasons that I do not know.
For now, I want to try to temporarily deploy the site on another hosting, where I also cannot see the load statistics, but I can compare the behavior of the systems.
I ask you for help in determining some place in the fetch-grid code into which I could insert some commands for outputting additional debugging information. Unfortunately, I do not have enough knowledge to understand the code myself. In addition, it is likely that the print command will not be the right choice in this case for displaying the values of variables.